From 25673619e599a1dbd61408cbc34fc575972c7b4e Mon Sep 17 00:00:00 2001 From: Andrei Litvin Date: Wed, 5 Jul 2023 15:17:36 -0400 Subject: [PATCH] Allow json tracing to go to files instead of just logs (#27628) * Rename log_json to just json * Add file output option for json tracing * make the output look like a json array when outputing to file * Restyle * Fix support of "json:log" * Fix support of "json:log" * Rename open/close to openfile/closefile to avoid override errors * Restyle * StartsWith should be available now globally as it is always used * Forward declare json to make arm cross compile pass * Restyle * Add json_tracing exceptions for includes checks --- examples/common/tracing/BUILD.gn | 2 +- .../tracing/TracingCommandLineArgument.cpp | 25 +++- .../tracing/TracingCommandLineArgument.h | 10 +- .../tv-casting-app/tv-casting-common/BUILD.gn | 2 +- scripts/tools/check_includes_config.py | 3 +- src/tracing/{log_json => json}/BUILD.gn | 6 +- .../json_tracing.cpp} | 140 ++++++++++++------ .../json_tracing.h} | 30 +++- 8 files changed, 151 insertions(+), 67 deletions(-) rename src/tracing/{log_json => json}/BUILD.gn (91%) rename src/tracing/{log_json/log_json_tracing.cpp => json/json_tracing.cpp} (69%) rename src/tracing/{log_json/log_json_tracing.h => json/json_tracing.h} (71%) diff --git a/examples/common/tracing/BUILD.gn b/examples/common/tracing/BUILD.gn index 9139fbeb88d133..57eaaca3952245 100644 --- a/examples/common/tracing/BUILD.gn +++ b/examples/common/tracing/BUILD.gn @@ -47,7 +47,7 @@ source_set("commandline") { deps = [ "${chip_root}/src/lib/support", "${chip_root}/src/tracing", - "${chip_root}/src/tracing/log_json", + "${chip_root}/src/tracing/json", ] public_deps = [ ":tracing_features" ] diff --git a/examples/common/tracing/TracingCommandLineArgument.cpp b/examples/common/tracing/TracingCommandLineArgument.cpp index 727d835678e9e9..1ef52b6eba5b58 100644 --- a/examples/common/tracing/TracingCommandLineArgument.cpp +++ b/examples/common/tracing/TracingCommandLineArgument.cpp @@ -19,7 +19,7 @@ #include #include -#include +#include #include #if ENABLE_PERFETTO_TRACING @@ -34,7 +34,6 @@ namespace chip { namespace CommandLineApp { namespace { -#if ENABLE_PERFETTO_TRACING bool StartsWith(CharSpan argument, const char * prefix) { @@ -48,8 +47,6 @@ bool StartsWith(CharSpan argument, const char * prefix) return argument.data_equal(CharSpan(prefix, prefix_len)); } -#endif - } // namespace void TracingSetup::EnableTracingFor(const char * cliArg) @@ -59,9 +56,23 @@ void TracingSetup::EnableTracingFor(const char * cliArg) while (splitter.Next(value)) { - if (value.data_equal(CharSpan::fromCharString("log"))) + if (StartsWith(value, "json:")) { - chip::Tracing::Register(mLogJsonBackend); + std::string fileName(value.data() + 5, value.size() - 5); + + if (fileName != "log") + { + CHIP_ERROR err = mJsonBackend.OpenFile(fileName.c_str()); + if (err != CHIP_NO_ERROR) + { + ChipLogError(AppServer, "Failed to open json trace output: %" CHIP_ERROR_FORMAT, err.Format()); + } + } + else + { + mJsonBackend.CloseFile(); // just in case, ensure no file output + } + chip::Tracing::Register(mJsonBackend); } #if ENABLE_PERFETTO_TRACING else if (value.data_equal(CharSpan::fromCharString("perfetto"))) @@ -101,7 +112,7 @@ void TracingSetup::StopTracing() #endif - chip::Tracing::Unregister(mLogJsonBackend); + chip::Tracing::Unregister(mJsonBackend); } } // namespace CommandLineApp diff --git a/examples/common/tracing/TracingCommandLineArgument.h b/examples/common/tracing/TracingCommandLineArgument.h index 277c6652adf1df..f3d95fd3ba4faa 100644 --- a/examples/common/tracing/TracingCommandLineArgument.h +++ b/examples/common/tracing/TracingCommandLineArgument.h @@ -19,7 +19,7 @@ #include "tracing/enabled_features.h" -#include +#include #if ENABLE_PERFETTO_TRACING #include // nogncheck @@ -29,9 +29,9 @@ /// A string with supported command line tracing targets /// to be pretty-printed in help strings if needed #if ENABLE_PERFETTO_TRACING -#define SUPPORTED_COMMAND_LINE_TRACING_TARGETS "log, perfetto, perfetto:" +#define SUPPORTED_COMMAND_LINE_TRACING_TARGETS "json:log, json: perfetto, perfetto:" #else -#define SUPPORTED_COMMAND_LINE_TRACING_TARGETS "log" +#define SUPPORTED_COMMAND_LINE_TRACING_TARGETS "json:log, json:" #endif namespace chip { @@ -44,7 +44,7 @@ class TracingSetup ~TracingSetup() { StopTracing(); } /// Enable tracing based on the given command line argument - /// like "log" or "log,perfetto" or similar + /// like "json:log" or "json:/tmp/foo.txt,perfetto" or similar /// /// Single arguments as well as comma separated ones are accepted. /// @@ -57,7 +57,7 @@ class TracingSetup void StopTracing(); private: - ::chip::Tracing::LogJson::LogJsonBackend mLogJsonBackend; + ::chip::Tracing::Json::JsonBackend mJsonBackend; #if ENABLE_PERFETTO_TRACING chip::Tracing::Perfetto::FileTraceOutput mPerfettoFileOutput; diff --git a/examples/tv-casting-app/tv-casting-common/BUILD.gn b/examples/tv-casting-app/tv-casting-common/BUILD.gn index 129604f9468de2..65a4c36e90b44c 100644 --- a/examples/tv-casting-app/tv-casting-common/BUILD.gn +++ b/examples/tv-casting-app/tv-casting-common/BUILD.gn @@ -90,7 +90,7 @@ chip_data_model("tv-casting-common") { "${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}/src/tracing/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 fec2328f348b74..c632eb34d12af4 100644 --- a/scripts/tools/check_includes_config.py +++ b/scripts/tools/check_includes_config.py @@ -156,5 +156,6 @@ 'src/controller/ExamplePersistentStorage.cpp': {'fstream'}, # Library meant for non-embedded - 'src/tracing/log_json/log_json_tracing.cpp': {'string', 'sstream'} + 'src/tracing/json/json_tracing.cpp': {'string', 'sstream'}, + 'src/tracing/json/json_tracing.h': {'fstream'} } diff --git a/src/tracing/log_json/BUILD.gn b/src/tracing/json/BUILD.gn similarity index 91% rename from src/tracing/log_json/BUILD.gn rename to src/tracing/json/BUILD.gn index 655fda8e6a2c97..c303db0b900a89 100644 --- a/src/tracing/log_json/BUILD.gn +++ b/src/tracing/json/BUILD.gn @@ -17,10 +17,10 @@ import("//build_overrides/chip.gni") # As this uses std::string, this library is NOT for use # for embedded devices. -static_library("log_json") { +static_library("json") { sources = [ - "log_json_tracing.cpp", - "log_json_tracing.h", + "json_tracing.cpp", + "json_tracing.h", ] public_deps = [ diff --git a/src/tracing/log_json/log_json_tracing.cpp b/src/tracing/json/json_tracing.cpp similarity index 69% rename from src/tracing/log_json/log_json_tracing.cpp rename to src/tracing/json/json_tracing.cpp index 1dc46c1ab02a09..d3c3e1c54de80a 100644 --- a/src/tracing/log_json/log_json_tracing.cpp +++ b/src/tracing/json/json_tracing.cpp @@ -16,7 +16,7 @@ * limitations under the License. */ -#include +#include #include #include @@ -25,31 +25,20 @@ #include +#include + #include #include namespace chip { namespace Tracing { -namespace LogJson { +namespace Json { namespace { using chip::StringBuilder; -/// 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()); -} - -void DecodePayloadHeader(Json::Value & value, const PayloadHeader * payloadHeader) +void DecodePayloadHeader(::Json::Value & value, const PayloadHeader * payloadHeader) { value["exchangeFlags"] = payloadHeader->GetExchangeFlags(); @@ -66,7 +55,7 @@ void DecodePayloadHeader(Json::Value & value, const PayloadHeader * payloadHeade } } -void DecodePacketHeader(Json::Value & value, const PacketHeader * packetHeader) +void DecodePacketHeader(::Json::Value & value, const PacketHeader * packetHeader) { value["msgCounter"] = packetHeader->GetMessageCounter(); value["sessionId"] = packetHeader->GetSessionId(); @@ -98,9 +87,9 @@ void DecodePacketHeader(Json::Value & value, const PacketHeader * packetHeader) } } -void DecodePayloadData(Json::Value & value, chip::ByteSpan payload) +void DecodePayloadData(::Json::Value & value, chip::ByteSpan payload) { - value["payloadSize"] = static_cast(payload.size()); + value["payloadSize"] = static_cast<::Json::Value::UInt>(payload.size()); // TODO: a decode would be useful however it likely requires more decode // metadata @@ -108,36 +97,42 @@ void DecodePayloadData(Json::Value & value, chip::ByteSpan payload) } // namespace -void LogJsonBackend::TraceBegin(const char * label, const char * group) +JsonBackend::~JsonBackend() +{ + CloseFile(); +} + +void JsonBackend::TraceBegin(const char * label, const char * group) { - Json::Value value; + ::Json::Value value; + value["event"] = "TraceBegin"; value["label"] = label; value["group"] = group; - LogJsonValue(value); + OutputValue(value); } -void LogJsonBackend::TraceEnd(const char * label, const char * group) +void JsonBackend::TraceEnd(const char * label, const char * group) { - Json::Value value; + ::Json::Value value; value["event"] = "TraceEnd"; value["label"] = label; value["group"] = group; - LogJsonValue(value); + OutputValue(value); } -void LogJsonBackend::TraceInstant(const char * label, const char * group) +void JsonBackend::TraceInstant(const char * label, const char * group) { - Json::Value value; + ::Json::Value value; value["event"] = "TraceInstant"; value["label"] = label; value["group"] = group; - LogJsonValue(value); + OutputValue(value); } -void LogJsonBackend::LogMessageSend(MessageSendInfo & info) +void JsonBackend::LogMessageSend(MessageSendInfo & info) { - Json::Value value; + ::Json::Value value; value["event"] = "MessageSend"; switch (info.messageType) @@ -157,12 +152,12 @@ void LogJsonBackend::LogMessageSend(MessageSendInfo & info) DecodePacketHeader(value["packetHeader"], info.packetHeader); DecodePayloadData(value["payload"], info.payload); - LogJsonValue(value); + OutputValue(value); } -void LogJsonBackend::LogMessageReceived(MessageReceivedInfo & info) +void JsonBackend::LogMessageReceived(MessageReceivedInfo & info) { - Json::Value value; + ::Json::Value value; value["event"] = "MessageReceived"; @@ -183,12 +178,12 @@ void LogJsonBackend::LogMessageReceived(MessageReceivedInfo & info) DecodePacketHeader(value["packetHeader"], info.packetHeader); DecodePayloadData(value["payload"], info.payload); - LogJsonValue(value); + OutputValue(value); } -void LogJsonBackend::LogNodeLookup(NodeLookupInfo & info) +void JsonBackend::LogNodeLookup(NodeLookupInfo & info) { - Json::Value value; + ::Json::Value value; value["event"] = "LogNodeLookup"; value["node_id"] = info.request->GetPeerId().GetNodeId(); @@ -196,12 +191,12 @@ void LogJsonBackend::LogNodeLookup(NodeLookupInfo & info) value["min_lookup_time_ms"] = info.request->GetMinLookupTime().count(); value["max_lookup_time_ms"] = info.request->GetMaxLookupTime().count(); - LogJsonValue(value); + OutputValue(value); } -void LogJsonBackend::LogNodeDiscovered(NodeDiscoveredInfo & info) +void JsonBackend::LogNodeDiscovered(NodeDiscoveredInfo & info) { - Json::Value value; + ::Json::Value value; value["event"] = "LogNodeDiscovered"; value["node_id"] = info.peerId->GetNodeId(); @@ -221,7 +216,7 @@ void LogJsonBackend::LogNodeDiscovered(NodeDiscoveredInfo & info) } { - Json::Value result; + ::Json::Value result; char address_buff[chip::Transport::PeerAddress::kMaxToStringSize]; @@ -236,21 +231,76 @@ void LogJsonBackend::LogNodeDiscovered(NodeDiscoveredInfo & info) value["result"] = result; } - LogJsonValue(value); + OutputValue(value); } -void LogJsonBackend::LogNodeDiscoveryFailed(NodeDiscoveryFailedInfo & info) +void JsonBackend::LogNodeDiscoveryFailed(NodeDiscoveryFailedInfo & info) { - Json::Value value; + ::Json::Value value; value["event"] = "LogNodeDiscoveryFailed"; value["node_id"] = info.peerId->GetNodeId(); value["compressed_fabric_id"] = info.peerId->GetCompressedFabricId(); value["error"] = chip::ErrorStr(info.error); - LogJsonValue(value); + OutputValue(value); +} + +void JsonBackend::CloseFile() +{ + if (!mOutputFile.is_open()) + { + return; + } + + mOutputFile << "]\n"; + + mOutputFile.close(); +} + +CHIP_ERROR JsonBackend::OpenFile(const char * path) +{ + CloseFile(); + mOutputFile.open(path, std::ios_base::out); + + if (!mOutputFile) + { + return CHIP_ERROR_POSIX(errno); + } + + mOutputFile << "[\n"; + mFirstRecord = true; + + return CHIP_NO_ERROR; +} + +void JsonBackend::OutputValue(::Json::Value & value) +{ + ::Json::StreamWriterBuilder builder; + std::unique_ptr<::Json::StreamWriter> writer(builder.newStreamWriter()); + + if (mOutputFile.is_open()) + { + if (!mFirstRecord) + { + mOutputFile << ",\n"; + } + else + { + mFirstRecord = false; + } + value["time_ms"] = chip::System::SystemClock().GetMonotonicTimestamp().count(); + writer->write(value, &mOutputFile); + mOutputFile.flush(); + } + else + { + std::stringstream output; + writer->write(value, &output); + ChipLogProgress(Automation, "%s", output.str().c_str()); + } } -} // namespace LogJson +} // namespace Json } // namespace Tracing } // namespace chip diff --git a/src/tracing/log_json/log_json_tracing.h b/src/tracing/json/json_tracing.h similarity index 71% rename from src/tracing/log_json/log_json_tracing.h rename to src/tracing/json/json_tracing.h index 99ee15337b86c4..74451b705b73e0 100644 --- a/src/tracing/log_json/log_json_tracing.h +++ b/src/tracing/json/json_tracing.h @@ -17,11 +17,16 @@ */ #pragma once +#include #include +namespace Json { +class Value; +} + namespace chip { namespace Tracing { -namespace LogJson { +namespace Json { /// A Backend that outputs data to chip logging. /// @@ -30,10 +35,17 @@ namespace LogJson { /// THREAD SAFETY: /// class assumes that ChipLog* is thread_safe (generally /// we ChipLog* everywhere, so that condition seems to be met). -class LogJsonBackend : public ::chip::Tracing::Backend +class JsonBackend : public ::chip::Tracing::Backend { public: - LogJsonBackend() = default; + JsonBackend() = default; + ~JsonBackend(); + + // Start tracing output to the given file + CHIP_ERROR OpenFile(const char * path); + + // Close if an output file is open + void CloseFile(); void TraceBegin(const char * label, const char * group) override; void TraceEnd(const char * label, const char * group) override; @@ -43,8 +55,18 @@ class LogJsonBackend : public ::chip::Tracing::Backend void LogNodeLookup(NodeLookupInfo &) override; void LogNodeDiscovered(NodeDiscoveredInfo &) override; void LogNodeDiscoveryFailed(NodeDiscoveryFailedInfo &) override; + void Close() override { CloseFile(); } + +private: + /// Does the actual write of the value + void OutputValue(::Json::Value & value); + + // Output file if writing to a file. If closed, writing + // to ChipLog* + std::fstream mOutputFile; + bool mFirstRecord = true; }; -} // namespace LogJson +} // namespace Json } // namespace Tracing } // namespace chip