Skip to content

Commit

Permalink
Update message layer logging for consistency of information and ease …
Browse files Browse the repository at this point in the history
…of debugging. (#22465)

* A refresh of a couple of key message layer log lines to not only contain
more information needed to aid with debugging issues or building
automated analyzers, but to also make it much more readable at a glance.

* Review feedback

* Review feedback

* Review feedback

* Wordlist ammendment
  • Loading branch information
mrjerryjohns authored Sep 13, 2022
1 parent abafb40 commit 9441289
Show file tree
Hide file tree
Showing 20 changed files with 473 additions and 74 deletions.
6 changes: 6 additions & 0 deletions .github/.wordlist.txt
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,8 @@ AccessControlEntry
accessor
AccountLogin
acdbc
ack
ACK
ACKed
ACL
ACLs
Expand Down Expand Up @@ -596,6 +598,7 @@ Gradle
gradlew
GroupId
GroupKeyManagement
Groupcast
groupKeySecurityPolicy
groupKeySetID
groupsettings
Expand Down Expand Up @@ -649,6 +652,7 @@ ignoreQueryImage
ihex
IlluminanceMeasurement
IM
IsInitiator
imager
imagetool
imageUri
Expand Down Expand Up @@ -1376,6 +1380,7 @@ unfocus
Unicast
UniFlash
UnitLocalization
Unencrypted
unpair
unprovisioned
untrusted
Expand All @@ -1395,6 +1400,7 @@ userConsentState
userguide
USERINTERFACE
UserLabel
Unsecure
usermod
usr
UTF
Expand Down
10 changes: 0 additions & 10 deletions src/messaging/ExchangeMessageDispatch.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -55,16 +55,6 @@ CHIP_ERROR ExchangeMessageDispatch::SendMessage(SessionManager * sessionManager,
if (reliableMessageContext->HasPiggybackAckPending())
{
payloadHeader.SetAckMessageCounter(reliableMessageContext->TakePendingPeerAckMessageCounter());

#if !defined(NDEBUG)
if (!payloadHeader.HasMessageType(Protocols::SecureChannel::MsgType::StandaloneAck))
{
ChipLogDetail(ExchangeManager,
"Piggybacking Ack for MessageCounter:" ChipLogFormatMessageCounter
" on exchange: " ChipLogFormatExchangeId,
payloadHeader.GetAckMessageCounter().Value(), ChipLogValueExchangeId(exchangeId, isInitiator));
}
#endif
}

if (IsReliableTransmissionAllowed() && reliableMessageContext->AutoRequestAck() &&
Expand Down
42 changes: 36 additions & 6 deletions src/messaging/ExchangeMgr.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -191,11 +191,41 @@ void ExchangeManager::OnMessageReceived(const PacketHeader & packetHeader, const
{
UnsolicitedMessageHandlerSlot * matchingUMH = nullptr;

#if CHIP_PROGRESS_LOGGING
auto * protocolName = Protocols::GetProtocolName(payloadHeader.GetProtocolID());
auto * msgTypeName = Protocols::GetMessageTypeName(payloadHeader.GetProtocolID(), payloadHeader.GetMessageType());

//
// 32-bit value maximum = 10 chars + text preamble (6) + trailer (1) + null (1) + 2 buffer = 20
//
char ackBuf[20];
ackBuf[0] = '\0';
if (payloadHeader.GetAckMessageCounter().HasValue())
{
snprintf(ackBuf, sizeof(ackBuf), " (Ack:" ChipLogFormatMessageCounter ")", payloadHeader.GetAckMessageCounter().Value());
}

CompressedFabricId compressedFabricId = 0;
if (session->IsSecureSession() && mSessionManager->GetFabricTable() != nullptr)
{
auto fabricInfo = mSessionManager->GetFabricTable()->FindFabricWithIndex(session->AsSecureSession()->GetFabricIndex());
if (fabricInfo)
{
compressedFabricId = fabricInfo->GetCompressedFabricId();
}
}

//
// Legend that can be used to decode this log line can be found in README.md
//
ChipLogProgress(ExchangeManager,
"Received message of type " ChipLogFormatMessageType " with protocolId " ChipLogFormatProtocolId
" and MessageCounter:" ChipLogFormatMessageCounter " on exchange " ChipLogFormatExchangeId,
payloadHeader.GetMessageType(), ChipLogValueProtocolId(payloadHeader.GetProtocolID()),
packetHeader.GetMessageCounter(), ChipLogValueExchangeIdFromReceivedHeader(payloadHeader));
">>> [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(),
ChipLogValueX64(session->GetPeer().GetNodeId()), static_cast<uint16_t>(compressedFabricId),
payloadHeader.GetProtocolID().GetProtocolId(), payloadHeader.GetMessageType(), protocolName, msgTypeName);
#endif

MessageFlags msgFlags;
if (isDuplicate == DuplicateMessage::Yes)
Expand Down Expand Up @@ -230,8 +260,8 @@ void ExchangeManager::OnMessageReceived(const PacketHeader & packetHeader, const
}
else
{
ChipLogProgress(ExchangeManager, "Received Groupcast Message with GroupId of %d",
packetHeader.GetDestinationGroupId().Value());
ChipLogProgress(ExchangeManager, "Received Groupcast Message with GroupId 0x%04X (%d)",
packetHeader.GetDestinationGroupId().Value(), packetHeader.GetDestinationGroupId().Value());
}

// Do not handle messages that don't match an existing exchange on an
Expand Down
90 changes: 90 additions & 0 deletions src/messaging/README.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,90 @@
# Message Layer

## Debug Prints

When progress logging is enabled, the message layer emits a number of prints
that provide more details on the messages being sent or received. Most of these
are fairly self explanatory with the exception of the ones listed below.

### Message Transmission

#### Legend

On message transmission, the following print is emitted. The various fields that
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)
```

| Field | Description |
| -------------------- | -------------------------------------------------------------------------------------------------------------------------------------- |
| exchange_id | Exchange ID + IsInitiator flag from message header ('i' if initiator, 'r' if responder') |
| 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 |
| 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. |
| 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 |
| msg_type_name | If available, a logical name for the message type |

#### Examples:

_Unencrypted Unicast:_

```
<<< [E:26341i 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)
```

_Secure Groupcast:_

```
<<< [E:26349i M: 2000] (G) Msg TX to 1:FFFFFFFFFFFF0102 [1667] --- Type 0001:06 (IM:WriteRequest)
```

### Message Reception

#### Legend

On message transmission, the following print is emitted. The various fields that
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)
```

This has a similar legend to that for transmission except `$source` denotes the
source's node identifier and `$fabric_index` is the index on the recipient.

#### Examples

_Unencrypted Unicast:_

```
>>> [E:26341i 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)
```

_Secure Groupcast:_

```
>>> [E:26349i M: 2000] (G) Msg RX from 1:000000000001B669 [0000] --- Type 0001:06 (IM:WriteRequest)
```
12 changes: 0 additions & 12 deletions src/messaging/ReliableMessageContext.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -91,13 +91,6 @@ void ReliableMessageContext::HandleRcvdAck(uint32_t ackMessageCounter)
"CHIP MessageCounter:" ChipLogFormatMessageCounter " not in RetransTable on exchange " ChipLogFormatExchange,
ackMessageCounter, ChipLogValueExchange(GetExchangeContext()));
}
else
{
ChipLogDetail(ExchangeManager,
"Removed CHIP MessageCounter:" ChipLogFormatMessageCounter
" from RetransTable on exchange " ChipLogFormatExchange,
ackMessageCounter, ChipLogValueExchange(GetExchangeContext()));
}
}

CHIP_ERROR ReliableMessageContext::HandleNeedsAck(uint32_t messageCounter, BitFlags<MessageFlagValues> messageFlags)
Expand Down Expand Up @@ -179,11 +172,6 @@ CHIP_ERROR ReliableMessageContext::SendStandaloneAckMessage()
return CHIP_ERROR_NO_MEMORY;
}

// Send the null message
ChipLogDetail(ExchangeManager,
"Sending Standalone Ack for MessageCounter:" ChipLogFormatMessageCounter " on exchange " ChipLogFormatExchange,
mPendingPeerAckMessageCounter, ChipLogValueExchange(GetExchangeContext()));

CHIP_ERROR err = GetExchangeContext()->SendMessage(Protocols::SecureChannel::MsgType::StandaloneAck, std::move(msgBuf),
BitFlags<SendMessageFlags>{ SendMessageFlags::kNoAutoRequestAck });
if (IsSendErrorNonCritical(err))
Expand Down
1 change: 1 addition & 0 deletions src/protocols/BUILD.gn
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@ static_library("protocols") {
output_name = "libChipProtocols"

sources = [
"Protocols.cpp",
"echo/Echo.h",
"echo/EchoClient.cpp",
"echo/EchoServer.cpp",
Expand Down
125 changes: 125 additions & 0 deletions src/protocols/Protocols.cpp
Original file line number Diff line number Diff line change
@@ -0,0 +1,125 @@
/*
* Copyright (c) 2022 Project CHIP Authors
* All rights reserved.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/

#include <protocols/bdx/BdxMessages.h>
#include <protocols/echo/Echo.h>
#include <protocols/interaction_model/Constants.h>
#include <protocols/secure_channel/Constants.h>
#include <protocols/user_directed_commissioning/UserDirectedCommissioning.h>

namespace chip {
namespace Protocols {

static const char * sUnknownTypeName = "----";

static const char * LookupMessageTypeName(const MessageTypeNameLookup * lookupTable, size_t tableSize, uint8_t msgType)
{
for (auto ptr = lookupTable; ptr != (lookupTable + tableSize); ptr++)
{
if (ptr->mId == msgType)
{
return ptr->mName;
}
}

return sUnknownTypeName;
}

const char * GetProtocolName(Id protocolId)
{
if (protocolId.GetVendorId() != VendorId::Common)
{
return sUnknownTypeName;
}

switch (protocolId.GetProtocolId())
{
case InteractionModel::Id.GetProtocolId():
return InteractionModel::kProtocolName;
break;

case SecureChannel::Id.GetProtocolId():
return SecureChannel::kProtocolName;
break;

case BDX::Id.GetProtocolId():
return bdx::kProtocolName;
break;

case Echo::Id.GetProtocolId():
return Echo::kProtocolName;
break;

case UserDirectedCommissioning::Id.GetProtocolId():
return UserDirectedCommissioning::kProtocolName;
break;

default:
return sUnknownTypeName;
}
}

const char * GetMessageTypeName(Id protocolId, uint8_t msgType)
{
if (protocolId.GetVendorId() != VendorId::Common)
{
return sUnknownTypeName;
}

const MessageTypeNameLookup * lookupTable = nullptr;
size_t lookupTableSize = 0;

switch (protocolId.GetProtocolId())
{
case InteractionModel::Id.GetProtocolId():
lookupTable = MessageTypeTraits<InteractionModel::MsgType>::GetTypeToNameTable()->begin();
lookupTableSize = MessageTypeTraits<InteractionModel::MsgType>::GetTypeToNameTable()->size();
break;

case SecureChannel::Id.GetProtocolId():
lookupTable = MessageTypeTraits<SecureChannel::MsgType>::GetTypeToNameTable()->begin();
lookupTableSize = MessageTypeTraits<SecureChannel::MsgType>::GetTypeToNameTable()->size();
break;

case BDX::Id.GetProtocolId():
lookupTable = MessageTypeTraits<bdx::MessageType>::GetTypeToNameTable()->begin();
lookupTableSize = MessageTypeTraits<bdx::MessageType>::GetTypeToNameTable()->size();
break;

case Echo::Id.GetProtocolId():
lookupTable = MessageTypeTraits<Echo::MsgType>::GetTypeToNameTable()->begin();
lookupTableSize = MessageTypeTraits<Echo::MsgType>::GetTypeToNameTable()->size();
break;

case UserDirectedCommissioning::Id.GetProtocolId():
lookupTable = MessageTypeTraits<UserDirectedCommissioning::MsgType>::GetTypeToNameTable()->begin();
lookupTableSize = MessageTypeTraits<UserDirectedCommissioning::MsgType>::GetTypeToNameTable()->size();
break;

default:
//
// TODO: Add support at some point to let applications to route to custom protocols defined outside of the standard
// namespace in the SDK.
//
return sUnknownTypeName;
}

return LookupMessageTypeName(lookupTable, lookupTableSize, msgType);
}

} // namespace Protocols
} // namespace chip
Loading

0 comments on commit 9441289

Please sign in to comment.