Skip to content

Commit

Permalink
[MRP] Log target retransmission time for a given session/exchange
Browse files Browse the repository at this point in the history
  • Loading branch information
@vivien-apple
vivien-apple committed Sep 20, 2024
1 parent afb1a33 commit 53ace16
Showing 1 changed file with 50 additions and 13 deletions.
63 changes: 50 additions & 13 deletions src/messaging/ReliableMessageMgr.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -129,9 +129,18 @@ void ReliableMessageMgr::ExecuteActions()

VerifyOrDie(!entry->retainedBuf.IsNull());

// Don't check whether the session in the exchange is valid, because when the session is released, the retrans entry is
// cleared inside ExchangeContext::OnSessionReleased, so the session must be valid if the entry exists.
auto session = entry->ec->GetSessionHandle();
uint8_t sendCount = entry->sendCount;
#if CHIP_ERROR_LOGGING || CHIP_DETAIL_LOGGING
#if CHIP_ERROR_LOGGING || CHIP_PROGRESS_LOGGING
uint32_t messageCounter = entry->retainedBuf.GetMessageCounter();
auto fabricIndex = session->GetFabricIndex();
auto destination = kUndefinedNodeId;
if (session->IsSecureSession())
{
destination = session->AsSecureSession()->GetPeerNodeId();
}
#endif // CHIP_ERROR_LOGGING || CHIP_DETAIL_LOGGING

if (sendCount == CHIP_CONFIG_RMP_DEFAULT_MAX_RETRANS)
Expand All @@ -140,13 +149,11 @@ void ReliableMessageMgr::ExecuteActions()
ExchangeHandle ec(entry->ec);

ChipLogError(ExchangeManager,
"Failed to Send CHIP MessageCounter:" ChipLogFormatMessageCounter " on exchange " ChipLogFormatExchange
" sendCount: %u max retries: %d",
messageCounter, ChipLogValueExchange(&ec.Get()), sendCount, CHIP_CONFIG_RMP_DEFAULT_MAX_RETRANS);

// Don't check whether the session in the exchange is valid, because when the session is released, the retrans entry is
// cleared inside ExchangeContext::OnSessionReleased, so the session must be valid if the entry exists.
SessionHandle session = ec->GetSessionHandle();
"<<%d [E:" ChipLogFormatExchange " S:%u M:" ChipLogFormatMessageCounter
"] (%s) Msg Retransmission to %u:" ChipLogFormatX64 " failure (max retries:%d)",
sendCount + 1, ChipLogValueExchange(&entry->ec.Get()), session->SessionIdForLogging(), messageCounter,
Transport::GetSessionTypeString(session), fabricIndex, ChipLogValueX64(destination),
CHIP_CONFIG_RMP_DEFAULT_MAX_RETRANS);

// If the exchange is expecting a response, it will handle sending
// this notification once it detects that it has not gotten a
Expand All @@ -167,10 +174,12 @@ void ReliableMessageMgr::ExecuteActions()
}

entry->sendCount++;

ChipLogProgress(ExchangeManager,
"Retransmitting MessageCounter:" ChipLogFormatMessageCounter " on exchange " ChipLogFormatExchange
" Send Cnt %d",
messageCounter, ChipLogValueExchange(&entry->ec.Get()), entry->sendCount);
"<<%d [E:" ChipLogFormatExchange " S:%u M:" ChipLogFormatMessageCounter
"] (%s) Msg Retransmission to %u:" ChipLogFormatX64,
entry->sendCount, ChipLogValueExchange(&entry->ec.Get()), session->SessionIdForLogging(), messageCounter,
Transport::GetSessionTypeString(session), fabricIndex, ChipLogValueX64(destination));
MATTER_LOG_METRIC(Tracing::kMetricDeviceRMPRetryCount, entry->sendCount);

CalculateNextRetransTime(*entry);
Expand Down Expand Up @@ -467,22 +476,50 @@ void ReliableMessageMgr::SetAdditionalMRPBackoffTime(const Optional<System::Cloc
void ReliableMessageMgr::CalculateNextRetransTime(RetransTableEntry & entry)
{
System::Clock::Timeout baseTimeout = System::Clock::Timeout(0);
const auto sessionHandle = entry.ec->GetSessionHandle();

// Check if we have received at least one application-level message
if (entry.ec->HasReceivedAtLeastOneMessage())
{
// If we have received at least one message, assume peer is active and use ActiveRetransTimeout
baseTimeout = entry.ec->GetSessionHandle()->GetRemoteMRPConfig().mActiveRetransTimeout;
baseTimeout = sessionHandle->GetRemoteMRPConfig().mActiveRetransTimeout;
}
else
{
// If we haven't received at least one message
// Choose active/idle timeout from PeerActiveMode of session per 4.11.2.1. Retransmissions.
baseTimeout = entry.ec->GetSessionHandle()->GetMRPBaseTimeout();
baseTimeout = sessionHandle->GetMRPBaseTimeout();
}

System::Clock::Timeout backoff = ReliableMessageMgr::GetBackoff(baseTimeout, entry.sendCount);
entry.nextRetransTime = System::SystemClock().GetMonotonicTimestamp() + backoff;

#if CHIP_PROGRESS_LOGGING
const auto config = sessionHandle->GetRemoteMRPConfig();
uint32_t messageCounter = entry.retainedBuf.GetMessageCounter();
auto fabricIndex = sessionHandle->GetFabricIndex();
auto destination = kUndefinedNodeId;
bool peerIsActive = false;

if (sessionHandle->IsSecureSession())
{
peerIsActive = sessionHandle->AsSecureSession()->IsPeerActive();
destination = sessionHandle->AsSecureSession()->GetPeerNodeId();
}
else if (sessionHandle->IsUnauthenticatedSession())
{
peerIsActive = sessionHandle->AsUnauthenticatedSession()->IsPeerActive();
}

ChipLogProgress(ExchangeManager,
"??%d [E:" ChipLogFormatExchange " S:%u M:" ChipLogFormatMessageCounter
"] (%s) Msg Retransmission to %u:" ChipLogFormatX64 " in %" PRIu32 "ms [State:%s II:%" PRIu32 " AI:%" PRIu32
" AT:%" PRIu16 "]",
entry.sendCount + 1, ChipLogValueExchange(&entry.ec.Get()), sessionHandle->SessionIdForLogging(),
messageCounter, Transport::GetSessionTypeString(sessionHandle), fabricIndex, ChipLogValueX64(destination),
backoff.count(), peerIsActive ? "Active" : "Idle", config.mIdleRetransTimeout.count(),
config.mActiveRetransTimeout.count(), config.mActiveThresholdTime.count());
#endif // CHIP_PROGRESS_LOGGING
}

#if CHIP_CONFIG_TEST
Expand Down

0 comments on commit 53ace16

Please sign in to comment.