From 123632913c90de660d5776fb61c09b815472b428 Mon Sep 17 00:00:00 2001 From: Andrei Litvin Date: Thu, 8 Jun 2023 18:29:54 -0400 Subject: [PATCH] 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 Co-authored-by: Restyled.io --- examples/chip-tool/BUILD.gn | 2 + examples/chip-tool/args.gni | 2 + .../chip-tool/commands/common/CHIPCommand.cpp | 34 +++ .../chip-tool/commands/common/CHIPCommand.h | 3 + .../chip-tool/commands/common/Command.cpp | 52 ++++ examples/chip-tool/commands/common/Command.h | 4 + .../tv-casting-app/tv-casting-common/BUILD.gn | 2 + scripts/tools/check_includes_config.py | 5 +- src/BUILD.gn | 6 +- .../general-commissioning-server.cpp | 4 + .../network-commissioning.cpp | 7 + .../operational-credentials-server.cpp | 9 + src/controller/BUILD.gn | 1 + src/controller/CHIPDeviceController.cpp | 34 +++ src/lib/dnssd/BUILD.gn | 2 +- src/lib/dnssd/IncrementalResolve.cpp | 13 +- src/protocols/secure_channel/BUILD.gn | 1 + src/protocols/secure_channel/CASESession.cpp | 12 + src/protocols/secure_channel/PASESession.cpp | 12 + src/tracing/BUILD.gn | 4 +- src/tracing/log_json/BUILD.gn | 30 ++ src/tracing/log_json/log_json_tracing.cpp | 283 ++++++++++++++++++ src/tracing/log_json/log_json_tracing.h | 46 +++ src/tracing/macros.h | 2 +- src/tracing/scope.h | 12 + src/tracing/scopes.h | 1 + src/tracing/tests/BUILD.gn | 23 +- src/tracing/tracing_args.gni | 20 ++ 28 files changed, 604 insertions(+), 22 deletions(-) create mode 100644 src/tracing/log_json/BUILD.gn create mode 100644 src/tracing/log_json/log_json_tracing.cpp create mode 100644 src/tracing/log_json/log_json_tracing.h create mode 100644 src/tracing/tracing_args.gni diff --git a/examples/chip-tool/BUILD.gn b/examples/chip-tool/BUILD.gn index 8f01267ff9c03a..73c90413af32db 100644 --- a/examples/chip-tool/BUILD.gn +++ b/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", ] diff --git a/examples/chip-tool/args.gni b/examples/chip-tool/args.gni index a76f3e8996ce3c..290c027d9c822d 100644 --- a/examples/chip-tool/args.gni +++ b/examples/chip-tool/args.gni @@ -22,3 +22,5 @@ chip_system_project_config_include = "" 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 diff --git a/examples/chip-tool/commands/common/CHIPCommand.cpp b/examples/chip-tool/commands/common/CHIPCommand.cpp index be612efa637bd9..57a8eaeb376581 100644 --- a/examples/chip-tool/commands/common/CHIPCommand.cpp +++ b/examples/chip-tool/commands/common/CHIPCommand.cpp @@ -26,6 +26,9 @@ #include #include +#include +#include + #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> 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(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 diff --git a/examples/chip-tool/commands/common/CHIPCommand.h b/examples/chip-tool/commands/common/CHIPCommand.h index 76b01b40434ce3..624dd79a255bb0 100644 --- a/examples/chip-tool/commands/common/CHIPCommand.h +++ b/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 mTraceLog; chip::Optional mTraceDecode; #endif // CHIP_CONFIG_TRANSPORT_TRACE_ENABLED + + chip::Optional> mTraceTo; }; diff --git a/examples/chip-tool/commands/common/Command.cpp b/examples/chip-tool/commands/common/Command.cpp index 64bea6faf81486..1c054c1b530e25 100644 --- a/examples/chip-tool/commands/common/Command.cpp +++ b/examples/chip-tool/commands/common/Command.cpp @@ -35,6 +35,7 @@ #include #include #include +#include #include 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 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> *>(arg.value); + argument->SetValue(vectorArgument); + } + else + { + auto argument = static_cast *>(arg.value); + *argument = vectorArgument; + } + return true; + } case ArgumentType::VectorBool: { // Currently only chip::Optional> 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 * value, const char * desc) +{ + Argument arg; + arg.type = ArgumentType::VectorString; + arg.name = name; + arg.value = static_cast(value); + arg.flags = 0; + arg.desc = desc; + + return AddArgumentToList(std::move(arg)); +} + +size_t Command::AddArgument(const char * name, chip::Optional> * value, const char * desc) +{ + Argument arg; + arg.type = ArgumentType::VectorString; + arg.name = name; + arg.value = static_cast(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>(arg); + break; + } case ArgumentType::VectorBool: { ResetOptionalArg>(arg); break; diff --git a/examples/chip-tool/commands/common/Command.h b/examples/chip-tool/commands/common/Command.h index c3c59f41f99477..06bf5ef6f3dc8b 100644 --- a/examples/chip-tool/commands/common/Command.h +++ b/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(value), desc, flags | Argument::kNullable); } + size_t AddArgument(const char * name, std::vector * value, const char * desc); + size_t AddArgument(const char * name, chip::Optional> * value, const char * desc); + void ResetArguments(); virtual CHIP_ERROR Run() = 0; diff --git a/examples/tv-casting-app/tv-casting-common/BUILD.gn b/examples/tv-casting-app/tv-casting-common/BUILD.gn index b08c23e5e810c7..37ec1452b5bf17 100644 --- a/examples/tv-casting-app/tv-casting-common/BUILD.gn +++ b/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", ] diff --git a/scripts/tools/check_includes_config.py b/scripts/tools/check_includes_config.py index e7fc6b1b5b72bd..fec2328f348b74 100644 --- a/scripts/tools/check_includes_config.py +++ b/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'} } diff --git a/src/BUILD.gn b/src/BUILD.gn index 26cf7c085938dd..fd4df956a2ac42 100644 --- a/src/BUILD.gn +++ b/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") { diff --git a/src/app/clusters/general-commissioning-server/general-commissioning-server.cpp b/src/app/clusters/general-commissioning-server/general-commissioning-server.cpp index 763bb15c47f5be..6e5893a5ef7248 100644 --- a/src/app/clusters/general-commissioning-server/general-commissioning-server.cpp +++ b/src/app/clusters/general-commissioning-server/general-commissioning-server.cpp @@ -35,6 +35,7 @@ #include #include #include +#include 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; diff --git a/src/app/clusters/network-commissioning/network-commissioning.cpp b/src/app/clusters/network-commissioning/network-commissioning.cpp index a7d47e930dd8d3..7dea1a6f3e55fc 100644 --- a/src/app/clusters/network-commissioning/network-commissioning.cpp +++ b/src/app/clusters/network-commissioning/network-commissioning.cpp @@ -32,6 +32,7 @@ #include #include #include +#include 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 diff --git a/src/app/clusters/operational-credentials-server/operational-credentials-server.cpp b/src/app/clusters/operational-credentials-server/operational-credentials-server.cpp index 118e46ba6c6d50..765c0de0c3d9a4 100644 --- a/src/app/clusters/operational-credentials-server/operational-credentials-server.cpp +++ b/src/app/clusters/operational-credentials-server/operational-credentials-server.cpp @@ -49,6 +49,7 @@ #include #include #include +#include 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 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; diff --git a/src/controller/BUILD.gn b/src/controller/BUILD.gn index 797d09b24f0b1b..951bac4f5dc5b5 100644 --- a/src/controller/BUILD.gn +++ b/src/controller/BUILD.gn @@ -64,6 +64,7 @@ static_library("controller") { "${chip_root}/src/protocols", "${chip_root}/src/setup_payload", "${chip_root}/src/trace", + "${chip_root}/src/tracing", "${chip_root}/src/transport", ] diff --git a/src/controller/CHIPDeviceController.cpp b/src/controller/CHIPDeviceController.cpp index 4c0e21619d427d..acb524769ed37a 100644 --- a/src/controller/CHIPDeviceController.cpp +++ b/src/controller/CHIPDeviceController.cpp @@ -68,6 +68,7 @@ #include #include #include +#include #if CONFIG_NETWORK_LAYER_BLE #include @@ -520,6 +521,7 @@ void DeviceCommissioner::Shutdown() CommissioneeDeviceProxy * DeviceCommissioner::FindCommissioneeDevice(NodeId id) { MATTER_TRACE_EVENT_SCOPE("FindCommissioneeDevice", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_FindCommissioneeDevice); CommissioneeDeviceProxy * foundDevice = nullptr; mCommissioneeDevicePool.ForEachActiveObject([&](auto * deviceProxy) { if (deviceProxy->GetDeviceId() == id) @@ -590,6 +592,7 @@ CHIP_ERROR DeviceCommissioner::PairDevice(NodeId remoteDeviceId, const char * se DiscoveryType discoveryType, Optional resolutionData) { MATTER_TRACE_EVENT_SCOPE("PairDevice", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_PairDevice); if (mDefaultCommissioner == nullptr) { @@ -606,6 +609,7 @@ CHIP_ERROR DeviceCommissioner::PairDevice(NodeId remoteDeviceId, const char * se Optional resolutionData) { MATTER_TRACE_EVENT_SCOPE("PairDevice", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_PairDevice); return mSetUpCodePairer.PairDevice(remoteDeviceId, setUpCode, SetupCodePairerBehaviour::kCommission, discoveryType, resolutionData); } @@ -613,6 +617,7 @@ CHIP_ERROR DeviceCommissioner::PairDevice(NodeId remoteDeviceId, const char * se CHIP_ERROR DeviceCommissioner::PairDevice(NodeId remoteDeviceId, RendezvousParameters & params) { MATTER_TRACE_EVENT_SCOPE("PairDevice", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_PairDevice); ReturnErrorOnFailure(EstablishPASEConnection(remoteDeviceId, params)); return Commission(remoteDeviceId); } @@ -621,6 +626,7 @@ CHIP_ERROR DeviceCommissioner::PairDevice(NodeId remoteDeviceId, RendezvousParam CommissioningParameters & commissioningParams) { MATTER_TRACE_EVENT_SCOPE("PairDevice", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_PairDevice); ReturnErrorOnFailure(EstablishPASEConnection(remoteDeviceId, rendezvousParams)); return Commission(remoteDeviceId, commissioningParams); } @@ -629,6 +635,7 @@ CHIP_ERROR DeviceCommissioner::EstablishPASEConnection(NodeId remoteDeviceId, co Optional resolutionData) { MATTER_TRACE_EVENT_SCOPE("EstablishPASEConnection", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_EstablishPASEConnection); return mSetUpCodePairer.PairDevice(remoteDeviceId, setUpCode, SetupCodePairerBehaviour::kPaseOnly, discoveryType, resolutionData); } @@ -636,6 +643,7 @@ CHIP_ERROR DeviceCommissioner::EstablishPASEConnection(NodeId remoteDeviceId, co CHIP_ERROR DeviceCommissioner::EstablishPASEConnection(NodeId remoteDeviceId, RendezvousParameters & params) { MATTER_TRACE_EVENT_SCOPE("EstablishPASEConnection", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_EstablishPASEConnection); CHIP_ERROR err = CHIP_NO_ERROR; CommissioneeDeviceProxy * device = nullptr; CommissioneeDeviceProxy * current = nullptr; @@ -823,6 +831,7 @@ CHIP_ERROR DeviceCommissioner::Commission(NodeId remoteDeviceId, CommissioningPa CHIP_ERROR DeviceCommissioner::Commission(NodeId remoteDeviceId) { MATTER_TRACE_EVENT_SCOPE("Commission", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_Commission); CommissioneeDeviceProxy * device = FindCommissioneeDevice(remoteDeviceId); if (device == nullptr || (!device->IsSecureConnected() && !device->IsSessionSetupInProgress())) { @@ -867,6 +876,7 @@ DeviceCommissioner::ContinueCommissioningAfterDeviceAttestation(DeviceProxy * de Credentials::AttestationVerificationResult attestationResult) { MATTER_TRACE_EVENT_SCOPE("continueCommissioningDevice", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_continueCommissioningDevice); if (device == nullptr || device != mDeviceBeingCommissioned) { ChipLogError(Controller, "Invalid device for commissioning %p", device); @@ -931,6 +941,7 @@ CHIP_ERROR DeviceCommissioner::StopPairing(NodeId remoteDeviceId) CHIP_ERROR DeviceCommissioner::UnpairDevice(NodeId remoteDeviceId) { MATTER_TRACE_EVENT_SCOPE("UnpairDevice", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_UnpairDevice); VerifyOrReturnError(mState == State::Initialized, CHIP_ERROR_INCORRECT_STATE); return AutoCurrentFabricRemover::RemoveCurrentFabric(this, remoteDeviceId); @@ -999,6 +1010,7 @@ CHIP_ERROR DeviceCommissioner::SendCertificateChainRequestCommand(DeviceProxy * Optional timeout) { MATTER_TRACE_EVENT_SCOPE("SendCertificateChainRequestCommand", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_SendCertificateChainRequestCommand); ChipLogDetail(Controller, "Sending Certificate Chain request to %p device", device); VerifyOrReturnError(device != nullptr, CHIP_ERROR_INVALID_ARGUMENT); @@ -1012,6 +1024,7 @@ CHIP_ERROR DeviceCommissioner::SendCertificateChainRequestCommand(DeviceProxy * void DeviceCommissioner::OnCertificateChainFailureResponse(void * context, CHIP_ERROR error) { MATTER_TRACE_EVENT_SCOPE("OnCertificateChainFailureResponse", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_OnCertificateChainFailureResponse); ChipLogProgress(Controller, "Device failed to receive the Certificate Chain request Response: %s", chip::ErrorStr(error)); DeviceCommissioner * commissioner = reinterpret_cast(context); commissioner->CommissioningStageComplete(error); @@ -1021,6 +1034,7 @@ void DeviceCommissioner::OnCertificateChainResponse( void * context, const chip::app::Clusters::OperationalCredentials::Commands::CertificateChainResponse::DecodableType & response) { MATTER_TRACE_EVENT_SCOPE("OnCertificateChainResponse", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_OnCertificateChainResponse); ChipLogProgress(Controller, "Received certificate chain from the device"); DeviceCommissioner * commissioner = reinterpret_cast(context); @@ -1034,6 +1048,7 @@ CHIP_ERROR DeviceCommissioner::SendAttestationRequestCommand(DeviceProxy * devic Optional timeout) { MATTER_TRACE_EVENT_SCOPE("SendAttestationRequestCommand", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_SendAttestationRequestCommand); ChipLogDetail(Controller, "Sending Attestation request to %p device", device); VerifyOrReturnError(device != nullptr, CHIP_ERROR_INVALID_ARGUMENT); @@ -1048,6 +1063,7 @@ CHIP_ERROR DeviceCommissioner::SendAttestationRequestCommand(DeviceProxy * devic void DeviceCommissioner::OnAttestationFailureResponse(void * context, CHIP_ERROR error) { MATTER_TRACE_EVENT_SCOPE("OnAttestationFailureResponse", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_OnAttestationFailureResponse); ChipLogProgress(Controller, "Device failed to receive the Attestation Information Response: %s", chip::ErrorStr(error)); DeviceCommissioner * commissioner = reinterpret_cast(context); commissioner->CommissioningStageComplete(error); @@ -1057,6 +1073,7 @@ void DeviceCommissioner::OnAttestationResponse(void * context, const OperationalCredentials::Commands::AttestationResponse::DecodableType & data) { MATTER_TRACE_EVENT_SCOPE("OnAttestationResponse", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_OnAttestationResponse); ChipLogProgress(Controller, "Received Attestation Information from the device"); DeviceCommissioner * commissioner = reinterpret_cast(context); @@ -1069,6 +1086,7 @@ void DeviceCommissioner::OnDeviceAttestationInformationVerification( void * context, const Credentials::DeviceAttestationVerifier::AttestationInfo & info, AttestationVerificationResult result) { MATTER_TRACE_EVENT_SCOPE("OnDeviceAttestationInformationVerification", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_OnDeviceAttestationInformationVerification); DeviceCommissioner * commissioner = reinterpret_cast(context); if (!commissioner->mDeviceBeingCommissioned) @@ -1237,6 +1255,7 @@ void DeviceCommissioner::ExtendArmFailSafeForDeviceAttestation(const Credentials CHIP_ERROR DeviceCommissioner::ValidateAttestationInfo(const Credentials::DeviceAttestationVerifier::AttestationInfo & info) { MATTER_TRACE_EVENT_SCOPE("ValidateAttestationInfo", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_ValidateAttestationInfo); VerifyOrReturnError(mState == State::Initialized, CHIP_ERROR_INCORRECT_STATE); VerifyOrReturnError(mDeviceAttestationVerifier != nullptr, CHIP_ERROR_INCORRECT_STATE); @@ -1251,6 +1270,7 @@ CHIP_ERROR DeviceCommissioner::ValidateCSR(DeviceProxy * proxy, const ByteSpan & const ByteSpan & AttestationSignature, const ByteSpan & dac, const ByteSpan & csrNonce) { MATTER_TRACE_EVENT_SCOPE("ValidateCSR", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_ValidateCSR); VerifyOrReturnError(mState == State::Initialized, CHIP_ERROR_INCORRECT_STATE); VerifyOrReturnError(mDeviceAttestationVerifier != nullptr, CHIP_ERROR_INCORRECT_STATE); @@ -1270,6 +1290,7 @@ CHIP_ERROR DeviceCommissioner::SendOperationalCertificateSigningRequestCommand(D Optional timeout) { MATTER_TRACE_EVENT_SCOPE("SendOperationalCertificateSigningRequestCommand", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_SendOperationalCertificateSigningRequestCommand); ChipLogDetail(Controller, "Sending CSR request to %p device", device); VerifyOrReturnError(device != nullptr, CHIP_ERROR_INVALID_ARGUMENT); @@ -1284,6 +1305,7 @@ CHIP_ERROR DeviceCommissioner::SendOperationalCertificateSigningRequestCommand(D void DeviceCommissioner::OnCSRFailureResponse(void * context, CHIP_ERROR error) { MATTER_TRACE_EVENT_SCOPE("OnCSRFailureResponse", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_OnCSRFailureResponse); ChipLogProgress(Controller, "Device failed to receive the CSR request Response: %s", chip::ErrorStr(error)); DeviceCommissioner * commissioner = static_cast(context); commissioner->CommissioningStageComplete(error); @@ -1293,6 +1315,7 @@ void DeviceCommissioner::OnOperationalCertificateSigningRequest( void * context, const OperationalCredentials::Commands::CSRResponse::DecodableType & data) { MATTER_TRACE_EVENT_SCOPE("OnOperationalCertificateSigningRequest", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_OnOperationalCertificateSigningRequest); ChipLogProgress(Controller, "Received certificate signing request from the device"); DeviceCommissioner * commissioner = static_cast(context); @@ -1306,6 +1329,7 @@ void DeviceCommissioner::OnDeviceNOCChainGeneration(void * context, CHIP_ERROR s Optional adminSubject) { MATTER_TRACE_EVENT_SCOPE("OnDeviceNOCChainGeneration", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_OnDeviceNOCChainGeneration); DeviceCommissioner * commissioner = static_cast(context); // The placeholder IPK is not satisfactory, but is there to fill the NocChain struct on error. It will still fail. @@ -1338,6 +1362,7 @@ CHIP_ERROR DeviceCommissioner::IssueNOCChain(const ByteSpan & NOCSRElements, Nod chip::Callback::Callback * callback) { MATTER_TRACE_EVENT_SCOPE("IssueNOCChain", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_IssueNOCChain); VerifyOrReturnError(mState == State::Initialized, CHIP_ERROR_INCORRECT_STATE); ChipLogProgress(Controller, "Getting certificate chain for the device on fabric idx %u", static_cast(mFabricIndex)); @@ -1360,6 +1385,7 @@ CHIP_ERROR DeviceCommissioner::ProcessCSR(DeviceProxy * proxy, const ByteSpan & const ByteSpan & csrNonce) { MATTER_TRACE_EVENT_SCOPE("ProcessOpCSR", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_ProcessOpCSR); VerifyOrReturnError(mState == State::Initialized, CHIP_ERROR_INCORRECT_STATE); ChipLogProgress(Controller, "Getting certificate chain for the device from the issuer"); @@ -1388,6 +1414,7 @@ CHIP_ERROR DeviceCommissioner::SendOperationalCertificate(DeviceProxy * device, Optional timeout) { MATTER_TRACE_EVENT_SCOPE("SendOperationalCertificate", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_SendOperationalCertificate); VerifyOrReturnError(device != nullptr, CHIP_ERROR_INVALID_ARGUMENT); @@ -1441,6 +1468,7 @@ CHIP_ERROR DeviceCommissioner::ConvertFromOperationalCertStatus(OperationalCrede void DeviceCommissioner::OnAddNOCFailureResponse(void * context, CHIP_ERROR error) { MATTER_TRACE_EVENT_SCOPE("OnAddNOCFailureResponse", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_OnAddNOCFailureResponse); ChipLogProgress(Controller, "Device failed to receive the operational certificate Response: %s", chip::ErrorStr(error)); DeviceCommissioner * commissioner = static_cast(context); commissioner->CommissioningStageComplete(error); @@ -1450,6 +1478,7 @@ void DeviceCommissioner::OnOperationalCertificateAddResponse( void * context, const OperationalCredentials::Commands::NOCResponse::DecodableType & data) { MATTER_TRACE_EVENT_SCOPE("OnOperationalCertificateAddResponse", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_OnOperationalCertificateAddResponse); ChipLogProgress(Controller, "Device returned status %d on receiving the NOC", to_underlying(data.statusCode)); DeviceCommissioner * commissioner = static_cast(context); @@ -1476,6 +1505,7 @@ CHIP_ERROR DeviceCommissioner::SendTrustedRootCertificate(DeviceProxy * device, Optional timeout) { MATTER_TRACE_EVENT_SCOPE("SendTrustedRootCertificate", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_SendTrustedRootCertificate); VerifyOrReturnError(device != nullptr, CHIP_ERROR_INVALID_ARGUMENT); ChipLogProgress(Controller, "Sending root certificate to the device"); @@ -1492,6 +1522,7 @@ CHIP_ERROR DeviceCommissioner::SendTrustedRootCertificate(DeviceProxy * device, void DeviceCommissioner::OnRootCertSuccessResponse(void * context, const chip::app::DataModel::NullObjectType &) { MATTER_TRACE_EVENT_SCOPE("OnRootCertSuccessResponse", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_OnRootCertSuccessResponse); ChipLogProgress(Controller, "Device confirmed that it has received the root certificate"); DeviceCommissioner * commissioner = static_cast(context); commissioner->CommissioningStageComplete(CHIP_NO_ERROR); @@ -1500,6 +1531,7 @@ void DeviceCommissioner::OnRootCertSuccessResponse(void * context, const chip::a void DeviceCommissioner::OnRootCertFailureResponse(void * context, CHIP_ERROR error) { MATTER_TRACE_EVENT_SCOPE("OnRootCertFailureResponse", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_OnRootCertFailureResponse); ChipLogProgress(Controller, "Device failed to receive the root certificate Response: %s", chip::ErrorStr(error)); DeviceCommissioner * commissioner = static_cast(context); commissioner->CommissioningStageComplete(error); @@ -1508,6 +1540,7 @@ void DeviceCommissioner::OnRootCertFailureResponse(void * context, CHIP_ERROR er CHIP_ERROR DeviceCommissioner::OnOperationalCredentialsProvisioningCompletion(DeviceProxy * device) { MATTER_TRACE_EVENT_SCOPE("OnOperationalCredentialsProvisioningCompletion", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_OnOperationalCredentialsProvisioningCompletion); ChipLogProgress(Controller, "Operational credentials provisioned on device %p", device); VerifyOrReturnError(device != nullptr, CHIP_ERROR_INVALID_ARGUMENT); @@ -1699,6 +1732,7 @@ void DeviceCommissioner::CommissioningStageComplete(CHIP_ERROR err, Commissionin { // Once this stage is complete, reset mDeviceBeingCommissioned - this will be reset when the delegate calls the next step. MATTER_TRACE_EVENT_SCOPE("CommissioningStageComplete", "DeviceCommissioner"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::DeviceCommissioner_CommissioningStageComplete); if (mDeviceBeingCommissioned == nullptr) { // We are getting a stray callback (e.g. due to un-cancellable diff --git a/src/lib/dnssd/BUILD.gn b/src/lib/dnssd/BUILD.gn index b33b304f195df6..a9147a7842c522 100644 --- a/src/lib/dnssd/BUILD.gn +++ b/src/lib/dnssd/BUILD.gn @@ -58,7 +58,7 @@ static_library("dnssd") { ] public_deps += [ "${chip_root}/src/lib/dnssd/minimal_mdns", - "${chip_root}/src/trace", + "${chip_root}/src/tracing", ] } else if (chip_mdns == "platform") { sources += [ diff --git a/src/lib/dnssd/IncrementalResolve.cpp b/src/lib/dnssd/IncrementalResolve.cpp index 7131cbfaaf4d88..1b8915acd10470 100644 --- a/src/lib/dnssd/IncrementalResolve.cpp +++ b/src/lib/dnssd/IncrementalResolve.cpp @@ -22,7 +22,9 @@ #include #include #include -#include +#include +#include +#include namespace chip { namespace Dnssd { @@ -239,7 +241,7 @@ IncrementalResolver::RequiredInformationFlags IncrementalResolver::GetMissingReq CHIP_ERROR IncrementalResolver::OnRecord(Inet::InterfaceId interface, const ResourceData & data, BytesRange packetRange) { - MATTER_TRACE_EVENT_SCOPE("Incremental resolver record parsing"); // measure until loop finished + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::Resolve_IncrementalRecordParse); if (!IsActive()) { @@ -251,14 +253,15 @@ CHIP_ERROR IncrementalResolver::OnRecord(Inet::InterfaceId interface, const Reso case QType::TXT: if (data.GetName() != mRecordName.Get()) { - MATTER_TRACE_EVENT_INSTANT("TXT not applicable"); + MATTER_TRACE_INSTANT(::chip::Tracing::Instant::Resolve_TxtNotApplicable); + return CHIP_NO_ERROR; } return OnTxtRecord(data, packetRange); case QType::A: { if (data.GetName() != mTargetHostName.Get()) { - MATTER_TRACE_EVENT_INSTANT("A (IPv4) not applicable"); + MATTER_TRACE_INSTANT(::chip::Tracing::Instant::Resolve_Ipv4NotApplicable); return CHIP_NO_ERROR; } @@ -281,7 +284,7 @@ CHIP_ERROR IncrementalResolver::OnRecord(Inet::InterfaceId interface, const Reso case QType::AAAA: { if (data.GetName() != mTargetHostName.Get()) { - MATTER_TRACE_EVENT_INSTANT("AAAA (IPv6) not applicable"); + MATTER_TRACE_INSTANT(::chip::Tracing::Instant::Resolve_Ipv6NotApplicable); return CHIP_NO_ERROR; } diff --git a/src/protocols/secure_channel/BUILD.gn b/src/protocols/secure_channel/BUILD.gn index 819218f3ffd080..f2d2b87a78cd9a 100644 --- a/src/protocols/secure_channel/BUILD.gn +++ b/src/protocols/secure_channel/BUILD.gn @@ -37,5 +37,6 @@ static_library("secure_channel") { "${chip_root}/src/messaging", "${chip_root}/src/system", "${chip_root}/src/trace", + "${chip_root}/src/tracing", ] } diff --git a/src/protocols/secure_channel/CASESession.cpp b/src/protocols/secure_channel/CASESession.cpp index b56076a9cd200e..aaccba973b2f08 100644 --- a/src/protocols/secure_channel/CASESession.cpp +++ b/src/protocols/secure_channel/CASESession.cpp @@ -46,6 +46,7 @@ #include #include #include +#include #include #if CHIP_CRYPTO_HSM #include @@ -435,6 +436,7 @@ CHIP_ERROR CASESession::EstablishSession(SessionManager & sessionManager, Fabric Optional mrpLocalConfig) { MATTER_TRACE_EVENT_SCOPE("EstablishSession", "CASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::CASESession_EstablishSession); CHIP_ERROR err = CHIP_NO_ERROR; // Return early on error here, as we have not initialized any state yet @@ -583,6 +585,7 @@ CHIP_ERROR CASESession::RecoverInitiatorIpk() CHIP_ERROR CASESession::SendSigma1() { MATTER_TRACE_EVENT_SCOPE("SendSigma1", "CASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::CASESession_SendSigma1); const size_t mrpParamsSize = mLocalMRPConfig.HasValue() ? TLV::EstimateStructOverhead(sizeof(uint16_t), sizeof(uint16_t)) : 0; size_t data_len = TLV::EstimateStructOverhead(kSigmaParamRandomNumberSize, // initiatorRandom sizeof(uint16_t), // initiatorSessionId, @@ -689,6 +692,7 @@ CHIP_ERROR CASESession::SendSigma1() CHIP_ERROR CASESession::HandleSigma1_and_SendSigma2(System::PacketBufferHandle && msg) { MATTER_TRACE_EVENT_SCOPE("HandleSigma1_and_SendSigma2", "CASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::CASESession_HandleSigma1_and_SendSigma2); ReturnErrorOnFailure(HandleSigma1(std::move(msg))); return CHIP_NO_ERROR; @@ -774,6 +778,7 @@ CHIP_ERROR CASESession::TryResumeSession(SessionResumptionStorage::ConstResumpti CHIP_ERROR CASESession::HandleSigma1(System::PacketBufferHandle && msg) { MATTER_TRACE_EVENT_SCOPE("HandleSigma1", "CASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::CASESession_HandleSigma1); CHIP_ERROR err = CHIP_NO_ERROR; System::PacketBufferTLVReader tlvReader; @@ -858,6 +863,7 @@ CHIP_ERROR CASESession::HandleSigma1(System::PacketBufferHandle && msg) CHIP_ERROR CASESession::SendSigma2Resume() { MATTER_TRACE_EVENT_SCOPE("SendSigma2Resume", "CASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::CASESession_SendSigma2Resume); const size_t mrpParamsSize = mLocalMRPConfig.HasValue() ? TLV::EstimateStructOverhead(sizeof(uint16_t), sizeof(uint16_t)) : 0; size_t max_sigma2_resume_data_len = TLV::EstimateStructOverhead( SessionResumptionStorage::kResumptionIdSize, CHIP_CRYPTO_AEAD_MIC_LENGTH_BYTES, sizeof(uint16_t), mrpParamsSize); @@ -912,6 +918,7 @@ CHIP_ERROR CASESession::SendSigma2Resume() CHIP_ERROR CASESession::SendSigma2() { MATTER_TRACE_EVENT_SCOPE("SendSigma2", "CASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::CASESession_SendSigma2); VerifyOrReturnError(GetLocalSessionId().HasValue(), CHIP_ERROR_INCORRECT_STATE); VerifyOrReturnError(mFabricsTable != nullptr, CHIP_ERROR_INCORRECT_STATE); @@ -1050,6 +1057,7 @@ CHIP_ERROR CASESession::SendSigma2() CHIP_ERROR CASESession::HandleSigma2Resume(System::PacketBufferHandle && msg) { MATTER_TRACE_EVENT_SCOPE("HandleSigma2Resume", "CASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::CASESession_HandleSigma2Resume); CHIP_ERROR err = CHIP_NO_ERROR; System::PacketBufferTLVReader tlvReader; TLV::TLVType containerType = TLV::kTLVType_Structure; @@ -1116,6 +1124,7 @@ CHIP_ERROR CASESession::HandleSigma2Resume(System::PacketBufferHandle && msg) CHIP_ERROR CASESession::HandleSigma2_and_SendSigma3(System::PacketBufferHandle && msg) { MATTER_TRACE_EVENT_SCOPE("HandleSigma2_and_SendSigma3", "CASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::CASESession_HandleSigma2_and_SendSigma3); ReturnErrorOnFailure(HandleSigma2(std::move(msg))); ReturnErrorOnFailure(SendSigma3a()); @@ -1125,6 +1134,7 @@ CHIP_ERROR CASESession::HandleSigma2_and_SendSigma3(System::PacketBufferHandle & CHIP_ERROR CASESession::HandleSigma2(System::PacketBufferHandle && msg) { MATTER_TRACE_EVENT_SCOPE("HandleSigma2", "CASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::CASESession_HandleSigma2); CHIP_ERROR err = CHIP_NO_ERROR; System::PacketBufferTLVReader tlvReader; TLV::TLVReader decryptedDataTlvReader; @@ -1294,6 +1304,7 @@ CHIP_ERROR CASESession::HandleSigma2(System::PacketBufferHandle && msg) CHIP_ERROR CASESession::SendSigma3a() { MATTER_TRACE_EVENT_SCOPE("SendSigma3", "CASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::CASESession_SendSigma3); CHIP_ERROR err = CHIP_NO_ERROR; ChipLogDetail(SecureChannel, "Sending Sigma3"); @@ -1508,6 +1519,7 @@ CHIP_ERROR CASESession::SendSigma3c(SendSigma3Data & data, CHIP_ERROR status) CHIP_ERROR CASESession::HandleSigma3a(System::PacketBufferHandle && msg) { MATTER_TRACE_EVENT_SCOPE("HandleSigma3", "CASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::CASESession_HandleSigma3); CHIP_ERROR err = CHIP_NO_ERROR; System::PacketBufferTLVReader tlvReader; TLV::TLVReader decryptedDataTlvReader; diff --git a/src/protocols/secure_channel/PASESession.cpp b/src/protocols/secure_channel/PASESession.cpp index ae81480d623c3b..c8ee3bc97a9e96 100644 --- a/src/protocols/secure_channel/PASESession.cpp +++ b/src/protocols/secure_channel/PASESession.cpp @@ -45,6 +45,7 @@ #include #include #include +#include #include namespace chip { @@ -135,6 +136,7 @@ CHIP_ERROR PASESession::GeneratePASEVerifier(Spake2pVerifier & verifier, uint32_ bool useRandomPIN, uint32_t & setupPINCode) { MATTER_TRACE_EVENT_SCOPE("GeneratePASEVerifier", "PASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::PASESession_GeneratePASEVerifier); if (useRandomPIN) { @@ -150,6 +152,7 @@ CHIP_ERROR PASESession::GeneratePASEVerifier(Spake2pVerifier & verifier, uint32_ CHIP_ERROR PASESession::SetupSpake2p() { MATTER_TRACE_EVENT_SCOPE("SetupSpake2p", "PASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::PASESession_SetupSpake2p); uint8_t context[kSHA256_Hash_Length] = { 0 }; MutableByteSpan contextSpan{ context }; @@ -211,6 +214,7 @@ CHIP_ERROR PASESession::Pair(SessionManager & sessionManager, uint32_t peerSetUp SessionEstablishmentDelegate * delegate) { MATTER_TRACE_EVENT_SCOPE("Pair", "PASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::PASESession_Pair); ReturnErrorCodeIf(exchangeCtxt == nullptr, CHIP_ERROR_INVALID_ARGUMENT); CHIP_ERROR err = Init(sessionManager, peerSetUpPINCode, delegate); SuccessOrExit(err); @@ -265,6 +269,7 @@ CHIP_ERROR PASESession::DeriveSecureSession(CryptoContext & session) const CHIP_ERROR PASESession::SendPBKDFParamRequest() { MATTER_TRACE_EVENT_SCOPE("SendPBKDFParamRequest", "PASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::PASESession_SendPBKDFParamRequest); VerifyOrReturnError(GetLocalSessionId().HasValue(), CHIP_ERROR_INCORRECT_STATE); @@ -314,6 +319,7 @@ CHIP_ERROR PASESession::SendPBKDFParamRequest() CHIP_ERROR PASESession::HandlePBKDFParamRequest(System::PacketBufferHandle && msg) { MATTER_TRACE_EVENT_SCOPE("HandlePBKDFParamRequest", "PASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::PASESession_HandlePBKDFParamRequest); CHIP_ERROR err = CHIP_NO_ERROR; System::PacketBufferTLVReader tlvReader; @@ -377,6 +383,7 @@ CHIP_ERROR PASESession::HandlePBKDFParamRequest(System::PacketBufferHandle && ms CHIP_ERROR PASESession::SendPBKDFParamResponse(ByteSpan initiatorRandom, bool initiatorHasPBKDFParams) { MATTER_TRACE_EVENT_SCOPE("SendPBKDFParamResponse", "PASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::PASESession_SendPBKDFParamResponse); VerifyOrReturnError(GetLocalSessionId().HasValue(), CHIP_ERROR_INCORRECT_STATE); @@ -438,6 +445,7 @@ CHIP_ERROR PASESession::SendPBKDFParamResponse(ByteSpan initiatorRandom, bool in CHIP_ERROR PASESession::HandlePBKDFParamResponse(System::PacketBufferHandle && msg) { MATTER_TRACE_EVENT_SCOPE("HandlePBKDFParamResponse", "PASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::PASESession_HandlePBKDFParamResponse); CHIP_ERROR err = CHIP_NO_ERROR; System::PacketBufferTLVReader tlvReader; @@ -534,6 +542,7 @@ CHIP_ERROR PASESession::HandlePBKDFParamResponse(System::PacketBufferHandle && m CHIP_ERROR PASESession::SendMsg1() { MATTER_TRACE_EVENT_SCOPE("SendMsg1", "PASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::PASESession_SendMsg1); const size_t max_msg_len = TLV::EstimateStructOverhead(kMAX_Point_Length); System::PacketBufferHandle msg = System::PacketBufferHandle::New(max_msg_len); VerifyOrReturnError(!msg.IsNull(), CHIP_ERROR_NO_MEMORY); @@ -567,6 +576,7 @@ CHIP_ERROR PASESession::SendMsg1() CHIP_ERROR PASESession::HandleMsg1_and_SendMsg2(System::PacketBufferHandle && msg1) { MATTER_TRACE_EVENT_SCOPE("HandleMsg1_and_SendMsg2", "PASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::PASESession_HandleMsg1_and_SendMsg2); CHIP_ERROR err = CHIP_NO_ERROR; uint8_t Y[kMAX_Point_Length]; @@ -637,6 +647,7 @@ CHIP_ERROR PASESession::HandleMsg1_and_SendMsg2(System::PacketBufferHandle && ms CHIP_ERROR PASESession::HandleMsg2_and_SendMsg3(System::PacketBufferHandle && msg2) { MATTER_TRACE_EVENT_SCOPE("HandleMsg2_and_SendMsg3", "PASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::PASESession_HandleMsg2_and_SendMsg3); CHIP_ERROR err = CHIP_NO_ERROR; uint8_t verifier[kMAX_Hash_Length]; @@ -713,6 +724,7 @@ CHIP_ERROR PASESession::HandleMsg2_and_SendMsg3(System::PacketBufferHandle && ms CHIP_ERROR PASESession::HandleMsg3(System::PacketBufferHandle && msg) { MATTER_TRACE_EVENT_SCOPE("HandleMsg3", "PASESession"); + MATTER_TRACE_SCOPE(::chip::Tracing::Scope::PASESession_HandleMsg3); CHIP_ERROR err = CHIP_NO_ERROR; ChipLogDetail(SecureChannel, "Received spake2p msg3"); diff --git a/src/tracing/BUILD.gn b/src/tracing/BUILD.gn index 673f5adc260833..218962c9805ec1 100644 --- a/src/tracing/BUILD.gn +++ b/src/tracing/BUILD.gn @@ -15,9 +15,7 @@ import("//build_overrides/build.gni") import("//build_overrides/chip.gni") -declare_args() { - matter_enable_tracing_support = true -} +import("${chip_root}/src/tracing/tracing_args.gni") config("tracing_enabled") { defines = [ "MATTER_TRACING_ENABLED" ] diff --git a/src/tracing/log_json/BUILD.gn b/src/tracing/log_json/BUILD.gn new file mode 100644 index 00000000000000..641c7135fc700f --- /dev/null +++ b/src/tracing/log_json/BUILD.gn @@ -0,0 +1,30 @@ +# Copyright (c) 2023 Project CHIP Authors +# +# 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. + +import("//build_overrides/build.gni") +import("//build_overrides/chip.gni") + +# As this uses std::string, this library is NOT for use +# for embedded devices. +static_library("log_json") { + sources = [ + "log_json_tracing.cpp", + "log_json_tracing.h", + ] + + public_deps = [ + "${chip_root}/src/tracing", + "${chip_root}/third_party/jsoncpp", + ] +} diff --git a/src/tracing/log_json/log_json_tracing.cpp b/src/tracing/log_json/log_json_tracing.cpp new file mode 100644 index 00000000000000..f3d8c5d591a7c3 --- /dev/null +++ b/src/tracing/log_json/log_json_tracing.cpp @@ -0,0 +1,283 @@ +/* + * + * 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. + */ + +#include + +#include + +#include + +#include +#include + +namespace chip { +namespace Tracing { +namespace LogJson { + +namespace { + +using chip::StringBuilder; + +std::string ScopeToString(Scope scope) +{ + switch (scope) + { + case Scope::CASESession_EstablishSession: + return "CASESession::EstablishSession"; + case Scope::CASESession_HandleSigma1: + return "CASESession::HandleSigma1"; + case Scope::CASESession_HandleSigma1_and_SendSigma2: + return "CASESession_HandleSigma1_and::SendSigma2"; + case Scope::CASESession_HandleSigma2: + return "CASESession::HandleSigma2"; + case Scope::CASESession_HandleSigma2_and_SendSigma3: + return "CASESession_HandleSigma2_and::SendSigma3"; + case Scope::CASESession_HandleSigma2Resume: + return "CASESession::HandleSigma2Resume"; + case Scope::CASESession_HandleSigma3: + return "CASESession::HandleSigma3"; + case Scope::CASESession_SendSigma1: + return "CASESession::SendSigma1"; + case Scope::CASESession_SendSigma2: + return "CASESession::SendSigma2"; + case Scope::CASESession_SendSigma2Resume: + return "CASESession::SendSigma2Resume"; + case Scope::CASESession_SendSigma3: + return "CASESession::SendSigma3"; + case Scope::DeviceCommissioner_Commission: + return "DeviceCommissioner::Commission"; + case Scope::DeviceCommissioner_CommissioningStageComplete: + return "DeviceCommissioner::CommissioningStageComplete"; + case Scope::DeviceCommissioner_continueCommissioningDevice: + return "DeviceCommissioner::continueCommissioningDevice"; + case Scope::DeviceCommissioner_EstablishPASEConnection: + return "DeviceCommissioner::EstablishPASEConnection"; + case Scope::DeviceCommissioner_FindCommissioneeDevice: + return "DeviceCommissioner::FindCommissioneeDevice"; + case Scope::DeviceCommissioner_IssueNOCChain: + return "DeviceCommissioner::IssueNOCChain"; + case Scope::DeviceCommissioner_OnAddNOCFailureResponse: + return "DeviceCommissioner::OnAddNOCFailureResponse"; + case Scope::DeviceCommissioner_OnAttestationFailureResponse: + return "DeviceCommissioner::OnAttestationFailureResponse"; + case Scope::DeviceCommissioner_OnAttestationResponse: + return "DeviceCommissioner::OnAttestationResponse"; + case Scope::DeviceCommissioner_OnCertificateChainFailureResponse: + return "DeviceCommissioner::OnCertificateChainFailureResponse"; + case Scope::DeviceCommissioner_OnCertificateChainResponse: + return "DeviceCommissioner::OnCertificateChainResponse"; + case Scope::DeviceCommissioner_OnCSRFailureResponse: + return "DeviceCommissioner::OnCSRFailureResponse"; + case Scope::DeviceCommissioner_OnDeviceAttestationInformationVerification: + return "DeviceCommissioner::OnDeviceAttestationInformationVerification"; + case Scope::DeviceCommissioner_OnDeviceNOCChainGeneration: + return "DeviceCommissioner::OnDeviceNOCChainGeneration"; + case Scope::DeviceCommissioner_OnOperationalCertificateAddResponse: + return "DeviceCommissioner::OnOperationalCertificateAddResponse"; + case Scope::DeviceCommissioner_OnOperationalCertificateSigningRequest: + return "DeviceCommissioner::OnOperationalCertificateSigningRequest"; + case Scope::DeviceCommissioner_OnOperationalCredentialsProvisioningCompletion: + return "DeviceCommissioner::OnOperationalCredentialsProvisioningCompletion"; + case Scope::DeviceCommissioner_OnRootCertFailureResponse: + return "DeviceCommissioner::OnRootCertFailureResponse"; + case Scope::DeviceCommissioner_OnRootCertSuccessResponse: + return "DeviceCommissioner::OnRootCertSuccessResponse"; + case Scope::DeviceCommissioner_PairDevice: + return "DeviceCommissioner::PairDevice"; + case Scope::DeviceCommissioner_ProcessOpCSR: + return "DeviceCommissioner::ProcessOpCSR"; + case Scope::DeviceCommissioner_SendAttestationRequestCommand: + return "DeviceCommissioner::SendAttestationRequestCommand"; + case Scope::DeviceCommissioner_SendCertificateChainRequestCommand: + return "DeviceCommissioner::SendCertificateChainRequestCommand"; + case Scope::DeviceCommissioner_SendOperationalCertificate: + return "DeviceCommissioner::SendOperationalCertificate"; + case Scope::DeviceCommissioner_SendOperationalCertificateSigningRequestCommand: + return "DeviceCommissioner::SendOperationalCertificateSigningRequestCommand"; + case Scope::DeviceCommissioner_SendTrustedRootCertificate: + return "DeviceCommissioner::SendTrustedRootCertificate"; + case Scope::DeviceCommissioner_UnpairDevice: + return "DeviceCommissioner::UnpairDevice"; + case Scope::DeviceCommissioner_ValidateAttestationInfo: + return "DeviceCommissioner::ValidateAttestationInfo"; + case Scope::DeviceCommissioner_ValidateCSR: + return "DeviceCommissioner::ValidateCSR"; + case Scope::GeneralCommissioning_ArmFailSafe: + return "GeneralCommissioning::ArmFailSafe"; + case Scope::GeneralCommissioning_CommissioningComplete: + return "GeneralCommissioning::CommissioningComplete"; + case Scope::GeneralCommissioning_SetRegulatoryConfig: + return "GeneralCommissioning::SetRegulatoryConfig"; + case Scope::NetworkCommissioning_HandleAddOrUpdateThreadNetwork: + return "NetworkCommissioning::HandleAddOrUpdateThreadNetwork"; + case Scope::NetworkCommissioning_HandleAddOrUpdateWiFiNetwork: + return "NetworkCommissioning::HandleAddOrUpdateWiFiNetwork"; + case Scope::NetworkCommissioning_HandleConnectNetwork: + return "NetworkCommissioning::HandleConnectNetwork"; + case Scope::NetworkCommissioning_HandleRemoveNetwork: + return "NetworkCommissioning::HandleRemoveNetwork"; + case Scope::NetworkCommissioning_HandleReorderNetwork: + return "NetworkCommissioning::HandleReorderNetwork"; + case Scope::NetworkCommissioning_HandleScanNetwork: + return "NetworkCommissioning::HandleScanNetwork"; + case Scope::OperationalCredentials_AddNOC: + return "OperationalCredentials::AddNOC"; + case Scope::OperationalCredentials_AddTrustedRootCertificate: + return "OperationalCredentials::AddTrustedRootCertificate"; + case Scope::OperationalCredentials_AttestationRequest: + return "OperationalCredentials::AttestationRequest"; + case Scope::OperationalCredentials_CertificateChainRequest: + return "OperationalCredentials::CertificateChainRequest"; + case Scope::OperationalCredentials_CSRRequest: + return "OperationalCredentials::CSRRequest"; + case Scope::OperationalCredentials_RemoveFabric: + return "OperationalCredentials::RemoveFabric"; + case Scope::OperationalCredentials_UpdateFabricLabel: + return "OperationalCredentials::UpdateFabricLabel"; + case Scope::OperationalCredentials_UpdateNOC: + return "OperationalCredentials::UpdateNOC"; + case Scope::PASESession_GeneratePASEVerifier: + return "PASESession::GeneratePASEVerifier"; + case Scope::PASESession_HandleMsg1_and_SendMsg2: + return "PASESession_HandleMsg1_and::SendMsg2"; + case Scope::PASESession_HandleMsg2_and_SendMsg3: + return "PASESession_HandleMsg2_and::SendMsg3"; + case Scope::PASESession_HandleMsg3: + return "PASESession::HandleMsg3"; + case Scope::PASESession_HandlePBKDFParamRequest: + return "PASESession::HandlePBKDFParamRequest"; + case Scope::PASESession_HandlePBKDFParamResponse: + return "PASESession::HandlePBKDFParamResponse"; + case Scope::PASESession_Pair: + return "PASESession::Pair"; + case Scope::PASESession_SendMsg1: + return "PASESession::SendMsg1"; + case Scope::PASESession_SendPBKDFParamRequest: + return "PASESession::SendPBKDFParamRequest"; + case Scope::PASESession_SendPBKDFParamResponse: + return "PASESession::SendPBKDFParamResponse"; + case Scope::PASESession_SetupSpake2p: + return "PASESession::SetupSpake2p"; + case Scope::Resolve_IncrementalRecordParse: + return "Resolve::IncrementalRecordParse"; + default: { + StringBuilder<64> builder; + builder.Add("Scope::Unknown("); + builder.Add(static_cast(scope)); + builder.Add(")"); + return builder.c_str(); + } + } +} + +std::string InstantToString(Instant instant) +{ + switch (instant) + { + case Instant::Resolve_TxtNotApplicable: + return "Resolve::TxtNotApplicable"; + case Instant::Resolve_Ipv4NotApplicable: + return "Resolve::Ipv4NotApplicable"; + case Instant::Resolve_Ipv6NotApplicable: + return "Resolve::Ipv6NotApplicable"; + default: { + StringBuilder<64> builder; + builder.Add("Instant::Unknown("); + builder.Add(static_cast(instant)); + builder.Add(")"); + return builder.c_str(); + } + } +} +/// Writes the given value to chip log +void LogJsonValue(Json::Value const & value) +{ + Json::StreamWriterBuilder builder; + + std::unique_ptr writer(builder.newStreamWriter()); + std::stringstream output; + + writer->write(value, &output); + + ChipLogProgress(Automation, "%s", output.str().c_str()); +} + +} // namespace + +void LogJsonBackend::TraceBegin(Scope scope) +{ + Json::Value value; + value["event"] = "begin"; + value["scope"] = ScopeToString(scope); + LogJsonValue(value); +} + +void LogJsonBackend::TraceEnd(Scope scope) +{ + Json::Value value; + value["event"] = "end"; + value["scope"] = ScopeToString(scope); + LogJsonValue(value); +} + +void LogJsonBackend::TraceInstant(Instant instant) +{ + Json::Value value; + value["event"] = "instant"; + value["instant"] = InstantToString(instant); + LogJsonValue(value); +} + +void LogJsonBackend::LogMessageSend(MessageSendInfo &) +{ + Json::Value value; + value["TODO"] = "LogMessageSend"; + LogJsonValue(value); +} + +void LogJsonBackend::LogMessageReceived(MessageReceiveInfo &) +{ + Json::Value value; + value["TODO"] = "LogMessageReceived"; + LogJsonValue(value); +} + +void LogJsonBackend::LogNodeLookup(NodeLookupInfo &) +{ + Json::Value value; + value["TODO"] = "LogNodeLookup"; + LogJsonValue(value); +} + +void LogJsonBackend::LogNodeDiscovered(NodeDiscoveredInfo &) +{ + Json::Value value; + value["TODO"] = "LogNodeDiscovered"; + LogJsonValue(value); +} + +void LogJsonBackend::LogNodeDiscoveryFailed(NodeDiscoveryFailedInfo &) +{ + Json::Value value; + value["TODO"] = "LogNodeDiscoveryFailed"; + LogJsonValue(value); +} + +} // namespace LogJson +} // namespace Tracing +} // namespace chip diff --git a/src/tracing/log_json/log_json_tracing.h b/src/tracing/log_json/log_json_tracing.h new file mode 100644 index 00000000000000..ca15c8f27e6448 --- /dev/null +++ b/src/tracing/log_json/log_json_tracing.h @@ -0,0 +1,46 @@ +/* + * + * 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 + +namespace chip { +namespace Tracing { +namespace LogJson { + +/// A Backend that outputs data to chip logging. +/// +/// Structured data is formatted as json strings. +class LogJsonBackend : public ::chip::Tracing::Backend +{ +public: + LogJsonBackend() = default; + + void TraceBegin(Scope scope) override; + void TraceEnd(Scope scope) override; + void TraceInstant(Instant instant) override; + void LogMessageSend(MessageSendInfo &) override; + void LogMessageReceived(MessageReceiveInfo &) override; + void LogNodeLookup(NodeLookupInfo &) override; + void LogNodeDiscovered(NodeDiscoveredInfo &) override; + void LogNodeDiscoveryFailed(NodeDiscoveryFailedInfo &) override; +}; + +} // namespace LogJson +} // namespace Tracing +} // namespace chip diff --git a/src/tracing/macros.h b/src/tracing/macros.h index 3b024e147bd2f4..e4599c67656263 100644 --- a/src/tracing/macros.h +++ b/src/tracing/macros.h @@ -19,7 +19,7 @@ #ifndef MATTER_TRACING_ENABLED -#define _MATTER_TRACE_DISABLE \ +#define _MATTER_TRACE_DISABLE(...) \ do \ { \ } while (false) diff --git a/src/tracing/scope.h b/src/tracing/scope.h index a636d2511d0dc8..5bbcd078bd6a4b 100644 --- a/src/tracing/scope.h +++ b/src/tracing/scope.h @@ -20,6 +20,8 @@ #include #include +#ifdef MATTER_TRACING_ENABLED + namespace chip { namespace Tracing { @@ -33,6 +35,7 @@ namespace Tracing { /// // ... add code here /// /// } // TRACE_END called here + class Scoped { public: @@ -60,3 +63,12 @@ class Scoped /// /// } // TRACE_END called here #define MATTER_TRACE_SCOPE(scope) ::chip::Tracing::Scoped _MACRO_CONCAT(_trace_scope, __COUNTER__)(scope) + +#else // ifdef MATTER_TRACING_ENABLED + +#define MATTER_TRACE_SCOPE(scope) \ + do \ + { \ + } while (false) + +#endif diff --git a/src/tracing/scopes.h b/src/tracing/scopes.h index f184d7fc521b27..5447652a9cd52b 100644 --- a/src/tracing/scopes.h +++ b/src/tracing/scopes.h @@ -95,6 +95,7 @@ enum class Scope PASESession_SendPBKDFParamRequest = 66, PASESession_SendPBKDFParamResponse = 67, PASESession_SetupSpake2p = 68, + Resolve_IncrementalRecordParse = 69, }; /// An event that happened at an instant (like a zero sized scope) diff --git a/src/tracing/tests/BUILD.gn b/src/tracing/tests/BUILD.gn index 674f33ec5b3c78..081a8309e6c382 100644 --- a/src/tracing/tests/BUILD.gn +++ b/src/tracing/tests/BUILD.gn @@ -17,17 +17,20 @@ import("//build_overrides/chip.gni") import("//build_overrides/nlunit_test.gni") import("${chip_root}/build/chip/chip_test_suite.gni") +import("${chip_root}/src/tracing/tracing_args.gni") -chip_test_suite("tests") { - output_name = "libTracingTests" +if (matter_enable_tracing_support) { + chip_test_suite("tests") { + output_name = "libTracingTests" - test_sources = [ "TestTracing.cpp" ] - sources = [] + test_sources = [ "TestTracing.cpp" ] + sources = [] - public_deps = [ - "${chip_root}/src/lib/support:testing", - "${chip_root}/src/platform", - "${chip_root}/src/tracing", - "${nlunit_test_root}:nlunit-test", - ] + public_deps = [ + "${chip_root}/src/lib/support:testing", + "${chip_root}/src/platform", + "${chip_root}/src/tracing", + "${nlunit_test_root}:nlunit-test", + ] + } } diff --git a/src/tracing/tracing_args.gni b/src/tracing/tracing_args.gni new file mode 100644 index 00000000000000..7ae979be92a911 --- /dev/null +++ b/src/tracing/tracing_args.gni @@ -0,0 +1,20 @@ +# Copyright (c) 2023 Project CHIP Authors +# +# 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. + +declare_args() { + # Tracing can have a non-zero size impact to binaries. We try to make + # the impact minimal (the backends themselves add some size), however + # for now tracing is opt-in + matter_enable_tracing_support = target_os == "linux" +}