Skip to content

Commit

Permalink
Log session ids when sending/receiving on a secure session. (#24902)
Browse files Browse the repository at this point in the history 
* 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.
  • Loading branch information
@bzbarsky-apple @pull
bzbarsky-apple authored and pull[bot] committed Feb 1, 2024
1 parent 4ab754b commit 3708476
Show file tree
Hide file tree
Showing 5 changed files with 63 additions and 17 deletions.
8 changes: 4 additions & 4 deletions src/messaging/ExchangeMgr.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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<uint16_t>(compressedFabricId),
payloadHeader.GetProtocolID().GetProtocolId(), payloadHeader.GetMessageType(), protocolName, msgTypeName);
#endif
Expand Down
15 changes: 8 additions & 7 deletions src/messaging/README.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 |
Expand All @@ -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
Expand All @@ -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)
```
36 changes: 36 additions & 0 deletions src/transport/Session.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -28,6 +28,12 @@ SecureSession * Session::AsSecureSession()
return static_cast<SecureSession *>(this);
}

const SecureSession * Session::AsConstSecureSession() const
{
VerifyOrDie(GetSessionType() == SessionType::kSecure);
return static_cast<const SecureSession *>(this);
}

UnauthenticatedSession * Session::AsUnauthenticatedSession()
{
VerifyOrDie(GetSessionType() == SessionType::kUnauthenticated);
Expand All @@ -40,12 +46,24 @@ IncomingGroupSession * Session::AsIncomingGroupSession()
return static_cast<IncomingGroupSession *>(this);
}

const IncomingGroupSession * Session::AsConstIncomingGroupSession() const
{
VerifyOrDie(GetSessionType() == SessionType::kGroupIncoming);
return static_cast<const IncomingGroupSession *>(this);
}

OutgoingGroupSession * Session::AsOutgoingGroupSession()
{
VerifyOrDie(GetSessionType() == SessionType::kGroupOutgoing);
return static_cast<OutgoingGroupSession *>(this);
}

const OutgoingGroupSession * Session::AsConstOutgoingGroupSession() const
{
VerifyOrDie(GetSessionType() == SessionType::kGroupOutgoing);
return static_cast<const OutgoingGroupSession *>(this);
}

System::Clock::Timeout Session::ComputeRoundTripTimeout(System::Clock::Timeout upperlayerProcessingTimeout)
{
if (IsGroupSession())
Expand All @@ -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())
Expand Down
9 changes: 9 additions & 0 deletions src/transport/Session.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand All @@ -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<SessionHolder> mHolders;

private:
Expand Down
12 changes: 6 additions & 6 deletions src/transport/SessionManager.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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<uint16_t>(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<uint16_t>(compressedFabricId),
payloadHeader.GetProtocolID().GetProtocolId(), payloadHeader.GetMessageType(), protocolName, msgTypeName);
#endif

ReturnErrorOnFailure(packetHeader.EncodeBeforeData(message));
Expand Down

0 comments on commit 3708476

Please sign in to comment.