Skip to content

Commit

Permalink
Include the peer address in "Msg TX" logs. (#29351)
Browse files Browse the repository at this point in the history 
* 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.
  • Loading branch information
@bzbarsky-apple @pull
bzbarsky-apple authored and pull[bot] committed Nov 17, 2023
1 parent 1b349b7 commit 1070723
Show file tree
Hide file tree
Showing 2 changed files with 19 additions and 24 deletions.
3 changes: 2 additions & 1 deletion src/messaging/README.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 |
Expand All @@ -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 |
Expand Down
40 changes: 17 additions & 23 deletions src/transport/SessionManager.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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: {
Expand All @@ -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,
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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<uint16_t>(compressedFabricId),
payloadHeader.GetProtocolID().GetProtocolId(), payloadHeader.GetMessageType(), protocolName, msgTypeName);
ChipLogValueX64(destination), static_cast<uint16_t>(compressedFabricId), addressStr, typeStr, protocolName,
msgTypeName);
#endif

ReturnErrorOnFailure(packetHeader.EncodeBeforeData(message));
Expand Down Expand Up @@ -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: {
Expand All @@ -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:
Expand Down

0 comments on commit 1070723

Please sign in to comment.