From 37618722da11b5df296d9963a6f678efb1dbef04 Mon Sep 17 00:00:00 2001 From: Boris Zbarsky Date: Tue, 21 Sep 2021 16:06:03 -0400 Subject: [PATCH] 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 | 4 ++-- src/app/InteractionModelEngine.cpp | 3 ++- src/app/ReadClient.cpp | 4 ++-- src/app/ReadHandler.cpp | 4 ++-- src/app/WriteClient.cpp | 4 ++-- src/controller/CHIPDeviceController.cpp | 3 ++- src/lib/support/logging/CHIPLogging.h | 15 +++++++++++++++ src/messaging/ExchangeContext.cpp | 16 ++++++++-------- src/messaging/ExchangeMessageDispatch.cpp | 8 +++++--- src/messaging/ExchangeMgr.cpp | 11 +++++++---- src/protocols/bdx/TransferFacilitator.cpp | 2 +- src/transport/SecureSessionMgr.cpp | 8 ++++---- 12 files changed, 52 insertions(+), 30 deletions(-) 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()); }