From 34424621c1e3e9b8b2d05eb431f24b17b38ba0f0 Mon Sep 17 00:00:00 2001 From: Pankaj Garg Date: Thu, 28 Oct 2021 12:18:15 -0700 Subject: [PATCH] Add logs to debug Darwin CI failures (#11005) * Debug failures in Darwin CI * Formalize PR by adding ChipLogByteSpan --- src/lib/support/logging/CHIPLogging.cpp | 32 +++++++++++++++++++++++++ src/lib/support/logging/CHIPLogging.h | 16 +++++++++++++ src/transport/FabricTable.cpp | 17 +++++++++++++ 3 files changed, 65 insertions(+) diff --git a/src/lib/support/logging/CHIPLogging.cpp b/src/lib/support/logging/CHIPLogging.cpp index d7a3f06af8c616..df5439bd952697 100644 --- a/src/lib/support/logging/CHIPLogging.cpp +++ b/src/lib/support/logging/CHIPLogging.cpp @@ -28,6 +28,7 @@ #include #include #include +#include #include #include @@ -142,6 +143,37 @@ DLL_EXPORT void Log(uint8_t module, uint8_t category, const char * msg, ...) va_end(v); } +DLL_EXPORT void LogByteSpan(uint8_t module, uint8_t category, const chip::ByteSpan & span) +{ + // Maximum number of characters needed to print 8 byte buffer including formatting (0x) + // 8 bytes * (2 nibbles per byte + 4 character for ", 0x") + null termination. + // Rounding up to 50 bytes. + char output[50]; + size_t offset = 0; + for (unsigned int i = 0; i < span.size(); i++) + { + if (i % 8 == 0 && offset != 0) + { + Log(module, category, "%s", output); + offset = 0; + } + int result = snprintf(&output[offset], sizeof(output) - offset, "0x%02x, ", (unsigned char) span.data()[i]); + if (result > 0) + { + offset += static_cast(result); + } + else + { + Log(module, chip::Logging::kLogCategory_Error, "Failed to print ByteSpan buffer"); + return; + } + } + if (offset != 0) + { + Log(module, category, "%s", output); + } +} + void LogV(uint8_t module, uint8_t category, const char * msg, va_list args) { if (!IsCategoryEnabled(category)) diff --git a/src/lib/support/logging/CHIPLogging.h b/src/lib/support/logging/CHIPLogging.h index a8b82dd5bf84b2..ac8f6820b2701f 100644 --- a/src/lib/support/logging/CHIPLogging.h +++ b/src/lib/support/logging/CHIPLogging.h @@ -66,6 +66,11 @@ */ namespace chip { + +template +class Span; +using ByteSpan = Span; + namespace Logging { using LogRedirectCallback_t = void (*)(const char * module, uint8_t category, const char * msg, va_list args); @@ -88,6 +93,8 @@ void SetLogRedirectCallback(LogRedirectCallback_t callback); void LogV(uint8_t module, uint8_t category, const char * msg, va_list args); void Log(uint8_t module, uint8_t category, const char * msg, ...) ENFORCE_FORMAT(3, 4); +void LogByteSpan(uint8_t module, uint8_t category, const ByteSpan & span); + uint8_t GetLogFilter(); void SetLogFilter(uint8_t category); @@ -158,6 +165,15 @@ void SetLogFilter(uint8_t category); #define ChipLogDetail(MOD, MSG, ...) ((void) 0) #endif +#if CHIP_DETAIL_LOGGING +#ifndef ChipLogByteSpan +#define ChipLogByteSpan(MOD, DATA) \ + chip::Logging::LogByteSpan(chip::Logging::kLogModule_##MOD, chip::Logging::kLogCategory_Detail, DATA) +#endif +#else +#define ChipLogByteSpan(MOD, DATA) ((void) 0) +#endif + #if CHIP_ERROR_LOGGING || CHIP_PROGRESS_LOGGING || CHIP_DETAIL_LOGGING #define _CHIP_USE_LOGGING 1 #else diff --git a/src/transport/FabricTable.cpp b/src/transport/FabricTable.cpp index ef1f9ed45293fc..5987c326b5dd8b 100644 --- a/src/transport/FabricTable.cpp +++ b/src/transport/FabricTable.cpp @@ -187,7 +187,12 @@ CHIP_ERROR FabricInfo::GetCompressedId(FabricId fabricId, NodeId nodeId, PeerId uint8_t compressedFabricIdBuf[sizeof(uint64_t)]; MutableByteSpan compressedFabricIdSpan(compressedFabricIdBuf); P256PublicKey rootPubkey(GetRootPubkey()); + ChipLogDetail(Inet, "Generating compressed fabric ID using uncompressed fabric ID 0x" ChipLogFormatX64 " and root pubkey", + ChipLogValueX64(fabricId)); + ChipLogByteSpan(Inet, ByteSpan(rootPubkey.ConstBytes(), rootPubkey.Length())); ReturnErrorOnFailure(GenerateCompressedFabricId(rootPubkey, fabricId, compressedFabricIdSpan)); + ChipLogDetail(Inet, "Generated compressed fabric ID"); + ChipLogByteSpan(Inet, compressedFabricIdSpan); // Decode compressed fabric ID accounting for endianness, as GenerateCompressedFabricId() // returns a binary buffer and is agnostic of usage of the output as an integer type. @@ -325,12 +330,19 @@ CHIP_ERROR FabricInfo::GenerateDestinationID(const ByteSpan & ipk, const ByteSpa Encoding::LittleEndian::BufferWriter bbuf(destinationMessage, sizeof(destinationMessage)); + ChipLogDetail(Inet, + "Generating DestinationID. Fabric ID 0x" ChipLogFormatX64 ", Dest node ID 0x" ChipLogFormatX64 ", Random data", + ChipLogValueX64(mFabricId), ChipLogValueX64(destNodeId)); + ChipLogByteSpan(Inet, random); + bbuf.Put(random.data(), random.size()); // TODO: In the current implementation this check is required because in some cases the // GenerateDestinationID() is called before mRootCert is initialized and GetRootPubkey() returns // empty Span. if (!rootPubkeySpan.empty()) { + ChipLogDetail(Inet, "Root pubkey"); + ChipLogByteSpan(Inet, rootPubkeySpan); bbuf.Put(rootPubkeySpan.data(), rootPubkeySpan.size()); } bbuf.Put64(mFabricId); @@ -339,8 +351,13 @@ CHIP_ERROR FabricInfo::GenerateDestinationID(const ByteSpan & ipk, const ByteSpa size_t written = 0; VerifyOrReturnError(bbuf.Fit(written), CHIP_ERROR_BUFFER_TOO_SMALL); + ChipLogDetail(Inet, "IPK"); + ChipLogByteSpan(Inet, ipk); + CHIP_ERROR err = hmac.HMAC_SHA256(ipk.data(), ipk.size(), destinationMessage, written, destinationId.data(), destinationId.size()); + ChipLogDetail(Inet, "Generated DestinationID output"); + ChipLogByteSpan(Inet, destinationId); return err; }