Create a JSON Log tracing backend (#27135)

* Start a backend implementation, empty for now

* Add jsonpp support

* Allow sstream and string usage in the log tracing library

* remove unneeded log line

* Restyle

* Make matter tracing opt-in by default. Will enable it for chip-tool and linux apps at start

* make things compile, add dependency into chip-command

* Enable tracing for CHIPTool

* Ensure uniqueness

* Restyle

* Add a few more comments

* Add MATTER_TRACE_EVENT_SCOPE everywhere.

Ran:

```sh
rg MATTER_TRACE_EVENT_SCOPE --files-with-matches \
  | grep -v src/trace \
  | xargs sd \
     '(^(\s*)MATTER_TRACE_EVENT_SCOPE\("(.*)",\s*"(.*)"\);)' \
     "\${1}\n\${2}MATTER_TRACE_SCOPE(::chip::Tracing::Scope::\${4}_\${3});"
```

* Add tracing/scope.h include to have access to MATTER_TRACE_SCOPE

* Switch addressresolve to use matter tracing instead of tracevent (instant is one of the cases where matter_trace did not actually work)

* Switch out and add incremental resolve record parse

* Restyle

* Make chip-tool compile. Still need to fix device apps

* Fix compilation with tracing disabled

* Enable tracing by defaulf for a lot of example apps

* Add some dependencies to tracing

* Make sure no unused member error

* Another update for tracing disabled

* Restyle

* Scope the macros a bit more

* Restyle

* Only build tracing tests if tracing is enabled on the platform

* Restyle

* Enable tracing on linux using a different logic - all linux builds have tracing by default

* Restyle

* Fix check_includes_config

* Add a string splitter class

* Switch to use the support string splitter class

* Use standard command argument handling for CSV string vector

* Support optional string vector arguments

* Fix typo

* Do not fail on stringop-truncation in tests

* Fix initialization of mData for null cases for stringsplitter

* Restyled by clang-format

* Add more unit tests and ensure final empty element is emitted

* Restyled by clang-format

* separator should be const

* Restyled by clang-format

* Review comment: use char span

* Use char span for string splitting

* Restyled by clang-format

* Restyled by clang-format

* Force a static cast for size compares

* make linter happy

* Restyled by clang-format

---------

Co-authored-by: Andrei Litvin <[email protected]>
Co-authored-by: Restyled.io <[email protected]>

examples/chip-tool/BUILD.gn

@@ -114,6 +114,8 @@ static_library("chip-tool-utils") {
     "${chip_root}/src/lib",
     "${chip_root}/src/lib/support/jsontlv",
     "${chip_root}/src/platform",
+    "${chip_root}/src/tracing",
+    "${chip_root}/src/tracing/log_json",
     "${chip_root}/third_party/inipp",
     "${chip_root}/third_party/jsoncpp",
   ]

examples/chip-tool/args.gni

@@ -22,3 +22,5 @@ chip_system_project_config_include = "<SystemProjectConfig.h>"
 
 chip_project_config_include_dirs = [ "${chip_root}/examples/chip-tool/include" ]
 chip_project_config_include_dirs += [ "${chip_root}/config/standalone" ]
+
+matter_enable_tracing_support = true

examples/chip-tool/commands/common/CHIPCommand.cpp

@@ -26,6 +26,9 @@
 #include <lib/support/ScopedBuffer.h>
 #include <lib/support/TestGroupData.h>
 
+#include <tracing/log_json/log_json_tracing.h>
+#include <tracing/registry.h>
+
 #if CHIP_CONFIG_TRANSPORT_TRACE_ENABLED
 #include "TraceDecoder.h"
 #include "TraceHandlers.h"
@@ -48,6 +51,7 @@ const chip::Credentials::AttestationTrustStore * CHIPCommand::sTrustStore = null
 chip::Credentials::GroupDataProviderImpl CHIPCommand::sGroupDataProvider{ kMaxGroupsPerFabric, kMaxGroupKeysPerFabric };
 
 namespace {
+
 CHIP_ERROR GetAttestationTrustStore(const char * paaTrustStorePath, const chip::Credentials::AttestationTrustStore ** trustStore)
 {
     if (paaTrustStorePath == nullptr)
@@ -77,6 +81,16 @@ CHIP_ERROR GetAttestationTrustStore(const char * paaTrustStorePath, const chip::
     *trustStore = &attestationTrustStore;
     return CHIP_NO_ERROR;
 }
+
+using ::chip::Tracing::ScopedRegistration;
+using ::chip::Tracing::LogJson::LogJsonBackend;
+
+LogJsonBackend log_json_backend;
+
+// ScopedRegistration ensures register/unregister is met, as long
+// as the vector is cleared (and we do so when stopping tracing).
+std::vector<std::unique_ptr<ScopedRegistration>> tracing_backends;
+
 } // namespace
 
 CHIP_ERROR CHIPCommand::MaybeSetUpStack()
@@ -240,6 +254,24 @@ CHIP_ERROR CHIPCommand::Run()
 
 void CHIPCommand::StartTracing()
 {
+    if (mTraceTo.HasValue())
+    {
+        for (const auto & destination : mTraceTo.Value())
+        {
+            if (destination == "log")
+            {
+                if (!log_json_backend.IsInList())
+                {
+                    tracing_backends.push_back(std::make_unique<ScopedRegistration>(log_json_backend));
+                }
+            }
+            else
+            {
+                ChipLogError(AppServer, "Unknown trace destination: '%s'", destination.c_str());
+            }
+        }
+    }
+
 #if CHIP_CONFIG_TRANSPORT_TRACE_ENABLED
     chip::trace::InitTrace();
 
@@ -266,6 +298,8 @@ void CHIPCommand::StartTracing()
 
 void CHIPCommand::StopTracing()
 {
+    tracing_backends.clear();
+
 #if CHIP_CONFIG_TRANSPORT_TRACE_ENABLED
     chip::trace::DeInitTrace();
 #endif // CHIP_CONFIG_TRANSPORT_TRACE_ENABLED

examples/chip-tool/commands/common/CHIPCommand.h

@@ -85,6 +85,7 @@ class CHIPCommand : public Command
         AddArgument("trace_log", 0, 1, &mTraceLog);
         AddArgument("trace_decode", 0, 1, &mTraceDecode);
 #endif // CHIP_CONFIG_TRANSPORT_TRACE_ENABLED
+        AddArgument("trace-to", &mTraceTo, "Trace destinations, comma-separated (e.g. log)");
         AddArgument("ble-adapter", 0, UINT16_MAX, &mBleAdapterId);
         AddArgument("storage-directory", &mStorageDirectory,
                     "Directory to place chip-tool's storage files in.  Defaults to $TMPDIR, with fallback to /tmp");
@@ -238,4 +239,6 @@ class CHIPCommand : public Command
     chip::Optional<bool> mTraceLog;
     chip::Optional<bool> mTraceDecode;
 #endif // CHIP_CONFIG_TRANSPORT_TRACE_ENABLED
+
+    chip::Optional<std::vector<std::string>> mTraceTo;
 };

examples/chip-tool/commands/common/Command.cpp

@@ -35,6 +35,7 @@
 #include <lib/support/CodeUtils.h>
 #include <lib/support/SafeInt.h>
 #include <lib/support/ScopedBuffer.h>
+#include <lib/support/StringSplitter.h>
 #include <lib/support/logging/CHIPLogging.h>
 
 constexpr const char * kOptionalArgumentPrefix = "--";
@@ -220,6 +221,29 @@ bool Command::InitArgument(size_t argIndex, char * argValue)
         return CHIP_NO_ERROR == customArgument->Parse(arg.name, argValue);
     }
 
+    case ArgumentType::VectorString: {
+        std::vector<std::string> vectorArgument;
+
+        chip::StringSplitter splitter(argValue, ',');
+        chip::CharSpan value;
+
+        while (splitter.Next(value))
+        {
+            vectorArgument.push_back(std::string(value.data(), value.size()));
+        }
+
+        if (arg.flags == Argument::kOptional)
+        {
+            auto argument = static_cast<chip::Optional<std::vector<std::string>> *>(arg.value);
+            argument->SetValue(vectorArgument);
+        }
+        else
+        {
+            auto argument = static_cast<std::vector<std::string> *>(arg.value);
+            *argument     = vectorArgument;
+        }
+        return true;
+    }
     case ArgumentType::VectorBool: {
         // Currently only chip::Optional<std::vector<bool>> is supported.
         if (arg.flags != Argument::kOptional)
@@ -798,6 +822,30 @@ size_t Command::AddArgument(const char * name, int64_t min, uint64_t max, void *
     return AddArgumentToList(std::move(arg));
 }
 
+size_t Command::AddArgument(const char * name, std::vector<std::string> * value, const char * desc)
+{
+    Argument arg;
+    arg.type  = ArgumentType::VectorString;
+    arg.name  = name;
+    arg.value = static_cast<void *>(value);
+    arg.flags = 0;
+    arg.desc  = desc;
+
+    return AddArgumentToList(std::move(arg));
+}
+
+size_t Command::AddArgument(const char * name, chip::Optional<std::vector<std::string>> * value, const char * desc)
+{
+    Argument arg;
+    arg.type  = ArgumentType::VectorString;
+    arg.name  = name;
+    arg.value = static_cast<void *>(value);
+    arg.flags = Argument::kOptional;
+    arg.desc  = desc;
+
+    return AddArgumentToList(std::move(arg));
+}
+
 const char * Command::GetArgumentName(size_t index) const
 {
     if (index < mArgs.size())
@@ -916,6 +964,10 @@ void Command::ResetArguments()
                 VerifyOrDie(false);
                 break;
             }
+            case ArgumentType::VectorString: {
+                ResetOptionalArg<std::vector<std::string>>(arg);
+                break;
+            }
             case ArgumentType::VectorBool: {
                 ResetOptionalArg<std::vector<bool>>(arg);
                 break;

examples/chip-tool/commands/common/Command.h

@@ -72,6 +72,7 @@ enum ArgumentType
     Vector16,
     Vector32,
     VectorCustom,
+    VectorString, // comma separated string items
 };
 
 struct Argument
@@ -254,6 +255,9 @@ class Command
         return AddArgument(name, min, max, reinterpret_cast<double *>(value), desc, flags | Argument::kNullable);
     }
 
+    size_t AddArgument(const char * name, std::vector<std::string> * value, const char * desc);
+    size_t AddArgument(const char * name, chip::Optional<std::vector<std::string>> * value, const char * desc);
+
     void ResetArguments();
 
     virtual CHIP_ERROR Run() = 0;

examples/tv-casting-app/tv-casting-common/BUILD.gn

@@ -88,6 +88,8 @@ chip_data_model("tv-casting-common") {
   deps = [
     "${chip_root}/src/app/tests/suites/commands/interaction_model",
     "${chip_root}/src/lib/support/jsontlv",
+    "${chip_root}/src/tracing",
+    "${chip_root}/src/tracing/log_json",
     "${chip_root}/third_party/inipp",
     "${chip_root}/third_party/jsoncpp",
   ]

scripts/tools/check_includes_config.py

@@ -153,5 +153,8 @@
     # of a list of discovered things.
     'src/controller/SetUpCodePairer.h': {'deque'},
 
-    'src/controller/ExamplePersistentStorage.cpp': {'fstream'}
+    'src/controller/ExamplePersistentStorage.cpp': {'fstream'},
+
+    # Library meant for non-embedded
+    'src/tracing/log_json/log_json_tracing.cpp': {'string', 'sstream'}
 }

src/BUILD.gn

@@ -21,6 +21,7 @@ import("${chip_root}/build/chip/tests.gni")
 import("${chip_root}/src/ble/ble.gni")
 import("${chip_root}/src/lwip/lwip.gni")
 import("${chip_root}/src/platform/device.gni")
+import("${chip_root}/src/tracing/tracing_args.gni")
 
 declare_args() {
   # Build monolithic test library.
@@ -94,9 +95,12 @@ if (chip_build_tests) {
         "${chip_root}/src/lib/support/tests",
         "${chip_root}/src/protocols/secure_channel/tests",
         "${chip_root}/src/system/tests",
-        "${chip_root}/src/tracing/tests",
         "${chip_root}/src/transport/tests",
       ]
+
+      if (matter_enable_tracing_support) {
+        deps += [ "${chip_root}/src/tracing/tests" ]
+      }
     }
 
     if (chip_device_platform != "none") {

src/app/clusters/general-commissioning-server/general-commissioning-server.cpp

@@ -35,6 +35,7 @@
 #include <platform/ConfigurationManager.h>
 #include <platform/DeviceControlServer.h>
 #include <trace/trace.h>
+#include <tracing/scope.h>
 
 using namespace chip;
 using namespace chip::app;
@@ -155,6 +156,7 @@ bool emberAfGeneralCommissioningClusterArmFailSafeCallback(app::CommandHandler *
                                                            const Commands::ArmFailSafe::DecodableType & commandData)
 {
     MATTER_TRACE_EVENT_SCOPE("ArmFailSafe", "GeneralCommissioning");
+    MATTER_TRACE_SCOPE(::chip::Tracing::Scope::GeneralCommissioning_ArmFailSafe);
     auto & failSafeContext = Server::GetInstance().GetFailSafeContext();
     Commands::ArmFailSafeResponse::Type response;
 
@@ -217,6 +219,7 @@ bool emberAfGeneralCommissioningClusterCommissioningCompleteCallback(
     const Commands::CommissioningComplete::DecodableType & commandData)
 {
     MATTER_TRACE_EVENT_SCOPE("CommissioningComplete", "GeneralCommissioning");
+    MATTER_TRACE_SCOPE(::chip::Tracing::Scope::GeneralCommissioning_CommissioningComplete);
 
     DeviceControlServer * devCtrl = &DeviceLayer::DeviceControlServer::DeviceControlSvr();
     auto & failSafe               = Server::GetInstance().GetFailSafeContext();
@@ -284,6 +287,7 @@ bool emberAfGeneralCommissioningClusterSetRegulatoryConfigCallback(app::CommandH
                                                                    const Commands::SetRegulatoryConfig::DecodableType & commandData)
 {
     MATTER_TRACE_EVENT_SCOPE("SetRegulatoryConfig", "GeneralCommissioning");
+    MATTER_TRACE_SCOPE(::chip::Tracing::Scope::GeneralCommissioning_SetRegulatoryConfig);
     DeviceControlServer * server = &DeviceLayer::DeviceControlServer::DeviceControlSvr();
     Commands::SetRegulatoryConfigResponse::Type response;
 

src/app/clusters/network-commissioning/network-commissioning.cpp

@@ -32,6 +32,7 @@
 #include <platform/PlatformManager.h>
 #include <platform/internal/DeviceNetworkInfo.h>
 #include <trace/trace.h>
+#include <tracing/scope.h>
 
 using namespace chip;
 using namespace chip::app;
@@ -244,6 +245,7 @@ void Instance::OnNetworkingStatusChange(NetworkCommissioning::Status aCommission
 void Instance::HandleScanNetworks(HandlerContext & ctx, const Commands::ScanNetworks::DecodableType & req)
 {
     MATTER_TRACE_EVENT_SCOPE("HandleScanNetwork", "NetworkCommissioning");
+    MATTER_TRACE_SCOPE(::chip::Tracing::Scope::NetworkCommissioning_HandleScanNetwork);
     if (mFeatureFlags.Has(Feature::kWiFiNetworkInterface))
     {
         ByteSpan ssid;
@@ -316,6 +318,7 @@ bool CheckFailSafeArmed(CommandHandlerInterface::HandlerContext & ctx)
 void Instance::HandleAddOrUpdateWiFiNetwork(HandlerContext & ctx, const Commands::AddOrUpdateWiFiNetwork::DecodableType & req)
 {
     MATTER_TRACE_EVENT_SCOPE("HandleAddOrUpdateWiFiNetwork", "NetworkCommissioning");
+    MATTER_TRACE_SCOPE(::chip::Tracing::Scope::NetworkCommissioning_HandleAddOrUpdateWiFiNetwork);
 
     VerifyOrReturn(CheckFailSafeArmed(ctx));
 
@@ -374,6 +377,7 @@ void Instance::HandleAddOrUpdateWiFiNetwork(HandlerContext & ctx, const Commands
 void Instance::HandleAddOrUpdateThreadNetwork(HandlerContext & ctx, const Commands::AddOrUpdateThreadNetwork::DecodableType & req)
 {
     MATTER_TRACE_EVENT_SCOPE("HandleAddOrUpdateThreadNetwork", "NetworkCommissioning");
+    MATTER_TRACE_SCOPE(::chip::Tracing::Scope::NetworkCommissioning_HandleAddOrUpdateThreadNetwork);
 
     VerifyOrReturn(CheckFailSafeArmed(ctx));
 
@@ -411,6 +415,7 @@ void Instance::CommitSavedBreadcrumb()
 void Instance::HandleRemoveNetwork(HandlerContext & ctx, const Commands::RemoveNetwork::DecodableType & req)
 {
     MATTER_TRACE_EVENT_SCOPE("HandleRemoveNetwork", "NetworkCommissioning");
+    MATTER_TRACE_SCOPE(::chip::Tracing::Scope::NetworkCommissioning_HandleRemoveNetwork);
 
     VerifyOrReturn(CheckFailSafeArmed(ctx));
 
@@ -433,6 +438,7 @@ void Instance::HandleRemoveNetwork(HandlerContext & ctx, const Commands::RemoveN
 void Instance::HandleConnectNetwork(HandlerContext & ctx, const Commands::ConnectNetwork::DecodableType & req)
 {
     MATTER_TRACE_EVENT_SCOPE("HandleConnectNetwork", "NetworkCommissioning");
+    MATTER_TRACE_SCOPE(::chip::Tracing::Scope::NetworkCommissioning_HandleConnectNetwork);
     if (req.networkID.size() > DeviceLayer::NetworkCommissioning::kMaxNetworkIDLen)
     {
         ctx.mCommandHandler.AddStatus(ctx.mRequestPath, Protocols::InteractionModel::Status::InvalidValue);
@@ -451,6 +457,7 @@ void Instance::HandleConnectNetwork(HandlerContext & ctx, const Commands::Connec
 void Instance::HandleReorderNetwork(HandlerContext & ctx, const Commands::ReorderNetwork::DecodableType & req)
 {
     MATTER_TRACE_EVENT_SCOPE("HandleReorderNetwork", "NetworkCommissioning");
+    MATTER_TRACE_SCOPE(::chip::Tracing::Scope::NetworkCommissioning_HandleReorderNetwork);
     Commands::NetworkConfigResponse::Type response;
     MutableCharSpan debugText;
 #if CHIP_CONFIG_NETWORK_COMMISSIONING_DEBUG_TEXT_BUFFER_SIZE

src/app/clusters/operational-credentials-server/operational-credentials-server.cpp

@@ -49,6 +49,7 @@
 #include <platform/CHIPDeviceLayer.h>
 #include <string.h>
 #include <trace/trace.h>
+#include <tracing/scope.h>
 
 using namespace chip;
 using namespace ::chip::Transport;
@@ -408,6 +409,7 @@ bool emberAfOperationalCredentialsClusterRemoveFabricCallback(app::CommandHandle
                                                               const Commands::RemoveFabric::DecodableType & commandData)
 {
     MATTER_TRACE_EVENT_SCOPE("RemoveFabric", "OperationalCredentials");
+    MATTER_TRACE_SCOPE(::chip::Tracing::Scope::OperationalCredentials_RemoveFabric);
     auto & fabricBeingRemoved = commandData.fabricIndex;
 
     ChipLogProgress(Zcl, "OpCreds: Received a RemoveFabric Command for FabricIndex 0x%x",
@@ -468,6 +470,7 @@ bool emberAfOperationalCredentialsClusterUpdateFabricLabelCallback(app::CommandH
                                                                    const Commands::UpdateFabricLabel::DecodableType & commandData)
 {
     MATTER_TRACE_EVENT_SCOPE("UpdateFabricLabel", "OperationalCredentials");
+    MATTER_TRACE_SCOPE(::chip::Tracing::Scope::OperationalCredentials_UpdateFabricLabel);
     auto & label        = commandData.label;
     auto ourFabricIndex = commandObj->GetAccessingFabricIndex();
     auto finalStatus    = Status::Failure;
@@ -590,6 +593,7 @@ bool emberAfOperationalCredentialsClusterAddNOCCallback(app::CommandHandler * co
                                                         const Commands::AddNOC::DecodableType & commandData)
 {
     MATTER_TRACE_EVENT_SCOPE("AddNOC", "OperationalCredentials");
+    MATTER_TRACE_SCOPE(::chip::Tracing::Scope::OperationalCredentials_AddNOC);
     auto & NOCValue          = commandData.NOCValue;
     auto & ICACValue         = commandData.ICACValue;
     auto & adminVendorId     = commandData.adminVendorId;
@@ -763,6 +767,7 @@ bool emberAfOperationalCredentialsClusterUpdateNOCCallback(app::CommandHandler *
                                                            const Commands::UpdateNOC::DecodableType & commandData)
 {
     MATTER_TRACE_EVENT_SCOPE("UpdateNOC", "OperationalCredentials");
+    MATTER_TRACE_SCOPE(::chip::Tracing::Scope::OperationalCredentials_UpdateNOC);
     auto & NOCValue  = commandData.NOCValue;
     auto & ICACValue = commandData.ICACValue;
 
@@ -855,6 +860,7 @@ bool emberAfOperationalCredentialsClusterCertificateChainRequestCallback(
     const Commands::CertificateChainRequest::DecodableType & commandData)
 {
     MATTER_TRACE_EVENT_SCOPE("CertificateChainRequest", "OperationalCredentials");
+    MATTER_TRACE_SCOPE(::chip::Tracing::Scope::OperationalCredentials_CertificateChainRequest);
     auto & certificateType = commandData.certificateType;
 
     CHIP_ERROR err = CHIP_NO_ERROR;
@@ -903,6 +909,7 @@ bool emberAfOperationalCredentialsClusterAttestationRequestCallback(app::Command
                                                                     const Commands::AttestationRequest::DecodableType & commandData)
 {
     MATTER_TRACE_EVENT_SCOPE("AttestationRequest", "OperationalCredentials");
+    MATTER_TRACE_SCOPE(::chip::Tracing::Scope::OperationalCredentials_AttestationRequest);
     auto & attestationNonce = commandData.attestationNonce;
 
     auto finalStatus = Status::Failure;
@@ -999,6 +1006,7 @@ bool emberAfOperationalCredentialsClusterCSRRequestCallback(app::CommandHandler
                                                             const Commands::CSRRequest::DecodableType & commandData)
 {
     MATTER_TRACE_EVENT_SCOPE("CSRRequest", "OperationalCredentials");
+    MATTER_TRACE_SCOPE(::chip::Tracing::Scope::OperationalCredentials_CSRRequest);
     ChipLogProgress(Zcl, "OpCreds: Received a CSRRequest command");
 
     chip::Platform::ScopedMemoryBuffer<uint8_t> nocsrElements;
@@ -1134,6 +1142,7 @@ bool emberAfOperationalCredentialsClusterAddTrustedRootCertificateCallback(
     const Commands::AddTrustedRootCertificate::DecodableType & commandData)
 {
     MATTER_TRACE_EVENT_SCOPE("AddTrustedRootCertificate", "OperationalCredentials");
+    MATTER_TRACE_SCOPE(::chip::Tracing::Scope::OperationalCredentials_AddTrustedRootCertificate);
 
     auto & fabricTable = Server::GetInstance().GetFabricTable();
     auto finalStatus   = Status::Failure;