Rmp log source destination for txrx messages (project-chip#35672)

* [Logging] Add destination to RX logs

* [Logging] Add source to TX logs

* Update the readme about RX/TX logs formatting

Author: vivien-apple

.github/.wordlist.txt

@@ -462,6 +462,7 @@ DV
 DVK
 dynload
 eabi
+EAF
 EB
 ECC
 ECD
@@ -552,6 +553,7 @@ feff
 ffaa
 ffeebaefa
 FFF
+FFFFFFFFFFFF0102
 fffe
 fffff
 Fi

src/messaging/ExchangeMgr.cpp

@@ -195,6 +195,16 @@ void ExchangeManager::OnMessageReceived(const PacketHeader & packetHeader, const
     auto * protocolName = Protocols::GetProtocolName(payloadHeader.GetProtocolID());
     auto * msgTypeName  = Protocols::GetMessageTypeName(payloadHeader.GetProtocolID(), payloadHeader.GetMessageType());
 
+    auto destination = kUndefinedNodeId;
+    if (packetHeader.GetDestinationNodeId().HasValue())
+    {
+        destination = packetHeader.GetDestinationNodeId().Value();
+    }
+    else if (session->IsSecureSession())
+    {
+        destination = session->AsSecureSession()->GetLocalNodeId();
+    }
+
     //
     // 32-bit value maximum = 10 chars + text preamble (6) + trailer (1) + null (1) + 2 buffer = 20
     //
@@ -220,18 +230,25 @@ void ExchangeManager::OnMessageReceived(const PacketHeader & packetHeader, const
     char typeStr[4 + 1 + 2 + 1];
     snprintf(typeStr, sizeof(typeStr), "%04X:%02X", payloadHeader.GetProtocolID().GetProtocolId(), payloadHeader.GetMessageType());
 
+    // More work around pigweed not allowing more than 14 format args in a log
+    // message when using tokenized logs.
+    // text(5) + fabricIndex (uint16_t, at most 5 chars) + text (1) + source (16) + text (2) + compressed fabric id (4) + text (5) +
+    // destination + null-terminator
+    char sourceDestinationStr[5 + 5 + 1 + 16 + 2 + 4 + 5 + 16 + 1];
+    snprintf(sourceDestinationStr, sizeof(sourceDestinationStr), "from %u:" ChipLogFormatX64 " [%04X] to " ChipLogFormatX64,
+             session->GetFabricIndex(), ChipLogValueX64(session->GetPeer().GetNodeId()), static_cast<uint16_t>(compressedFabricId),
+             ChipLogValueX64(destination));
+
     //
     // Legend that can be used to decode this log line can be found in README.md
     //
-    ChipLogProgress(ExchangeManager,
-                    ">>> [E:" ChipLogFormatExchangeId " S:%u M:" ChipLogFormatMessageCounter
-                    "%s] (%s) Msg RX from %u:" ChipLogFormatX64 " [%04X] --- Type %s (%s:%s) (B:%u)",
-                    ChipLogValueExchangeIdFromReceivedHeader(payloadHeader), session->SessionIdForLogging(),
-                    packetHeader.GetMessageCounter(), ackBuf, Transport::GetSessionTypeString(session), session->GetFabricIndex(),
-                    ChipLogValueX64(session->GetPeer().GetNodeId()), static_cast<uint16_t>(compressedFabricId), typeStr,
-                    protocolName, msgTypeName,
-                    static_cast<unsigned>(msgBuf->TotalLength() + packetHeader.EncodeSizeBytes() + packetHeader.MICTagLength() +
-                                          payloadHeader.EncodeSizeBytes()));
+    ChipLogProgress(
+        ExchangeManager,
+        ">>> [E:" ChipLogFormatExchangeId " S:%u M:" ChipLogFormatMessageCounter "%s] (%s) Msg RX %s --- Type %s (%s:%s) (B:%u)",
+        ChipLogValueExchangeIdFromReceivedHeader(payloadHeader), session->SessionIdForLogging(), packetHeader.GetMessageCounter(),
+        ackBuf, Transport::GetSessionTypeString(session), sourceDestinationStr, typeStr, protocolName, msgTypeName,
+        static_cast<unsigned>(msgBuf->TotalLength() + packetHeader.EncodeSizeBytes() + packetHeader.MICTagLength() +
+                              payloadHeader.EncodeSizeBytes()));
 #endif
 
     MessageFlags msgFlags;

src/messaging/README.md

@@ -16,7 +16,7 @@ will be expanded are denoted with `$` .
 Unless specified, numerical values are represented in decimal notation.
 
 ```
-<<< [E:$exchange_id S:$session_id M:$msg_id (Ack: $ack_msg_id)] ($msg_category) Msg TX to $fabric_index:$destination [$compressed_fabric_id] [$peer_address] --- Type $protocol_id:$msg_type ($protocol_name:$msg_type_name) (B:$size)
+<<< [E:$exchange_id S:$session_id M:$msg_id (Ack: $ack_msg_id)] ($msg_category) Msg TX from $source to $fabric_index:$destination [$compressed_fabric_id] [$peer_address] --- Type $protocol_id:$msg_type ($protocol_name:$msg_type_name) (B:$size)
 ```
 
 | Field                | Description                                                                                                                            |
@@ -27,6 +27,7 @@ Unless specified, numerical values are represented in decimal notation.
 | 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                                                                           |
 | fabric_index         | Fabric index on the sending side                                                                                                       |
+| source               | 64-bit Node Identifier that can represent both group, operational and temporary node identifiers depending on `$msg_category` (in hex) |
 | destination          | 64-bit Node Identifier that can represent both group, operational and temporary node identifiers depending on `$msg_category` (in hex) |
 | compressed_fabric_id | If present and valid, lower 16-bits of the compressed fabric ID (in hex). Otherwise, it will be set to 0000.                           |
 | peer_address         | The peer address (IP and port) for the session                                                                                         |
@@ -41,19 +42,19 @@ Unless specified, numerical values are represented in decimal notation.
 _Unencrypted Unicast:_
 
 ```
-<<< [E:26341i S:0 M:264589322] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
+<<< [E:26341i S:0 M:264589322] (U) Msg TX from 0FDE2AE2EAF5D74D to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
 ```
 
 _Secure Unicast:_
 
 ```
-<<< [E:26347i S:5110 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 from 000000000001B669 to 1:0000000012344321 [1667] --- Type 0001:06 (IM:WriteRequest)
 ```
 
 _Secure Groupcast:_
 
 ```
-<<< [E:26349i S:17850 M:2000] (G) Msg TX to 1:FFFFFFFFFFFF0102 [1667] --- Type 0001:06 (IM:WriteRequest)
+<<< [E:26349i S:17850 M:2000] (G) Msg TX from 000000000001B669 to 1:FFFFFFFFFFFF0102 [1667] --- Type 0001:06 (IM:WriteRequest)
 ```
 
 ### Message Reception
@@ -66,7 +67,7 @@ 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 RX from $fabric_index:$source [$compressed_fabric_id] --- Type $protocol_id:$msg_type ($protocol_name:$msg_type_name) (B:$size)
+>>> [E:$exchange_id M: $msg_id (Ack: $ack_msg_id)] ($msg_category) Msg RX from $fabric_index:$source to $destination [$compressed_fabric_id] --- Type $protocol_id:$msg_type ($protocol_name:$msg_type_name) (B:$size)
 ```
 
 This has a similar legend to that for transmission except `$source` denotes the
@@ -77,17 +78,17 @@ source's node identifier and `$fabric_index` is the index on the recipient.
 _Unencrypted Unicast:_
 
 ```
->>> [E:26341i S:0 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 to 0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
 ```
 
 _Secure Unicast:_
 
 ```
->>> [E:26342i S:62311 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 to 0000000012344321 [1667] --- Type 0001:08 (IM:InvokeCommandRequest)
 ```
 
 _Secure Groupcast:_
 
 ```
->>> [E:26349i S:1720 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 to FFFFFFFFFFFF0102 [0000] --- Type 0001:06 (IM:WriteRequest)
 ```

src/transport/SessionManager.cpp

@@ -220,6 +220,7 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P
     FabricIndex fabricIndex;
 #endif // CHIP_PROGRESS_LOGGING
 
+    NodeId sourceNodeId = kUndefinedNodeId;
     PeerAddress destination_address;
 
     switch (sessionHandle->GetSessionType())
@@ -236,7 +237,7 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P
         packetHeader.SetMessageCounter(mGroupClientCounter.GetCounter(isControlMsg));
         mGroupClientCounter.IncrementCounter(isControlMsg);
         packetHeader.SetSessionType(Header::SessionType::kGroupSession);
-        NodeId sourceNodeId = fabric->GetNodeId();
+        sourceNodeId = fabric->GetNodeId();
         packetHeader.SetSourceNodeId(sourceNodeId);
 
         if (!packetHeader.IsValidGroupMsg())
@@ -292,7 +293,7 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P
         CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, destination_address, message->Start(), message->TotalLength());
 
         CryptoContext::NonceStorage nonce;
-        NodeId sourceNodeId = session->GetLocalScopedNodeId().GetNodeId();
+        sourceNodeId = session->GetLocalScopedNodeId().GetNodeId();
         CryptoContext::BuildNonce(nonce, packetHeader.GetSecurityFlags(), messageCounter, sourceNodeId);
 
         ReturnErrorOnFailure(SecureMessageCodec::Encrypt(session->GetCryptoContext(), nonce, payloadHeader, packetHeader, message));
@@ -336,6 +337,10 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P
         {
             destination = session->GetEphemeralInitiatorNodeID();
         }
+        else if (session->GetSessionRole() == Transport::UnauthenticatedSession::SessionRole::kInitiator)
+        {
+            sourceNodeId = session->GetEphemeralInitiatorNodeID();
+        }
 #endif // CHIP_PROGRESS_LOGGING
     }
     break;
@@ -386,16 +391,22 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P
     char exchangeStr[5 + 1 + 1];
     snprintf(exchangeStr, sizeof(exchangeStr), ChipLogFormatExchangeId, ChipLogValueExchangeIdFromSentHeader(payloadHeader));
 
+    // More work around pigweed not allowing more than 14 format args in a log
+    // message when using tokenized logs.
+    // text(5) + source(16) + text(4) + fabricIndex(uint16_t, at most 5 chars) + text(1) + destination(16) + text(2) + compressed
+    // fabric id(4) + text(1) + null-terminator
+    char sourceDestinationStr[5 + 16 + 4 + 5 + 1 + 16 + 2 + 4 + 1 + 1];
+    snprintf(sourceDestinationStr, sizeof(sourceDestinationStr), "from " ChipLogFormatX64 " to %u:" ChipLogFormatX64 " [%04X]",
+             ChipLogValueX64(sourceNodeId), fabricIndex, ChipLogValueX64(destination), static_cast<uint16_t>(compressedFabricId));
+
     //
     // Legend that can be used to decode this log line can be found in messaging/README.md
     //
     ChipLogProgress(ExchangeManager,
-                    "<<< [E:%s S:%u M:" ChipLogFormatMessageCounter "%s] (%s) Msg TX to %u:" ChipLogFormatX64
-                    " [%04X] [%s] --- Type %s (%s:%s) (B:%u)",
+                    "<<< [E:%s S:%u M:" ChipLogFormatMessageCounter "%s] (%s) Msg TX %s [%s] --- Type %s (%s:%s) (B:%u)",
                     exchangeStr, sessionHandle->SessionIdForLogging(), packetHeader.GetMessageCounter(), ackBuf,
-                    Transport::GetSessionTypeString(sessionHandle), fabricIndex, ChipLogValueX64(destination),
-                    static_cast<uint16_t>(compressedFabricId), addressStr, typeStr, protocolName, msgTypeName,
-                    static_cast<unsigned>(message->TotalLength()));
+                    Transport::GetSessionTypeString(sessionHandle), sourceDestinationStr, addressStr, typeStr, protocolName,
+                    msgTypeName, static_cast<unsigned>(message->TotalLength()));
 #endif
 
     preparedMessage = EncryptedPacketBufferHandle::MarkEncrypted(std::move(message));