From 1973346d408a530f2392e32fb3609c3760795ff1 Mon Sep 17 00:00:00 2001 From: Boris Zbarsky Date: Wed, 8 Feb 2023 11:00:38 -0500 Subject: [PATCH] Log session ids when sending/receiving on a secure session. (#24902) * Log session ids when sending/receiving on a secure session. Includes an "S:..." bit when TX or RX is happening on a secure session. * Address review comment. * Address more review comments. * More review comments. --- src/messaging/ExchangeMgr.cpp | 8 +++---- src/messaging/README.md | 15 ++++++------- src/transport/Session.cpp | 36 ++++++++++++++++++++++++++++++++ src/transport/Session.h | 9 ++++++++ src/transport/SessionManager.cpp | 12 +++++------ 5 files changed, 63 insertions(+), 17 deletions(-) diff --git a/src/messaging/ExchangeMgr.cpp b/src/messaging/ExchangeMgr.cpp index d0592a226411da..1ffce3e3de0316 100644 --- a/src/messaging/ExchangeMgr.cpp +++ b/src/messaging/ExchangeMgr.cpp @@ -219,10 +219,10 @@ void ExchangeManager::OnMessageReceived(const PacketHeader & packetHeader, const // Legend that can be used to decode this log line can be found in README.md // ChipLogProgress(ExchangeManager, - ">>> [E:" ChipLogFormatExchangeId " M:" ChipLogFormatMessageCounter "%s] (%s) Msg RX from %u:" ChipLogFormatX64 - " [%04X] --- Type %04x:%02x (%s:%s)", - ChipLogValueExchangeIdFromReceivedHeader(payloadHeader), packetHeader.GetMessageCounter(), ackBuf, - Transport::GetSessionTypeString(session), session->GetFabricIndex(), + ">>> [E:" ChipLogFormatExchangeId " S:%u M:" ChipLogFormatMessageCounter + "%s] (%s) Msg RX from %u:" ChipLogFormatX64 " [%04X] --- Type %04x:%02x (%s:%s)", + ChipLogValueExchangeIdFromReceivedHeader(payloadHeader), session->SessionIdForLogging(), + packetHeader.GetMessageCounter(), ackBuf, Transport::GetSessionTypeString(session), session->GetFabricIndex(), ChipLogValueX64(session->GetPeer().GetNodeId()), static_cast(compressedFabricId), payloadHeader.GetProtocolID().GetProtocolId(), payloadHeader.GetMessageType(), protocolName, msgTypeName); #endif diff --git a/src/messaging/README.md b/src/messaging/README.md index bab614e85360ae..af5357e5dece2f 100644 --- a/src/messaging/README.md +++ b/src/messaging/README.md @@ -16,12 +16,13 @@ will be expanded are denoted with `$` . Unless specified, numerical values are represented in decimal notation. ``` -<<< [E:$exchange_id M: $msg_id (Ack: $ack_msg_id)] ($msg_category) Msg TX to $fabric_index:$destination [$compressed_fabric_id] --- Type $protocol_id:$msg_type ($protocol_name:$msg_type_name) +<<< [E:$exchange_id S:$session_id M:$msg_id (Ack: $ack_msg_id)] ($msg_category) Msg TX to $fabric_index:$destination [$compressed_fabric_id] --- Type $protocol_id:$msg_type ($protocol_name:$msg_type_name) ``` | Field | Description | | -------------------- | -------------------------------------------------------------------------------------------------------------------------------------- | | exchange_id | Exchange ID + `IsInitiator` flag from message header ('i' if initiator, 'r' if responder') | +| session_id | Local session id for unicast secure, 0 for unicast un-secure, group id for groupcast | | msg_id | Message counter | | ack_msg_id | If present, the ACK message counter. Otherwise, this entire field is omitted from display | | msg_category | U: Un-secure Unicast, S: Secure Unicast, G: Secure Groupcast | @@ -38,19 +39,19 @@ Unless specified, numerical values are represented in decimal notation. _Unencrypted Unicast:_ ``` -<<< [E:26341i M: 264589322] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) +<<< [E:26341i S:0 M:264589322] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) ``` _Secure Unicast:_ ``` -<<< [E:26347i M: 30642895 (Ack: 9203233)] (S) Msg TX to 1:0000000012344321 [1667] --- Type 0001:06 (IM:WriteRequest) +<<< [E:26347i S:5110 M:30642895 (Ack: 9203233)] (S) Msg TX to 1:0000000012344321 [1667] --- Type 0001:06 (IM:WriteRequest) ``` _Secure Groupcast:_ ``` -<<< [E:26349i M: 2000] (G) Msg TX to 1:FFFFFFFFFFFF0102 [1667] --- Type 0001:06 (IM:WriteRequest) +<<< [E:26349i S:17850 M:2000] (G) Msg TX to 1:FFFFFFFFFFFF0102 [1667] --- Type 0001:06 (IM:WriteRequest) ``` ### Message Reception @@ -74,17 +75,17 @@ source's node identifier and `$fabric_index` is the index on the recipient. _Unencrypted Unicast:_ ``` ->>> [E:26341i M: 264589322] (U) Msg RX from 0:0FDE2AE2EAF5D74D [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) +>>> [E:26341i S:0 M:264589322] (U) Msg RX from 0:0FDE2AE2EAF5D74D [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) ``` _Secure Unicast:_ ``` ->>> [E:26342i M: 30642885] (S) Msg RX from 1:000000000001B669 [1667] --- Type 0001:08 (IM:InvokeCommandRequest) +>>> [E:26342i S:62311 M:30642885] (S) Msg RX from 1:000000000001B669 [1667] --- Type 0001:08 (IM:InvokeCommandRequest) ``` _Secure Groupcast:_ ``` ->>> [E:26349i M: 2000] (G) Msg RX from 1:000000000001B669 [0000] --- Type 0001:06 (IM:WriteRequest) +>>> [E:26349i S:1720 M:2000] (G) Msg RX from 1:000000000001B669 [0000] --- Type 0001:06 (IM:WriteRequest) ``` diff --git a/src/transport/Session.cpp b/src/transport/Session.cpp index bae62431dc4fde..18737fb10be961 100644 --- a/src/transport/Session.cpp +++ b/src/transport/Session.cpp @@ -28,6 +28,12 @@ SecureSession * Session::AsSecureSession() return static_cast(this); } +const SecureSession * Session::AsConstSecureSession() const +{ + VerifyOrDie(GetSessionType() == SessionType::kSecure); + return static_cast(this); +} + UnauthenticatedSession * Session::AsUnauthenticatedSession() { VerifyOrDie(GetSessionType() == SessionType::kUnauthenticated); @@ -40,12 +46,24 @@ IncomingGroupSession * Session::AsIncomingGroupSession() return static_cast(this); } +const IncomingGroupSession * Session::AsConstIncomingGroupSession() const +{ + VerifyOrDie(GetSessionType() == SessionType::kGroupIncoming); + return static_cast(this); +} + OutgoingGroupSession * Session::AsOutgoingGroupSession() { VerifyOrDie(GetSessionType() == SessionType::kGroupOutgoing); return static_cast(this); } +const OutgoingGroupSession * Session::AsConstOutgoingGroupSession() const +{ + VerifyOrDie(GetSessionType() == SessionType::kGroupOutgoing); + return static_cast(this); +} + System::Clock::Timeout Session::ComputeRoundTripTimeout(System::Clock::Timeout upperlayerProcessingTimeout) { if (IsGroupSession()) @@ -55,6 +73,24 @@ System::Clock::Timeout Session::ComputeRoundTripTimeout(System::Clock::Timeout u return GetAckTimeout() + upperlayerProcessingTimeout; } +uint16_t Session::SessionIdForLogging() const +{ + switch (GetSessionType()) + { + case Session::SessionType::kGroupIncoming: + return AsConstIncomingGroupSession()->GetGroupId(); + case Session::SessionType::kGroupOutgoing: + return AsConstOutgoingGroupSession()->GetGroupId(); + case Session::SessionType::kSecure: + return AsConstSecureSession()->GetLocalSessionId(); + case Session::SessionType::kUnauthenticated: + return 0; + default: + VerifyOrDie(false); + return 0; + } +} + const char * GetSessionTypeString(const SessionHandle & session) { switch (session->GetSessionType()) diff --git a/src/transport/Session.h b/src/transport/Session.h index e55c4547699864..a05c27f1f7ca3b 100644 --- a/src/transport/Session.h +++ b/src/transport/Session.h @@ -234,6 +234,11 @@ class Session } } + // Return a session id that is usable for logging. This is the local session + // id for secure unicast sessions, 0 for non-secure unicast sessions, and + // the group id for group sessions. + uint16_t SessionIdForLogging() const; + protected: // This should be called by sub-classes at the very beginning of the destructor, before any data field is disposed, such that // the session is still functional during the callback. @@ -248,6 +253,10 @@ class Session void SetFabricIndex(FabricIndex index) { mFabricIndex = index; } + const SecureSession * AsConstSecureSession() const; + const IncomingGroupSession * AsConstIncomingGroupSession() const; + const OutgoingGroupSession * AsConstOutgoingGroupSession() const; + IntrusiveList mHolders; private: diff --git a/src/transport/SessionManager.cpp b/src/transport/SessionManager.cpp index 7cec122a9bcdeb..56f3d16db5039c 100644 --- a/src/transport/SessionManager.cpp +++ b/src/transport/SessionManager.cpp @@ -285,12 +285,12 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P // Legend that can be used to decode this log line can be found in messaging/README.md // ChipLogProgress(ExchangeManager, - "<<< [E:" ChipLogFormatExchangeId " M:" ChipLogFormatMessageCounter "%s] (%s) Msg TX to %u:" ChipLogFormatX64 - " [%04X] --- Type %04X:%02X (%s:%s)", - ChipLogValueExchangeIdFromSentHeader(payloadHeader), packetHeader.GetMessageCounter(), ackBuf, - Transport::GetSessionTypeString(sessionHandle), fabricIndex, ChipLogValueX64(destination), - static_cast(compressedFabricId), payloadHeader.GetProtocolID().GetProtocolId(), - payloadHeader.GetMessageType(), protocolName, msgTypeName); + "<<< [E:" ChipLogFormatExchangeId " S:%u M:" ChipLogFormatMessageCounter + "%s] (%s) Msg TX to %u:" ChipLogFormatX64 " [%04X] --- Type %04X:%02X (%s:%s)", + ChipLogValueExchangeIdFromSentHeader(payloadHeader), sessionHandle->SessionIdForLogging(), + packetHeader.GetMessageCounter(), ackBuf, Transport::GetSessionTypeString(sessionHandle), fabricIndex, + ChipLogValueX64(destination), static_cast(compressedFabricId), + payloadHeader.GetProtocolID().GetProtocolId(), payloadHeader.GetMessageType(), protocolName, msgTypeName); #endif ReturnErrorOnFailure(packetHeader.EncodeBeforeData(message));