diff --git a/src/app/CommandSender.cpp b/src/app/CommandSender.cpp index 90e7914448cb01..f7f549f6b54dae 100644 --- a/src/app/CommandSender.cpp +++ b/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) { diff --git a/src/app/InteractionModelEngine.cpp b/src/app/InteractionModelEngine.cpp index bda1188f806f47..bd481ad5201db3 100644 --- a/src/app/InteractionModelEngine.cpp +++ b/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) diff --git a/src/app/ReadClient.cpp b/src/app/ReadClient.cpp index 61f3e32328b165..4a13829b75f4cf 100644 --- a/src/app/ReadClient.cpp +++ b/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); } diff --git a/src/app/ReadHandler.cpp b/src/app/ReadHandler.cpp index e8c94a0c8292dd..d0526d1fe36107 100644 --- a/src/app/ReadHandler.cpp +++ b/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(); } diff --git a/src/app/WriteClient.cpp b/src/app/WriteClient.cpp index 0bdc867c964389..b4379efad33e25 100644 --- a/src/app/WriteClient.cpp +++ b/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) { diff --git a/src/controller/CHIPDeviceController.cpp b/src/controller/CHIPDeviceController.cpp index 87ec792bf8d5ec..35876116302b9f 100644 --- a/src/controller/CHIPDeviceController.cpp +++ b/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) diff --git a/src/lib/support/logging/CHIPLogging.h b/src/lib/support/logging/CHIPLogging.h index 833452d103ac57..a0bd7aa5919c03 100644 --- a/src/lib/support/logging/CHIPLogging.h +++ b/src/lib/support/logging/CHIPLogging.h @@ -323,5 +323,20 @@ bool IsCategoryEnabled(uint8_t category); */ #define ChipLogValueMEI(aValue) static_cast(aValue >> 16), static_cast(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 diff --git a/src/messaging/ExchangeContext.cpp b/src/messaging/ExchangeContext.cpp index 7428e23113935c..adac7a13267c5c 100644 --- a/src/messaging/ExchangeContext.cpp +++ b/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); } diff --git a/src/messaging/ExchangeMessageDispatch.cpp b/src/messaging/ExchangeMessageDispatch.cpp index fe7c260443269b..3bb55a9551b8c3 100644 --- a/src/messaging/ExchangeMessageDispatch.cpp +++ b/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); diff --git a/src/messaging/ExchangeMgr.cpp b/src/messaging/ExchangeMgr.cpp index 73869298434d24..2d0fb231e96d97 100644 --- a/src/messaging/ExchangeMgr.cpp +++ b/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)) { diff --git a/src/protocols/bdx/TransferFacilitator.cpp b/src/protocols/bdx/TransferFacilitator.cpp index 854e7cabbb93c5..3347fa4c0770e4 100644 --- a/src/protocols/bdx/TransferFacilitator.cpp +++ b/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(); } diff --git a/src/transport/SecureSessionMgr.cpp b/src/transport/SecureSessionMgr.cpp index bb15a85bb7e486..41103b38be6ddb 100644 --- a/src/transport/SecureSessionMgr.cpp +++ b/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()); }