diff --git a/.github/.wordlist.txt b/.github/.wordlist.txt index 3a5f2a11cf5095..e693e22c2850be 100644 --- a/.github/.wordlist.txt +++ b/.github/.wordlist.txt @@ -19,6 +19,8 @@ AccessControlEntry accessor AccountLogin acdbc +ack +ACK ACKed ACL ACLs @@ -596,6 +598,7 @@ Gradle gradlew GroupId GroupKeyManagement +Groupcast groupKeySecurityPolicy groupKeySetID groupsettings @@ -649,6 +652,7 @@ ignoreQueryImage ihex IlluminanceMeasurement IM +IsInitiator imager imagetool imageUri @@ -1376,6 +1380,7 @@ unfocus Unicast UniFlash UnitLocalization +Unencrypted unpair unprovisioned untrusted @@ -1395,6 +1400,7 @@ userConsentState userguide USERINTERFACE UserLabel +Unsecure usermod usr UTF diff --git a/src/messaging/ExchangeMessageDispatch.cpp b/src/messaging/ExchangeMessageDispatch.cpp index 5d39fda0dbdc31..1ffbfe3657c6cd 100644 --- a/src/messaging/ExchangeMessageDispatch.cpp +++ b/src/messaging/ExchangeMessageDispatch.cpp @@ -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() && diff --git a/src/messaging/ExchangeMgr.cpp b/src/messaging/ExchangeMgr.cpp index 9859854c5d54c0..8f6a16c15fa2fb 100644 --- a/src/messaging/ExchangeMgr.cpp +++ b/src/messaging/ExchangeMgr.cpp @@ -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(compressedFabricId), + payloadHeader.GetProtocolID().GetProtocolId(), payloadHeader.GetMessageType(), protocolName, msgTypeName); +#endif MessageFlags msgFlags; if (isDuplicate == DuplicateMessage::Yes) @@ -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 diff --git a/src/messaging/README.md b/src/messaging/README.md new file mode 100644 index 00000000000000..f85a2767b1c8c6 --- /dev/null +++ b/src/messaging/README.md @@ -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) +``` diff --git a/src/messaging/ReliableMessageContext.cpp b/src/messaging/ReliableMessageContext.cpp index d2b47cf52dd64c..06decfc320c41f 100644 --- a/src/messaging/ReliableMessageContext.cpp +++ b/src/messaging/ReliableMessageContext.cpp @@ -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 messageFlags) @@ -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::kNoAutoRequestAck }); if (IsSendErrorNonCritical(err)) diff --git a/src/protocols/BUILD.gn b/src/protocols/BUILD.gn index 463f941e6b8c8e..ed5b9dd94e3cd9 100644 --- a/src/protocols/BUILD.gn +++ b/src/protocols/BUILD.gn @@ -18,6 +18,7 @@ static_library("protocols") { output_name = "libChipProtocols" sources = [ + "Protocols.cpp", "echo/Echo.h", "echo/EchoClient.cpp", "echo/EchoServer.cpp", diff --git a/src/protocols/Protocols.cpp b/src/protocols/Protocols.cpp new file mode 100644 index 00000000000000..a4ad43013fb5e6 --- /dev/null +++ b/src/protocols/Protocols.cpp @@ -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 +#include +#include +#include +#include + +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::GetTypeToNameTable()->begin(); + lookupTableSize = MessageTypeTraits::GetTypeToNameTable()->size(); + break; + + case SecureChannel::Id.GetProtocolId(): + lookupTable = MessageTypeTraits::GetTypeToNameTable()->begin(); + lookupTableSize = MessageTypeTraits::GetTypeToNameTable()->size(); + break; + + case BDX::Id.GetProtocolId(): + lookupTable = MessageTypeTraits::GetTypeToNameTable()->begin(); + lookupTableSize = MessageTypeTraits::GetTypeToNameTable()->size(); + break; + + case Echo::Id.GetProtocolId(): + lookupTable = MessageTypeTraits::GetTypeToNameTable()->begin(); + lookupTableSize = MessageTypeTraits::GetTypeToNameTable()->size(); + break; + + case UserDirectedCommissioning::Id.GetProtocolId(): + lookupTable = MessageTypeTraits::GetTypeToNameTable()->begin(); + lookupTableSize = MessageTypeTraits::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 diff --git a/src/protocols/Protocols.h b/src/protocols/Protocols.h index faadaeedf652d3..feb075e05ae422 100644 --- a/src/protocols/Protocols.h +++ b/src/protocols/Protocols.h @@ -25,6 +25,7 @@ #pragma once #include +#include namespace chip { namespace Protocols { @@ -92,10 +93,48 @@ CHIP_STANDARD_PROTOCOL(Echo, 0x0004) // Echo Protocol. To // Protocols reserved for internal protocol use static constexpr Id NotSpecified(VendorId::NotSpecified, 0xFFFF); // The profile ID is either not specified or a wildcard -// Pre-delare our MessageTypeTraits so message type headers know what they are -// specializing. +// +// Pre-declaration of type traits that protocol headers are expected to define. +// +// A protocol header should first define an enumeration that lists the various message types as enum classes. +// +// It should then define MessageTypeTraits as a template specialization of that enumeration containing two methods: +// 1. static constexpr const Protocols::Id & ProtocolId() that returns the Protocol ID +// 2. static auto GetTypeToNameTable() that returns a pointer to std::array where N = number of +// messages in protocol. +// template struct MessageTypeTraits; +// +// Encapsulates a tuple of message type ID and its associated name. +// +struct MessageTypeNameLookup +{ + // + // Constructor that takes an enumeration value for a specific message ID and its associated name. + // + template + constexpr MessageTypeNameLookup(T id, const char * name) : mId(to_underlying(id)), mName(name) + {} + + const uint8_t mId; + const char * mName; +}; + +// +// Given a protocol ID and a message type ID, retrieve the logical name of that message. +// +// This will not return a nullptr. +// +const char * GetMessageTypeName(Id protocolId, uint8_t msgType); + +// +// Given a protool ID, retrieve the logical name for that protocol. +// +// This will not return a nullptr. +// +const char * GetProtocolName(Id protocolId); + } // namespace Protocols } // namespace chip diff --git a/src/protocols/bdx/BdxMessages.h b/src/protocols/bdx/BdxMessages.h index d1fb419cc0f470..72e1ad2969ab5d 100644 --- a/src/protocols/bdx/BdxMessages.h +++ b/src/protocols/bdx/BdxMessages.h @@ -29,11 +29,14 @@ #include #include #include + namespace chip { namespace bdx { constexpr uint16_t kMaxFileDesignatorLen = 0xFF; +constexpr const char * kProtocolName = "BDX"; + enum class MessageType : uint8_t { SendInit = 0x01, @@ -312,6 +315,26 @@ template <> struct MessageTypeTraits { static constexpr const Protocols::Id & ProtocolId() { return BDX::Id; } + + static auto GetTypeToNameTable() + { + static const std::array typeToNameTable = { + { + { bdx::MessageType::SendInit, "SendInit" }, + { bdx::MessageType::SendAccept, "SendAccept" }, + { bdx::MessageType::ReceiveInit, "ReceiveInit" }, + { bdx::MessageType::ReceiveAccept, "ReceiveAccept" }, + { bdx::MessageType::BlockQuery, "BlockQuery" }, + { bdx::MessageType::Block, "Block" }, + { bdx::MessageType::BlockEOF, "BlockEOF" }, + { bdx::MessageType::BlockAck, "BlockAck" }, + { bdx::MessageType::BlockAckEOF, "BlockAckEOF" }, + { bdx::MessageType::BlockQueryWithSkip, "BlockQueryWithSkip" }, + }, + }; + + return &typeToNameTable; + } }; } // namespace Protocols diff --git a/src/protocols/echo/Echo.h b/src/protocols/echo/Echo.h index c6fba415b20ba6..510bad30c24ca9 100644 --- a/src/protocols/echo/Echo.h +++ b/src/protocols/echo/Echo.h @@ -38,6 +38,8 @@ namespace chip { namespace Protocols { namespace Echo { +constexpr const char * kProtocolName = "Echo"; + /** * Echo Protocol Message Types */ @@ -159,6 +161,18 @@ template <> struct MessageTypeTraits { static constexpr const Protocols::Id & ProtocolId() { return Echo::Id; } + + static auto GetTypeToNameTable() + { + static const std::array typeToNameTable = { + { + { Echo::MsgType::EchoRequest, "EchoRequest" }, + { Echo::MsgType::EchoResponse, "EchoResponse" }, + }, + }; + + return &typeToNameTable; + } }; } // namespace Protocols diff --git a/src/protocols/interaction_model/Constants.h b/src/protocols/interaction_model/Constants.h index 13bd0481eaf0bd..77839513fa66d1 100644 --- a/src/protocols/interaction_model/Constants.h +++ b/src/protocols/interaction_model/Constants.h @@ -27,6 +27,7 @@ #include +#include #include #include @@ -44,6 +45,8 @@ namespace chip { namespace Protocols { namespace InteractionModel { +constexpr const char * kProtocolName = "IM"; + /** * Version of the Interaction Model used by the node. */ @@ -72,6 +75,26 @@ template <> struct MessageTypeTraits { static constexpr const Protocols::Id & ProtocolId() { return InteractionModel::Id; } + + static auto GetTypeToNameTable() + { + static const std::array typeToNameTable = { + { + { InteractionModel::MsgType::StatusResponse, "StatusResponse" }, + { InteractionModel::MsgType::ReadRequest, "ReadRequest" }, + { InteractionModel::MsgType::SubscribeRequest, "SubscribeRequest" }, + { InteractionModel::MsgType::SubscribeResponse, "SubscribeResponse" }, + { InteractionModel::MsgType::ReportData, "ReportData" }, + { InteractionModel::MsgType::WriteRequest, "WriteRequest" }, + { InteractionModel::MsgType::WriteResponse, "WriteResponse" }, + { InteractionModel::MsgType::InvokeCommandRequest, "InvokeCommandRequest" }, + { InteractionModel::MsgType::InvokeCommandResponse, "InvokeCommandResponse" }, + { InteractionModel::MsgType::TimedRequest, "TimedRequest" }, + }, + }; + + return &typeToNameTable; + } }; } // namespace Protocols diff --git a/src/protocols/secure_channel/Constants.h b/src/protocols/secure_channel/Constants.h index 108b547f86e4f8..2e0b104599e1dc 100644 --- a/src/protocols/secure_channel/Constants.h +++ b/src/protocols/secure_channel/Constants.h @@ -25,6 +25,7 @@ #pragma once +#include #include #include @@ -42,6 +43,8 @@ namespace chip { namespace Protocols { namespace SecureChannel { +constexpr const char * kProtocolName = "SecureChannel"; + /** * SecureChannel Protocol Message Types */ @@ -121,6 +124,29 @@ template <> struct MessageTypeTraits { static constexpr const Protocols::Id & ProtocolId() { return SecureChannel::Id; } + + static auto GetTypeToNameTable() + { + static const std::array typeToNameTable = { + { + { SecureChannel::MsgType::MsgCounterSyncReq, "MsgCounterSyncReq" }, + { SecureChannel::MsgType::MsgCounterSyncRsp, "MsgCounterSyncRsp" }, + { SecureChannel::MsgType::StandaloneAck, "StandaloneAck" }, + { SecureChannel::MsgType::PBKDFParamRequest, "PBKDFParamRequest" }, + { SecureChannel::MsgType::PBKDFParamResponse, "PBKDFParamResponse" }, + { SecureChannel::MsgType::PASE_Pake1, "PASE_Pake1" }, + { SecureChannel::MsgType::PASE_Pake2, "PASE_Pake2" }, + { SecureChannel::MsgType::PASE_Pake3, "PASE_Pake3" }, + { SecureChannel::MsgType::CASE_Sigma1, "CASE_Sigma1" }, + { SecureChannel::MsgType::CASE_Sigma2, "CASE_Sigma2" }, + { SecureChannel::MsgType::CASE_Sigma3, "CASE_Sigma3" }, + { SecureChannel::MsgType::CASE_Sigma2Resume, "CASE_Sigma2Resume" }, + { SecureChannel::MsgType::StatusReport, "StatusReport" }, + }, + }; + + return &typeToNameTable; + } }; } // namespace Protocols diff --git a/src/protocols/user_directed_commissioning/UserDirectedCommissioning.h b/src/protocols/user_directed_commissioning/UserDirectedCommissioning.h index 5857266601c2d7..e21c933455e594 100644 --- a/src/protocols/user_directed_commissioning/UserDirectedCommissioning.h +++ b/src/protocols/user_directed_commissioning/UserDirectedCommissioning.h @@ -41,6 +41,8 @@ namespace chip { namespace Protocols { namespace UserDirectedCommissioning { +constexpr const char * kProtocolName = "UserDirectedCommissioning"; + // Cache contains 16 clients. This may need to be tweaked. constexpr uint8_t kMaxUDCClients = 16; @@ -206,6 +208,17 @@ template <> struct MessageTypeTraits { static constexpr const Protocols::Id & ProtocolId() { return UserDirectedCommissioning::Id; } + + static auto GetTypeToNameTable() + { + static const std::array typeToNameTable = { + { + { UserDirectedCommissioning::MsgType::IdentificationDeclaration, "IdentificationDeclaration" }, + }, + }; + + return &typeToNameTable; + } }; } // namespace Protocols diff --git a/src/transport/GroupSession.h b/src/transport/GroupSession.h index 674e4d4537acac..2bc2d82345e151 100644 --- a/src/transport/GroupSession.h +++ b/src/transport/GroupSession.h @@ -44,9 +44,6 @@ class IncomingGroupSession : public Session, public ReferenceCountedGetSessionType()) + { + case Session::SessionType::kGroupIncoming: + case Session::SessionType::kGroupOutgoing: + return "G"; + case Session::SessionType::kSecure: + return "S"; + case Session::SessionType::kUnauthenticated: + return "U"; + default: + return "?"; + } +} + } // namespace Transport } // namespace chip diff --git a/src/transport/Session.h b/src/transport/Session.h index 1e8daac22373a6..52c2868871bf39 100644 --- a/src/transport/Session.h +++ b/src/transport/Session.h @@ -174,9 +174,6 @@ class Session }; virtual SessionType GetSessionType() const = 0; -#if CHIP_PROGRESS_LOGGING - virtual const char * GetSessionTypeString() const = 0; -#endif void AddHolder(SessionHolder & holder) { @@ -257,5 +254,12 @@ class Session FabricIndex mFabricIndex = kUndefinedFabricIndex; }; +// +// Return a string representation of the underlying session. +// +// Always returns a non-null pointer. +// +const char * GetSessionTypeString(const SessionHandle & session); + } // namespace Transport } // namespace chip diff --git a/src/transport/SessionManager.cpp b/src/transport/SessionManager.cpp index 252d8ad02959d6..12f76f4b5073a9 100644 --- a/src/transport/SessionManager.cpp +++ b/src/transport/SessionManager.cpp @@ -32,19 +32,19 @@ #include "transport/TraceMessage.h" #include #include +#include #include #include #include #include #include +#include #include #include #include #include #include -#include - // Global object chip::Transport::GroupPeerTable mGroupPeerMsgCounter; @@ -190,7 +190,7 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P ReturnErrorOnFailure(err); #if CHIP_PROGRESS_LOGGING - destination = kUndefinedNodeId; + destination = NodeIdFromGroupId(groupSession->GetGroupId()); fabricIndex = groupSession->GetFabricIndex(); #endif // CHIP_PROGRESS_LOGGING } @@ -256,13 +256,42 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P return CHIP_ERROR_INTERNAL; } - ChipLogProgress(Inet, - "Prepared %s message %p to 0x" ChipLogFormatX64 " (%u) of type " ChipLogFormatMessageType - " and protocolId " ChipLogFormatProtocolId " on exchange " ChipLogFormatExchangeId - " with MessageCounter:" ChipLogFormatMessageCounter ".", - sessionHandle->GetSessionTypeString(), &preparedMessage, ChipLogValueX64(destination), fabricIndex, - payloadHeader.GetMessageType(), ChipLogValueProtocolId(payloadHeader.GetProtocolID()), - ChipLogValueExchangeIdFromSentHeader(payloadHeader), packetHeader.GetMessageCounter()); +#if CHIP_PROGRESS_LOGGING + CompressedFabricId compressedFabricId = kUndefinedCompressedFabricId; + + if (fabricIndex != kUndefinedFabricIndex && mFabricTable != nullptr) + { + auto fabricInfo = mFabricTable->FindFabricWithIndex(fabricIndex); + if (fabricInfo) + { + compressedFabricId = fabricInfo->GetCompressedFabricId(); + } + } + + 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()); + } + + // + // 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(compressedFabricId), payloadHeader.GetProtocolID().GetProtocolId(), + payloadHeader.GetMessageType(), protocolName, msgTypeName); +#endif ReturnErrorOnFailure(packetHeader.EncodeBeforeData(message)); preparedMessage = EncryptedPacketBufferHandle::MarkEncrypted(std::move(message)); @@ -292,13 +321,8 @@ CHIP_ERROR SessionManager::SendPreparedMessage(const SessionHandle & sessionHand char addressStr[Transport::PeerAddress::kMaxToStringSize]; multicastAddress.ToString(addressStr, Transport::PeerAddress::kMaxToStringSize); - ChipLogProgress(Inet, - "Sending %s msg %p with MessageCounter:" ChipLogFormatMessageCounter " to %d" - " at monotonic time: " ChipLogFormatX64 - " msec to Multicast IPV6 address : %s with GroupID of %d and fabric index of %x", - "encrypted group", &preparedMessage, preparedMessage.GetMessageCounter(), groupSession->GetGroupId(), - ChipLogValueX64(System::SystemClock().GetMonotonicMilliseconds64().count()), addressStr, - groupSession->GetGroupId(), groupSession->GetFabricIndex()); + ChipLogProgress(Inet, "(G) Sending msg " ChipLogFormatMessageCounter " to Multicast IPV6 address '%s'", + preparedMessage.GetMessageCounter(), addressStr); } break; case Transport::Session::SessionType::kSecure: { @@ -310,12 +334,8 @@ CHIP_ERROR SessionManager::SendPreparedMessage(const SessionHandle & sessionHand destination = &secure->GetPeerAddress(); - ChipLogProgress(Inet, - "Sending %s msg %p with MessageCounter:" ChipLogFormatMessageCounter " to 0x" ChipLogFormatX64 - " (%u) at monotonic time: " ChipLogFormatX64 " msec", - "encrypted", &preparedMessage, preparedMessage.GetMessageCounter(), - ChipLogValueX64(secure->GetPeerNodeId()), secure->GetFabricIndex(), - ChipLogValueX64(System::SystemClock().GetMonotonicMilliseconds64().count())); + ChipLogProgress(Inet, "(S) Sending msg " ChipLogFormatMessageCounter " on secure session with LSID: %u", + preparedMessage.GetMessageCounter(), secure->GetLocalSessionId()); } break; case Transport::Session::SessionType::kUnauthenticated: { @@ -323,12 +343,13 @@ CHIP_ERROR SessionManager::SendPreparedMessage(const SessionHandle & sessionHand unauthenticated->MarkActive(); destination = &unauthenticated->GetPeerAddress(); - ChipLogProgress(Inet, - "Sending %s msg %p with MessageCounter:" ChipLogFormatMessageCounter " to 0x" ChipLogFormatX64 - " at monotonic time: " ChipLogFormatX64 " msec", - sessionHandle->GetSessionTypeString(), &preparedMessage, preparedMessage.GetMessageCounter(), - ChipLogValueX64(kUndefinedNodeId), - ChipLogValueX64(System::SystemClock().GetMonotonicMilliseconds64().count())); +#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: diff --git a/src/transport/SessionManager.h b/src/transport/SessionManager.h index 4337c84ee49408..9fac1a18347626 100644 --- a/src/transport/SessionManager.h +++ b/src/transport/SessionManager.h @@ -444,6 +444,8 @@ class DLL_EXPORT SessionManager : public TransportMgrDelegate, public FabricTabl this->FabricRemoved(fabricIndex); } + FabricTable * GetFabricTable() const { return mFabricTable; } + private: /** * The State of a secure transport object. diff --git a/src/transport/UnauthenticatedSessionTable.h b/src/transport/UnauthenticatedSessionTable.h index cdaa7a8a7307c0..a19fb2d908f262 100644 --- a/src/transport/UnauthenticatedSessionTable.h +++ b/src/transport/UnauthenticatedSessionTable.h @@ -66,9 +66,6 @@ class UnauthenticatedSession : public Session, } Session::SessionType GetSessionType() const override { return Session::SessionType::kUnauthenticated; } -#if CHIP_PROGRESS_LOGGING - const char * GetSessionTypeString() const override { return "unauthenticated"; }; -#endif void Retain() override { ReferenceCounted, 0>::Retain(); } void Release() override { ReferenceCounted, 0>::Release(); }