Add logs to debug Darwin CI failures (#11005)

* Debug failures in Darwin CI * Formalize PR by adding ChipLogByteSpan
project-chip · Sep 22, 2022 · 3442462 · 3442462
1 parent f58e70a
commit 3442462
Show file tree

Hide file tree

Showing 3 changed files with 65 additions and 0 deletions.
diff --git a/src/lib/support/logging/CHIPLogging.cpp b/src/lib/support/logging/CHIPLogging.cpp
@@ -28,6 +28,7 @@
 #include <lib/core/CHIPCore.h>
 #include <lib/support/CodeUtils.h>
 #include <lib/support/DLLUtil.h>
+#include <lib/support/Span.h>
 
 #include <stdarg.h>
 #include <stdio.h>
@@ -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<size_t>(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
@@ -66,6 +66,11 @@
  */
 
 namespace chip {
+
+template <class T>
+class Span;
+using ByteSpan = Span<const uint8_t>;
+
 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
@@ -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;
 }