From 1883599972a7577225ee6f9999d64130a082f553 Mon Sep 17 00:00:00 2001 From: Andrei Litvin Date: Tue, 18 Jul 2023 22:03:45 -0400 Subject: [PATCH] Json tracing updates and fixes (enable in all clusters, fix lists and large payloads) (#28022) * Fix json tracing * Increase the buffer size for json tracing as well * Full json trace decoding for all clusters app on linux * Better formatting of lists - make indices make sense * Restyle * Updated comments based on code review * Restyled by whitespace * Add error logging when exit container fails * Fix typo * Update src/tracing/json/json_tracing.cpp Co-authored-by: Boris Zbarsky * rename [] to Anonymous<> for lists * Rename exit to end for containers * Use a `@` format instead of - * One more anonymous update * Fix unit tests --------- Co-authored-by: Andrei Litvin Co-authored-by: Restyled.io Co-authored-by: Boris Zbarsky --- examples/all-clusters-app/linux/args.gni | 2 + .../cpp/tlvmeta/TLVMetaData_cpp.jinja | 2 +- .../generators/cpp/tlvmeta/__init__.py | 2 +- .../cpp-tlvmeta/clusters_meta.cpp | 4 +- .../cpp-tlvmeta/clusters_meta.cpp | 2 +- src/lib/format/protocol_decoder.cpp | 10 ++- src/lib/format/tests/TestDecoding.cpp | 82 +++++++++---------- src/tracing/json/json_tracing.cpp | 78 +++++++++++++++++- 8 files changed, 131 insertions(+), 51 deletions(-) diff --git a/examples/all-clusters-app/linux/args.gni b/examples/all-clusters-app/linux/args.gni index 49ecbd6dff99e8..38e844a7016951 100644 --- a/examples/all-clusters-app/linux/args.gni +++ b/examples/all-clusters-app/linux/args.gni @@ -25,6 +25,8 @@ chip_project_config_include_dirs = chip_project_config_include_dirs += [ "${chip_root}/config/standalone" ] matter_enable_tracing_support = true +matter_log_json_payload_decode_full = true +matter_log_json_payload_hex = true # Perfetto requires C++17 cpp_standard = "gnu++17" diff --git a/scripts/py_matter_idl/matter_idl/generators/cpp/tlvmeta/TLVMetaData_cpp.jinja b/scripts/py_matter_idl/matter_idl/generators/cpp/tlvmeta/TLVMetaData_cpp.jinja index f748875b7d7996..548f8f399feb66 100644 --- a/scripts/py_matter_idl/matter_idl/generators/cpp/tlvmeta/TLVMetaData_cpp.jinja +++ b/scripts/py_matter_idl/matter_idl/generators/cpp/tlvmeta/TLVMetaData_cpp.jinja @@ -25,7 +25,7 @@ const Entry _all_clusters[] = { // For any non-structure list like u64[] or similar. const Entry _primitive_type_list[] = { - { { AnonymousTag(), "[]", ItemType::kDefault }, kInvalidNodeIndex }, + { { AnonymousTag(), "Anonymous<>", ItemType::kDefault }, kInvalidNodeIndex }, }; } // namespace diff --git a/scripts/py_matter_idl/matter_idl/generators/cpp/tlvmeta/__init__.py b/scripts/py_matter_idl/matter_idl/generators/cpp/tlvmeta/__init__.py index c93d55c32de081..6a567ee122d551 100644 --- a/scripts/py_matter_idl/matter_idl/generators/cpp/tlvmeta/__init__.py +++ b/scripts/py_matter_idl/matter_idl/generators/cpp/tlvmeta/__init__.py @@ -187,7 +187,7 @@ def GenerateTables(self) -> Generator[Table, None, None]: entries=[ TableEntry( code="AnonymousTag()", - name="[]", + name="Anonymous<>", reference=name, real_type="%s[]" % name, ) diff --git a/scripts/py_matter_idl/matter_idl/tests/outputs/cluster_struct_attribute/cpp-tlvmeta/clusters_meta.cpp b/scripts/py_matter_idl/matter_idl/tests/outputs/cluster_struct_attribute/cpp-tlvmeta/clusters_meta.cpp index 4985c3e09a7dfa..a6d25bd54707df 100644 --- a/scripts/py_matter_idl/matter_idl/tests/outputs/cluster_struct_attribute/cpp-tlvmeta/clusters_meta.cpp +++ b/scripts/py_matter_idl/matter_idl/tests/outputs/cluster_struct_attribute/cpp-tlvmeta/clusters_meta.cpp @@ -19,7 +19,7 @@ const Entry _DemoCluster_ArmFailSafeRequest[] = { }; const Entry _DemoCluster_ArmFailSafeRequest_list_[] = { - { { AnonymousTag(), "[]", ItemType::kDefault }, 3 }, // DemoCluster_ArmFailSafeRequest[] + { { AnonymousTag(), "Anonymous<>", ItemType::kDefault }, 3 }, // DemoCluster_ArmFailSafeRequest[] }; const Entry _all_clusters[] = { @@ -29,7 +29,7 @@ const Entry _all_clusters[] = { // For any non-structure list like u64[] or similar. const Entry _primitive_type_list[] = { - { { AnonymousTag(), "[]", ItemType::kDefault }, kInvalidNodeIndex }, + { { AnonymousTag(), "Anonymous<>", ItemType::kDefault }, kInvalidNodeIndex }, }; } // namespace diff --git a/scripts/py_matter_idl/matter_idl/tests/outputs/cluster_with_commands/cpp-tlvmeta/clusters_meta.cpp b/scripts/py_matter_idl/matter_idl/tests/outputs/cluster_with_commands/cpp-tlvmeta/clusters_meta.cpp index 05d308526e1368..d96c8564e626dd 100644 --- a/scripts/py_matter_idl/matter_idl/tests/outputs/cluster_with_commands/cpp-tlvmeta/clusters_meta.cpp +++ b/scripts/py_matter_idl/matter_idl/tests/outputs/cluster_with_commands/cpp-tlvmeta/clusters_meta.cpp @@ -55,7 +55,7 @@ const Entry _all_clusters[] = { // For any non-structure list like u64[] or similar. const Entry _primitive_type_list[] = { - { { AnonymousTag(), "[]", ItemType::kDefault }, kInvalidNodeIndex }, + { { AnonymousTag(), "Anonymous<>", ItemType::kDefault }, kInvalidNodeIndex }, }; } // namespace diff --git a/src/lib/format/protocol_decoder.cpp b/src/lib/format/protocol_decoder.cpp index 97d6dd857d9198..a0dc009d3d97b0 100644 --- a/src/lib/format/protocol_decoder.cpp +++ b/src/lib/format/protocol_decoder.cpp @@ -292,7 +292,15 @@ void PayloadDecoderBase::ExitContainer(PayloadEntry & entry) { mPayloadPosition.Exit(); } - mReader.ExitContainer(mNestingEnters[--mCurrentNesting]); + CHIP_ERROR err = mReader.ExitContainer(mNestingEnters[--mCurrentNesting]); + if (err != CHIP_NO_ERROR) + { + mValueBuilder.AddFormat("ERROR: %" CHIP_ERROR_FORMAT, err.Format()); + mNameBuilder.AddFormat("END CONTAINER"); + entry = PayloadEntry::SimpleValue(mNameBuilder.c_str(), mValueBuilder.c_str()); + mState = State::kDone; + return; + } } if (mCurrentNesting == 0) diff --git a/src/lib/format/tests/TestDecoding.cpp b/src/lib/format/tests/TestDecoding.cpp index 3c6edd3000fa3a..e822c6869a82f9 100644 --- a/src/lib/format/tests/TestDecoding.cpp +++ b/src/lib/format/tests/TestDecoding.cpp @@ -174,34 +174,34 @@ void TestFullDataDecoding(nlTestSuite * inSuite, void * inContext) TestSampleData(inSuite, params, im_protocol_read_request, "read_request\n" " attribute_requests\n" - " []\n" + " Anonymous<>\n" " cluster_id: 49 == 'NetworkCommissioning'\n" " attribute_id: 65532 == 'featureMap'\n" - " []\n" + " Anonymous<>\n" " endpoint_id: 0\n" " cluster_id: 48 == 'GeneralCommissioning'\n" " attribute_id: 0 == 'breadcrumb'\n" - " []\n" + " Anonymous<>\n" " endpoint_id: 0\n" " cluster_id: 48 == 'GeneralCommissioning'\n" " attribute_id: 1 == 'basicCommissioningInfo'\n" - " []\n" + " Anonymous<>\n" " endpoint_id: 0\n" " cluster_id: 48 == 'GeneralCommissioning'\n" " attribute_id: 2 == 'regulatoryConfig'\n" - " []\n" + " Anonymous<>\n" " endpoint_id: 0\n" " cluster_id: 48 == 'GeneralCommissioning'\n" " attribute_id: 3 == 'locationCapability'\n" - " []\n" + " Anonymous<>\n" " endpoint_id: 0\n" " cluster_id: 40 == 'BasicInformation'\n" " attribute_id: 2 == 'vendorID'\n" - " []\n" + " Anonymous<>\n" " endpoint_id: 0\n" " cluster_id: 40 == 'BasicInformation'\n" " attribute_id: 4 == 'productID'\n" - " []\n" + " Anonymous<>\n" " cluster_id: 49 == 'NetworkCommissioning'\n" " attribute_id: 3 == 'connectMaxTimeSeconds'\n" " fabric_filtered: false\n" @@ -209,7 +209,7 @@ void TestFullDataDecoding(nlTestSuite * inSuite, void * inContext) TestSampleData(inSuite, params, im_protocol_report_data, "report_data\n" " attribute_reports\n" - " []\n" + " Anonymous<>\n" " attribute_data\n" " data_version: 28559721\n" " path\n" @@ -217,7 +217,7 @@ void TestFullDataDecoding(nlTestSuite * inSuite, void * inContext) " cluster_id: 49 == 'NetworkCommissioning'\n" " attribute_id: 3 == 'connectMaxTimeSeconds'\n" " NetworkCommissioning::connectMaxTimeSeconds: 0\n" - " []\n" + " Anonymous<>\n" " attribute_data\n" " data_version: 664978787\n" " path\n" @@ -225,7 +225,7 @@ void TestFullDataDecoding(nlTestSuite * inSuite, void * inContext) " cluster_id: 40 == 'BasicInformation'\n" " attribute_id: 4 == 'productID'\n" " BasicInformation::productID: 32769\n" - " []\n" + " Anonymous<>\n" " attribute_data\n" " data_version: 664978787\n" " path\n" @@ -233,7 +233,7 @@ void TestFullDataDecoding(nlTestSuite * inSuite, void * inContext) " cluster_id: 40 == 'BasicInformation'\n" " attribute_id: 2 == 'vendorID'\n" " BasicInformation::vendorID: 65521\n" - " []\n" + " Anonymous<>\n" " attribute_data\n" " data_version: 1414030794\n" " path\n" @@ -241,7 +241,7 @@ void TestFullDataDecoding(nlTestSuite * inSuite, void * inContext) " cluster_id: 48 == 'GeneralCommissioning'\n" " attribute_id: 3 == 'locationCapability'\n" " GeneralCommissioning::locationCapability: 2 == kIndoorOutdoor\n" - " []\n" + " Anonymous<>\n" " attribute_data\n" " data_version: 1414030794\n" " path\n" @@ -249,7 +249,7 @@ void TestFullDataDecoding(nlTestSuite * inSuite, void * inContext) " cluster_id: 48 == 'GeneralCommissioning'\n" " attribute_id: 2 == 'regulatoryConfig'\n" " GeneralCommissioning::regulatoryConfig: 0 == kIndoor\n" - " []\n" + " Anonymous<>\n" " attribute_data\n" " data_version: 1414030794\n" " path\n" @@ -259,7 +259,7 @@ void TestFullDataDecoding(nlTestSuite * inSuite, void * inContext) " GeneralCommissioning::basicCommissioningInfo\n" " failSafeExpiryLengthSeconds: 60\n" " maxCumulativeFailsafeSeconds: 900\n" - " []\n" + " Anonymous<>\n" " attribute_data\n" " data_version: 1414030794\n" " path\n" @@ -267,7 +267,7 @@ void TestFullDataDecoding(nlTestSuite * inSuite, void * inContext) " cluster_id: 48 == 'GeneralCommissioning'\n" " attribute_id: 0 == 'breadcrumb'\n" " GeneralCommissioning::breadcrumb: 0\n" - " []\n" + " Anonymous<>\n" " attribute_data\n" " data_version: 28559721\n" " path\n" @@ -282,7 +282,7 @@ void TestFullDataDecoding(nlTestSuite * inSuite, void * inContext) TestSampleData(inSuite, params, im_protocol_report_data_acl, "report_data\n" " attribute_reports\n" - " []\n" + " Anonymous<>\n" " attribute_data\n" " data_version: 3420147058\n" " path\n" @@ -290,11 +290,11 @@ void TestFullDataDecoding(nlTestSuite * inSuite, void * inContext) " cluster_id: 31 == 'AccessControl'\n" " attribute_id: 0 == 'acl'\n" " AccessControl::acl\n" - " []\n" + " Anonymous<>\n" " privilege: 5 == kAdminister\n" " authMode: 2 == kCASE\n" " subjects\n" - " []: 112233\n" + " Anonymous<>: 112233\n" " targets: NULL\n" " fabricIndex: 1\n" " suppress_response: true\n" @@ -304,7 +304,7 @@ void TestFullDataDecoding(nlTestSuite * inSuite, void * inContext) inSuite, params, im_protocol_report_data_window_covering, "report_data\n" " attribute_reports\n" - " []\n" + " Anonymous<>\n" " attribute_data\n" " data_version: 2054986218\n" " path\n" @@ -320,7 +320,7 @@ void TestFullDataDecoding(nlTestSuite * inSuite, void * inContext) " suppress_response: false\n" " timed_request: false\n" " invoke_requests\n" - " []\n" + " Anonymous<>\n" " path\n" " endpoint_id: 1\n" " cluster_id: 6 == 'OnOff'\n" @@ -332,7 +332,7 @@ void TestFullDataDecoding(nlTestSuite * inSuite, void * inContext) "invoke_response\n" " suppress_response: false\n" " invoke_responses\n" - " []\n" + " Anonymous<>\n" " status\n" " path\n" " endpoint_id: 1\n" @@ -347,7 +347,7 @@ void TestFullDataDecoding(nlTestSuite * inSuite, void * inContext) " suppress_response: false\n" " timed_request: false\n" " invoke_requests\n" - " []\n" + " Anonymous<>\n" " path\n" " endpoint_id: 1\n" " cluster_id: 1284 == 'Channel'\n" @@ -375,34 +375,34 @@ void TestMetaDataOnlyDecoding(nlTestSuite * inSuite, void * inContext) TestSampleData(inSuite, params, im_protocol_read_request, "read_request\n" " attribute_requests\n" - " []\n" + " Anonymous<>\n" " cluster_id: 49\n" " attribute_id: 65532\n" - " []\n" + " Anonymous<>\n" " endpoint_id: 0\n" " cluster_id: 48\n" " attribute_id: 0\n" - " []\n" + " Anonymous<>\n" " endpoint_id: 0\n" " cluster_id: 48\n" " attribute_id: 1\n" - " []\n" + " Anonymous<>\n" " endpoint_id: 0\n" " cluster_id: 48\n" " attribute_id: 2\n" - " []\n" + " Anonymous<>\n" " endpoint_id: 0\n" " cluster_id: 48\n" " attribute_id: 3\n" - " []\n" + " Anonymous<>\n" " endpoint_id: 0\n" " cluster_id: 40\n" " attribute_id: 2\n" - " []\n" + " Anonymous<>\n" " endpoint_id: 0\n" " cluster_id: 40\n" " attribute_id: 4\n" - " []\n" + " Anonymous<>\n" " cluster_id: 49\n" " attribute_id: 3\n" " fabric_filtered: false\n" @@ -410,7 +410,7 @@ void TestMetaDataOnlyDecoding(nlTestSuite * inSuite, void * inContext) TestSampleData(inSuite, params, im_protocol_report_data, "report_data\n" " attribute_reports\n" - " []\n" + " Anonymous<>\n" " attribute_data\n" " data_version: 28559721\n" " path\n" @@ -418,7 +418,7 @@ void TestMetaDataOnlyDecoding(nlTestSuite * inSuite, void * inContext) " cluster_id: 49\n" " attribute_id: 3\n" " ATTRIBUTE: 49/3\n" - " []\n" + " Anonymous<>\n" " attribute_data\n" " data_version: 664978787\n" " path\n" @@ -426,7 +426,7 @@ void TestMetaDataOnlyDecoding(nlTestSuite * inSuite, void * inContext) " cluster_id: 40\n" " attribute_id: 4\n" " ATTRIBUTE: 40/4\n" - " []\n" + " Anonymous<>\n" " attribute_data\n" " data_version: 664978787\n" " path\n" @@ -434,7 +434,7 @@ void TestMetaDataOnlyDecoding(nlTestSuite * inSuite, void * inContext) " cluster_id: 40\n" " attribute_id: 2\n" " ATTRIBUTE: 40/2\n" - " []\n" + " Anonymous<>\n" " attribute_data\n" " data_version: 1414030794\n" " path\n" @@ -442,7 +442,7 @@ void TestMetaDataOnlyDecoding(nlTestSuite * inSuite, void * inContext) " cluster_id: 48\n" " attribute_id: 3\n" " ATTRIBUTE: 48/3\n" - " []\n" + " Anonymous<>\n" " attribute_data\n" " data_version: 1414030794\n" " path\n" @@ -450,7 +450,7 @@ void TestMetaDataOnlyDecoding(nlTestSuite * inSuite, void * inContext) " cluster_id: 48\n" " attribute_id: 2\n" " ATTRIBUTE: 48/2\n" - " []\n" + " Anonymous<>\n" " attribute_data\n" " data_version: 1414030794\n" " path\n" @@ -458,7 +458,7 @@ void TestMetaDataOnlyDecoding(nlTestSuite * inSuite, void * inContext) " cluster_id: 48\n" " attribute_id: 1\n" " ATTRIBUTE: 48/1\n" - " []\n" + " Anonymous<>\n" " attribute_data\n" " data_version: 1414030794\n" " path\n" @@ -466,7 +466,7 @@ void TestMetaDataOnlyDecoding(nlTestSuite * inSuite, void * inContext) " cluster_id: 48\n" " attribute_id: 0\n" " ATTRIBUTE: 48/0\n" - " []\n" + " Anonymous<>\n" " attribute_data\n" " data_version: 28559721\n" " path\n" @@ -481,7 +481,7 @@ void TestMetaDataOnlyDecoding(nlTestSuite * inSuite, void * inContext) TestSampleData(inSuite, params, im_protocol_report_data_acl, "report_data\n" " attribute_reports\n" - " []\n" + " Anonymous<>\n" " attribute_data\n" " data_version: 3420147058\n" " path\n" @@ -503,7 +503,7 @@ void TestEmptyClusterMetaDataDecode(nlTestSuite * inSuite, void * inContext) TestSampleData(inSuite, params, im_protocol_report_data_acl, "report_data\n" " attribute_reports\n" - " []\n" + " Anonymous<>\n" " attribute_data\n" " data_version: 3420147058\n" " path\n" diff --git a/src/tracing/json/json_tracing.cpp b/src/tracing/json/json_tracing.cpp index b0e3959b3922c9..e375c2c1113b31 100644 --- a/src/tracing/json/json_tracing.cpp +++ b/src/tracing/json/json_tracing.cpp @@ -56,20 +56,89 @@ using namespace chip::Decoders; using PayloadDecoderType = chip::Decoders::PayloadDecoder<64, 256>; +/// Figures out a unique name within a json object. +/// +/// Decoded keys may be duplicated, like list elements are denoted as "[]". +/// The existing code does not attempt to encode lists and everything is an object, +/// so this name builder attempts to find unique keys for elements inside a json. +/// +/// In particular a repeated "Anonymous<>", "Anonymous<>", ... will become "Anonymous<0>", ... +class UniqueNameBuilder +{ +public: + UniqueNameBuilder(chip::StringBuilderBase & formatter) : mFormatter(formatter) {} + const char * c_str() const { return mFormatter.c_str(); } + + // Figure out the next unique name in the given value + // + // After this returns, c_str() will return a name based on `baseName` that is + // not a key of `value` (unless on overflows, which are just logged) + void ComputeNextUniqueName(const char * baseName, ::Json::Value & value) + { + FirstName(baseName); + while (value.isMember(mFormatter.c_str())) + { + NextName(baseName); + if (!mFormatter.Fit()) + { + ChipLogError(Automation, "Potential data loss: insufficient space for unique keys in json"); + return; + } + } + } + +private: + void FirstName(const char * baseName) + { + if (strcmp(baseName, "Anonymous<>") == 0) + { + mFormatter.Reset().Add("Anonymous<0>"); + } + else + { + mFormatter.Reset().Add(baseName); + } + } + + void NextName(const char * baseName) + { + if (strcmp(baseName, "Anonymous<>") == 0) + { + mFormatter.Reset().Add("Anonymous<").Add(mUniqueIndex++).Add(">"); + } + else + { + mFormatter.Reset().Add(baseName).Add("@").Add(mUniqueIndex++); + } + } + + chip::StringBuilderBase & mFormatter; + int mUniqueIndex = 0; +}; + // Gets the current value of the decoder until a NEST exit is returned ::Json::Value GetPayload(PayloadDecoderType & decoder) { ::Json::Value value; PayloadEntry entry; StringBuilder<128> formatter; + UniqueNameBuilder nameBuilder(formatter); while (decoder.Next(entry)) { switch (entry.GetType()) { case PayloadEntry::IMPayloadType::kNestingEnter: - formatter.Reset().Add(entry.GetName()); // name gets destroyed by decoding - value[formatter.c_str()] = GetPayload(decoder); + // PayloadEntry validity is only until any decoder calls are made, + // because the entry Name/Value may point into a shared Decoder buffer. + // + // As such entry.GetName() is only valid here and would not be valid once + // GetPayload() is called as GetPayload calls decoder.Next, which invalidates + // internal name and value buffers (makes them point to the next element). + // + // TLDR: name MUST be used and saved before GetPayload is executed. + nameBuilder.ComputeNextUniqueName(entry.GetName(), value); + value[nameBuilder.c_str()] = GetPayload(decoder); break; case PayloadEntry::IMPayloadType::kNestingExit: return value; @@ -84,7 +153,8 @@ ::Json::Value GetPayload(PayloadDecoderType & decoder) value[formatter.Reset().AddFormat("EVNT(%u/%u)", entry.GetClusterId(), entry.GetEventId()).c_str()] = ""; continue; default: - value[entry.GetName()] = entry.GetValueText(); + nameBuilder.ComputeNextUniqueName(entry.GetName(), value); + value[nameBuilder.c_str()] = entry.GetValueText(); break; } } @@ -147,7 +217,7 @@ void DecodePayloadData(::Json::Value & value, chip::ByteSpan payload, Protocols: value["size"] = static_cast<::Json::Value::UInt>(payload.size()); #if MATTER_LOG_JSON_DECODE_HEX - char hex_buffer[1024]; + char hex_buffer[4096]; if (chip::Encoding::BytesToUppercaseHexString(payload.data(), payload.size(), hex_buffer, sizeof(hex_buffer)) == CHIP_NO_ERROR) { value["hex"] = hex_buffer;