Log BDX messages (project-chip#11510)

* Log BDX messages

* Create a new macro ChipLogAutomation

- This macro is to be used only for test validation purpose

* Remove private struct members from BdxMessage types

- Pass in the message type directly during logging

src/lib/core/BUILD.gn

@@ -46,6 +46,7 @@ buildconfig_header("chip_buildconfig") {
     "CHIP_ERROR_LOGGING=${chip_error_logging}",
     "CHIP_PROGRESS_LOGGING=${chip_progress_logging}",
     "CHIP_DETAIL_LOGGING=${chip_detail_logging}",
+    "CHIP_AUTOMATION_LOGGING=${chip_automation_logging}",
     "CHIP_CONFIG_SHORT_ERROR_STR=${chip_config_short_error_str}",
     "CHIP_CONFIG_ENABLE_ARG_PARSER=${chip_config_enable_arg_parser}",
     "CHIP_TARGET_STYLE_UNIX=${chip_target_style_unix}",

src/lib/core/CHIPConfig.h

@@ -1832,6 +1832,18 @@
 #define CHIP_DETAIL_LOGGING 1
 #endif // CHIP_DETAIL_LOGGING
 
+/**
+ *  @def CHIP_AUTOMATION_LOGGING
+ *
+ *  @brief
+ *    If asserted (1), enable logging of all messages in the
+ *    chip::Logging::kLogCategory_Automation category.
+ *
+ */
+#ifndef CHIP_AUTOMATION_LOGGING
+#define CHIP_AUTOMATION_LOGGING 1
+#endif // CHIP_AUTOMATION_LOGGING
+
 /**
  * CHIP_CONFIG_LOG_MESSAGE_MAX_SIZE
  *

src/lib/core/core.gni

@@ -30,6 +30,9 @@ declare_args() {
   # Enable detail logging.
   chip_detail_logging = chip_logging
 
+  # Enable automation logging.
+  chip_automation_logging = chip_logging
+
   # Enable short error strings.
   chip_config_short_error_str = false
 

src/lib/support/logging/CHIPLogging.cpp

@@ -95,6 +95,7 @@ static const char ModuleNames[] = "-\0\0" // None
                                   "IM\0"  // InteractionModel
                                   "TST"   // Test
                                   "ODP"   // OperationalDeviceProxy
+                                  "ATM"   // Automation
     ;
 
 #define ModuleNamesCount ((sizeof(ModuleNames) - 1) / chip::Logging::kMaxModuleNameLen)

src/lib/support/logging/CHIPLogging.h

@@ -29,6 +29,7 @@
  *         - #CHIP_ERROR_LOGGING
  *         - #CHIP_PROGRESS_LOGGING
  *         - #CHIP_DETAIL_LOGGING
+ *         - #CHIP_AUTOMATION_LOGGING
  *
  */
 
@@ -62,6 +63,7 @@
  *        - #CHIP_ERROR_LOGGING
  *        - #CHIP_PROGRESS_LOGGING
  *        - #CHIP_DETAIL_LOGGING
+ *         - #CHIP_AUTOMATION_LOGGING
  *
  */
 
@@ -174,11 +176,32 @@ void SetLogFilter(uint8_t category);
 #define ChipLogByteSpan(MOD, DATA) ((void) 0)
 #endif
 
-#if CHIP_ERROR_LOGGING || CHIP_PROGRESS_LOGGING || CHIP_DETAIL_LOGGING
+#ifndef CHIP_AUTOMATION_LOGGING
+#define CHIP_AUTOMATION_LOGGING 1
+#endif
+
+#if CHIP_AUTOMATION_LOGGING
+/**
+ * @def ChipLogAutomation(MSG, ...)
+ *
+ * @brief
+ *   Log a chip message for the specified module in the 'Automation'
+ *   category.
+ *
+ */
+#ifndef ChipLogAutomation
+#define ChipLogAutomation(MSG, ...)                                                                                                \
+    chip::Logging::Log(chip::Logging::kLogModule_Automation, chip::Logging::kLogCategory_Automation, MSG, ##__VA_ARGS__)
+#endif
+#else
+#define ChipLogAutomation(MOD, MSG, ...) ((void) 0)
+#endif
+
+#if CHIP_ERROR_LOGGING || CHIP_PROGRESS_LOGGING || CHIP_DETAIL_LOGGING || CHIP_AUTOMATION_LOGGING
 #define _CHIP_USE_LOGGING 1
 #else
 #define _CHIP_USE_LOGGING 0
-#endif /* CHIP_ERROR_LOGGING || CHIP_PROGRESS_LOGGING || CHIP_DETAIL_LOGGING */
+#endif /* CHIP_ERROR_LOGGING || CHIP_PROGRESS_LOGGING || CHIP_DETAIL_LOGGING || CHIP_AUTOMATION_LOGGING */
 
 #if _CHIP_USE_LOGGING
 

src/lib/support/logging/Constants.h

@@ -57,6 +57,7 @@ enum LogModule
     kLogModule_InteractionModel,
     kLogModule_Test,
     kLogModule_OperationalDeviceProxy,
+    kLogModule_Automation,
 
     kLogModule_Max
 };
@@ -125,7 +126,16 @@ enum LogCategory
      */
     kLogCategory_Detail = 3,
 
-    kLogCategory_Max = kLogCategory_Detail
+    /*!<
+     *   Indicates a category of log message that describes automation
+     *   information about an event or the state of the system.
+     *
+     *   Such messages can be used by automation for test validation.
+     *
+     */
+    kLogCategory_Automation = 4,
+
+    kLogCategory_Max = kLogCategory_Automation
 };
 
 } // namespace Logging

src/platform/qpg/args.gni

@@ -31,6 +31,7 @@ chip_inet_config_enable_tcp_endpoint = false
 # Size opt's
 #chip_progress_logging = false
 chip_detail_logging = false
+chip_automation_logging = false
 
 # Use -Os
 is_debug = false

src/protocols/bdx/BdxMessages.cpp

@@ -31,7 +31,8 @@
 #include <utility>
 
 namespace {
-constexpr uint8_t kVersionMask = 0x0F;
+constexpr uint8_t kVersionMask          = 0x0F;
+constexpr uint8_t kMaxFileDesignatorLen = 32;
 } // namespace
 
 using namespace chip;
@@ -99,17 +100,16 @@ CHIP_ERROR TransferInit::Parse(System::PacketBufferHandle aBuffer)
     uint32_t tmpUint32Value = 0; // Used for reading non-wide length and offset fields
     uint8_t * bufStart      = aBuffer->Start();
     Reader bufReader(bufStart, aBuffer->DataLength());
-    BitFlags<RangeControlFlags> rangeCtlFlags;
 
-    SuccessOrExit(bufReader.Read8(&proposedTransferCtl).Read8(rangeCtlFlags.RawStorage()).Read16(&MaxBlockSize).StatusCode());
+    SuccessOrExit(bufReader.Read8(&proposedTransferCtl).Read8(mRangeCtlFlags.RawStorage()).Read16(&MaxBlockSize).StatusCode());
 
     Version = proposedTransferCtl & kVersionMask;
     TransferCtlOptions.SetRaw(static_cast<uint8_t>(proposedTransferCtl & ~kVersionMask));
 
     StartOffset = 0;
-    if (rangeCtlFlags.Has(RangeControlFlags::kStartOffset))
+    if (mRangeCtlFlags.Has(RangeControlFlags::kStartOffset))
     {
-        if (rangeCtlFlags.Has(RangeControlFlags::kWiderange))
+        if (mRangeCtlFlags.Has(RangeControlFlags::kWiderange))
         {
             SuccessOrExit(bufReader.Read64(&StartOffset).StatusCode());
         }
@@ -121,9 +121,9 @@ CHIP_ERROR TransferInit::Parse(System::PacketBufferHandle aBuffer)
     }
 
     MaxLength = 0;
-    if (rangeCtlFlags.Has(RangeControlFlags::kDefLen))
+    if (mRangeCtlFlags.Has(RangeControlFlags::kDefLen))
     {
-        if (rangeCtlFlags.Has(RangeControlFlags::kWiderange))
+        if (mRangeCtlFlags.Has(RangeControlFlags::kWiderange))
         {
             SuccessOrExit(bufReader.Read64(&MaxLength).StatusCode());
         }
@@ -166,6 +166,34 @@ size_t TransferInit::MessageSize() const
     return WriteToBuffer(emptyBuf).Needed();
 }
 
+#if CHIP_AUTOMATION_LOGGING
+void TransferInit::LogMessage(bdx::MessageType messageType) const
+{
+    char fd[kMaxFileDesignatorLen];
+    snprintf(fd, sizeof(fd), "%s", FileDesignator);
+
+    switch (messageType)
+    {
+    case MessageType::SendInit:
+        ChipLogAutomation("SendInit");
+        break;
+    case MessageType::ReceiveInit:
+        ChipLogAutomation("ReceiveInit");
+        break;
+    default:
+        break;
+    }
+
+    ChipLogAutomation("  Proposed Transfer Control: 0x%X", static_cast<unsigned>(TransferCtlOptions.Raw() | Version));
+    ChipLogAutomation("  Range Control: 0x%X", static_cast<unsigned>(mRangeCtlFlags.Raw()));
+    ChipLogAutomation("  Proposed Max Block Size: %" PRIu16, MaxBlockSize);
+    ChipLogAutomation("  Start Offset: 0x" ChipLogFormatX64, ChipLogValueX64(StartOffset));
+    ChipLogAutomation("  Proposed Max Length: 0x" ChipLogFormatX64, ChipLogValueX64(MaxLength));
+    ChipLogAutomation("  File Designator Length: %" PRIu16, FileDesLength);
+    ChipLogAutomation("  File Designator: %s", fd);
+}
+#endif // CHIP_AUTOMATION_LOGGING
+
 bool TransferInit::operator==(const TransferInit & another) const
 {
     if ((MetadataLength != another.MetadataLength) || (FileDesLength != another.FileDesLength))
@@ -246,6 +274,16 @@ size_t SendAccept::MessageSize() const
     return WriteToBuffer(emptyBuf).Needed();
 }
 
+#if CHIP_AUTOMATION_LOGGING
+void SendAccept::LogMessage(bdx::MessageType messageType) const
+{
+    (void) messageType;
+    ChipLogAutomation("SendAccept");
+    ChipLogAutomation("  Transfer Control: 0x%X", static_cast<unsigned>(TransferCtlFlags.Raw() | Version));
+    ChipLogAutomation("  Max Block Size: %" PRIu16, MaxBlockSize);
+}
+#endif // CHIP_AUTOMATION_LOGGING
+
 bool SendAccept::operator==(const SendAccept & another) const
 {
     if (MetadataLength != another.MetadataLength)
@@ -317,19 +355,18 @@ CHIP_ERROR ReceiveAccept::Parse(System::PacketBufferHandle aBuffer)
     uint32_t tmpUint32Value = 0; // Used for reading non-wide length and offset fields
     uint8_t * bufStart      = aBuffer->Start();
     Reader bufReader(bufStart, aBuffer->DataLength());
-    BitFlags<RangeControlFlags> rangeCtlFlags;
 
-    SuccessOrExit(bufReader.Read8(&transferCtl).Read8(rangeCtlFlags.RawStorage()).Read16(&MaxBlockSize).StatusCode());
+    SuccessOrExit(bufReader.Read8(&transferCtl).Read8(mRangeCtlFlags.RawStorage()).Read16(&MaxBlockSize).StatusCode());
 
     Version = transferCtl & kVersionMask;
 
     // Only one of these values should be set. It is up to the caller to verify this.
     TransferCtlFlags.SetRaw(static_cast<uint8_t>(transferCtl & ~kVersionMask));
 
     StartOffset = 0;
-    if (rangeCtlFlags.Has(RangeControlFlags::kStartOffset))
+    if (mRangeCtlFlags.Has(RangeControlFlags::kStartOffset))
     {
-        if (rangeCtlFlags.Has(RangeControlFlags::kWiderange))
+        if (mRangeCtlFlags.Has(RangeControlFlags::kWiderange))
         {
             SuccessOrExit(bufReader.Read64(&StartOffset).StatusCode());
         }
@@ -341,9 +378,9 @@ CHIP_ERROR ReceiveAccept::Parse(System::PacketBufferHandle aBuffer)
     }
 
     Length = 0;
-    if (rangeCtlFlags.Has(RangeControlFlags::kDefLen))
+    if (mRangeCtlFlags.Has(RangeControlFlags::kDefLen))
     {
-        if (rangeCtlFlags.Has(RangeControlFlags::kWiderange))
+        if (mRangeCtlFlags.Has(RangeControlFlags::kWiderange))
         {
             SuccessOrExit(bufReader.Read64(&Length).StatusCode());
         }
@@ -380,6 +417,18 @@ size_t ReceiveAccept::MessageSize() const
     return WriteToBuffer(emptyBuf).Needed();
 }
 
+#if CHIP_AUTOMATION_LOGGING
+void ReceiveAccept::LogMessage(bdx::MessageType messageType) const
+{
+    (void) messageType;
+    ChipLogAutomation("ReceiveAccept");
+    ChipLogAutomation("  Transfer Control: 0x%X", TransferCtlFlags.Raw() | Version);
+    ChipLogAutomation("  Range Control: 0x%X", mRangeCtlFlags.Raw());
+    ChipLogAutomation("  Max Block Size: %" PRIu16, MaxBlockSize);
+    ChipLogAutomation("  Length: 0x" ChipLogFormatX64, ChipLogValueX64(Length));
+}
+#endif // CHIP_AUTOMATION_LOGGING
+
 bool ReceiveAccept::operator==(const ReceiveAccept & another) const
 {
     if (MetadataLength != another.MetadataLength)
@@ -423,6 +472,28 @@ bool CounterMessage::operator==(const CounterMessage & another) const
     return (BlockCounter == another.BlockCounter);
 }
 
+#if CHIP_AUTOMATION_LOGGING
+void CounterMessage::LogMessage(bdx::MessageType messageType) const
+{
+    switch (messageType)
+    {
+    case MessageType::BlockQuery:
+        ChipLogAutomation("BlockQuery");
+        break;
+    case MessageType::BlockAck:
+        ChipLogAutomation("BlockAck");
+        break;
+    case MessageType::BlockAckEOF:
+        ChipLogAutomation("BlockAckEOF");
+        break;
+    default:
+        break;
+    }
+
+    ChipLogAutomation("  Block Counter: %" PRIu32, BlockCounter);
+}
+#endif // CHIP_AUTOMATION_LOGGING
+
 // WARNING: this function should never return early, since MessageSize() relies on it to calculate
 // the size of the message (even if the message is incomplete or filled out incorrectly).
 Encoding::LittleEndian::BufferWriter & DataBlock::WriteToBuffer(Encoding::LittleEndian::BufferWriter & aBuffer) const
@@ -469,6 +540,26 @@ size_t DataBlock::MessageSize() const
     return WriteToBuffer(emptyBuf).Needed();
 }
 
+#if CHIP_AUTOMATION_LOGGING
+void DataBlock::LogMessage(bdx::MessageType messageType) const
+{
+    switch (messageType)
+    {
+    case MessageType::Block:
+        ChipLogAutomation("Block");
+        break;
+    case MessageType::BlockEOF:
+        ChipLogAutomation("BlockEOF");
+        break;
+    default:
+        break;
+    }
+
+    ChipLogAutomation("  Block Counter: %" PRIu32, BlockCounter);
+    ChipLogAutomation("  Data Length: %zu", DataLength);
+}
+#endif // CHIP_AUTOMATION_LOGGING
+
 bool DataBlock::operator==(const DataBlock & another) const
 {
     if (DataLength != another.DataLength)