Fix chip-tool threading asserts if an interactive command times out. (project-chip#29277)

* Fix chip-tool threading asserts if an interactive command times out.

Since the Matter event loop is still running in interacive mode, we need to do
the command cleanup on that event loop.

* Fixes project-chip#29275
* Fixes project-chip#27535

* Address review comment.

Author: bzbarsky-apple

examples/chip-tool/commands/common/CHIPCommand.cpp

@@ -25,6 +25,7 @@
 #include <lib/support/CodeUtils.h>
 #include <lib/support/ScopedBuffer.h>
 #include <lib/support/TestGroupData.h>
+#include <platform/LockTracker.h>
 
 #if CHIP_CONFIG_TRANSPORT_TRACE_ENABLED
 #include "TraceDecoder.h"
@@ -222,17 +223,17 @@ CHIP_ERROR CHIPCommand::Run()
 
     CHIP_ERROR err = StartWaiting(GetWaitDuration());
 
-    bool deferCleanup = (IsInteractive() && DeferInteractiveCleanup());
-
-    Shutdown();
-
-    if (deferCleanup)
+    if (IsInteractive())
     {
-        sDeferredCleanups.insert(this);
+        bool timedOut;
+        // Give it 2 hours to run our cleanup; that should never get hit in practice.
+        CHIP_ERROR cleanupErr = RunOnMatterQueue(RunCommandCleanup, chip::System::Clock::Seconds16(7200), &timedOut);
+        VerifyOrDie(cleanupErr == CHIP_NO_ERROR);
+        VerifyOrDie(!timedOut);
     }
     else
     {
-        Cleanup();
+        CleanupAfterRun();
     }
 
     MaybeTearDownStack();
@@ -504,6 +505,56 @@ void CHIPCommand::RunQueuedCommand(intptr_t commandArg)
     }
 }
 
+void CHIPCommand::RunCommandCleanup(intptr_t commandArg)
+{
+    auto * command = reinterpret_cast<CHIPCommand *>(commandArg);
+    command->CleanupAfterRun();
+    command->StopWaiting();
+}
+
+void CHIPCommand::CleanupAfterRun()
+{
+    assertChipStackLockedByCurrentThread();
+    bool deferCleanup = (IsInteractive() && DeferInteractiveCleanup());
+
+    Shutdown();
+
+    if (deferCleanup)
+    {
+        sDeferredCleanups.insert(this);
+    }
+    else
+    {
+        Cleanup();
+    }
+}
+
+CHIP_ERROR CHIPCommand::RunOnMatterQueue(MatterWorkCallback callback, chip::System::Clock::Timeout timeout, bool * timedOut)
+{
+    {
+        std::lock_guard<std::mutex> lk(cvWaitingForResponseMutex);
+        mWaitingForResponse = true;
+    }
+
+    auto err = chip::DeviceLayer::PlatformMgr().ScheduleWork(callback, reinterpret_cast<intptr_t>(this));
+    if (CHIP_NO_ERROR != err)
+    {
+        {
+            std::lock_guard<std::mutex> lk(cvWaitingForResponseMutex);
+            mWaitingForResponse = false;
+        }
+        return err;
+    }
+
+    auto waitingUntil = std::chrono::system_clock::now() + std::chrono::duration_cast<std::chrono::seconds>(timeout);
+    {
+        std::unique_lock<std::mutex> lk(cvWaitingForResponseMutex);
+        *timedOut = !cvWaitingForResponse.wait_until(lk, waitingUntil, [this]() { return !this->mWaitingForResponse; });
+    }
+
+    return CHIP_NO_ERROR;
+}
+
 #if !CONFIG_USE_SEPARATE_EVENTLOOP
 static void OnResponseTimeout(chip::System::Layer *, void * appState)
 {
@@ -526,28 +577,15 @@ CHIP_ERROR CHIPCommand::StartWaiting(chip::System::Clock::Timeout duration)
     }
     else
     {
-        {
-            std::lock_guard<std::mutex> lk(cvWaitingForResponseMutex);
-            mWaitingForResponse = true;
-        }
-
-        auto err = chip::DeviceLayer::PlatformMgr().ScheduleWork(RunQueuedCommand, reinterpret_cast<intptr_t>(this));
+        bool timedOut;
+        CHIP_ERROR err = RunOnMatterQueue(RunQueuedCommand, duration, &timedOut);
         if (CHIP_NO_ERROR != err)
         {
-            {
-                std::lock_guard<std::mutex> lk(cvWaitingForResponseMutex);
-                mWaitingForResponse = false;
-            }
             return err;
         }
-
-        auto waitingUntil = std::chrono::system_clock::now() + std::chrono::duration_cast<std::chrono::seconds>(duration);
+        if (timedOut)
         {
-            std::unique_lock<std::mutex> lk(cvWaitingForResponseMutex);
-            if (!cvWaitingForResponse.wait_until(lk, waitingUntil, [this]() { return !this->mWaitingForResponse; }))
-            {
-                mCommandExitStatus = CHIP_ERROR_TIMEOUT;
-            }
+            mCommandExitStatus = CHIP_ERROR_TIMEOUT;
         }
     }
     if (!IsInteractive())

examples/chip-tool/commands/common/CHIPCommand.h

@@ -220,6 +220,18 @@ class CHIPCommand : public Command
     static const chip::Credentials::AttestationTrustStore * sTrustStore;
 
     static void RunQueuedCommand(intptr_t commandArg);
+    typedef decltype(RunQueuedCommand) MatterWorkCallback;
+    static void RunCommandCleanup(intptr_t commandArg);
+
+    // Do cleanup after a commmand is done running.  Must happen with the
+    // Matter stack locked.
+    void CleanupAfterRun();
+
+    // Run the given callback on the Matter thread.  Return whether we managed
+    // to successfully dispatch it to the Matter thread.  If we did, *timedOut
+    // will be set to whether we timed out or whether our mWaitingForResponse
+    // got set to false by the callback itself.
+    CHIP_ERROR RunOnMatterQueue(MatterWorkCallback callback, chip::System::Clock::Timeout timeout, bool * timedOut);
 
     CHIP_ERROR mCommandExitStatus = CHIP_ERROR_INTERNAL;
 

src/app/CommandSender.cpp

@@ -26,6 +26,7 @@
 #include "InteractionModelEngine.h"
 #include "StatusResponse.h"
 #include <app/TimedRequest.h>
+#include <platform/LockTracker.h>
 #include <protocols/Protocols.h>
 #include <protocols/interaction_model/Constants.h>
 
@@ -36,7 +37,14 @@ CommandSender::CommandSender(Callback * apCallback, Messaging::ExchangeManager *
                              bool aSuppressResponse) :
     mExchangeCtx(*this),
     mpCallback(apCallback), mpExchangeMgr(apExchangeMgr), mSuppressResponse(aSuppressResponse), mTimedRequest(aIsTimedRequest)
-{}
+{
+    assertChipStackLockedByCurrentThread();
+}
+
+CommandSender::~CommandSender()
+{
+    assertChipStackLockedByCurrentThread();
+}
 
 CHIP_ERROR CommandSender::AllocateBuffer()
 {

src/app/CommandSender.h

@@ -123,6 +123,7 @@ class CommandSender final : public Messaging::ExchangeDelegate
      */
     CommandSender(Callback * apCallback, Messaging::ExchangeManager * apExchangeMgr, bool aIsTimedRequest = false,
                   bool aSuppressResponse = false);
+    ~CommandSender();
     CHIP_ERROR PrepareCommand(const CommandPathParams & aCommandPathParams, bool aStartDataStruct = true);
     CHIP_ERROR FinishCommand(bool aEndDataStruct = true);
     TLV::TLVWriter * GetCommandDataIBTLVWriter();

src/app/ReadClient.cpp

@@ -32,6 +32,7 @@
 #include <lib/support/FibonacciUtils.h>
 #include <messaging/ReliableMessageMgr.h>
 #include <messaging/ReliableMessageProtocolConfig.h>
+#include <platform/LockTracker.h>
 
 namespace chip {
 namespace app {
@@ -44,6 +45,8 @@ ReadClient::ReadClient(InteractionModelEngine * apImEngine, Messaging::ExchangeM
     mpCallback(apCallback), mOnConnectedCallback(HandleDeviceConnected, this),
     mOnConnectionFailureCallback(HandleDeviceConnectionFailure, this)
 {
+    assertChipStackLockedByCurrentThread();
+
     mpExchangeMgr    = apExchangeMgr;
     mInteractionType = aInteractionType;
 
@@ -89,6 +92,8 @@ void ReadClient::StopResubscription()
 
 ReadClient::~ReadClient()
 {
+    assertChipStackLockedByCurrentThread();
+
     if (IsSubscriptionType())
     {
         StopResubscription();

src/app/WriteClient.h

@@ -36,6 +36,7 @@
 #include <messaging/ExchangeHolder.h>
 #include <messaging/ExchangeMgr.h>
 #include <messaging/Flags.h>
+#include <platform/LockTracker.h>
 #include <protocols/Protocols.h>
 #include <system/SystemPacketBuffer.h>
 #include <system/TLVPacketBufferBackingStore.h>
@@ -127,16 +128,22 @@ class WriteClient : public Messaging::ExchangeDelegate
         mpExchangeMgr(apExchangeMgr),
         mExchangeCtx(*this), mpCallback(apCallback), mTimedWriteTimeoutMs(aTimedWriteTimeoutMs),
         mSuppressResponse(aSuppressResponse)
-    {}
+    {
+        assertChipStackLockedByCurrentThread();
+    }
 
 #if CONFIG_BUILD_FOR_HOST_UNIT_TEST
     WriteClient(Messaging::ExchangeManager * apExchangeMgr, Callback * apCallback, const Optional<uint16_t> & aTimedWriteTimeoutMs,
                 uint16_t aReservedSize) :
         mpExchangeMgr(apExchangeMgr),
         mExchangeCtx(*this), mpCallback(apCallback), mTimedWriteTimeoutMs(aTimedWriteTimeoutMs), mReservedSize(aReservedSize)
-    {}
+    {
+        assertChipStackLockedByCurrentThread();
+    }
 #endif
 
+    ~WriteClient() { assertChipStackLockedByCurrentThread(); }
+
     /**
      *  Encode an attribute value that can be directly encoded using DataModel::Encode. Will create a new chunk when necessary.
      */