From 10567483d4067c0508dc8fb4f4bcd0a23b167185 Mon Sep 17 00:00:00 2001 From: Boris Zbarsky Date: Thu, 2 Dec 2021 06:55:34 -0500 Subject: [PATCH] Fix failing TestTimedHandler unit test. (#12470) This is failing due to a merge conflict between https://github.com/project-chip/connectedhomeip/pull/11988 and https://github.com/project-chip/connectedhomeip/pull/12389: the latter ends up in an error state as described in https://github.com/project-chip/connectedhomeip/pull/12466#issue-793500688 and the former makes our code a lot more sensitive to being in that error state. The fix for the test is to not use the sync mode of loopback transport, which allows the stack for sending a message to unwind before responses are delivered and avoids the "object deleted by response while we are still working with it" problem described in https://github.com/project-chip/connectedhomeip/pull/12466#issue-793500688. When the responses were made async, it turned out the test was missing some "expect response" flags that should have been there all along and it was only passing because the response happened before the send could get to the "close the exchange" stage. With async responses, exchanges were closing too early without the "expect response" flags. Separately we should figure out which parts of https://github.com/project-chip/connectedhomeip/pull/12466 we should do. --- src/app/TimedHandler.cpp | 10 +++++++--- src/app/tests/TestTimedHandler.cpp | 16 +++++++++++++--- 2 files changed, 20 insertions(+), 6 deletions(-) diff --git a/src/app/TimedHandler.cpp b/src/app/TimedHandler.cpp index ae71dcbc03d8ef..52400bce8feb71 100644 --- a/src/app/TimedHandler.cpp +++ b/src/app/TimedHandler.cpp @@ -17,6 +17,7 @@ */ #include "TimedHandler.h" +#include #include #include #include @@ -122,10 +123,13 @@ CHIP_ERROR TimedHandler::HandleTimedRequestAction(Messaging::ExchangeContext * a ChipLogDetail(DataManagement, "Got Timed Request with timeout %" PRIu16 ": handler %p exchange " ChipLogFormatExchange, timeoutMs, this, ChipLogValueExchange(aExchangeContext)); - // Tell the exchange to close after the timeout passes, so we don't get - // stuck waiting forever if the client never sends another message. + // Use at least our default IM timeout, because if we close our exchange as + // soon as we know the delay has passed we won't be able to send the + // UNSUPPORTED_ACCESS status code the spec tells us to send (and in fact + // will send nothing and the other side will have to time out to realize + // it's missed its window). auto delay = System::Clock::Milliseconds32(timeoutMs); - aExchangeContext->SetResponseTimeout(delay); + aExchangeContext->SetResponseTimeout(std::max(delay, kImMessageTimeout)); ReturnErrorOnFailure(StatusResponse::Send(Status::Success, aExchangeContext, /* aExpectResponse = */ true)); // Now just wait for the client. diff --git a/src/app/tests/TestTimedHandler.cpp b/src/app/tests/TestTimedHandler.cpp index cf6dfd9c775945..63d7f1958f42e7 100644 --- a/src/app/tests/TestTimedHandler.cpp +++ b/src/app/tests/TestTimedHandler.cpp @@ -124,6 +124,8 @@ void TestTimedHandler::TestFollowingMessageFastEnough(nlTestSuite * aSuite, void CHIP_ERROR err = exchange->SendMessage(MsgType::TimedRequest, std::move(payload), SendMessageFlags::kExpectResponse); NL_TEST_ASSERT(aSuite, err == CHIP_NO_ERROR); + + ctx.DrainAndServiceIO(); NL_TEST_ASSERT(aSuite, delegate.mNewMessageReceived); NL_TEST_ASSERT(aSuite, delegate.mLastMessageWasStatus); NL_TEST_ASSERT(aSuite, delegate.mStatus.mStatus == Status::Success); @@ -136,8 +138,10 @@ void TestTimedHandler::TestFollowingMessageFastEnough(nlTestSuite * aSuite, void delegate.mKeepExchangeOpen = false; delegate.mNewMessageReceived = false; - err = exchange->SendMessage(aMsgType, std::move(payload)); + err = exchange->SendMessage(aMsgType, std::move(payload), SendMessageFlags::kExpectResponse); NL_TEST_ASSERT(aSuite, err == CHIP_NO_ERROR); + + ctx.DrainAndServiceIO(); NL_TEST_ASSERT(aSuite, delegate.mNewMessageReceived); NL_TEST_ASSERT(aSuite, delegate.mLastMessageWasStatus); NL_TEST_ASSERT(aSuite, delegate.mStatus.mStatus != Status::UnsupportedAccess); @@ -170,6 +174,8 @@ void TestTimedHandler::TestFollowingMessageTooSlow(nlTestSuite * aSuite, void * CHIP_ERROR err = exchange->SendMessage(MsgType::TimedRequest, std::move(payload), SendMessageFlags::kExpectResponse); NL_TEST_ASSERT(aSuite, err == CHIP_NO_ERROR); + + ctx.DrainAndServiceIO(); NL_TEST_ASSERT(aSuite, delegate.mNewMessageReceived); NL_TEST_ASSERT(aSuite, delegate.mLastMessageWasStatus); NL_TEST_ASSERT(aSuite, delegate.mStatus.mStatus == Status::Success); @@ -185,8 +191,10 @@ void TestTimedHandler::TestFollowingMessageTooSlow(nlTestSuite * aSuite, void * delegate.mKeepExchangeOpen = false; delegate.mNewMessageReceived = false; - err = exchange->SendMessage(aMsgType, std::move(payload)); + err = exchange->SendMessage(aMsgType, std::move(payload), SendMessageFlags::kExpectResponse); NL_TEST_ASSERT(aSuite, err == CHIP_NO_ERROR); + + ctx.DrainAndServiceIO(); NL_TEST_ASSERT(aSuite, delegate.mNewMessageReceived); NL_TEST_ASSERT(aSuite, delegate.mLastMessageWasStatus); NL_TEST_ASSERT(aSuite, delegate.mStatus.mStatus == Status::UnsupportedAccess); @@ -217,6 +225,8 @@ void TestTimedHandler::TestInvokeNeverComes(nlTestSuite * aSuite, void * aContex CHIP_ERROR err = exchange->SendMessage(MsgType::TimedRequest, std::move(payload), SendMessageFlags::kExpectResponse); NL_TEST_ASSERT(aSuite, err == CHIP_NO_ERROR); + + ctx.DrainAndServiceIO(); NL_TEST_ASSERT(aSuite, delegate.mNewMessageReceived); NL_TEST_ASSERT(aSuite, delegate.mLastMessageWasStatus); NL_TEST_ASSERT(aSuite, delegate.mStatus.mStatus == Status::Success); @@ -249,7 +259,7 @@ nlTestSuite sSuite = { "TestTimedHandler", &sTests[0], - TestContext::Initialize, + TestContext::InitializeAsync, TestContext::Finalize }; // clang-format on