Add clearer logging of exchange ids. (#9861)

Exchange ids are scoped to the initiator, so a bare exchange id does
not uniquely identify he exchange.  For now, just log with each id
whether we are the initiator or the responder, which should at least
help disambiguate that.

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());
  }