TRACE: Add transport tracing to linux example apps (project-chip#16893)

* TRACE: Add transport tracing to linux example apps - Add tracing to the linux example platform for linux apps. - Separate message tracing from pigweed trace, to support handling the trace messages without enabling full pigweed tracing. - Enable just the transport trace by default for linux. * Fix trace failure on standalone ack * Restyled by clang-format Co-authored-by: Tennessee Carmel-Veilleux <[email protected]> Co-authored-by: Restyled.io <[email protected]>
andrei-menzopol · Apr 14, 2022 · 7abbcfe · 7abbcfe
1 parent a0c3d44
commit 7abbcfe
Show file tree

Hide file tree

Showing 17 changed files with 233 additions and 323 deletions.
diff --git a/examples/chip-tool/args.gni b/examples/chip-tool/args.gni
@@ -15,7 +15,6 @@
 import("//build_overrides/chip.gni")
 
 import("${chip_root}/config/standalone/args.gni")
-import("${chip_root}/examples/chip-tool/with_pw_trace.gni")
 
 chip_device_project_config_include = "<CHIPProjectAppConfig.h>"
 chip_project_config_include = "<CHIPProjectAppConfig.h>"

diff --git a/examples/chip-tool/with_pw_trace.gni b/examples/chip-tool/with_pw_trace.gni
diff --git a/examples/common/tracing/BUILD.gn b/examples/common/tracing/BUILD.gn
@@ -12,11 +12,8 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-import("//build_overrides/pigweed.gni")
-
 import("//build_overrides/build.gni")
 import("//build_overrides/chip.gni")
-import("$dir_pw_build/target_types.gni")
 import("${chip_root}/src/lib/lib.gni")
 
 config("default_config") {
@@ -26,10 +23,7 @@ config("default_config") {
 source_set("trace_handlers") {
   sources = [ "TraceHandlers.cpp" ]
 
-  deps = [
-    "$dir_pw_trace",
-    "${chip_root}/src/lib",
-  ]
+  deps = [ "${chip_root}/src/lib" ]
 
   public_configs = [ ":default_config" ]
 }
diff --git a/examples/common/tracing/TraceHandlers.cpp b/examples/common/tracing/TraceHandlers.cpp
@@ -20,9 +20,8 @@
 #include <mutex>
 #include <stdint.h>
 #include <string>
+#include <vector>
 
-#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>
@@ -82,8 +81,14 @@ class TraceOutput
         }
     }
 
+    bool HasStreamAvailable() const
+    {
+        std::lock_guard<std::mutex> guard(mLock);
+        return (mStream != nullptr);
+    }
+
 private:
-    std::mutex mLock;
+    mutable std::mutex mLock;
     TraceStream * mStream = nullptr;
 };
 
@@ -130,15 +135,25 @@ std::string AsJsonBool(bool isTrue)
 
 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');
+    // Avoid hex conversion that would fail on empty
+    if (bufLen == 0)
+    {
+        return AsJsonString("");
+    }
+
+    // Fill a buffer long enough for the hex conversion, that will be overwritten
+    std::vector<char> 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);
+    if (status != CHIP_NO_ERROR)
+    {
+        ChipLogError(Support, "Unexpected failure: %" CHIP_ERROR_FORMAT, status.Format());
+        VerifyOrDie(status == CHIP_NO_ERROR);
+    }
 
-    return AsJsonString(hexBuf);
+    return AsJsonString(std::string(hexBuf.data(), hexBuf.size()));
 }
 
 std::string PacketHeaderToJson(const PacketHeader * packetHeader)
@@ -230,17 +245,15 @@ std::string PreparedSecureMessageDataToJson(const TracePreparedSecureMessageData
     return jsonBody;
 }
 
-bool SecureMessageSentHandler(const TraceEventFields & eventFields, void * context)
+void SecureMessageSentHandler(const TraceSecureMessageSentData * eventData)
 {
-    TraceHandlerContext * ourContext = reinterpret_cast<TraceHandlerContext *>(context);
-    if ((std::string{ eventFields.dataFormat } != kTraceMessageSentDataFormat) ||
-        (eventFields.dataSize != sizeof(TraceSecureMessageSentData)))
+    TraceOutput * sink = gTraceHandlerContext.sink;
+    if (!sink->HasStreamAvailable())
     {
-        return false;
+        return;
     }
 
-    const auto * eventData = reinterpret_cast<const TraceSecureMessageSentData *>(eventFields.dataBuffer);
-    std::string jsonBody   = "{";
+    std::string jsonBody = "{";
     jsonBody += PacketHeaderToJson(eventData->packetHeader);
     jsonBody += ", ";
     jsonBody += PayloadHeaderToJson(eventData->payloadHeader);
@@ -250,25 +263,19 @@ bool SecureMessageSentHandler(const TraceEventFields & eventFields, void * conte
     jsonBody += AsFirstJsonKey("payload_hex", AsJsonHexString(eventData->packetPayload, eventData->packetSize));
     jsonBody += "}";
 
-    TraceOutput * sink = ourContext->sink;
     sink->StartEvent(std::string{ kTraceMessageEvent } + "." + kTraceMessageSentDataFormat);
     sink->AddField("json", jsonBody);
     sink->FinishEvent();
-
-    return true;
 }
 
-bool SecureMessageReceivedHandler(const TraceEventFields & eventFields, void * context)
+void SecureMessageReceivedHandler(const TraceSecureMessageReceivedData * eventData)
 {
-    TraceHandlerContext * ourContext = reinterpret_cast<TraceHandlerContext *>(context);
-    if ((std::string{ eventFields.dataFormat } != kTraceMessageReceivedDataFormat) ||
-        (eventFields.dataSize != sizeof(TraceSecureMessageReceivedData)))
+    TraceOutput * sink = gTraceHandlerContext.sink;
+    if (!sink->HasStreamAvailable())
     {
-        return false;
+        return;
     }
 
-    const auto * eventData = reinterpret_cast<const TraceSecureMessageReceivedData *>(eventFields.dataBuffer);
-
     std::string jsonBody = "{";
     jsonBody += AsFirstJsonKey("peer_address", AsJsonString(eventData->peerAddress));
     jsonBody += ", ";
@@ -281,50 +288,57 @@ bool SecureMessageReceivedHandler(const TraceEventFields & eventFields, void * c
     jsonBody += AsFirstJsonKey("payload_hex", AsJsonHexString(eventData->packetPayload, eventData->packetSize));
     jsonBody += "}";
 
-    TraceOutput * sink = ourContext->sink;
     sink->StartEvent(std::string{ kTraceMessageEvent } + "." + kTraceMessageReceivedDataFormat);
     sink->AddField("json", jsonBody);
     sink->FinishEvent();
 
     // Note that `eventData->session` is currently ignored.
-
-    return true;
 }
 
-bool PreparedMessageSentHandler(const TraceEventFields & eventFields, void * context)
+void PreparedMessageSentHandler(const TracePreparedSecureMessageData * eventData)
 {
-    TraceHandlerContext * ourContext = reinterpret_cast<TraceHandlerContext *>(context);
-    if ((std::string{ eventFields.dataFormat } != kTracePreparedMessageSentDataFormat) ||
-        (eventFields.dataSize != sizeof(TracePreparedSecureMessageData)))
+    TraceOutput * sink = gTraceHandlerContext.sink;
+    if (!sink->HasStreamAvailable())
     {
-        return false;
+        return;
     }
 
-    const auto * eventData = reinterpret_cast<const TracePreparedSecureMessageData *>(eventFields.dataBuffer);
-    TraceOutput * sink     = ourContext->sink;
     sink->StartEvent(std::string{ kTraceMessageEvent } + "." + kTracePreparedMessageSentDataFormat);
     sink->AddField("json", PreparedSecureMessageDataToJson(eventData, "destination"));
     sink->FinishEvent();
-
-    return true;
 }
 
-bool PreparedMessageReceivedHandler(const TraceEventFields & eventFields, void * context)
+void PreparedMessageReceivedHandler(const TracePreparedSecureMessageData * eventData)
 {
-    TraceHandlerContext * ourContext = reinterpret_cast<TraceHandlerContext *>(context);
-    if ((std::string{ eventFields.dataFormat } != kTracePreparedMessageReceivedDataFormat) ||
-        (eventFields.dataSize != sizeof(TracePreparedSecureMessageData)))
+    TraceOutput * sink = gTraceHandlerContext.sink;
+    if (!sink->HasStreamAvailable())
     {
-        return false;
+        return;
     }
 
-    const auto * eventData = reinterpret_cast<const TracePreparedSecureMessageData *>(eventFields.dataBuffer);
-    TraceOutput * sink     = ourContext->sink;
     sink->StartEvent(std::string{ kTraceMessageEvent } + "." + kTracePreparedMessageReceivedDataFormat);
     sink->AddField("json", PreparedSecureMessageDataToJson(eventData, "source"));
     sink->FinishEvent();
+}
 
-    return true;
+void TraceHandler(const char * type, const void * data, size_t size)
+{
+    if ((std::string{ type } == kTracePreparedMessageReceivedDataFormat) && (size == sizeof(TracePreparedSecureMessageData)))
+    {
+        PreparedMessageReceivedHandler(reinterpret_cast<const TracePreparedSecureMessageData *>(data));
+    }
+    else if ((std::string{ type } == kTracePreparedMessageSentDataFormat) && (size == sizeof(TracePreparedSecureMessageData)))
+    {
+        PreparedMessageSentHandler(reinterpret_cast<const TracePreparedSecureMessageData *>(data));
+    }
+    else if ((std::string{ type } == kTraceMessageSentDataFormat) && (size == sizeof(TraceSecureMessageSentData)))
+    {
+        SecureMessageSentHandler(reinterpret_cast<const TraceSecureMessageSentData *>(data));
+    }
+    else if ((std::string{ type } == kTraceMessageReceivedDataFormat) && (size == sizeof(TraceSecureMessageReceivedData)))
+    {
+        SecureMessageReceivedHandler(reinterpret_cast<const TraceSecureMessageReceivedData *>(data));
+    }
 }
 
 } // namespace
@@ -336,16 +350,11 @@ void SetTraceStream(TraceStream * stream)
 
 void InitTrace()
 {
-    void * context = &gTraceHandlerContext;
-    RegisterTraceHandler(SecureMessageSentHandler, context);
-    RegisterTraceHandler(SecureMessageReceivedHandler, context);
-    RegisterTraceHandler(PreparedMessageSentHandler, context);
-    RegisterTraceHandler(PreparedMessageReceivedHandler, context);
+    SetTransportTraceHook(TraceHandler);
 }
 
 void DeInitTrace()
 {
-    UnregisterAllTraceHandlers();
     gTraceOutput.DeleteStream();
 }
 

diff --git a/examples/platform/linux/AppMain.cpp b/examples/platform/linux/AppMain.cpp
@@ -60,6 +60,10 @@
 #include <CommonRpc.h>
 #endif
 
+#if CHIP_CONFIG_TRANSPORT_TRACE_ENABLED
+#include "TraceHandlers.h"
+#endif // CHIP_CONFIG_TRANSPORT_TRACE_ENABLED
+
 #include <signal.h>
 
 #include "AppMain.h"
@@ -89,6 +93,13 @@ static constexpr uint8_t kWiFiStartCheckAttempts    = 5;
 #endif
 
 namespace {
+// To hold SPAKE2+ verifier, discriminator, passcode
+LinuxCommissionableDataProvider gCommissionableDataProvider;
+
+#if CHIP_CONFIG_TRANSPORT_TRACE_ENABLED
+chip::trace::TraceStream * gTraceStream = nullptr;
+#endif // CHIP_CONFIG_TRANSPORT_TRACE_ENABLED
+
 void EventHandler(const DeviceLayer::ChipDeviceEvent * event, intptr_t arg)
 {
     (void) arg;
@@ -208,8 +219,18 @@ CHIP_ERROR InitCommissionableDataProvider(LinuxCommissionableDataProvider & prov
                          options.payload.discriminator);
 }
 
-// To hold SPAKE2+ verifier, discriminator, passcode
-LinuxCommissionableDataProvider gCommissionableDataProvider;
+void Cleanup()
+{
+#if CHIP_CONFIG_TRANSPORT_TRACE_ENABLED
+    if (gTraceStream != nullptr)
+    {
+        delete gTraceStream;
+        gTraceStream = nullptr;
+    }
+    chip::trace::DeInitTrace();
+#endif // CHIP_CONFIG_TRANSPORT_TRACE_ENABLED
+}
+
 } // namespace
 
 #if CHIP_DEVICE_CONFIG_ENABLE_WPA
@@ -291,6 +312,23 @@ int ChipLinuxAppInit(int argc, char ** argv, OptionSet * customOptions)
 
     DeviceLayer::PlatformMgrImpl().AddEventHandler(EventHandler, 0);
 
+#if CHIP_CONFIG_TRANSPORT_TRACE_ENABLED
+    if (LinuxDeviceOptions::GetInstance().traceStreamFilename.HasValue())
+    {
+        const char * traceFilename = LinuxDeviceOptions::GetInstance().traceStreamFilename.Value().c_str();
+        gTraceStream               = new chip::trace::TraceStreamFile(traceFilename);
+    }
+    else if (LinuxDeviceOptions::GetInstance().traceStreamToLogEnabled)
+    {
+        gTraceStream = new chip::trace::TraceStreamLog();
+    }
+    chip::trace::InitTrace();
+    if (gTraceStream != nullptr)
+    {
+        chip::trace::SetTraceStream(gTraceStream);
+    }
+#endif // CHIP_CONFIG_TRANSPORT_TRACE_ENABLED
+
 #if CONFIG_NETWORK_LAYER_BLE
     DeviceLayer::ConnectivityMgr().SetBLEDeviceName(nullptr); // Use default device name (CHIP-XXXX)
     DeviceLayer::Internal::BLEMgrImpl().ConfigureBle(LinuxDeviceOptions::GetInstance().mBleDevice, false);
@@ -320,6 +358,8 @@ int ChipLinuxAppInit(int argc, char ** argv, OptionSet * customOptions)
     if (err != CHIP_NO_ERROR)
     {
         ChipLogProgress(NotSpecified, "Failed to init Linux App: %s ", ErrorStr(err));
+        Cleanup();
+
         // End the program with non zero error code to indicate a error.
         return 1;
     }
@@ -704,4 +744,6 @@ void ChipLinuxAppMainLoop()
     Server::GetInstance().Shutdown();
 
     DeviceLayer::PlatformMgr().Shutdown();
+
+    Cleanup();
 }
diff --git a/examples/platform/linux/BUILD.gn b/examples/platform/linux/BUILD.gn
@@ -15,6 +15,7 @@
 import("//build_overrides/chip.gni")
 import("${chip_root}/examples/common/pigweed/pigweed_rpcs.gni")
 import("${chip_root}/src/app/common_flags.gni")
+import("${chip_root}/src/lib/core/core.gni")
 import("${chip_root}/src/lib/lib.gni")
 
 config("app-main-config") {
@@ -53,5 +54,9 @@ source_set("app-main") {
     "${chip_root}/src/lib/shell:shell_core",
   ]
 
+  if (chip_enable_transport_trace) {
+    public_deps += [ "${chip_root}/examples/common/tracing:trace_handlers" ]
+  }
+
   public_configs = [ ":app-main-config" ]
 }