From 88037d449058f59566c928766272b13344cc909a Mon Sep 17 00:00:00 2001 From: Vivien Nicolas Date: Fri, 20 Sep 2024 10:22:42 +0200 Subject: [PATCH 1/2] [MRP] Log target retransmission time for a given session/exchange --- src/messaging/ReliableMessageMgr.cpp | 63 ++++++++++++++++++++++------ 1 file changed, 50 insertions(+), 13 deletions(-) diff --git a/src/messaging/ReliableMessageMgr.cpp b/src/messaging/ReliableMessageMgr.cpp index b7bd96f12e1e00..119adeef876972 100644 --- a/src/messaging/ReliableMessageMgr.cpp +++ b/src/messaging/ReliableMessageMgr.cpp @@ -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) @@ -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 @@ -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); @@ -467,22 +476,50 @@ void ReliableMessageMgr::SetAdditionalMRPBackoffTime(const OptionalGetSessionHandle(); // 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:%u]", + 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 From 6c29685986d1b0d94fb4604b999f3c0e664c2cbd Mon Sep 17 00:00:00 2001 From: Vivien Nicolas Date: Tue, 17 Sep 2024 13:52:14 +0200 Subject: [PATCH 2/2] [MRP] Log the local MRP values used when establishing a PASE or a CASE session --- src/protocols/secure_channel/CASESession.cpp | 7 ++++++- src/protocols/secure_channel/PASESession.cpp | 7 ++++++- 2 files changed, 12 insertions(+), 2 deletions(-) diff --git a/src/protocols/secure_channel/CASESession.cpp b/src/protocols/secure_channel/CASESession.cpp index 96cd7e17eef449..e0a0fa744e4cc3 100644 --- a/src/protocols/secure_channel/CASESession.cpp +++ b/src/protocols/secure_channel/CASESession.cpp @@ -872,7 +872,12 @@ CHIP_ERROR CASESession::SendSigma1() mState = State::kSentSigma1; } - ChipLogProgress(SecureChannel, "Sent Sigma1 msg to " ChipLogFormatScopedNodeId, ChipLogValueScopedNodeId(GetPeer())); +#if CHIP_PROGRESS_LOGGING + const auto localMRPConfig = mLocalMRPConfig.Value(); +#endif // CHIP_PROGRESS_LOGGING + ChipLogProgress(SecureChannel, "Sent Sigma1 msg to " ChipLogFormatScopedNodeId " [II:%" PRIu32 "ms AI:%" PRIu32 "ms AT:%ums]", + ChipLogValueScopedNodeId(GetPeer()), localMRPConfig.mIdleRetransTimeout.count(), + localMRPConfig.mActiveRetransTimeout.count(), localMRPConfig.mActiveThresholdTime.count()); mDelegate->OnSessionEstablishmentStarted(); diff --git a/src/protocols/secure_channel/PASESession.cpp b/src/protocols/secure_channel/PASESession.cpp index 1702a159bb111c..6178348ad5d5d5 100644 --- a/src/protocols/secure_channel/PASESession.cpp +++ b/src/protocols/secure_channel/PASESession.cpp @@ -314,7 +314,12 @@ CHIP_ERROR PASESession::SendPBKDFParamRequest() mNextExpectedMsg.SetValue(MsgType::PBKDFParamResponse); - ChipLogDetail(SecureChannel, "Sent PBKDF param request"); +#if CHIP_PROGRESS_LOGGING + const auto localMRPConfig = mLocalMRPConfig.Value(); +#endif // CHIP_PROGRESS_LOGGING + ChipLogProgress(SecureChannel, "Sent PBKDF param request [II:%" PRIu32 "ms AI:%" PRIu32 "ms AT:%ums)", + localMRPConfig.mIdleRetransTimeout.count(), localMRPConfig.mActiveRetransTimeout.count(), + localMRPConfig.mActiveThresholdTime.count()); return CHIP_NO_ERROR; }