Add message receive and send tracing to chip-tool (#13637)

* Add message receive and send tracing to chip-tool - Move tracing from SecureMessageCodec to SessionManager to allow covering both received and sent messages - Add received message tracing - Update trace handling to be flexible to receiving a context pointer. - Refactor trace handling logic in common/tracing to be more flexible to - Add bookend FinishEvent to the TraceStream interface to assist in event flushing. Testing done: - Integration tests pass, unit tests all pass - Validated manually through several runs that with chip-tool (using `--trace_log 1`) that dumped received/sent message traces match the outer higher-level (but less detailed) logs around them * Restyled by clang-format * Address review comments Co-authored-by: Restyled.io <[email protected]>
project-chip · Jan 19, 2022 · a04bf54 · a04bf54
1 parent 150c479
commit a04bf54
Show file tree

Hide file tree

Showing 8 changed files with 318 additions and 51 deletions.
diff --git a/examples/common/tracing/TraceHandlers.cpp b/examples/common/tracing/TraceHandlers.cpp
@@ -24,8 +24,13 @@
 #include "pw_trace/trace.h"
 #include "pw_trace_chip/trace_chip.h"
 #include "transport/TraceMessage.h"
+#include <lib/support/BytesToHex.h>
+#include <lib/support/CodeUtils.h>
 #include <lib/support/logging/CHIPLogging.h>
 
+// For `s` std::string literal suffix
+using namespace std::string_literals;
+
 namespace chip {
 namespace trace {
 
@@ -50,21 +55,30 @@ class TraceOutput
 
     void DeleteStream() { SetStream(nullptr); }
 
-    void Stream(const std::string & tag, const std::string & data)
+    void StartEvent(const std::string & label)
+    {
+        std::lock_guard<std::mutex> guard(mLock);
+        if (mStream)
+        {
+            mStream->StartEvent(label);
+        }
+    }
+
+    void AddField(const std::string & tag, const std::string & data)
     {
         std::lock_guard<std::mutex> guard(mLock);
         if (mStream)
         {
-            mStream->Stream(tag, data);
+            mStream->AddField(tag, data);
         }
     }
 
-    void Handler(const std::string & label)
+    void FinishEvent()
     {
         std::lock_guard<std::mutex> guard(mLock);
         if (mStream)
         {
-            mStream->Handler(label);
+            mStream->FinishEvent();
         }
     }
 
@@ -73,42 +87,228 @@ class TraceOutput
     TraceStream * mStream = nullptr;
 };
 
-TraceOutput output;
+struct TraceHandlerContext
+{
+    TraceOutput * sink;
+};
+
+TraceOutput gTraceOutput;
+TraceHandlerContext gTraceHandlerContext = { .sink = &gTraceOutput };
 
-// TODO: Framework this into a registry of handlers for different message types.
-bool TraceDefaultHandler(const TraceEventFields & trace)
+std::string AsJsonKey(const std::string & key, const std::string & value, bool prepend_comma)
+{
+    return (prepend_comma ? ", "s : ""s) + "\""s + key + "\": " + value;
+}
+
+std::string AsFirstJsonKey(const std::string & key, const std::string & value)
+{
+    return AsJsonKey(key, value, /* prepend_comma = */ false);
+}
+
+std::string AsNextJsonKey(const std::string & key, const std::string & value)
+{
+    return AsJsonKey(key, value, /* prepend_comma = */ true);
+}
+
+std::string AsJsonString(const std::string & value)
+{
+    return "\""s + value + "\""s;
+}
+
+std::string AsJsonString(const Transport::PeerAddress * peerAddress)
+{
+    char convBuf[Transport::PeerAddress::kMaxToStringSize] = { 0 };
+
+    peerAddress->ToString(convBuf);
+    return AsJsonString(convBuf);
+}
+
+std::string AsJsonBool(bool isTrue)
+{
+    return isTrue ? "true"s : "false"s;
+}
+
+std::string AsJsonHexString(const uint8_t * buf, size_t bufLen)
+{
+    // Fill a string long enough for the hex conversion, that will be overwritten
+    std::string hexBuf(2 * bufLen, '0');
+
+    CHIP_ERROR status = Encoding::BytesToLowercaseHexBuffer(buf, bufLen, hexBuf.data(), hexBuf.size());
+
+    // Static conditions exist that should ensure never failing. Catch failure in an assert.
+    VerifyOrDie(status == CHIP_NO_ERROR);
+
+    return AsJsonString(hexBuf);
+}
+
+std::string PacketHeaderToJson(const PacketHeader * packetHeader)
+{
+    std::string jsonBody;
+
+    uint32_t messageCounter = packetHeader->GetMessageCounter();
+    jsonBody += AsFirstJsonKey("msg_counter", std::to_string(messageCounter));
+
+    const Optional<NodeId> & sourceNodeId = packetHeader->GetSourceNodeId();
+    if (sourceNodeId.HasValue())
+    {
+        jsonBody += AsNextJsonKey("source_node_id", std::to_string(sourceNodeId.Value()));
+    }
+
+    uint16_t sessionId                  = packetHeader->GetSessionId();
+    const Optional<GroupId> & groupId   = packetHeader->GetDestinationGroupId();
+    const Optional<NodeId> & destNodeId = packetHeader->GetDestinationNodeId();
+    if (packetHeader->IsValidGroupMsg())
+    {
+        if (groupId.HasValue())
+        {
+            jsonBody += AsNextJsonKey("group_id", std::to_string(groupId.Value()));
+        }
+
+        jsonBody += AsNextJsonKey("group_key_hash", std::to_string(sessionId));
+    }
+    else if (destNodeId.HasValue())
+    {
+        jsonBody += AsNextJsonKey("dest_node_id", std::to_string(destNodeId.Value()));
+    }
+
+    jsonBody += AsNextJsonKey("session_id", std::to_string(sessionId));
+
+    uint8_t messageFlags = packetHeader->GetMessageFlags();
+    jsonBody += AsNextJsonKey("msg_flags", std::to_string(messageFlags));
+
+    uint8_t securityFlags = packetHeader->GetSecurityFlags();
+    jsonBody += AsNextJsonKey("security_flags", std::to_string(securityFlags));
+
+    return jsonBody;
+}
+
+std::string PayloadHeaderToJson(const PayloadHeader * payloadHeader)
+{
+
+    std::string jsonBody;
+
+    uint8_t exchangeFlags = payloadHeader->GetExhangeFlags();
+    jsonBody += AsFirstJsonKey("exchange_flags", std::to_string(exchangeFlags));
+
+    uint16_t exchangeId = payloadHeader->GetExchangeID();
+    jsonBody += AsNextJsonKey("exchange_id", std::to_string(exchangeId));
+
+    uint32_t protocolId = payloadHeader->GetProtocolID().ToFullyQualifiedSpecForm();
+    jsonBody += AsNextJsonKey("protocol_id", std::to_string(protocolId));
+
+    uint8_t protocolOpcode = payloadHeader->GetMessageType();
+    jsonBody += AsNextJsonKey("protocol_opcode", std::to_string(protocolOpcode));
+
+    bool isInitiator = payloadHeader->IsInitiator();
+    jsonBody += AsNextJsonKey("is_initiator", AsJsonBool(isInitiator));
+
+    bool needsAck = payloadHeader->NeedsAck();
+    jsonBody += AsNextJsonKey("is_ack_requested", AsJsonBool(needsAck));
+
+    const Optional<uint32_t> & acknowledgedMessageCounter = payloadHeader->GetAckMessageCounter();
+    if (acknowledgedMessageCounter.HasValue())
+    {
+        jsonBody += AsNextJsonKey("acknowledged_msg_counter", std::to_string(acknowledgedMessageCounter.Value()));
+    }
+
+    return jsonBody;
+}
+
+bool SecureMessageSentHandler(const TraceEventFields & eventFields, TraceHandlerContext * context)
+{
+    if (eventFields.dataSize != sizeof(TraceSecureMessageSentData))
+    {
+        return false;
+    }
+
+    const auto * eventData = reinterpret_cast<const TraceSecureMessageSentData *>(eventFields.dataBuffer);
+    std::string jsonBody   = "{";
+    jsonBody += PacketHeaderToJson(eventData->packetHeader);
+    jsonBody += ", ";
+    jsonBody += PayloadHeaderToJson(eventData->payloadHeader);
+    jsonBody += ", ";
+    jsonBody += AsFirstJsonKey("payload_size", std::to_string(eventData->packetSize));
+    jsonBody += ", ";
+    jsonBody += AsFirstJsonKey("payload_hex", AsJsonHexString(eventData->packetPayload, eventData->packetSize));
+    jsonBody += "}";
+
+    TraceOutput * sink = context->sink;
+    sink->StartEvent(std::string{ kTraceMessageEvent } + "." + kTraceMessageSentDataFormat);
+    sink->AddField("json", jsonBody);
+    sink->FinishEvent();
+
+    return true;
+}
+
+bool SecureMessageReceivedHandler(const TraceEventFields & eventFields, TraceHandlerContext * context)
 {
-    if (strcmp(trace.dataFormat, kTraceSecureMessageDataFormat) != 0 || trace.dataSize != sizeof(TraceSecureMessageData))
+    if (eventFields.dataSize != sizeof(TraceSecureMessageReceivedData))
     {
         return false;
     }
 
-    const TraceSecureMessageData * msg = reinterpret_cast<const TraceSecureMessageData *>(trace.dataBuffer);
-    output.Handler("Default");
-    output.Stream("ExchangeId", std::to_string(msg->payloadHeader->GetExchangeID()));
-    output.Stream("MsgType", std::to_string(msg->payloadHeader->GetMessageType()));
-    output.Stream("MessageCounter", std::to_string(msg->packetHeader->GetMessageCounter()));
-    output.Stream("PacketSize", std::to_string(msg->packetSize));
+    const auto * eventData = reinterpret_cast<const TraceSecureMessageReceivedData *>(eventFields.dataBuffer);
+
+    std::string jsonBody = "{";
+    jsonBody += AsFirstJsonKey("peer_address", AsJsonString(eventData->peerAddress));
+    jsonBody += ", ";
+    jsonBody += PacketHeaderToJson(eventData->packetHeader);
+    jsonBody += ", ";
+    jsonBody += PayloadHeaderToJson(eventData->payloadHeader);
+    jsonBody += ", ";
+    jsonBody += AsFirstJsonKey("payload_size", std::to_string(eventData->packetSize));
+    jsonBody += ", ";
+    jsonBody += AsFirstJsonKey("payload_hex", AsJsonHexString(eventData->packetPayload, eventData->packetSize));
+    jsonBody += "}";
+
+    TraceOutput * sink = context->sink;
+    sink->StartEvent(std::string{ kTraceMessageEvent } + "." + kTraceMessageReceivedDataFormat);
+    sink->AddField("json", jsonBody);
+    sink->FinishEvent();
+
+    // Note that `eventData->session` is currently ignored.
 
     return true;
 }
 
+// TODO: Framework this into a registry of handlers for different message types.
+bool TraceDefaultHandler(const TraceEventFields & eventFields, void * context)
+{
+    TraceHandlerContext * ourContext = reinterpret_cast<TraceHandlerContext *>(context);
+    if (ourContext == nullptr)
+    {
+        return false;
+    }
+
+    if (std::string{ eventFields.dataFormat } == kTraceMessageSentDataFormat)
+    {
+        return SecureMessageSentHandler(eventFields, ourContext);
+    }
+    else if (std::string{ eventFields.dataFormat } == kTraceMessageReceivedDataFormat)
+    {
+        return SecureMessageReceivedHandler(eventFields, ourContext);
+    }
+
+    return false;
+}
+
 } // namespace
 
 void SetTraceStream(TraceStream * stream)
 {
-    output.SetStream(stream);
+    gTraceOutput.SetStream(stream);
 }
 
 void InitTrace()
 {
-    RegisterTraceHandler(TraceDefaultHandler);
+    void * context = &gTraceHandlerContext;
+    RegisterTraceHandler(TraceDefaultHandler, context);
 }
 
 void DeInitTrace()
 {
     UnregisterAllTraceHandlers();
-    output.DeleteStream();
+    gTraceOutput.DeleteStream();
 }
 
 } // namespace trace

diff --git a/examples/common/tracing/TraceHandlers.h b/examples/common/tracing/TraceHandlers.h
@@ -28,19 +28,32 @@ namespace trace {
 class TraceStream
 {
 public:
-    virtual ~TraceStream()                                                 = default;
-    virtual void Stream(const std::string & tag, const std::string & data) = 0;
-    virtual void Handler(const std::string & label)                        = 0;
+    virtual ~TraceStream()                                                   = default;
+    virtual void StartEvent(const std::string & label)                       = 0;
+    virtual void AddField(const std::string & tag, const std::string & data) = 0;
+    virtual void FinishEvent()                                               = 0;
 };
 
 class TraceStreamLog : public TraceStream
 {
 public:
-    void Stream(const std::string & tag, const std::string & data) override
+    void StartEvent(const std::string & label) override
     {
-        ChipLogAutomation("    %s: %s", tag.data(), data.data());
+        mStreamLine   = ">>>" + label + "<<<\t";
+        mIsFirstField = true;
     }
-    void Handler(const std::string & label) override { ChipLogAutomation("%s", label.data()); }
+
+    void AddField(const std::string & tag, const std::string & data) override
+    {
+        mStreamLine += (mIsFirstField ? "" : "\t") + tag + "|" + data;
+        mIsFirstField = false;
+    }
+
+    void FinishEvent() override { ChipLogAutomation("TraceStream:%s", mStreamLine.c_str()); }
+
+protected:
+    std::string mStreamLine;
+    bool mIsFirstField = true;
 };
 
 class TraceStreamFile : public TraceStream
@@ -49,25 +62,28 @@ class TraceStreamFile : public TraceStream
     TraceStreamFile(const char * fileName) { mFile.open(fileName); }
     ~TraceStreamFile() { mFile.close(); }
 
-    void Stream(const std::string & tag, const std::string & data) override
+    void AddField(const std::string & tag, const std::string & data) override
     {
         if (mFile.is_open())
         {
-            mFile << "    " << tag.data() << ": " << data.data() << "\n";
+            mFile << "    " << tag.data() << "\t" << data.data() << "\n";
             mFile.flush();
         }
     }
-    void Handler(const std::string & label) override
+
+    void StartEvent(const std::string & label) override
     {
         if (mFile.is_open())
         {
             struct timeval tv;
             gettimeofday(&tv, nullptr);
-            mFile << label << " [" << tv.tv_sec << "." << tv.tv_usec << "]\n";
+            mFile << "\f[" << tv.tv_sec << "." << tv.tv_usec << "]\t" << label << "\n";
             mFile.flush();
         }
     }
 
+    void FinishEvent() override {}
+
 private:
     std::ofstream mFile;
 };

diff --git a/examples/platform/linux/pw_trace_chip/public/pw_trace_chip/trace_chip.h b/examples/platform/linux/pw_trace_chip/public/pw_trace_chip/trace_chip.h
@@ -69,10 +69,10 @@ struct TraceEventFields
     size_t dataSize;
 };
 
-typedef bool (*TraceHandlerCallback)(const TraceEventFields & trace);
+typedef bool (*TraceHandlerCallback)(const TraceEventFields & eventFields, void * context);
 
-// Register a trace handler which gets called for all data trace events.
-void RegisterTraceHandler(TraceHandlerCallback callback);
+// Register an additional trace handler which gets called for all data trace events with the given context
+void RegisterTraceHandler(TraceHandlerCallback callback, void * context);
 void UnregisterAllTraceHandlers();
 
 // These are what the facade actually calls.