From 1100980d3146fdcd3fd51f87c65945b0f15b6b53 Mon Sep 17 00:00:00 2001 From: Boris Zbarsky Date: Fri, 15 Sep 2023 15:31:24 -0400 Subject: [PATCH] Fix chip-tool threading asserts if an interactive command times out. (#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 https://github.com/project-chip/connectedhomeip/issues/29275 * Fixes https://github.com/project-chip/connectedhomeip/issues/27535 * Address review comment. --- .../chip-tool/commands/common/CHIPCommand.cpp | 86 +++++++++++++------ .../chip-tool/commands/common/CHIPCommand.h | 12 +++ src/app/CommandSender.cpp | 10 ++- src/app/CommandSender.h | 1 + src/app/ReadClient.cpp | 5 ++ src/app/WriteClient.h | 11 ++- 6 files changed, 98 insertions(+), 27 deletions(-) diff --git a/examples/chip-tool/commands/common/CHIPCommand.cpp b/examples/chip-tool/commands/common/CHIPCommand.cpp index d348211af7e9e7..944360fb2eea3a 100644 --- a/examples/chip-tool/commands/common/CHIPCommand.cpp +++ b/examples/chip-tool/commands/common/CHIPCommand.cpp @@ -25,6 +25,7 @@ #include #include #include +#include #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(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 lk(cvWaitingForResponseMutex); + mWaitingForResponse = true; + } + + auto err = chip::DeviceLayer::PlatformMgr().ScheduleWork(callback, reinterpret_cast(this)); + if (CHIP_NO_ERROR != err) + { + { + std::lock_guard lk(cvWaitingForResponseMutex); + mWaitingForResponse = false; + } + return err; + } + + auto waitingUntil = std::chrono::system_clock::now() + std::chrono::duration_cast(timeout); + { + std::unique_lock 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 lk(cvWaitingForResponseMutex); - mWaitingForResponse = true; - } - - auto err = chip::DeviceLayer::PlatformMgr().ScheduleWork(RunQueuedCommand, reinterpret_cast(this)); + bool timedOut; + CHIP_ERROR err = RunOnMatterQueue(RunQueuedCommand, duration, &timedOut); if (CHIP_NO_ERROR != err) { - { - std::lock_guard lk(cvWaitingForResponseMutex); - mWaitingForResponse = false; - } return err; } - - auto waitingUntil = std::chrono::system_clock::now() + std::chrono::duration_cast(duration); + if (timedOut) { - std::unique_lock lk(cvWaitingForResponseMutex); - if (!cvWaitingForResponse.wait_until(lk, waitingUntil, [this]() { return !this->mWaitingForResponse; })) - { - mCommandExitStatus = CHIP_ERROR_TIMEOUT; - } + mCommandExitStatus = CHIP_ERROR_TIMEOUT; } } if (!IsInteractive()) diff --git a/examples/chip-tool/commands/common/CHIPCommand.h b/examples/chip-tool/commands/common/CHIPCommand.h index 36732793653504..f1cd84439eae49 100644 --- a/examples/chip-tool/commands/common/CHIPCommand.h +++ b/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; diff --git a/src/app/CommandSender.cpp b/src/app/CommandSender.cpp index 5daceaf05a088a..d579845d2e5d5a 100644 --- a/src/app/CommandSender.cpp +++ b/src/app/CommandSender.cpp @@ -26,6 +26,7 @@ #include "InteractionModelEngine.h" #include "StatusResponse.h" #include +#include #include #include @@ -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() { diff --git a/src/app/CommandSender.h b/src/app/CommandSender.h index 6da9b053856c82..194c4535457562 100644 --- a/src/app/CommandSender.h +++ b/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(); diff --git a/src/app/ReadClient.cpp b/src/app/ReadClient.cpp index caac866aeba08c..373d2051d3457f 100644 --- a/src/app/ReadClient.cpp +++ b/src/app/ReadClient.cpp @@ -32,6 +32,7 @@ #include #include #include +#include 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(); diff --git a/src/app/WriteClient.h b/src/app/WriteClient.h index 2323adc8a337e9..90f0f3a24b6c1a 100644 --- a/src/app/WriteClient.h +++ b/src/app/WriteClient.h @@ -36,6 +36,7 @@ #include #include #include +#include #include #include #include @@ -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 & 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. */