Add clearer logging of exchange ids.

src/app/CommandSender.cpp

@@ -100,8 +100,8 @@ CHIP_ERROR CommandSender::OnMessageReceived(Messaging::ExchangeContext * apExcha
 
 void CommandSender::OnResponseTimeout(Messaging::ExchangeContext * apExchangeContext)
 {
-    ChipLogProgress(DataManagement, "Time out! failed to receive invoke command response from Exchange: %d",
-                    apExchangeContext->GetExchangeId());
+    ChipLogProgress(DataManagement, "Time out! failed to receive invoke command response from Exchange: " ChipLogFormatExchange,
+                    ChipLogValueExchange(apExchangeContext));
 
     if (mpDelegate != nullptr)
     {

src/app/InteractionModelEngine.cpp

@@ -348,7 +348,8 @@ CHIP_ERROR InteractionModelEngine::OnMessageReceived(Messaging::ExchangeContext
 
 void InteractionModelEngine::OnResponseTimeout(Messaging::ExchangeContext * ec)
 {
-    ChipLogProgress(InteractionModel, "Time out! failed to receive echo response from Exchange: %d", ec->GetExchangeId());
+    ChipLogProgress(InteractionModel, "Time out! failed to receive echo response from Exchange: " ChipLogFormatExchange,
+                    ChipLogValueExchange(ec));
 }
 
 CHIP_ERROR InteractionModelEngine::SendReadRequest(ReadPrepareParams & aReadPrepareParams, uint64_t aAppIdentifier)

src/app/ReadClient.cpp

@@ -449,8 +449,8 @@ CHIP_ERROR ReadClient::ProcessReportData(System::PacketBufferHandle && aPayload)
 
 void ReadClient::OnResponseTimeout(Messaging::ExchangeContext * apExchangeContext)
 {
-    ChipLogProgress(DataManagement, "Time out! failed to receive report data from Exchange: %d",
-                    apExchangeContext->GetExchangeId());
+    ChipLogProgress(DataManagement, "Time out! failed to receive report data from Exchange: " ChipLogFormatExchange,
+                    ChipLogValueExchange(apExchangeContext));
     ShutdownInternal(CHIP_ERROR_TIMEOUT);
 }
 

src/app/ReadHandler.cpp

@@ -233,8 +233,8 @@ CHIP_ERROR ReadHandler::OnUnknownMsgType(Messaging::ExchangeContext * apExchange
 
 void ReadHandler::OnResponseTimeout(Messaging::ExchangeContext * apExchangeContext)
 {
-    ChipLogProgress(DataManagement, "Time out! failed to receive status response from Exchange: %d",
-                    apExchangeContext->GetExchangeId());
+    ChipLogProgress(DataManagement, "Time out! failed to receive status response from Exchange: " ChipLogFormatExchange,
+                    ChipLogValueExchange(apExchangeContext));
     Shutdown();
 }
 

src/app/WriteClient.cpp

@@ -315,8 +315,8 @@ CHIP_ERROR WriteClient::OnMessageReceived(Messaging::ExchangeContext * apExchang
 
 void WriteClient::OnResponseTimeout(Messaging::ExchangeContext * apExchangeContext)
 {
-    ChipLogProgress(DataManagement, "Time out! failed to receive write response from Exchange: %d",
-                    apExchangeContext->GetExchangeId());
+    ChipLogProgress(DataManagement, "Time out! failed to receive write response from Exchange: " ChipLogFormatExchange,
+                    ChipLogValueExchange(apExchangeContext));
 
     if (mpDelegate != nullptr)
     {

src/controller/CHIPDeviceController.cpp

@@ -503,7 +503,8 @@ CHIP_ERROR DeviceController::OnMessageReceived(Messaging::ExchangeContext * ec,
 
 void DeviceController::OnResponseTimeout(Messaging::ExchangeContext * ec)
 {
-    ChipLogProgress(Controller, "Time out! failed to receive response from Exchange: %p", ec);
+    ChipLogProgress(Controller, "Time out! failed to receive response from Exchange: " ChipLogFormatExchange,
+                    ChipLogValueExchange(ec));
 }
 
 void DeviceController::OnNewConnection(SessionHandle session, Messaging::ExchangeManager * mgr)

src/lib/support/logging/CHIPLogging.h

@@ -323,5 +323,20 @@ bool IsCategoryEnabled(uint8_t category);
  */
 #define ChipLogValueMEI(aValue) static_cast<uint16_t>(aValue >> 16), static_cast<uint16_t>(aValue)
 
+/**
+ * Logging helpers for exchanges.  For now just log the exchange id and whether
+ * it's an initiator or responder, but eventually we may want to log the peer
+ * node id as well (especially for the responder case).  Some callsites only
+ * have the exchange id and initiator/responder boolean, not an actual exchange,
+ * so we want to have a helper for that case too.
+ */
+#define ChipLogFormatExchangeId "%" PRIu16 "%c"
+#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)                                                                            \
+    ChipLogValueExchangeId((payloadHeader).GetExchangeID(), !(payloadHeader).IsInitiator())
+
 } // namespace Logging
 } // namespace chip

src/messaging/ExchangeContext.cpp

@@ -52,8 +52,8 @@ namespace Messaging {
 
 static void DefaultOnMessageReceived(ExchangeContext * ec, Protocols::Id protocolId, uint8_t msgType, PacketBufferHandle && payload)
 {
-    ChipLogError(ExchangeManager, "Dropping unexpected message %08" PRIX32 ":%d %04" PRIX16, protocolId.ToFullyQualifiedSpecForm(),
-                 msgType, ec->GetExchangeId());
+    ChipLogError(ExchangeManager, "Dropping unexpected message %08" PRIX32 ":%d " ChipLogFormatExchange,
+                 protocolId.ToFullyQualifiedSpecForm(), msgType, ChipLogValueExchange(ec));
 }
 
 bool ExchangeContext::IsInitiator() const
@@ -191,8 +191,8 @@ void ExchangeContext::Close()
     VerifyOrDie(mExchangeMgr != nullptr && GetReferenceCount() > 0);
 
 #if defined(CHIP_EXCHANGE_CONTEXT_DETAIL_LOGGING)
-    ChipLogDetail(ExchangeManager, "ec id: %d [%04" PRIX16 "], %s", (this - mExchangeMgr->mContextPool.begin()), mExchangeId,
-                  __func__);
+    ChipLogDetail(ExchangeManager, "ec id: %d [" ChipLogFormatExchange "], %s", (this - mExchangeMgr->mContextPool.begin()),
+                  ChipLogValueExchange(this), __func__);
 #endif
 
     DoClose(false);
@@ -208,8 +208,8 @@ void ExchangeContext::Abort()
     VerifyOrDie(mExchangeMgr != nullptr && GetReferenceCount() > 0);
 
 #if defined(CHIP_EXCHANGE_CONTEXT_DETAIL_LOGGING)
-    ChipLogDetail(ExchangeManager, "ec id: %d [%04" PRIX16 "], %s", (this - mExchangeMgr->mContextPool.begin()), mExchangeId,
-                  __func__);
+    ChipLogDetail(ExchangeManager, "ec id: %d [" ChipLogFormatExchange "], %s", (this - mExchangeMgr->mContextPool.begin()),
+                  ChipLogValueExchange(this), __func__);
 #endif
 
     DoClose(true);
@@ -254,7 +254,7 @@ ExchangeContext::ExchangeContext(ExchangeManager * em, uint16_t ExchangeId, Sess
     SetAutoRequestAck(true);
 
 #if defined(CHIP_EXCHANGE_CONTEXT_DETAIL_LOGGING)
-    ChipLogDetail(ExchangeManager, "ec++ id: %d", ExchangeId);
+    ChipLogDetail(ExchangeManager, "ec++ id: " ChipLogFormatExchange, ChipLogValueExchange(this));
 #endif
     SYSTEM_STATS_INCREMENT(chip::System::Stats::kExchangeMgr_NumContexts);
 }
@@ -284,7 +284,7 @@ ExchangeContext::~ExchangeContext()
     }
 
 #if defined(CHIP_EXCHANGE_CONTEXT_DETAIL_LOGGING)
-    ChipLogDetail(ExchangeManager, "ec-- id: %d", mExchangeId);
+    ChipLogDetail(ExchangeManager, "ec-- id: " ChipLogFormatExchange, ChipLogValueExchange(this));
 #endif
     SYSTEM_STATS_DECREMENT(chip::System::Stats::kExchangeMgr_NumContexts);
 }

src/messaging/ExchangeMessageDispatch.cpp

@@ -57,8 +57,9 @@ CHIP_ERROR ExchangeMessageDispatch::SendMessage(SessionHandle session, uint16_t
 #if !defined(NDEBUG)
         if (!payloadHeader.HasMessageType(Protocols::SecureChannel::MsgType::StandaloneAck))
         {
-            ChipLogDetail(ExchangeManager, "Piggybacking Ack for MessageCounter:%08" PRIX32 " with msg",
-                          payloadHeader.GetAckMessageCounter().Value());
+            ChipLogDetail(ExchangeManager,
+                          "Piggybacking Ack for MessageCounter:%08" PRIX32 " on exchange: " ChipLogFormatExchangeId,
+                          payloadHeader.GetAckMessageCounter().Value(), ChipLogValueExchangeId(exchangeId, isInitiator));
         }
 #endif
     }
@@ -90,7 +91,8 @@ CHIP_ERROR ExchangeMessageDispatch::SendMessage(SessionHandle session, uint16_t
             // This is typically a transient situation, so we pretend like this
             // packet drop happened somewhere on the network instead of inside
             // sendmsg and will just resend it in the normal MRP way later.
-            ChipLogError(ExchangeManager, "Ignoring ENOBUFS: %" CHIP_ERROR_FORMAT, err.Format());
+            ChipLogError(ExchangeManager, "Ignoring ENOBUFS: %" CHIP_ERROR_FORMAT " on exchange " ChipLogFormatExchangeId,
+                         err.Format(), ChipLogValueExchangeId(exchangeId, isInitiator));
             err = CHIP_NO_ERROR;
         }
         ReturnErrorOnFailure(err);

src/messaging/ExchangeMgr.cpp

@@ -201,9 +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 %d",
-                    payloadHeader.GetMessageType(), payloadHeader.GetProtocolID().GetVendorId(),
-                    payloadHeader.GetProtocolID().GetProtocolId(), payloadHeader.GetExchangeID());
+    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));
 
     MessageFlags msgFlags;
     if (isDuplicate == DuplicateMessage::Yes)
@@ -288,7 +290,8 @@ void ExchangeManager::OnMessageReceived(const PacketHeader & packetHeader, const
             return;
         }
 
-        ChipLogDetail(ExchangeManager, "ec id: %d, Delegate: 0x%p", ec->GetExchangeId(), ec->GetDelegate());
+        ChipLogDetail(ExchangeManager, "Handling via exchange: " ChipLogFormatExchange ", Delegate: 0x%p", ChipLogValueExchange(ec),
+                      ec->GetDelegate());
 
         if (ec->IsEncryptionRequired() != packetHeader.GetFlags().Has(Header::FlagValues::kEncryptedMessage))
         {

src/protocols/bdx/TransferFacilitator.cpp

@@ -56,7 +56,7 @@ CHIP_ERROR TransferFacilitator::OnMessageReceived(chip::Messaging::ExchangeConte
 
 void TransferFacilitator::OnResponseTimeout(Messaging::ExchangeContext * ec)
 {
-    ChipLogError(BDX, "%s, ec: %d", __FUNCTION__, ec->GetExchangeId());
+    ChipLogError(BDX, "%s, ec: " ChipLogFormatExchange, __FUNCTION__, ChipLogValueExchange(ec));
     mExchangeCtx = nullptr;
     mTransfer.Reset();
 }

src/transport/SecureSessionMgr.cpp

@@ -124,9 +124,9 @@ CHIP_ERROR SecureSessionMgr::PrepareMessage(SessionHandle session, PayloadHeader
 
         ChipLogProgress(Inet,
                         "Build %s message %p to 0x" ChipLogFormatX64 " of type %d and protocolId %" PRIu32
-                        " on exchange %d with MessageCounter %" PRIu32 ".",
+                        " on exchange " ChipLogFormatExchangeId " with MessageCounter %" PRIu32 ".",
                         "encrypted", &preparedMessage, ChipLogValueX64(state->GetPeerNodeId()), payloadHeader.GetMessageType(),
-                        payloadHeader.GetProtocolID().ToFullyQualifiedSpecForm(), payloadHeader.GetExchangeID(),
+                        payloadHeader.GetProtocolID().ToFullyQualifiedSpecForm(), ChipLogValueExchangeIdFromHeader(payloadHeader),
                         packetHeader.GetMessageCounter());
     }
     else
@@ -141,9 +141,9 @@ CHIP_ERROR SecureSessionMgr::PrepareMessage(SessionHandle session, PayloadHeader
 
         ChipLogProgress(Inet,
                         "Build %s message %p to 0x" ChipLogFormatX64 " of type %d and protocolId %" PRIu32
-                        " on exchange %d with MessageCounter %" PRIu32 ".",
+                        " on exchange " ChipLogFormatExchangeId " with MessageCounter %" PRIu32 ".",
                         "plaintext", &preparedMessage, ChipLogValueX64(kUndefinedNodeId), payloadHeader.GetMessageType(),
-                        payloadHeader.GetProtocolID().ToFullyQualifiedSpecForm(), payloadHeader.GetExchangeID(),
+                        payloadHeader.GetProtocolID().ToFullyQualifiedSpecForm(), ChipLogValueExchangeIdFromHeader(payloadHeader),
                         packetHeader.GetMessageCounter());
     }