Improve various logging to make it easier to undestand what happened. (…

…#9868)

* Improve various logging to make it easier to undestand what happened.

Specific changes:

1) Consistent formatting for message counters.
2) Consistent formatting for message types.
3) Consistent formatting of protocol ids.
4) Include the exchange context in various logging so we know which
   actual interaction/exchange is involved.
5) Include message counters in more places so we know which message is
   involved.

* Address review comments

src/lib/support/logging/CHIPLogging.h

@@ -334,9 +334,28 @@ bool IsCategoryEnabled(uint8_t category);
 #define ChipLogValueExchangeId(id, isInitiator) id, ((isInitiator) ? 'i' : 'r')
 #define ChipLogFormatExchange ChipLogFormatExchangeId
 #define ChipLogValueExchange(ec) ChipLogValueExchangeId((ec)->GetExchangeId(), (ec)->IsInitiator())
-// A header's initiator boolean is the inverse of the exchange's.
-#define ChipLogValueExchangeIdFromHeader(payloadHeader)                                                                            \
+#define ChipLogValueExchangeIdFromSentHeader(payloadHeader)                                                                        \
+    ChipLogValueExchangeId((payloadHeader).GetExchangeID(), (payloadHeader).IsInitiator())
+// A received header's initiator boolean is the inverse of the exchange's.
+#define ChipLogValueExchangeIdFromReceivedHeader(payloadHeader)                                                                    \
     ChipLogValueExchangeId((payloadHeader).GetExchangeID(), !(payloadHeader).IsInitiator())
 
+/**
+ * Logging helpers for protocol ids.  A protocol id is a (vendor-id,
+ * protocol-id) pair.
+ */
+#define ChipLogFormatProtocolId "(%" PRIu16 ", %" PRIu16 ")"
+#define ChipLogValueProtocolId(id) (id).GetVendorId(), (id).GetProtocolId()
+
+/**
+ * Logging helpers for message counters, so we format them consistently.
+ */
+#define ChipLogFormatMessageCounter "%" PRIu32
+
+/**
+ * Logging helpers for message types, so we format them consistently.
+ */
+#define ChipLogFormatMessageType "0x%" PRIx8
+
 } // namespace Logging
 } // namespace chip

src/messaging/ExchangeContext.cpp

@@ -50,10 +50,13 @@ using namespace chip::System;
 namespace chip {
 namespace Messaging {
 
-static void DefaultOnMessageReceived(ExchangeContext * ec, Protocols::Id protocolId, uint8_t msgType, PacketBufferHandle && payload)
+static void DefaultOnMessageReceived(ExchangeContext * ec, Protocols::Id protocolId, uint8_t msgType, uint32_t messageCounter,
+                                     PacketBufferHandle && payload)
 {
-    ChipLogError(ExchangeManager, "Dropping unexpected message %08" PRIX32 ":%d " ChipLogFormatExchange,
-                 protocolId.ToFullyQualifiedSpecForm(), msgType, ChipLogValueExchange(ec));
+    ChipLogError(ExchangeManager,
+                 "Dropping unexpected message of type " ChipLogFormatMessageType " with protocolId " ChipLogFormatProtocolId
+                 " and MessageCounter:" ChipLogFormatMessageCounter " on exchange " ChipLogFormatExchange,
+                 msgType, ChipLogValueProtocolId(protocolId), messageCounter, ChipLogValueExchange(ec));
 }
 
 bool ExchangeContext::IsInitiator() const
@@ -459,7 +462,8 @@ CHIP_ERROR ExchangeContext::HandleMessage(uint32_t messageCounter, const Payload
     }
     else
     {
-        DefaultOnMessageReceived(this, payloadHeader.GetProtocolID(), payloadHeader.GetMessageType(), std::move(msgBuf));
+        DefaultOnMessageReceived(this, payloadHeader.GetProtocolID(), payloadHeader.GetMessageType(), messageCounter,
+                                 std::move(msgBuf));
         return CHIP_NO_ERROR;
     }
 }

src/messaging/ExchangeMessageDispatch.cpp

@@ -58,7 +58,8 @@ CHIP_ERROR ExchangeMessageDispatch::SendMessage(SessionHandle session, uint16_t
         if (!payloadHeader.HasMessageType(Protocols::SecureChannel::MsgType::StandaloneAck))
         {
             ChipLogDetail(ExchangeManager,
-                          "Piggybacking Ack for MessageCounter:%08" PRIX32 " on exchange: " ChipLogFormatExchangeId,
+                          "Piggybacking Ack for MessageCounter:" ChipLogFormatMessageCounter
+                          " on exchange: " ChipLogFormatExchangeId,
                           payloadHeader.GetAckMessageCounter().Value(), ChipLogValueExchangeId(exchangeId, isInitiator));
         }
 #endif

src/messaging/ExchangeMgr.cpp

@@ -201,11 +201,11 @@ void ExchangeManager::OnMessageReceived(const PacketHeader & packetHeader, const
 {
     UnsolicitedMessageHandler * matchingUMH = nullptr;
 
-    ChipLogProgress(
-        ExchangeManager,
-        "Received message of type 0x%02x with vendorId 0x%04x and protocolId 0x%04x on exchange " ChipLogFormatExchangeId,
-        payloadHeader.GetMessageType(), payloadHeader.GetProtocolID().GetVendorId(), payloadHeader.GetProtocolID().GetProtocolId(),
-        ChipLogValueExchangeIdFromHeader(payloadHeader));
+    ChipLogProgress(ExchangeManager,
+                    "Received message of type " ChipLogFormatMessageType " with protocolId " ChipLogFormatProtocolId
+                    " and MessageCounter:" ChipLogFormatMessageCounter " on exchange " ChipLogFormatExchangeId,
+                    payloadHeader.GetMessageType(), ChipLogValueProtocolId(payloadHeader.GetProtocolID()),
+                    packetHeader.GetMessageCounter(), ChipLogValueExchangeIdFromReceivedHeader(payloadHeader));
 
     MessageFlags msgFlags;
     if (isDuplicate == DuplicateMessage::Yes)

src/messaging/ReliableMessageContext.cpp

@@ -125,7 +125,10 @@ CHIP_ERROR ReliableMessageContext::FlushAcks()
         if (err == CHIP_NO_ERROR)
         {
 #if !defined(NDEBUG)
-            ChipLogDetail(ExchangeManager, "Flushed pending ack for MessageCounter:%08" PRIX32, mPendingPeerAckMessageCounter);
+            ChipLogDetail(ExchangeManager,
+                          "Flushed pending ack for MessageCounter:" ChipLogFormatMessageCounter
+                          " on exchange " ChipLogFormatExchange,
+                          mPendingPeerAckMessageCounter, ChipLogValueExchange(GetExchangeContext()));
 #endif
         }
     }
@@ -165,15 +168,20 @@ CHIP_ERROR ReliableMessageContext::HandleRcvdAck(uint32_t ackMessageCounter)
     if (!GetReliableMessageMgr()->CheckAndRemRetransTable(this, ackMessageCounter))
     {
 #if !defined(NDEBUG)
-        ChipLogError(ExchangeManager, "CHIP MessageCounter:%08" PRIX32 " not in RetransTable", ackMessageCounter);
+        ChipLogError(ExchangeManager,
+                     "CHIP MessageCounter:" ChipLogFormatMessageCounter " not in RetransTable on exchange " ChipLogFormatExchange,
+                     ackMessageCounter, ChipLogValueExchange(GetExchangeContext()));
 #endif
         err = CHIP_ERROR_INVALID_ACK_MESSAGE_COUNTER;
         // Optionally call an application callback with this error.
     }
     else
     {
 #if !defined(NDEBUG)
-        ChipLogDetail(ExchangeManager, "Removed CHIP MessageCounter:%08" PRIX32 " from RetransTable", ackMessageCounter);
+        ChipLogDetail(ExchangeManager,
+                      "Removed CHIP MessageCounter:" ChipLogFormatMessageCounter
+                      " from RetransTable on exchange " ChipLogFormatExchange,
+                      ackMessageCounter, ChipLogValueExchange(GetExchangeContext()));
 #endif
     }
 
@@ -206,7 +214,10 @@ CHIP_ERROR ReliableMessageContext::HandleNeedsAckInner(uint32_t messageCounter,
     if (messageFlags.Has(MessageFlagValues::kDuplicateMessage))
     {
 #if !defined(NDEBUG)
-        ChipLogDetail(ExchangeManager, "Forcing tx of solitary ack for duplicate MessageCounter:%08" PRIX32, messageCounter);
+        ChipLogDetail(ExchangeManager,
+                      "Forcing tx of solitary ack for duplicate MessageCounter:" ChipLogFormatMessageCounter
+                      " on exchange " ChipLogFormatExchange,
+                      messageCounter, ChipLogValueExchange(GetExchangeContext()));
 #endif
         // Is there pending ack for a different message counter.
         bool wasAckPending = IsAckPending() && mPendingPeerAckMessageCounter != messageCounter;
@@ -235,8 +246,10 @@ CHIP_ERROR ReliableMessageContext::HandleNeedsAckInner(uint32_t messageCounter,
         if (IsAckPending())
         {
 #if !defined(NDEBUG)
-            ChipLogDetail(ExchangeManager, "Pending ack queue full; forcing tx of solitary ack for MessageCounter:%08" PRIX32,
-                          mPendingPeerAckMessageCounter);
+            ChipLogDetail(ExchangeManager,
+                          "Pending ack queue full; forcing tx of solitary ack for MessageCounter:" ChipLogFormatMessageCounter
+                          " on exchange " ChipLogFormatExchange,
+                          mPendingPeerAckMessageCounter, ChipLogValueExchange(GetExchangeContext()));
 #endif
             // Send the Ack for the currently pending Ack in a SecureChannel::StandaloneAck message.
             ReturnErrorOnFailure(SendStandaloneAckMessage());
@@ -262,20 +275,27 @@ CHIP_ERROR ReliableMessageContext::SendStandaloneAckMessage()
 
     // Send the null message
 #if !defined(NDEBUG)
-    ChipLogDetail(ExchangeManager, "Sending Standalone Ack for MessageCounter:%08" PRIX32, mPendingPeerAckMessageCounter);
+    ChipLogDetail(ExchangeManager,
+                  "Sending Standalone Ack for MessageCounter:" ChipLogFormatMessageCounter " on exchange " ChipLogFormatExchange,
+                  mPendingPeerAckMessageCounter, ChipLogValueExchange(GetExchangeContext()));
 #endif
 
     CHIP_ERROR err = GetExchangeContext()->SendMessage(Protocols::SecureChannel::MsgType::StandaloneAck, std::move(msgBuf),
                                                        BitFlags<SendMessageFlags>{ SendMessageFlags::kNoAutoRequestAck });
     if (IsSendErrorNonCritical(err))
     {
-        ChipLogError(ExchangeManager, "Non-crit err %" CHIP_ERROR_FORMAT " sending solitary ack", err.Format());
+        ChipLogError(ExchangeManager,
+                     "Non-crit err %" CHIP_ERROR_FORMAT " sending solitary ack for MessageCounter:" ChipLogFormatMessageCounter
+                     " on exchange " ChipLogFormatExchange,
+                     err.Format(), mPendingPeerAckMessageCounter, ChipLogValueExchange(GetExchangeContext()));
         return CHIP_NO_ERROR;
     }
     if (err != CHIP_NO_ERROR)
     {
-        ChipLogError(ExchangeManager, "Failed to send Solitary ack for MessageCounter:%08" PRIX32 ":%" CHIP_ERROR_FORMAT,
-                     mPendingPeerAckMessageCounter, err.Format());
+        ChipLogError(ExchangeManager,
+                     "Failed to send Solitary ack for MessageCounter:" ChipLogFormatMessageCounter
+                     " on exchange " ChipLogFormatExchange ":%" CHIP_ERROR_FORMAT,
+                     mPendingPeerAckMessageCounter, ChipLogValueExchange(GetExchangeContext()), err.Format());
     }
 
     return err;

src/messaging/ReliableMessageMgr.cpp

@@ -88,8 +88,10 @@ void ReliableMessageMgr::TicklessDebugDumpRetransTable(const char * log)
     {
         if (entry.rc)
         {
-            ChipLogDetail(ExchangeManager, "EC:%04" PRIX16 " MessageCounter:%08" PRIX32 " NextRetransTimeCtr:%04" PRIX16, entry.rc,
-                          entry.messageCounter, entry.nextRetransTimeTick);
+            ChipLogDetail(ExchangeManager,
+                          "EC:" ChipLogFormatExchange " MessageCounter:" ChipLogFormatMessageCounter
+                          " NextRetransTimeCtr:%04" PRIX16,
+                          ChipLogValueExchange(entry.rc->GetExchangeContext()), entry.messageCounter, entry.nextRetransTimeTick);
         }
     }
 }
@@ -150,8 +152,11 @@ void ReliableMessageMgr::ExecuteActions()
         {
             err = CHIP_ERROR_MESSAGE_NOT_ACKNOWLEDGED;
 
-            ChipLogError(ExchangeManager, "Failed to Send CHIP MessageCounter:%08" PRIX32 " sendCount: %" PRIu8 " max retries: %d",
-                         messageCounter, sendCount, CHIP_CONFIG_RMP_DEFAULT_MAX_RETRANS);
+            ChipLogError(ExchangeManager,
+                         "Failed to Send CHIP MessageCounter:" ChipLogFormatMessageCounter " on exchange " ChipLogFormatExchange
+                         " sendCount: %" PRIu8 " max retries: %d",
+                         messageCounter, ChipLogValueExchange(rc->GetExchangeContext()), sendCount,
+                         CHIP_CONFIG_RMP_DEFAULT_MAX_RETRANS);
 
             // Remove from Table
             ClearRetransTable(entry);
@@ -166,7 +171,10 @@ void ReliableMessageMgr::ExecuteActions()
             // If the retransmission was successful, update the passive timer
             entry.nextRetransTimeTick = static_cast<uint16_t>(rc->GetActiveRetransmitTimeoutTick());
 #if !defined(NDEBUG)
-            ChipLogDetail(ExchangeManager, "Retransmit MessageCounter:%08" PRIX32 " Send Cnt %d", messageCounter, entry.sendCount);
+            ChipLogDetail(ExchangeManager,
+                          "Retransmitted MessageCounter:" ChipLogFormatMessageCounter " on exchange " ChipLogFormatExchange
+                          " Send Cnt %d",
+                          messageCounter, ChipLogValueExchange(rc->GetExchangeContext()), entry.sendCount);
 #endif
         }
     }
@@ -339,7 +347,10 @@ bool ReliableMessageMgr::CheckAndRemRetransTable(ReliableMessageContext * rc, ui
             ClearRetransTable(entry);
 
 #if !defined(NDEBUG)
-            ChipLogDetail(ExchangeManager, "Rxd Ack; Removing MessageCounter:%08" PRIX32 " from Retrans Table", ackMessageCounter);
+            ChipLogDetail(ExchangeManager,
+                          "Rxd Ack; Removing MessageCounter:" ChipLogFormatMessageCounter
+                          " from Retrans Table on exchange " ChipLogFormatExchange,
+                          ackMessageCounter, ChipLogValueExchange(rc->GetExchangeContext()));
 #endif
             return true;
         }
@@ -361,8 +372,10 @@ CHIP_ERROR ReliableMessageMgr::SendFromRetransTable(RetransTableEntry * entry)
     {
         // Using same error message for all errors to reduce code size.
         ChipLogError(ExchangeManager,
-                     "Crit-err %" CHIP_ERROR_FORMAT " when sending CHIP MessageCounter:%08" PRIX32 ", send tries: %d",
-                     CHIP_ERROR_INCORRECT_STATE.Format(), entry->retainedBuf.GetMessageCounter(), entry->sendCount);
+                     "Crit-err %" CHIP_ERROR_FORMAT " when sending CHIP MessageCounter:" ChipLogFormatMessageCounter
+                     " on exchange " ChipLogFormatExchange ", send tries: %d",
+                     CHIP_ERROR_INCORRECT_STATE.Format(), entry->retainedBuf.GetMessageCounter(),
+                     ChipLogValueExchange(rc->GetExchangeContext()), entry->sendCount);
         ClearRetransTable(*entry);
         return CHIP_ERROR_INCORRECT_STATE;
     }
@@ -379,8 +392,10 @@ CHIP_ERROR ReliableMessageMgr::SendFromRetransTable(RetransTableEntry * entry)
         // Remove from table
         // Using same error message for all errors to reduce code size.
         ChipLogError(ExchangeManager,
-                     "Crit-err %" CHIP_ERROR_FORMAT " when sending CHIP MessageCounter:%08" PRIX32 ", send tries: %d", err.Format(),
-                     entry->retainedBuf.GetMessageCounter(), entry->sendCount);
+                     "Crit-err %" CHIP_ERROR_FORMAT " when sending CHIP MessageCounter:" ChipLogFormatMessageCounter
+                     " on exchange " ChipLogFormatExchange ", send tries: %d",
+                     err.Format(), entry->retainedBuf.GetMessageCounter(), ChipLogValueExchange(rc->GetExchangeContext()),
+                     entry->sendCount);
 
         ClearRetransTable(*entry);
     }

src/protocols/bdx/TransferFacilitator.cpp

@@ -37,8 +37,8 @@ CHIP_ERROR TransferFacilitator::OnMessageReceived(chip::Messaging::ExchangeConte
         mExchangeCtx = ec;
     }
 
-    ChipLogDetail(BDX, "%s: message 0x%x protocol %u", __FUNCTION__, static_cast<uint8_t>(payloadHeader.GetMessageType()),
-                  payloadHeader.GetProtocolID().GetProtocolId());
+    ChipLogDetail(BDX, "%s: message " ChipLogFormatMessageType " protocol " ChipLogFormatProtocolId, __FUNCTION__,
+                  payloadHeader.GetMessageType(), ChipLogValueProtocolId(payloadHeader.GetProtocolID()));
     CHIP_ERROR err = mTransfer.HandleMessageReceived(payloadHeader, std::move(payload), System::Clock::GetMonotonicMilliseconds());
     if (err != CHIP_NO_ERROR)
     {

src/transport/SecureMessageCodec.cpp

@@ -68,8 +68,6 @@ CHIP_ERROR Encode(Transport::PeerConnectionState * state, PayloadHeader & payloa
     VerifyOrReturnError(CanCastTo<uint16_t>(totalLen + taglen), CHIP_ERROR_INTERNAL);
     msgBuf->SetDataLength(static_cast<uint16_t>(totalLen + taglen));
 
-    ChipLogDetail(Inet, "Secure message was encrypted: Msg ID %" PRIu32, messageCounter);
-
     ReturnErrorOnFailure(counter.Advance());
     return CHIP_NO_ERROR;
 }