Skip to content

Commit

Permalink
Fix failing TestTimedHandler unit test.
Browse files Browse the repository at this point in the history
This is failing due to a merge conflict between
project-chip#11988 and
project-chip#12389: the latter
ends up in an error state as described in
project-chip#12466 (comment)
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
project-chip#12466 (comment).

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
project-chip#12466 we should
do.
  • Loading branch information
bzbarsky-apple committed Dec 2, 2021
1 parent 7b214c9 commit 6408b68
Show file tree
Hide file tree
Showing 2 changed files with 20 additions and 6 deletions.
10 changes: 7 additions & 3 deletions src/app/TimedHandler.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@
*/

#include "TimedHandler.h"
#include <app/InteractionModelDelegate.h>
#include <app/InteractionModelEngine.h>
#include <app/MessageDef/TimedRequestMessage.h>
#include <app/StatusResponse.h>
Expand Down Expand Up @@ -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.
Expand Down
16 changes: 13 additions & 3 deletions src/app/tests/TestTimedHandler.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand All @@ -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);
Expand Down Expand Up @@ -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);
Expand All @@ -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);
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -249,7 +259,7 @@ nlTestSuite sSuite =
{
"TestTimedHandler",
&sTests[0],
TestContext::Initialize,
TestContext::InitializeAsync,
TestContext::Finalize
};
// clang-format on
Expand Down

0 comments on commit 6408b68

Please sign in to comment.