From 7e2118ced85b79f88de6e83288b1c50e9dba623a Mon Sep 17 00:00:00 2001 From: Boris Zbarsky Date: Wed, 20 Sep 2023 18:01:51 -0400 Subject: [PATCH] Include the peer address in "Msg TX" logs. (#29351) * Include the peer address in "Msg TX" logs. We had our logging split up into a "Msg TX" log that listed all sorts of info but not the peer address and some "Sending msg" logs that listed the peer address for group and unauthenticated messages, but not secure ones. In the secure case the "Sending msg" log showed no information that was not also shown by the "Msg TX" log. The "Sending msg" log did get shown for MRP retransmits, but those are also logged with "Retransmitting MessageCounter:" logs that allow them to be correlated with the relevant initial "Msg TX" log. The fix here is: 1) Add peer address info in the "Msg TX" logs. 2) Remove the now-redunant "Sending msg" logs. * Address review comment. * Work around limited number of log arguments with pigweed tokenized logging. --- src/messaging/README.md | 3 ++- src/transport/SessionManager.cpp | 40 ++++++++++++++------------------ 2 files changed, 19 insertions(+), 24 deletions(-) diff --git a/src/messaging/README.md b/src/messaging/README.md index af5357e5dece2f..bfb379e22aa49c 100644 --- a/src/messaging/README.md +++ b/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] --- 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] [$peer_address] --- Type $protocol_id:$msg_type ($protocol_name:$msg_type_name) ``` | Field | Description | @@ -29,6 +29,7 @@ Unless specified, numerical values are represented in decimal notation. | fabric_index | Fabric index on the sending side | | 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 | | protocol_id | 16-bit Protocol ID within the common vendor namespace (in hex) | | msg_type | 8-bit message type ID (in hex) | | protocol_name | If available, a logical name for the protocol | diff --git a/src/transport/SessionManager.cpp b/src/transport/SessionManager.cpp index c2041446ab9be9..63e08822c2343c 100644 --- a/src/transport/SessionManager.cpp +++ b/src/transport/SessionManager.cpp @@ -162,6 +162,8 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P FabricIndex fabricIndex; #endif // CHIP_PROGRESS_LOGGING + PeerAddress destination_address; + switch (sessionHandle->GetSessionType()) { case Transport::Session::SessionType::kGroupOutgoing: { @@ -184,7 +186,7 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P return CHIP_ERROR_INTERNAL; } - PeerAddress destination_address = Transport::PeerAddress::Multicast(fabric->GetFabricId(), groupSession->GetGroupId()); + destination_address = Transport::PeerAddress::Multicast(fabric->GetFabricId(), groupSession->GetGroupId()); // Trace before any encryption MATTER_LOG_MESSAGE_SEND(chip::Tracing::OutgoingMessageType::kGroupMessage, &payloadHeader, &packetHeader, @@ -224,7 +226,7 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P .SetSessionId(session->GetPeerSessionId()) // .SetSessionType(Header::SessionType::kUnicastSession); - PeerAddress destination_address = session->GetPeerAddress(); + destination_address = session->GetPeerAddress(); // Trace before any encryption MATTER_LOG_MESSAGE_SEND(chip::Tracing::OutgoingMessageType::kSecureSession, &payloadHeader, &packetHeader, @@ -259,8 +261,8 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P break; } - auto unauthenticated = sessionHandle->AsUnauthenticatedSession(); - PeerAddress destination_address = unauthenticated->GetPeerAddress(); + auto unauthenticated = sessionHandle->AsUnauthenticatedSession(); + destination_address = unauthenticated->GetPeerAddress(); // Trace after all headers are settled. MATTER_LOG_MESSAGE_SEND(chip::Tracing::OutgoingMessageType::kUnauthenticated, &payloadHeader, &packetHeader, @@ -304,16 +306,24 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P snprintf(ackBuf, sizeof(ackBuf), " (Ack:" ChipLogFormatMessageCounter ")", payloadHeader.GetAckMessageCounter().Value()); } + char addressStr[Transport::PeerAddress::kMaxToStringSize] = { 0 }; + destination_address.ToString(addressStr); + + // Work around pigweed not allowing more than 14 format args in a log + // message when using tokenized logs. + char typeStr[4 + 1 + 2 + 1]; + snprintf(typeStr, sizeof(typeStr), "%04X:%02X", payloadHeader.GetProtocolID().GetProtocolId(), payloadHeader.GetMessageType()); + // // Legend that can be used to decode this log line can be found in messaging/README.md // ChipLogProgress(ExchangeManager, "<<< [E:" ChipLogFormatExchangeId " S:%u M:" ChipLogFormatMessageCounter - "%s] (%s) Msg TX to %u:" ChipLogFormatX64 " [%04X] --- Type %04X:%02X (%s:%s)", + "%s] (%s) Msg TX to %u:" ChipLogFormatX64 " [%04X] [%s] --- Type %s (%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); + ChipLogValueX64(destination), static_cast(compressedFabricId), addressStr, typeStr, protocolName, + msgTypeName); #endif ReturnErrorOnFailure(packetHeader.EncodeBeforeData(message)); @@ -341,11 +351,6 @@ CHIP_ERROR SessionManager::SendPreparedMessage(const SessionHandle & sessionHand multicastAddress = Transport::PeerAddress::Multicast(fabric->GetFabricId(), groupSession->GetGroupId()); destination = &multicastAddress; - char addressStr[Transport::PeerAddress::kMaxToStringSize]; - multicastAddress.ToString(addressStr, Transport::PeerAddress::kMaxToStringSize); - - ChipLogProgress(Inet, "(G) Sending msg " ChipLogFormatMessageCounter " to Multicast IPV6 address '%s'", - preparedMessage.GetMessageCounter(), addressStr); } break; case Transport::Session::SessionType::kSecure: { @@ -356,23 +361,12 @@ CHIP_ERROR SessionManager::SendPreparedMessage(const SessionHandle & sessionHand secure->MarkActive(); destination = &secure->GetPeerAddress(); - - ChipLogProgress(Inet, "(S) Sending msg " ChipLogFormatMessageCounter " on secure session with LSID: %u", - preparedMessage.GetMessageCounter(), secure->GetLocalSessionId()); } break; case Transport::Session::SessionType::kUnauthenticated: { auto unauthenticated = sessionHandle->AsUnauthenticatedSession(); unauthenticated->MarkActive(); destination = &unauthenticated->GetPeerAddress(); - -#if CHIP_PROGRESS_LOGGING - char addressStr[Transport::PeerAddress::kMaxToStringSize]; - destination->ToString(addressStr); - - ChipLogProgress(Inet, "(U) Sending msg " ChipLogFormatMessageCounter " to IP address '%s'", - preparedMessage.GetMessageCounter(), addressStr); -#endif } break; default: