From 40028c7a3932bf818f7825c14808d3c2ba488cd3 Mon Sep 17 00:00:00 2001 From: Andrei Litvin Date: Tue, 13 Jun 2023 11:32:16 -0400 Subject: [PATCH] Add tracing macros to addressresolve (#27180) * Dnssd tracing * Enable log-json-tracing for minmdns * Centralize command line tracing args, add tracing to minmdns * Make address resolve compile * log errors and make shutdown actually work * Reformat and add tracing for address lookup results * Restyled by whitespace * Restyled by clang-format * Restyled by gn * Fixed quotes on other macros too * Restyled by clang-format * Make advertiser support ctrl+c * Address review comments * Add better help on what tracing destinations exist * Restyled by clang-format * Fix typo in include and make tv casting app dependencies include the command line tracing support because it includes CHIPCommand.h * Fix compile of tv-casting * Fix TraceHandlers compile if tracing is disabled (tizen has it disabled) * Restyle * Make linter happy * Make clang tidy happy * Explain nolint in comment --------- Co-authored-by: Andrei Litvin Co-authored-by: Restyled.io --- examples/chip-tool/BUILD.gn | 3 +- .../chip-tool/commands/common/CHIPCommand.cpp | 27 +------ .../chip-tool/commands/common/CHIPCommand.h | 3 +- examples/common/tracing/BUILD.gn | 17 +++++ examples/common/tracing/TraceHandlers.cpp | 9 ++- .../tracing/TracingCommandLineArgument.cpp | 72 +++++++++++++++++++ .../tracing/TracingCommandLineArgument.h | 41 +++++++++++ examples/minimal-mdns/BUILD.gn | 3 + examples/minimal-mdns/advertiser.cpp | 21 ++++++ examples/minimal-mdns/client.cpp | 9 +++ examples/minimal-mdns/server.cpp | 17 ++++- examples/tv-casting-app/linux/BUILD.gn | 1 + .../tv-casting-app/tv-casting-common/BUILD.gn | 1 + src/app/server/Server.cpp | 7 -- .../AddressResolve_DefaultImpl.cpp | 16 +++++ src/lib/address_resolve/BUILD.gn | 3 + src/lib/address_resolve/TracingStructs.h | 57 +++++++++++++++ src/lib/address_resolve/tool.cpp | 65 +++++++++++++++-- src/tracing/log_json/BUILD.gn | 1 + src/tracing/log_json/log_json_tracing.cpp | 58 +++++++++++++-- src/tracing/macros.h | 10 +-- 21 files changed, 387 insertions(+), 54 deletions(-) create mode 100644 examples/common/tracing/TracingCommandLineArgument.cpp create mode 100644 examples/common/tracing/TracingCommandLineArgument.h create mode 100644 src/lib/address_resolve/TracingStructs.h diff --git a/examples/chip-tool/BUILD.gn b/examples/chip-tool/BUILD.gn index 73c90413af32db..f52f3a463196b7 100644 --- a/examples/chip-tool/BUILD.gn +++ b/examples/chip-tool/BUILD.gn @@ -101,6 +101,7 @@ static_library("chip-tool-utils") { } public_deps = [ + "${chip_root}/examples/common/tracing:commandline", "${chip_root}/src/app/server", "${chip_root}/src/app/tests/suites/commands/commissioner", "${chip_root}/src/app/tests/suites/commands/delay", @@ -114,8 +115,6 @@ 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/commands/common/CHIPCommand.cpp b/examples/chip-tool/commands/common/CHIPCommand.cpp index 57a8eaeb376581..ecb1f23c29ed76 100644 --- a/examples/chip-tool/commands/common/CHIPCommand.cpp +++ b/examples/chip-tool/commands/common/CHIPCommand.cpp @@ -18,6 +18,7 @@ #include "CHIPCommand.h" +#include #include #include #include @@ -26,9 +27,6 @@ #include #include -#include -#include - #if CHIP_CONFIG_TRANSPORT_TRACE_ENABLED #include "TraceDecoder.h" #include "TraceHandlers.h" @@ -82,15 +80,6 @@ CHIP_ERROR GetAttestationTrustStore(const char * paaTrustStorePath, const chip:: 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() @@ -258,17 +247,7 @@ void CHIPCommand::StartTracing() { 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()); - } + chip::CommandLineApp::EnableTracingFor(destination.c_str()); } } @@ -298,7 +277,7 @@ void CHIPCommand::StartTracing() void CHIPCommand::StopTracing() { - tracing_backends.clear(); + chip::CommandLineApp::StopTracing(); #if CHIP_CONFIG_TRANSPORT_TRACE_ENABLED chip::trace::DeInitTrace(); diff --git a/examples/chip-tool/commands/common/CHIPCommand.h b/examples/chip-tool/commands/common/CHIPCommand.h index 624dd79a255bb0..9b46f81b1e68b2 100644 --- a/examples/chip-tool/commands/common/CHIPCommand.h +++ b/examples/chip-tool/commands/common/CHIPCommand.h @@ -24,6 +24,7 @@ #include "Command.h" +#include #include #include #include @@ -85,7 +86,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("trace-to", &mTraceTo, "Trace destinations, comma-separated (" SUPPORTED_COMMAND_LINE_TRACING_TARGETS ")"); 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"); diff --git a/examples/common/tracing/BUILD.gn b/examples/common/tracing/BUILD.gn index 86ea5a1f63b4ff..61f9553f37e428 100644 --- a/examples/common/tracing/BUILD.gn +++ b/examples/common/tracing/BUILD.gn @@ -20,6 +20,23 @@ config("default_config") { include_dirs = [ "." ] } +source_set("commandline") { + sources = [ + "TracingCommandLineArgument.cpp", + "TracingCommandLineArgument.h", + ] + + deps = [ + "${chip_root}/src/lib/support", + "${chip_root}/src/tracing", + "${chip_root}/src/tracing/log_json", + ] + + public_configs = [ ":default_config" ] + + cflags = [ "-Wconversion" ] +} + source_set("trace_handlers") { sources = [ "TraceHandlers.cpp" ] diff --git a/examples/common/tracing/TraceHandlers.cpp b/examples/common/tracing/TraceHandlers.cpp index 1ffcb204882a0e..ea40e285df3844 100644 --- a/examples/common/tracing/TraceHandlers.cpp +++ b/examples/common/tracing/TraceHandlers.cpp @@ -22,10 +22,10 @@ #include #include -#include "transport/TraceMessage.h" #include #include #include +#include // For `s` std::string literal suffix using namespace std::string_literals; @@ -33,6 +33,7 @@ using namespace std::string_literals; namespace chip { namespace trace { +#if CHIP_CONFIG_TRANSPORT_TRACE_ENABLED namespace { // Handles the output from the trace handlers. @@ -350,5 +351,11 @@ void DeInitTrace() gTraceOutputs.UnregisterAllStreams(); } +#else +void AddTraceStream(TraceStream *) {} +void InitTrace() {} +void DeInitTrace() {} +#endif // CHIP_CONFIG_TRANSPORT_TRACE_ENABLED + } // namespace trace } // namespace chip diff --git a/examples/common/tracing/TracingCommandLineArgument.cpp b/examples/common/tracing/TracingCommandLineArgument.cpp new file mode 100644 index 00000000000000..64eb84820daa3a --- /dev/null +++ b/examples/common/tracing/TracingCommandLineArgument.cpp @@ -0,0 +1,72 @@ +/* + * + * 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 + +#include +#include +#include + +namespace chip { +namespace CommandLineApp { + +namespace { +using ::chip::Tracing::ScopedRegistration; +using ::chip::Tracing::LogJson::LogJsonBackend; + +// currently supported backends +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 + +void EnableTracingFor(const char * cliArg) +{ + chip::StringSplitter splitter(cliArg, ','); + chip::CharSpan value; + + while (splitter.Next(value)) + { + if (value.data_equal(CharSpan::fromCharString("log"))) + { + if (!log_json_backend.IsInList()) + { + tracing_backends.push_back(std::make_unique(log_json_backend)); + } + } + else + { + ChipLogError(AppServer, "Unknown trace destination: '%s'", std::string(value.data(), value.size()).c_str()); + } + } +} + +void StopTracing() +{ + tracing_backends.clear(); +} + +} // namespace CommandLineApp +} // namespace chip diff --git a/examples/common/tracing/TracingCommandLineArgument.h b/examples/common/tracing/TracingCommandLineArgument.h new file mode 100644 index 00000000000000..7f4d1bdfb55a15 --- /dev/null +++ b/examples/common/tracing/TracingCommandLineArgument.h @@ -0,0 +1,41 @@ +/* + * + * 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 + +/// A string with supported command line tracing targets +/// to be pretty-printed in help strings if needed +#define SUPPORTED_COMMAND_LINE_TRACING_TARGETS "log" + +namespace chip { +namespace CommandLineApp { + +/// Enable tracing based on the given command line argument +/// like "log" or "log,perfetto" or similar +/// +/// Single arguments as well as comma separated ones are accepted. +/// +/// Calling this method multiple times is ok and will enable each of +/// the given tracing modules if not already enabled. +void EnableTracingFor(const char * cliArg); + +/// If EnableTracingFor is called, this MUST be called as well +/// to unregister tracing backends +void StopTracing(); + +} // namespace CommandLineApp +} // namespace chip diff --git a/examples/minimal-mdns/BUILD.gn b/examples/minimal-mdns/BUILD.gn index 58ca4fa774a36c..a60dc611990b74 100644 --- a/examples/minimal-mdns/BUILD.gn +++ b/examples/minimal-mdns/BUILD.gn @@ -36,6 +36,7 @@ executable("minimal-mdns-client") { deps = [ ":minimal-mdns-example-common", + "${chip_root}/examples/common/tracing:commandline", "${chip_root}/src/lib", "${chip_root}/src/lib/dnssd/minimal_mdns", ] @@ -50,6 +51,7 @@ executable("minimal-mdns-server") { deps = [ ":minimal-mdns-example-common", + "${chip_root}/examples/common/tracing:commandline", "${chip_root}/src/lib", "${chip_root}/src/lib/dnssd/minimal_mdns", "${chip_root}/src/lib/dnssd/minimal_mdns/responders", @@ -65,6 +67,7 @@ executable("mdns-advertiser") { deps = [ ":minimal-mdns-example-common", + "${chip_root}/examples/common/tracing:commandline", "${chip_root}/src/lib", "${chip_root}/src/lib/dnssd", ] diff --git a/examples/minimal-mdns/advertiser.cpp b/examples/minimal-mdns/advertiser.cpp index b006dc38903c13..0194a3d7fb4c9a 100644 --- a/examples/minimal-mdns/advertiser.cpp +++ b/examples/minimal-mdns/advertiser.cpp @@ -20,6 +20,7 @@ #include #include +#include #include #include #include @@ -81,6 +82,7 @@ constexpr uint16_t kOptionCommissioningRotatingId = 0x700; constexpr uint16_t kOptionOperationalFabricId = 'f'; constexpr uint16_t kOptionOperationalNodeId = 'n'; +constexpr uint16_t kOptionTraceTo = 't'; bool HandleOptions(const char * aProgram, OptionSet * aOptions, int aIdentifier, const char * aName, const char * aValue) { @@ -90,6 +92,9 @@ bool HandleOptions(const char * aProgram, OptionSet * aOptions, int aIdentifier, case kOptionEnableIpV4: gOptions.enableIpV4 = true; return true; + case kOptionTraceTo: + CommandLineApp::EnableTracingFor(aValue); + return true; case kOptionAdvertisingMode: if (strcmp(aValue, "operational") == 0) { @@ -187,6 +192,7 @@ OptionDef cmdLineOptionsDef[] = { { "fabric-id", kArgumentRequired, kOptionOperationalFabricId }, { "node-id", kArgumentRequired, kOptionOperationalNodeId }, + { "trace-to", kArgumentRequired, kOptionTraceTo }, {}, }; @@ -228,12 +234,20 @@ OptionSet cmdLineOptions = { HandleOptions, cmdLineOptionsDef, "PROGRAM OPTIONS" " --node-id \n" " -n \n" " Operational node id.\n" + " -t \n" + " --trace-to \n" + " trace to the given destination (supported: " SUPPORTED_COMMAND_LINE_TRACING_TARGETS ").\n" "\n" }; HelpOptions helpOptions("advertiser", "Usage: advertiser [options]", "1.0"); OptionSet * allOptions[] = { &cmdLineOptions, &helpOptions, nullptr }; +void StopSignalHandler(int signal) +{ + DeviceLayer::PlatformMgr().StopEventLoopTask(); +} + } // namespace int main(int argc, char ** args) @@ -316,8 +330,15 @@ int main(int argc, char ** args) return 1; } + signal(SIGTERM, StopSignalHandler); + signal(SIGINT, StopSignalHandler); + DeviceLayer::PlatformMgr().RunEventLoop(); + CommandLineApp::StopTracing(); + Dnssd::Resolver::Instance().Shutdown(); + DeviceLayer::PlatformMgr().Shutdown(); + printf("Done...\n"); return 0; } diff --git a/examples/minimal-mdns/client.cpp b/examples/minimal-mdns/client.cpp index 6aa9c16cfb1ab0..b342c330673b20 100644 --- a/examples/minimal-mdns/client.cpp +++ b/examples/minimal-mdns/client.cpp @@ -20,6 +20,7 @@ #include #include +#include #include #include #include @@ -61,6 +62,7 @@ constexpr uint16_t kOptionListenPort = 0x100; constexpr uint16_t kOptionQueryPort = 0x101; constexpr uint16_t kOptionRuntimeMs = 0x102; constexpr uint16_t kOptionMulticastReplies = 0x103; +constexpr uint16_t kOptionTraceTo = 0x104; bool HandleOptions(const char * aProgram, OptionSet * aOptions, int aIdentifier, const char * aName, const char * aValue) { @@ -76,6 +78,9 @@ bool HandleOptions(const char * aProgram, OptionSet * aOptions, int aIdentifier, case kOptionQuery: gOptions.query = aValue; return true; + case kOptionTraceTo: + CommandLineApp::EnableTracingFor(aValue); + return true; case kOptionType: if (strcasecmp(aValue, "ANY") == 0) { @@ -145,6 +150,7 @@ OptionDef cmdLineOptionsDef[] = { { "query-port", kArgumentRequired, kOptionQueryPort }, { "timeout-ms", kArgumentRequired, kOptionRuntimeMs }, { "multicast-reply", kNoArgument, kOptionMulticastReplies }, + { "trace-to", kArgumentRequired, kOptionTraceTo }, {}, }; @@ -163,6 +169,8 @@ OptionSet cmdLineOptions = { HandleOptions, cmdLineOptionsDef, "PROGRAM OPTIONS" " How long to wait for replies\n" " --multicast-reply\n" " Do not request unicast replies\n" + " --trace-to \n" + " trace to the given destination (supported: " SUPPORTED_COMMAND_LINE_TRACING_TARGETS ").\n" "\n" }; HelpOptions helpOptions("minimal-mdns-client", "Usage: minimal-mdns-client [options]", "1.0"); @@ -351,6 +359,7 @@ int main(int argc, char ** args) DeviceLayer::PlatformMgr().RunEventLoop(); + CommandLineApp::StopTracing(); DeviceLayer::PlatformMgr().Shutdown(); Platform::MemoryShutdown(); diff --git a/examples/minimal-mdns/server.cpp b/examples/minimal-mdns/server.cpp index 44c03c784c4ab9..1f51b1da9bbdb1 100644 --- a/examples/minimal-mdns/server.cpp +++ b/examples/minimal-mdns/server.cpp @@ -20,6 +20,7 @@ #include +#include #include #include #include @@ -40,10 +41,10 @@ #include "PacketReporter.h" -using namespace chip; - namespace { +using namespace chip; + struct Options { bool enableIpV4 = false; @@ -56,6 +57,7 @@ using namespace ArgParser; constexpr uint16_t kOptionEnableIpV4 = '4'; constexpr uint16_t kOptionListenPort = 'p'; constexpr uint16_t kOptionInstanceName = 'i'; +constexpr uint16_t kOptionTraceTo = 't'; bool HandleOptions(const char * aProgram, OptionSet * aOptions, int aIdentifier, const char * aName, const char * aValue) { @@ -69,6 +71,10 @@ bool HandleOptions(const char * aProgram, OptionSet * aOptions, int aIdentifier, gOptions.instanceName = aValue; return true; + case kOptionTraceTo: + CommandLineApp::EnableTracingFor(aValue); + return true; + case kOptionListenPort: if (!ParseInt(aValue, gOptions.listenPort)) { @@ -87,6 +93,7 @@ OptionDef cmdLineOptionsDef[] = { { "listen-port", kArgumentRequired, kOptionListenPort }, { "enable-ip-v4", kNoArgument, kOptionEnableIpV4 }, { "instance-name", kArgumentRequired, kOptionInstanceName }, + { "trace-to", kArgumentRequired, kOptionTraceTo }, {}, }; @@ -100,6 +107,9 @@ OptionSet cmdLineOptions = { HandleOptions, cmdLineOptionsDef, "PROGRAM OPTIONS" " -i \n" " --instance-name \n" " instance name to advertise.\n" + " -t \n" + " --trace-to \n" + " trace to the given destination (supported: " SUPPORTED_COMMAND_LINE_TRACING_TARGETS ").\n" "\n" }; HelpOptions helpOptions("minimal-mdns-server", "Usage: minimal-mdns-server [options]", "1.0"); @@ -175,7 +185,6 @@ void StopSignalHandler(int signal) gMdnsServer.Shutdown(); DeviceLayer::PlatformMgr().StopEventLoopTask(); - DeviceLayer::PlatformMgr().Shutdown(); } } // namespace @@ -283,6 +292,8 @@ int main(int argc, char ** args) signal(SIGINT, StopSignalHandler); DeviceLayer::PlatformMgr().RunEventLoop(); + CommandLineApp::StopTracing(); + DeviceLayer::PlatformMgr().Shutdown(); printf("Done...\n"); return 0; diff --git a/examples/tv-casting-app/linux/BUILD.gn b/examples/tv-casting-app/linux/BUILD.gn index 52d8f77cca6f65..07d9af1a71c721 100644 --- a/examples/tv-casting-app/linux/BUILD.gn +++ b/examples/tv-casting-app/linux/BUILD.gn @@ -28,6 +28,7 @@ executable("chip-tv-casting-app") { ] deps = [ + "${chip_root}/examples/common/tracing:commandline", "${chip_root}/examples/platform/linux:app-main", "${chip_root}/examples/tv-casting-app/tv-casting-common", "${chip_root}/src/credentials:default_attestation_verifier", diff --git a/examples/tv-casting-app/tv-casting-common/BUILD.gn b/examples/tv-casting-app/tv-casting-common/BUILD.gn index 37ec1452b5bf17..129604f9468de2 100644 --- a/examples/tv-casting-app/tv-casting-common/BUILD.gn +++ b/examples/tv-casting-app/tv-casting-common/BUILD.gn @@ -86,6 +86,7 @@ chip_data_model("tv-casting-common") { ] deps = [ + "${chip_root}/examples/common/tracing:commandline", "${chip_root}/src/app/tests/suites/commands/interaction_model", "${chip_root}/src/lib/support/jsontlv", "${chip_root}/src/tracing", diff --git a/src/app/server/Server.cpp b/src/app/server/Server.cpp index 0793832d17271c..75a4262716f5a8 100644 --- a/src/app/server/Server.cpp +++ b/src/app/server/Server.cpp @@ -247,10 +247,6 @@ CHIP_ERROR Server::Init(const ServerInitParams & initParams) } #endif // CHIP_CONFIG_ENABLE_SERVER_IM_EVENT -#ifdef CHIP_CONFIG_ENABLE_ICD_SERVER - mICDEventManager.Init(&mICDManager); -#endif // CHIP_CONFIG_ENABLE_ICD_SERVER - // This initializes clusters, so should come after lower level initialization. InitDataModelHandler(); @@ -488,9 +484,6 @@ void Server::Shutdown() mAccessControl.Finish(); Access::ResetAccessControlToDefault(); Credentials::SetGroupDataProvider(nullptr); -#ifdef CHIP_CONFIG_ENABLE_ICD_SERVER - mICDEventManager.Shutdown(); -#endif // CHIP_CONFIG_ENABLE_ICD_SERVER mAttributePersister.Shutdown(); // TODO(16969): Remove chip::Platform::MemoryInit() call from Server class, it belongs to outer code chip::Platform::MemoryShutdown(); diff --git a/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp b/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp index 10e50cbd734cfe..bbfd5dcaf25348 100644 --- a/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp +++ b/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp @@ -17,6 +17,9 @@ #include +#include +#include + namespace chip { namespace AddressResolve { namespace Impl { @@ -35,6 +38,8 @@ void NodeLookupHandle::ResetForLookup(System::Clock::Timestamp now, const NodeLo void NodeLookupHandle::LookupResult(const ResolveResult & result) { + MATTER_LOG_NODE_DISCOVERED(Tracing::DiscoveryInfoType::kIntermediateResult, &GetRequest().GetPeerId(), &result); + auto score = Dnssd::IPAddressSorter::ScoreIpAddress(result.address.GetIPAddress(), result.address.GetInterface()); [[maybe_unused]] bool success = mResults.UpdateResults(result, score); @@ -176,6 +181,8 @@ bool NodeLookupResults::UpdateResults(const ResolveResult & result, const Dnssd: CHIP_ERROR Resolver::LookupNode(const NodeLookupRequest & request, Impl::NodeLookupHandle & handle) { + MATTER_LOG_NODE_LOOKUP(&request); + VerifyOrReturnError(mSystemLayer != nullptr, CHIP_ERROR_INCORRECT_STATE); handle.ResetForLookup(mTimeSource.GetMonotonicTimestamp(), request); @@ -193,6 +200,9 @@ CHIP_ERROR Resolver::TryNextResult(Impl::NodeLookupHandle & handle) auto listener = handle.GetListener(); auto peerId = handle.GetRequest().GetPeerId(); auto result = handle.TakeLookupResult(); + + MATTER_LOG_NODE_DISCOVERED(Tracing::DiscoveryInfoType::kRetryDifferent, &peerId, &result); + listener->OnNodeAddressResolved(peerId, result); return CHIP_NO_ERROR; } @@ -206,6 +216,8 @@ CHIP_ERROR Resolver::CancelLookup(Impl::NodeLookupHandle & handle, FailureCallba // Adjust any timing updates. ReArmTimer(); + MATTER_LOG_NODE_DISCOVERY_FAILED(&handle.GetRequest().GetPeerId(), CHIP_ERROR_CANCELLED); + if (cancel_method == FailureCallback::Call) { handle.GetListener()->OnNodeAddressResolutionFailed(handle.GetRequest().GetPeerId(), CHIP_ERROR_CANCELLED); @@ -239,6 +251,8 @@ void Resolver::Shutdown() mActiveLookups.Erase(current); + MATTER_LOG_NODE_DISCOVERY_FAILED(&peerId, CHIP_ERROR_SHUT_DOWN); + Dnssd::Resolver::Instance().NodeIdResolutionNoLongerNeeded(peerId); // Failure callback only called after iterator was cleared: // This allows failure handlers to deallocate structures that may @@ -315,9 +329,11 @@ void Resolver::HandleAction(IntrusiveList::Iterator & current) switch (action.Type()) { case NodeLookupResult::kLookupError: + MATTER_LOG_NODE_DISCOVERY_FAILED(&peerId, action.ErrorResult()); listener->OnNodeAddressResolutionFailed(peerId, action.ErrorResult()); break; case NodeLookupResult::kLookupSuccess: + MATTER_LOG_NODE_DISCOVERED(Tracing::DiscoveryInfoType::kResolutionDone, &peerId, &action.ResolveResult()); listener->OnNodeAddressResolved(peerId, action.ResolveResult()); break; default: diff --git a/src/lib/address_resolve/BUILD.gn b/src/lib/address_resolve/BUILD.gn index a4cdc3af668163..d0e5484ec410c3 100644 --- a/src/lib/address_resolve/BUILD.gn +++ b/src/lib/address_resolve/BUILD.gn @@ -28,12 +28,14 @@ static_library("address_resolve") { "${chip_root}/src/lib/dnssd", "${chip_root}/src/lib/support", "${chip_root}/src/messaging", + "${chip_root}/src/tracing", "${chip_root}/src/transport/raw", ] sources = [ "AddressResolve.cpp", "AddressResolve.h", + "TracingStructs.h", ] if (chip_address_resolve_strategy == "default") { @@ -61,6 +63,7 @@ executable("address-resolve-tool") { public_deps = [ ":address_resolve", + "${chip_root}/examples/common/tracing:commandline", "${chip_root}/src/lib/support", "${chip_root}/src/platform/logging:stdio", ] diff --git a/src/lib/address_resolve/TracingStructs.h b/src/lib/address_resolve/TracingStructs.h new file mode 100644 index 00000000000000..ed2f5b5f886a6b --- /dev/null +++ b/src/lib/address_resolve/TracingStructs.h @@ -0,0 +1,57 @@ +/* + * 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 +#include + +namespace chip { +namespace Tracing { + +/// Concrete definitions of the DNSSD tracing info that the address resolver will +/// report. + +/// A node lookup has been requested +struct NodeLookupInfo +{ + const chip::AddressResolve::NodeLookupRequest * request; // request for node lookup +}; + +enum class DiscoveryInfoType +{ + kIntermediateResult = 0, // Received intermediate address data + kResolutionDone = 1, // resolution completed + kRetryDifferent = 2, // Try a different/new IP address +}; + +/// A node was discovered and we have information about it. +struct NodeDiscoveredInfo +{ + DiscoveryInfoType type; // separate callbacks depending on state + const PeerId * peerId; // what peer was discovered + const chip::AddressResolve::ResolveResult * result; // a SINGLE result representing the resolution +}; + +/// A node lookup failed / give up on this discovery +struct NodeDiscoveryFailedInfo +{ + const PeerId * peerId; // what peer discovery failed + CHIP_ERROR error; // error that caused a failure +}; + +} // namespace Tracing +} // namespace chip diff --git a/src/lib/address_resolve/tool.cpp b/src/lib/address_resolve/tool.cpp index 7f6d1b3e34a517..2a8488e8c05869 100644 --- a/src/lib/address_resolve/tool.cpp +++ b/src/lib/address_resolve/tool.cpp @@ -17,6 +17,7 @@ #include "AddressResolve.h" +#include #include #include #include @@ -32,10 +33,19 @@ using namespace chip; using chip::Inet::InterfaceId; using chip::Transport::PeerAddress; +class AutoStopTracing +{ +public: + AutoStopTracing() {} + ~AutoStopTracing() { chip::CommandLineApp::StopTracing(); } +}; + // clang-format off const char * const sHelp = - "Usage: address-resolve-tool [ ]\n" + "Usage: address-resolve-tool [] [ ]\n" "\n" + "Options:\n" + " --trace-to -- Trace to the given destination (" SUPPORTED_COMMAND_LINE_TRACING_TARGETS ")\n" "Commands:\n" "\n" " node -- Find the node for the given node/fabric.\n" @@ -85,6 +95,7 @@ CHIP_ERROR Initialize() void Shutdown() { + chip::AddressResolve::Resolver::Instance().Shutdown(); Dnssd::Resolver::Instance().Shutdown(); DeviceLayer::PlatformMgr().Shutdown(); } @@ -130,18 +141,62 @@ bool Cmd_Node(int argc, const char ** argv) return true; } +extern "C" void StopSignalHandler(int signal) +{ + // no lint below because StopEventLoopTask is assumed to be async safe. + DeviceLayer::PlatformMgr().StopEventLoopTask(); // NOLINT(bugprone-signal-handler) +} + } // namespace extern "C" int main(int argc, const char ** argv) { Platform::MemoryInit(); - if (argc < 2) + signal(SIGTERM, StopSignalHandler); + signal(SIGINT, StopSignalHandler); + + // skip binary name + argc--; + argv++; + + AutoStopTracing auto_stop_tracing; + + while (argc > 0) + { + if (strcasecmp(argv[0], "--help") == 0 || strcasecmp(argv[0], "-h") == 0) + { + fputs(sHelp, stdout); + return 0; + } + + if (strcasecmp(argv[0], "--trace-to") == 0) + { + if (argc > 1) + { + chip::CommandLineApp::EnableTracingFor(argv[1]); + argc -= 2; + argv += 2; + } + else + { + ChipLogError(NotSpecified, "Missing trace to argument."); + return -1; + } + } + else + { + break; + } + } + + if (argc < 1) { ChipLogError(NotSpecified, "Please specify a command, or 'help' for help."); return -1; } - if (strcasecmp(argv[1], "help") == 0 || strcasecmp(argv[1], "--help") == 0 || strcasecmp(argv[1], "-h") == 0) + + if (strcasecmp(argv[0], "help") == 0) { fputs(sHelp, stdout); return 0; @@ -154,9 +209,9 @@ extern "C" int main(int argc, const char ** argv) return 1; } - if (strcasecmp(argv[1], "node") == 0) + if (strcasecmp(argv[0], "node") == 0) { - return Cmd_Node(argc - 2, argv + 2) ? 0 : 1; + return Cmd_Node(argc - 1, argv + 1) ? 0 : 1; } ChipLogError(NotSpecified, "Unrecognized command: %s", argv[1]); diff --git a/src/tracing/log_json/BUILD.gn b/src/tracing/log_json/BUILD.gn index 641c7135fc700f..1b8a3c8efdbbd4 100644 --- a/src/tracing/log_json/BUILD.gn +++ b/src/tracing/log_json/BUILD.gn @@ -24,6 +24,7 @@ static_library("log_json") { ] public_deps = [ + "${chip_root}/src/lib/address_resolve", "${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 index f3d8c5d591a7c3..2a89300f0eced6 100644 --- a/src/tracing/log_json/log_json_tracing.cpp +++ b/src/tracing/log_json/log_json_tracing.cpp @@ -18,6 +18,8 @@ #include +#include +#include #include #include @@ -257,24 +259,68 @@ void LogJsonBackend::LogMessageReceived(MessageReceiveInfo &) LogJsonValue(value); } -void LogJsonBackend::LogNodeLookup(NodeLookupInfo &) +void LogJsonBackend::LogNodeLookup(NodeLookupInfo & info) { Json::Value value; - value["TODO"] = "LogNodeLookup"; + + value["event"] = "LogNodeLookup"; + value["node_id"] = info.request->GetPeerId().GetNodeId(); + value["compressed_fabric_id"] = info.request->GetPeerId().GetCompressedFabricId(); + value["min_lookup_time_ms"] = info.request->GetMinLookupTime().count(); + value["max_lookup_time_ms"] = info.request->GetMaxLookupTime().count(); + LogJsonValue(value); } -void LogJsonBackend::LogNodeDiscovered(NodeDiscoveredInfo &) +void LogJsonBackend::LogNodeDiscovered(NodeDiscoveredInfo & info) { Json::Value value; - value["TODO"] = "LogNodeDiscovered"; + value["event"] = "LogNodeDiscovered"; + + value["node_id"] = info.peerId->GetNodeId(); + value["compressed_fabric_id"] = info.peerId->GetCompressedFabricId(); + + switch (info.type) + { + case chip::Tracing::DiscoveryInfoType::kIntermediateResult: + value["type"] = "intermediate"; + break; + case chip::Tracing::DiscoveryInfoType::kResolutionDone: + value["type"] = "done"; + break; + case chip::Tracing::DiscoveryInfoType::kRetryDifferent: + value["type"] = "retry-different"; + break; + } + + { + Json::Value result; + + char address_buff[chip::Transport::PeerAddress::kMaxToStringSize]; + + info.result->address.ToString(address_buff); + + result["supports_tcp"] = info.result->supportsTcp; + result["address"] = address_buff; + + result["mrp"]["idle_retransmit_timeout_ms"] = info.result->mrpRemoteConfig.mIdleRetransTimeout.count(); + result["mrp"]["active_retransmit_timeout_ms"] = info.result->mrpRemoteConfig.mActiveRetransTimeout.count(); + + value["result"] = result; + } + LogJsonValue(value); } -void LogJsonBackend::LogNodeDiscoveryFailed(NodeDiscoveryFailedInfo &) +void LogJsonBackend::LogNodeDiscoveryFailed(NodeDiscoveryFailedInfo & info) { Json::Value value; - value["TODO"] = "LogNodeDiscoveryFailed"; + + value["event"] = "LogNodeDiscoveryFailed"; + value["node_id"] = info.peerId->GetNodeId(); + value["compressed_fabric_id"] = info.peerId->GetCompressedFabricId(); + value["error"] = chip::ErrorStr(info.error); + LogJsonValue(value); } diff --git a/src/tracing/macros.h b/src/tracing/macros.h index e4599c67656263..3f9a828a161be9 100644 --- a/src/tracing/macros.h +++ b/src/tracing/macros.h @@ -49,35 +49,35 @@ #define MATTER_LOG_MESSAGE_SEND(...) \ do \ { \ - ::chip::Tracing::MessageSendInfo _trace_data(__VA_ARGS__); \ + ::chip::Tracing::MessageSendInfo _trace_data{ __VA_ARGS__ }; \ ::chip::Tracing::Internal::LogMessageSend(_trace_data); \ } while (false) #define MATTER_LOG_MESSAGE_RECEIVED(...) \ do \ { \ - ::chip::Tracing::MessageReceivedInfo _trace_data(__VA_ARGS__); \ + ::chip::Tracing::MessageReceivedInfo _trace_data{ __VA_ARGS__ }; \ ::chip::Tracing::Internal::LogMessageReceived(_trace_data); \ } while (false) #define MATTER_LOG_NODE_LOOKUP(...) \ do \ { \ - ::chip::Tracing::NodeLookupInfo _trace_data(__VA_ARGS__); \ + ::chip::Tracing::NodeLookupInfo _trace_data{ __VA_ARGS__ }; \ ::chip::Tracing::Internal::LogNodeLookup(_trace_data); \ } while (false) #define MATTER_LOG_NODE_DISCOVERED(...) \ do \ { \ - ::chip::Tracing::NodeDiscoveredInfo _trace_data(__VA_ARGS__); \ + ::chip::Tracing::NodeDiscoveredInfo _trace_data{ __VA_ARGS__ }; \ ::chip::Tracing::Internal::LogNodeDiscovered(_trace_data); \ } while (false) #define MATTER_LOG_NODE_DISCOVERY_FAILED(...) \ do \ { \ - ::chip::Tracing::NodeDiscoveryFailedInfo _trace_data(__VA_ARGS__); \ + ::chip::Tracing::NodeDiscoveryFailedInfo _trace_data{ __VA_ARGS__ }; \ ::chip::Tracing::Internal::LogNodeDiscoveryFailed(_trace_data); \ } while (false)