Make tracedecoder not stateful and ensure both sent and received messages are logged

examples/common/tracing/TraceDecoder.cpp

@@ -31,30 +31,50 @@ constexpr uint16_t kMaxLineLen    = 4096;
 constexpr const char * jsonPrefix = "    json\t";
 
 // Json keys
-constexpr const char * kProtocolIdKey                = "protocol_id";
-constexpr const char * kProtocolCodeKey              = "protocol_opcode";
-constexpr const char * kSessionIdKey                 = "session_id";
-constexpr const char * kExchangeIdKey                = "exchange_id";
-constexpr const char * kMessageCounterKey            = "msg_counter";
-constexpr const char * kSecurityFlagsKey             = "security_flags";
-constexpr const char * kMessageFlagsKey              = "msg_flags";
-constexpr const char * kSourceNodeIdKey              = "source_node_id";
-constexpr const char * kDestinationNodeIdKey         = "dest_node_id";
-constexpr const char * kDestinationGroupIdKey        = "group_id";
-constexpr const char * kExchangeFlagsKey             = "exchange_flags";
-constexpr const char * kIsInitiatorKey               = "is_initiator";
-constexpr const char * kNeedsAckKey                  = "is_ack_requested";
-constexpr const char * kAckMsgKey                    = "acknowledged_msg_counter";
-constexpr const char * kPayloadDataKey               = "payload_hex";
-constexpr const char * kPayloadSizeKey               = "payload_size";
-constexpr const char * kPayloadEncryptedDataKey      = "payload_hex_encrypted";
-constexpr const char * kPayloadEncryptedSizeKey      = "payload_size_encrypted";
-constexpr const char * kPayloadEncryptedBufferPtrKey = "buffer_ptr";
-constexpr const char * kSourceKey                    = "source";
-constexpr const char * kDestinationKey               = "destination";
+constexpr const char * kProtocolIdKey         = "protocol_id";
+constexpr const char * kProtocolCodeKey       = "protocol_opcode";
+constexpr const char * kSessionIdKey          = "session_id";
+constexpr const char * kExchangeIdKey         = "exchange_id";
+constexpr const char * kMessageCounterKey     = "msg_counter";
+constexpr const char * kSecurityFlagsKey      = "security_flags";
+constexpr const char * kMessageFlagsKey       = "msg_flags";
+constexpr const char * kSourceNodeIdKey       = "source_node_id";
+constexpr const char * kDestinationNodeIdKey  = "dest_node_id";
+constexpr const char * kDestinationGroupIdKey = "group_id";
+constexpr const char * kExchangeFlagsKey      = "exchange_flags";
+constexpr const char * kIsInitiatorKey        = "is_initiator";
+constexpr const char * kNeedsAckKey           = "is_ack_requested";
+constexpr const char * kAckMsgKey             = "acknowledged_msg_counter";
+constexpr const char * kPayloadDataKey        = "payload_hex";
+constexpr const char * kPayloadSizeKey        = "payload_size";
 
 namespace chip {
 namespace trace {
+namespace {
+
+constexpr const char * kDirectionKey = "direction";
+
+bool IsOutbound(const Json::Value & json)
+{
+    if (!json.isMember(kDirectionKey))
+    {
+        return false; // unknown
+    }
+
+    return strcmp(json[kDirectionKey].asCString(), "outbound") == 0;
+}
+
+bool IsInbound(const Json::Value & json)
+{
+    if (!json.isMember(kDirectionKey))
+    {
+        return false; // unknown
+    }
+
+    return strcmp(json[kDirectionKey].asCString(), "inbound") == 0;
+}
+
+} // namespace
 
 using namespace logging;
 
@@ -83,45 +103,8 @@ CHIP_ERROR TraceDecoder::ReadString(const char * str)
     str += strlen(jsonPrefix);
 
     Json::Reader reader;
-
-    if (mJsonBuffer.empty())
-    {
-        VerifyOrReturnError(reader.parse(str, mJsonBuffer), CHIP_ERROR_INVALID_ARGUMENT);
-        VerifyOrReturnError(mJsonBuffer.isMember(kPayloadDataKey) && mJsonBuffer.isMember(kPayloadSizeKey),
-                            CHIP_ERROR_INCORRECT_STATE);
-        return CHIP_NO_ERROR;
-    }
-
     Json::Value json;
     VerifyOrReturnError(reader.parse(str, json), CHIP_ERROR_INVALID_ARGUMENT);
-
-    // If there is a source, then it means the previously saved payload is an encrypted to decode, otherwise
-    // the previously saved payload is the non encrypted version, and the current decoded one is the encrypted version.
-    if (mJsonBuffer.isMember(kSourceKey))
-    {
-        json[kPayloadEncryptedDataKey] = mJsonBuffer[kPayloadDataKey];
-        json[kPayloadEncryptedSizeKey] = mJsonBuffer[kPayloadSizeKey];
-    }
-    else
-    {
-        auto data                      = json[kPayloadDataKey];
-        auto size                      = json[kPayloadSizeKey];
-        json[kPayloadDataKey]          = mJsonBuffer[kPayloadDataKey];
-        json[kPayloadSizeKey]          = mJsonBuffer[kPayloadSizeKey];
-        json[kPayloadEncryptedDataKey] = data;
-        json[kPayloadEncryptedSizeKey] = size;
-    }
-    mJsonBuffer.removeMember(kPayloadDataKey);
-    mJsonBuffer.removeMember(kPayloadSizeKey);
-
-    // If there is additional data in the previously saved json copy all of it.
-    for (const auto & key : mJsonBuffer.getMemberNames())
-    {
-        json[key] = mJsonBuffer[key];
-        mJsonBuffer.removeMember(key);
-    }
-
-    VerifyOrReturnError(json.isMember(kSourceKey) || json.isMember(kDestinationKey), CHIP_ERROR_INCORRECT_STATE);
     VerifyOrReturnError(json.isMember(kProtocolIdKey), CHIP_ERROR_INCORRECT_STATE);
     VerifyOrReturnError(json.isMember(kProtocolCodeKey), CHIP_ERROR_INCORRECT_STATE);
 
@@ -138,20 +121,19 @@ CHIP_ERROR TraceDecoder::LogJSON(Json::Value & json)
         return CHIP_NO_ERROR;
     }
 
-    if (!mOptions.mEnableMessageInitiator && json.isMember(kDestinationKey))
+    if (!mOptions.mEnableMessageInitiator && IsOutbound(json))
     {
         return CHIP_NO_ERROR;
     }
 
-    if (!mOptions.mEnableMessageResponder && json.isMember(kSourceKey))
+    if (!mOptions.mEnableMessageResponder && IsInbound(json))
     {
         return CHIP_NO_ERROR;
     }
 
-    bool isResponse = json.isMember(kSourceKey) ? true : false;
+    bool isResponse = IsInbound(json);
     ReturnErrorOnFailure(LogAndConsumeProtocol(json));
     ReturnErrorOnFailure(MaybeLogAndConsumeHeaderFlags(json));
-    ReturnErrorOnFailure(MaybeLogAndConsumeEncryptedPayload(json));
     ReturnErrorOnFailure(MaybeLogAndConsumePayload(json, isResponse));
     ReturnErrorOnFailure(MaybeLogAndConsumeOthers(json));
 
@@ -168,26 +150,6 @@ CHIP_ERROR TraceDecoder::MaybeLogAndConsumeHeaderFlags(Json::Value & json)
     return CHIP_NO_ERROR;
 }
 
-CHIP_ERROR TraceDecoder::MaybeLogAndConsumeEncryptedPayload(Json::Value & json)
-{
-    if (mOptions.mEnableDataEncryptedPayload)
-    {
-        size_t size = static_cast<uint16_t>(json[kPayloadEncryptedSizeKey].asLargestUInt());
-        if (size)
-        {
-            auto payload      = json[kPayloadEncryptedDataKey].asString();
-            auto bufferPtr    = json[kPayloadEncryptedBufferPtrKey].asString();
-            auto scopedIndent = ScopedLogIndentWithSize("Encrypted Payload", size);
-            Log("data", payload.c_str());
-            Log("buffer_ptr", bufferPtr.c_str());
-        }
-    }
-    json.removeMember(kPayloadEncryptedSizeKey);
-    json.removeMember(kPayloadEncryptedDataKey);
-    json.removeMember(kPayloadEncryptedBufferPtrKey);
-    return CHIP_NO_ERROR;
-}
-
 CHIP_ERROR TraceDecoder::MaybeLogAndConsumeOthers(Json::Value & json)
 {
     std::vector<std::string> keys = json.getMemberNames();
@@ -218,8 +180,16 @@ CHIP_ERROR TraceDecoder::LogAndConsumeProtocol(Json::Value & json)
 
     chip::StringBuilderBase builder(protocolInfo, sizeof(protocolInfo));
 
-    builder.Add(json.isMember(kSourceKey) ? "<< from " : ">> to ");
-    builder.Add(json.isMember(kSourceKey) ? json[kSourceKey].asCString() : json[kDestinationKey].asCString());
+    builder.Add(IsInbound(json) ? "<< from " : ">> to ");
+
+    if (json.isMember("peer_address"))
+    {
+        builder.Add(json["peer_address"].asCString());
+    }
+    else
+    {
+        builder.Add("UNKNOWN");
+    }
 
     builder.Add(" ");
     auto msgCounter = static_cast<uint32_t>(json[kMessageCounterKey].asLargestUInt());
@@ -258,11 +228,10 @@ CHIP_ERROR TraceDecoder::LogAndConsumeProtocol(Json::Value & json)
 
     ChipLogProgress(DataManagement, "%s", builder.c_str());
 
-    json.removeMember(kSourceKey);
-    json.removeMember(kDestinationKey);
     json.removeMember(kSessionIdKey);
     json.removeMember(kExchangeIdKey);
     json.removeMember(kMessageCounterKey);
+    json.removeMember(kDirectionKey);
 
     return CHIP_NO_ERROR;
 }

examples/common/tracing/TraceDecoder.h

@@ -42,7 +42,12 @@ class TraceDecoder : public TraceStream
     {
         char buffer[2048] = {};
         snprintf(buffer, sizeof(buffer), "    %s\t %s", tag.c_str(), data.c_str());
-        ReadString(buffer);
+        CHIP_ERROR err = ReadString(buffer);
+
+        if (err != CHIP_NO_ERROR)
+        {
+            ChipLogError(Automation, "Failed to add field: %" CHIP_ERROR_FORMAT, err.Format());
+        }
     }
 
     void FinishEvent() override {}
@@ -55,12 +60,10 @@ class TraceDecoder : public TraceStream
     CHIP_ERROR MaybeLogAndConsumeMessageFlags(Json::Value & value);
     CHIP_ERROR MaybeLogAndConsumeExchangeFlags(Json::Value & value);
     CHIP_ERROR MaybeLogAndConsumePayload(Json::Value & value, bool isResponse);
-    CHIP_ERROR MaybeLogAndConsumeEncryptedPayload(Json::Value & value);
     CHIP_ERROR MaybeLogAndConsumeOthers(Json::Value & value);
 
 private:
     TraceDecoderOptions mOptions;
-    Json::Value mJsonBuffer;
 };
 
 } // namespace trace

examples/common/tracing/TraceHandlers.cpp

@@ -233,7 +233,9 @@ void SecureMessageSentHandler(const TraceSecureMessageSentData * eventData)
         return;
     }
 
-    std::string jsonBody = "{";
+    std::string jsonBody = "{ \"direction\": \"outbound\", ";
+    jsonBody += AsFirstJsonKey("peer_address", AsJsonString(eventData->peerAddress));
+    jsonBody += ", ";
     jsonBody += PacketHeaderToJson(eventData->packetHeader);
     jsonBody += ", ";
     jsonBody += PayloadHeaderToJson(eventData->payloadHeader);
@@ -255,7 +257,7 @@ void SecureMessageReceivedHandler(const TraceSecureMessageReceivedData * eventDa
         return;
     }
 
-    std::string jsonBody = "{";
+    std::string jsonBody = "{ \"direction\": \"inbound\", ";
     jsonBody += AsFirstJsonKey("peer_address", AsJsonString(eventData->peerAddress));
     jsonBody += ", ";
     jsonBody += PacketHeaderToJson(eventData->packetHeader);

src/transport/Session.h

@@ -27,7 +27,6 @@
 #include <messaging/ReliableMessageProtocolConfig.h>
 #include <platform/LockTracker.h>
 #include <transport/SessionDelegate.h>
-#include <transport/raw/PeerAddress.h>
 
 namespace chip {
 namespace Transport {

src/transport/SessionManager.cpp

@@ -147,6 +147,9 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P
 {
     MATTER_TRACE_SCOPE("PrepareMessage", "SessionManager");
 
+    // FIXME: Fill it up
+    PeerAddress destination_address;
+
     PacketHeader packetHeader;
     bool isControlMsg = IsControlMessage(payloadHeader);
     if (isControlMsg)
@@ -181,11 +184,13 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P
             return CHIP_ERROR_INTERNAL;
         }
 
+        destination_address = Transport::PeerAddress::Multicast(fabric->GetFabricId(), groupSession->GetGroupId());
+
         // 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());
+        CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, destination_address, message->Start(), message->TotalLength());
 
         Crypto::SymmetricKeyContext * keyContext =
             groups->GetKeyContext(groupSession->GetFabricIndex(), groupSession->GetGroupId());
@@ -219,10 +224,12 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P
             .SetSessionId(session->GetPeerSessionId()) //
             .SetSessionType(Header::SessionType::kUnicastSession);
 
+        destination_address = session->GetPeerAddress();
+
         // 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());
+        CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, destination_address, message->Start(), message->TotalLength());
 
         CryptoContext::NonceStorage nonce;
         NodeId sourceNodeId = session->GetLocalScopedNodeId().GetNodeId();
@@ -252,10 +259,13 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P
             break;
         }
 
+        auto unauthenticated = sessionHandle->AsUnauthenticatedSession();
+        destination_address  = unauthenticated->GetPeerAddress();
+
         // 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());
+        CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, destination_address, message->Start(), message->TotalLength());
 
         ReturnErrorOnFailure(payloadHeader.EncodeBeforeData(message));
 

src/transport/TraceMessage.h

@@ -40,10 +40,10 @@
 #define _CHIP_TRACE_MESSAGE_INTERNAL(type, data, size) PW_TRACE_INSTANT_DATA(::chip::trace::kTraceMessageEvent, type, data, size);
 #endif // CHIP_CONFIG_TRANSPORT_TRACE_ENABLED && CHIP_CONFIG_TRANSPORT_PW_TRACE_ENABLED
 
-#define CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, data, dataLen)                                                        \
+#define CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, peerAddress, data, dataLen)                                           \
     do                                                                                                                             \
     {                                                                                                                              \
-        const ::chip::trace::TraceSecureMessageSentData _trace_data{ &payloadHeader, &packetHeader, data, dataLen };               \
+        const ::chip::trace::TraceSecureMessageSentData _trace_data{ &payloadHeader, &packetHeader, &peerAddress, data, dataLen }; \
         _CHIP_TRACE_MESSAGE_INTERNAL(::chip::trace::kTraceMessageSentDataFormat, reinterpret_cast<const char *>(&_trace_data),     \
                                      sizeof(_trace_data));                                                                         \
     } while (0)
@@ -58,7 +58,7 @@
     } while (0)
 
 #else // CHIP_CONFIG_TRANSPORT_TRACE_ENABLED || CHIP_CONFIG_TRANSPORT_PW_TRACE_ENABLED
-#define CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, data, dataLen)                                                        \
+#define CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, peerAddress, data, dataLen)                                           \
     do                                                                                                                             \
     {                                                                                                                              \
     } while (0)
@@ -81,6 +81,7 @@ struct TraceSecureMessageSentData
 {
     const PayloadHeader * payloadHeader;
     const PacketHeader * packetHeader;
+    const Transport::PeerAddress * peerAddress;
     const uint8_t * packetPayload;
     size_t packetSize;
 };