Add data logging using the tracing module for message send/receive (#…

…27281)

* Add message loging structures and definitions

* Run clang-format

* Fix a comment

* Restyled by clang-format

* Fix dependencies in build.gn

* Fix compile error for mac .. size_t cannot be easilu converted and we know size fits in a UInt

* Fix typo

---------

Co-authored-by: Andrei Litvin <andreilitvin@google.com>
Co-authored-by: Restyled.io <commits@restyled.io>

examples/common/tracing/TraceHandlers.cpp

@@ -199,7 +199,7 @@ std::string PayloadHeaderToJson(const PayloadHeader * payloadHeader)
 
     std::string jsonBody;
 
-    uint8_t exchangeFlags = payloadHeader->GetExhangeFlags();
+    uint8_t exchangeFlags = payloadHeader->GetExchangeFlags();
     jsonBody += AsFirstJsonKey("exchange_flags", std::to_string(exchangeFlags));
 
     uint16_t exchangeId = payloadHeader->GetExchangeID();

src/tracing/backend.h

@@ -58,7 +58,7 @@ class Backend : public ::chip::IntrusiveListNodeBase<>
     virtual void TraceInstant(Instant instant) = 0;
 
     virtual void LogMessageSend(MessageSendInfo &) { TraceInstant(Instant::Log_MessageSend); }
-    virtual void LogMessageReceived(MessageReceiveInfo &) { TraceInstant(Instant::Log_MessageReceived); }
+    virtual void LogMessageReceived(MessageReceivedInfo &) { TraceInstant(Instant::Log_MessageReceived); }
 
     virtual void LogNodeLookup(NodeLookupInfo &) { TraceInstant(Instant::Log_NodeLookup); }
     virtual void LogNodeDiscovered(NodeDiscoveredInfo &) { TraceInstant(Instant::Log_NodeDiscovered); }

src/tracing/log_declares.h

@@ -23,7 +23,7 @@ namespace Tracing {
 // on actual types. This allows tracing to be used anywhere lib/support could be used.
 
 struct MessageSendInfo;
-struct MessageReceiveInfo;
+struct MessageReceivedInfo;
 struct NodeLookupInfo;
 struct NodeDiscoveredInfo;
 struct NodeDiscoveryFailedInfo;

src/tracing/log_json/BUILD.gn

@@ -26,6 +26,7 @@ static_library("log_json") {
   public_deps = [
     "${chip_root}/src/lib/address_resolve",
     "${chip_root}/src/tracing",
+    "${chip_root}/src/transport",
     "${chip_root}/third_party/jsoncpp",
   ]
 }

src/tracing/log_json/log_json_tracing.cpp

@@ -21,6 +21,7 @@
 #include <lib/address_resolve/TracingStructs.h>
 #include <lib/support/ErrorStr.h>
 #include <lib/support/StringBuilder.h>
+#include <transport/TracingStructs.h>
 
 #include <json/json.h>
 
@@ -219,6 +220,63 @@ void LogJsonValue(Json::Value const & value)
     ChipLogProgress(Automation, "%s", output.str().c_str());
 }
 
+void DecodePayloadHeader(Json::Value & value, const PayloadHeader * payloadHeader)
+{
+
+    value["exchangeFlags"] = payloadHeader->GetExchangeFlags();
+    value["exchangeId"]    = payloadHeader->GetExchangeID();
+    value["protocolId"]    = payloadHeader->GetProtocolID().ToFullyQualifiedSpecForm();
+    value["messageType"]   = payloadHeader->GetMessageType();
+    value["initiator"]     = payloadHeader->IsInitiator();
+    value["needsAck"]      = payloadHeader->NeedsAck();
+
+    const Optional<uint32_t> & acknowledgedMessageCounter = payloadHeader->GetAckMessageCounter();
+    if (acknowledgedMessageCounter.HasValue())
+    {
+        value["ackMessageCounter"] = acknowledgedMessageCounter.Value();
+    }
+}
+
+void DecodePacketHeader(Json::Value & value, const PacketHeader * packetHeader)
+{
+    value["msgCounter"]    = packetHeader->GetMessageCounter();
+    value["sessionId"]     = packetHeader->GetSessionId();
+    value["flags"]         = packetHeader->GetMessageFlags();
+    value["securityFlags"] = packetHeader->GetSecurityFlags();
+
+    {
+        const Optional<NodeId> & nodeId = packetHeader->GetSourceNodeId();
+        if (nodeId.HasValue())
+        {
+            value["sourceNodeId"] = nodeId.Value();
+        }
+    }
+
+    {
+        const Optional<NodeId> & nodeId = packetHeader->GetDestinationNodeId();
+        if (nodeId.HasValue())
+        {
+            value["destinationNodeId"] = nodeId.Value();
+        }
+    }
+
+    {
+        const Optional<GroupId> & groupId = packetHeader->GetDestinationGroupId();
+        if (groupId.HasValue())
+        {
+            value["groupId"] = groupId.Value();
+        }
+    }
+}
+
+void DecodePayloadData(Json::Value & value, chip::ByteSpan payload)
+{
+    value["payloadSize"] = static_cast<Json::Value::UInt>(payload.size());
+
+    // TODO: a decode would be useful however it likely requires more decode
+    //       metadata
+}
+
 } // namespace
 
 void LogJsonBackend::TraceBegin(Scope scope)
@@ -245,17 +303,54 @@ void LogJsonBackend::TraceInstant(Instant instant)
     LogJsonValue(value);
 }
 
-void LogJsonBackend::LogMessageSend(MessageSendInfo &)
+void LogJsonBackend::LogMessageSend(MessageSendInfo & info)
 {
     Json::Value value;
-    value["TODO"] = "LogMessageSend";
+    value["event"] = "MessageSend";
+
+    switch (info.messageType)
+    {
+    case OutgoingMessageType::kGroupMessage:
+        value["messageType"] = "Group";
+        break;
+    case OutgoingMessageType::kSecureSession:
+        value["messageType"] = "Secure";
+        break;
+    case OutgoingMessageType::kUnauthenticated:
+        value["messageType"] = "Unauthenticated";
+        break;
+    }
+
+    DecodePayloadHeader(value["payloadHeader"], info.payloadHeader);
+    DecodePacketHeader(value["packetHeader"], info.packetHeader);
+    DecodePayloadData(value["payload"], info.payload);
+
     LogJsonValue(value);
 }
 
-void LogJsonBackend::LogMessageReceived(MessageReceiveInfo &)
+void LogJsonBackend::LogMessageReceived(MessageReceivedInfo & info)
 {
     Json::Value value;
-    value["TODO"] = "LogMessageReceived";
+
+    value["event"] = "MessageReceived";
+
+    switch (info.messageType)
+    {
+    case IncomingMessageType::kGroupMessage:
+        value["messageType"] = "Group";
+        break;
+    case IncomingMessageType::kSecureUnicast:
+        value["messageType"] = "Secure";
+        break;
+    case IncomingMessageType::kUnauthenticated:
+        value["messageType"] = "Unauthenticated";
+        break;
+    }
+
+    DecodePayloadHeader(value["payloadHeader"], info.payloadHeader);
+    DecodePacketHeader(value["packetHeader"], info.packetHeader);
+    DecodePayloadData(value["payload"], info.payload);
+
     LogJsonValue(value);
 }
 

src/tracing/log_json/log_json_tracing.h

@@ -35,7 +35,7 @@ class LogJsonBackend : public ::chip::Tracing::Backend
     void TraceEnd(Scope scope) override;
     void TraceInstant(Instant instant) override;
     void LogMessageSend(MessageSendInfo &) override;
-    void LogMessageReceived(MessageReceiveInfo &) override;
+    void LogMessageReceived(MessageReceivedInfo &) override;
     void LogNodeLookup(NodeLookupInfo &) override;
     void LogNodeDiscovered(NodeDiscoveredInfo &) override;
     void LogNodeDiscoveryFailed(NodeDiscoveryFailedInfo &) override;

src/tracing/registry.cpp

@@ -74,7 +74,7 @@ void LogMessageSend(::chip::Tracing::MessageSendInfo & info)
     }
 }
 
-void LogMessageReceived(::chip::Tracing::MessageReceiveInfo & info)
+void LogMessageReceived(::chip::Tracing::MessageReceivedInfo & info)
 {
     for (auto & backend : gTracingBackends)
     {

src/tracing/registry.h

@@ -64,7 +64,7 @@ void End(::chip::Tracing::Scope scope);
 void Instant(::chip::Tracing::Instant instant);
 
 void LogMessageSend(::chip::Tracing::MessageSendInfo & info);
-void LogMessageReceived(::chip::Tracing::MessageReceiveInfo & info);
+void LogMessageReceived(::chip::Tracing::MessageReceivedInfo & info);
 void LogNodeLookup(::chip::Tracing::NodeLookupInfo & info);
 void LogNodeDiscovered(::chip::Tracing::NodeDiscoveredInfo & info);
 void LogNodeDiscoveryFailed(::chip::Tracing::NodeDiscoveryFailedInfo & info);

src/transport/BUILD.gn

@@ -45,6 +45,7 @@ static_library("transport") {
     "SessionManager.h",
     "SessionMessageCounter.h",
     "SessionMessageDelegate.h",
+    "TracingStructs.h",
     "TransportMgr.h",
     "TransportMgrBase.cpp",
     "TransportMgrBase.h",
@@ -64,6 +65,7 @@ static_library("transport") {
     "${chip_root}/src/lib/support",
     "${chip_root}/src/platform",
     "${chip_root}/src/setup_payload",
+    "${chip_root}/src/tracing",
     "${chip_root}/src/transport/raw",
     "${nlio_root}:nlio",
   ]

src/transport/SessionManager.cpp

@@ -40,9 +40,11 @@
 #include <platform/CHIPDeviceLayer.h>
 #include <protocols/Protocols.h>
 #include <protocols/secure_channel/Constants.h>
+#include <tracing/macros.h>
 #include <transport/GroupPeerMessageCounter.h>
 #include <transport/GroupSession.h>
 #include <transport/SecureMessageCodec.h>
+#include <transport/TracingStructs.h>
 #include <transport/TransportMgr.h>
 
 // Global object
@@ -178,6 +180,9 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P
         }
 
         // Trace before any encryption
+        MATTER_LOG_MESSAGE_SEND(chip::Tracing::OutgoingMessageType::kGroupMessage, &payloadHeader, &packetHeader,
+                                chip::ByteSpan(message->Start(), message->TotalLength()));
+
         CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, message->Start(), message->TotalLength());
 
         Crypto::SymmetricKeyContext * keyContext =
@@ -213,6 +218,8 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P
             .SetSessionType(Header::SessionType::kUnicastSession);
 
         // Trace before any encryption
+        MATTER_LOG_MESSAGE_SEND(chip::Tracing::OutgoingMessageType::kSecureSession, &payloadHeader, &packetHeader,
+                                chip::ByteSpan(message->Start(), message->TotalLength()));
         CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, message->Start(), message->TotalLength());
 
         CryptoContext::NonceStorage nonce;
@@ -244,6 +251,8 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P
         }
 
         // Trace after all headers are settled.
+        MATTER_LOG_MESSAGE_SEND(chip::Tracing::OutgoingMessageType::kUnauthenticated, &payloadHeader, &packetHeader,
+                                chip::ByteSpan(message->Start(), message->TotalLength()));
         CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, message->Start(), message->TotalLength());
 
         ReturnErrorOnFailure(payloadHeader.EncodeBeforeData(message));
@@ -641,12 +650,18 @@ void SessionManager::UnauthenticatedMessageDispatch(const PacketHeader & partial
         // CHIP_ERROR_DUPLICATE_MESSAGE_RECEIVED.
         unsecuredSession->GetPeerMessageCounter().CommitUnencrypted(packetHeader.GetMessageCounter());
     }
-
     if (mCB != nullptr)
     {
+        MATTER_LOG_MESSAGE_RECEIVED(chip::Tracing::IncomingMessageType::kUnauthenticated, &payloadHeader, &packetHeader,
+                                    unsecuredSession, &peerAddress, chip::ByteSpan(msg->Start(), msg->TotalLength()));
+
         CHIP_TRACE_MESSAGE_RECEIVED(payloadHeader, packetHeader, unsecuredSession, peerAddress, msg->Start(), msg->TotalLength());
         mCB->OnMessageReceived(packetHeader, payloadHeader, session, isDuplicate, std::move(msg));
     }
+    else
+    {
+        ChipLogError(Inet, "Received UNSECURED message was not processed.");
+    }
 }
 
 void SessionManager::SecureUnicastMessageDispatch(const PacketHeader & partialPacketHeader,
@@ -751,9 +766,15 @@ void SessionManager::SecureUnicastMessageDispatch(const PacketHeader & partialPa
 
     if (mCB != nullptr)
     {
+        MATTER_LOG_MESSAGE_RECEIVED(chip::Tracing::IncomingMessageType::kSecureUnicast, &payloadHeader, &packetHeader,
+                                    secureSession, &peerAddress, chip::ByteSpan(msg->Start(), msg->TotalLength()));
         CHIP_TRACE_MESSAGE_RECEIVED(payloadHeader, packetHeader, secureSession, peerAddress, msg->Start(), msg->TotalLength());
         mCB->OnMessageReceived(packetHeader, payloadHeader, session.Value(), isDuplicate, std::move(msg));
     }
+    else
+    {
+        ChipLogError(Inet, "Received SECURED message was not processed.");
+    }
 }
 
 /**
@@ -958,10 +979,18 @@ void SessionManager::SecureGroupMessageDispatch(const PacketHeader & partialPack
         // TODO : When MCSP is done, clean up session creation logic
         Transport::IncomingGroupSession groupSession(groupContext.group_id, groupContext.fabric_index,
                                                      packetHeaderCopy.GetSourceNodeId().Value());
+
+        MATTER_LOG_MESSAGE_RECEIVED(chip::Tracing::IncomingMessageType::kGroupMessage, &payloadHeader, &packetHeaderCopy,
+                                    &groupSession, &peerAddress, chip::ByteSpan(msg->Start(), msg->TotalLength()));
+
         CHIP_TRACE_MESSAGE_RECEIVED(payloadHeader, packetHeaderCopy, &groupSession, peerAddress, msg->Start(), msg->TotalLength());
         mCB->OnMessageReceived(packetHeaderCopy, payloadHeader, SessionHandle(groupSession),
                                SessionMessageDelegate::DuplicateMessage::No, std::move(msg));
     }
+    else
+    {
+        ChipLogError(Inet, "Received GROUP message was not processed.");
+    }
 }
 
 Optional<SessionHandle> SessionManager::FindSecureSessionForNode(ScopedNodeId peerNodeId,

src/transport/TracingStructs.h

@@ -0,0 +1,64 @@
+/*
+ *    Copyright (c) 2023 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.
+ */
+#pragma once
+
+#include <lib/support/Span.h>
+#include <transport/Session.h>
+#include <transport/raw/MessageHeader.h>
+
+namespace chip {
+namespace Tracing {
+
+/// Concrete definitions of the message tracing info that session managers
+/// report
+
+enum class OutgoingMessageType
+{
+    kGroupMessage,
+    kSecureSession,
+    kUnauthenticated,
+};
+
+/// A message is about to be sent
+struct MessageSendInfo
+{
+    OutgoingMessageType messageType;
+    const PayloadHeader * payloadHeader;
+    const PacketHeader * packetHeader;
+    const chip::ByteSpan payload;
+};
+
+enum class IncomingMessageType
+{
+    kGroupMessage,
+    kSecureUnicast,
+    kUnauthenticated,
+};
+
+/// A message has been received
+struct MessageReceivedInfo
+{
+    const IncomingMessageType messageType;
+    const PayloadHeader * payloadHeader;
+    const PacketHeader * packetHeader;
+    const Transport::Session * session;
+    const Transport::PeerAddress * peerAddress;
+    const chip::ByteSpan payload;
+};
+
+} // namespace Tracing
+} // namespace chip

src/transport/raw/MessageHeader.h

@@ -511,7 +511,7 @@ class PayloadHeader
     uint8_t GetMessageType() const { return mMessageType; }
 
     /** Get the raw exchange flags from this header. */
-    uint8_t GetExhangeFlags() const { return mExchangeFlags.Raw(); }
+    uint8_t GetExchangeFlags() const { return mExchangeFlags.Raw(); }
 
     /** Check whether the header has a given secure message type */
     bool HasMessageType(uint8_t type) const { return mMessageType == type; }