From 88037d449058f59566c928766272b13344cc909a Mon Sep 17 00:00:00 2001
From: Vivien Nicolas <vnicolas@apple.com>
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 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:%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 <vnicolas@apple.com>
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;
}