From dad637561b0bee01982b71ab82d70874734e60d8 Mon Sep 17 00:00:00 2001 From: rgoliver Date: Thu, 24 Mar 2022 08:31:19 -0400 Subject: [PATCH] trace: Add tracing for prepared secure messages (#16565) - Add new traces for the prepared messages for send and receive. - Add handlers to pack the data into json. Note: This is only enabled when CHIP_CONFIG_TRANSPORT_TRACE is enabled, otherwise this is a no-op. --- examples/common/tracing/TraceHandlers.cpp | 72 +++++++++++++++++------ src/transport/SessionManager.cpp | 2 + src/transport/TraceMessage.h | 44 ++++++++++++-- 3 files changed, 96 insertions(+), 22 deletions(-) diff --git a/examples/common/tracing/TraceHandlers.cpp b/examples/common/tracing/TraceHandlers.cpp index fb131dd6d46fab..d0c54d07c7c7a1 100644 --- a/examples/common/tracing/TraceHandlers.cpp +++ b/examples/common/tracing/TraceHandlers.cpp @@ -214,9 +214,27 @@ std::string PayloadHeaderToJson(const PayloadHeader * payloadHeader) return jsonBody; } -bool SecureMessageSentHandler(const TraceEventFields & eventFields, TraceHandlerContext * context) +std::string PreparedSecureMessageDataToJson(const TracePreparedSecureMessageData * data, const std::string & peerAddressKey) { - if (eventFields.dataSize != sizeof(TraceSecureMessageSentData)) + const System::PacketBuffer * packetBuffer = data->packetBuffer->operator->(); + std::string jsonBody = "{"; + jsonBody += AsFirstJsonKey(peerAddressKey, AsJsonString(data->peerAddress)); + jsonBody += ", "; + jsonBody += AsFirstJsonKey("payload_size", std::to_string(packetBuffer->DataLength())); + jsonBody += ", "; + jsonBody += AsFirstJsonKey("payload_hex", AsJsonHexString(packetBuffer->Start(), packetBuffer->DataLength())); + jsonBody += ", "; + jsonBody += AsFirstJsonKey("buffer_ptr", std::to_string(reinterpret_cast(packetBuffer))); + jsonBody += "}"; + + return jsonBody; +} + +bool SecureMessageSentHandler(const TraceEventFields & eventFields, void * context) +{ + TraceHandlerContext * ourContext = reinterpret_cast(context); + if ((std::string{ eventFields.dataFormat } != kTraceMessageSentDataFormat) || + (eventFields.dataSize != sizeof(TraceSecureMessageSentData))) { return false; } @@ -232,7 +250,7 @@ bool SecureMessageSentHandler(const TraceEventFields & eventFields, TraceHandler jsonBody += AsFirstJsonKey("payload_hex", AsJsonHexString(eventData->packetPayload, eventData->packetSize)); jsonBody += "}"; - TraceOutput * sink = context->sink; + TraceOutput * sink = ourContext->sink; sink->StartEvent(std::string{ kTraceMessageEvent } + "." + kTraceMessageSentDataFormat); sink->AddField("json", jsonBody); sink->FinishEvent(); @@ -240,9 +258,11 @@ bool SecureMessageSentHandler(const TraceEventFields & eventFields, TraceHandler return true; } -bool SecureMessageReceivedHandler(const TraceEventFields & eventFields, TraceHandlerContext * context) +bool SecureMessageReceivedHandler(const TraceEventFields & eventFields, void * context) { - if (eventFields.dataSize != sizeof(TraceSecureMessageReceivedData)) + TraceHandlerContext * ourContext = reinterpret_cast(context); + if ((std::string{ eventFields.dataFormat } != kTraceMessageReceivedDataFormat) || + (eventFields.dataSize != sizeof(TraceSecureMessageReceivedData))) { return false; } @@ -261,7 +281,7 @@ bool SecureMessageReceivedHandler(const TraceEventFields & eventFields, TraceHan jsonBody += AsFirstJsonKey("payload_hex", AsJsonHexString(eventData->packetPayload, eventData->packetSize)); jsonBody += "}"; - TraceOutput * sink = context->sink; + TraceOutput * sink = ourContext->sink; sink->StartEvent(std::string{ kTraceMessageEvent } + "." + kTraceMessageReceivedDataFormat); sink->AddField("json", jsonBody); sink->FinishEvent(); @@ -271,25 +291,40 @@ bool SecureMessageReceivedHandler(const TraceEventFields & eventFields, TraceHan return true; } -// TODO: Framework this into a registry of handlers for different message types. -bool TraceDefaultHandler(const TraceEventFields & eventFields, void * context) +bool PreparedMessageSentHandler(const TraceEventFields & eventFields, void * context) { TraceHandlerContext * ourContext = reinterpret_cast(context); - if (ourContext == nullptr) + if ((std::string{ eventFields.dataFormat } != kTracePreparedMessageSentDataFormat) || + (eventFields.dataSize != sizeof(TracePreparedSecureMessageData))) { return false; } - if (std::string{ eventFields.dataFormat } == kTraceMessageSentDataFormat) - { - return SecureMessageSentHandler(eventFields, ourContext); - } - else if (std::string{ eventFields.dataFormat } == kTraceMessageReceivedDataFormat) + const auto * eventData = reinterpret_cast(eventFields.dataBuffer); + TraceOutput * sink = ourContext->sink; + sink->StartEvent(std::string{ kTraceMessageEvent } + "." + kTracePreparedMessageSentDataFormat); + sink->AddField("json", PreparedSecureMessageDataToJson(eventData, "destination")); + sink->FinishEvent(); + + return true; +} + +bool PreparedMessageReceivedHandler(const TraceEventFields & eventFields, void * context) +{ + TraceHandlerContext * ourContext = reinterpret_cast(context); + if ((std::string{ eventFields.dataFormat } != kTracePreparedMessageReceivedDataFormat) || + (eventFields.dataSize != sizeof(TracePreparedSecureMessageData))) { - return SecureMessageReceivedHandler(eventFields, ourContext); + return false; } - return false; + const auto * eventData = reinterpret_cast(eventFields.dataBuffer); + TraceOutput * sink = ourContext->sink; + sink->StartEvent(std::string{ kTraceMessageEvent } + "." + kTracePreparedMessageReceivedDataFormat); + sink->AddField("json", PreparedSecureMessageDataToJson(eventData, "source")); + sink->FinishEvent(); + + return true; } } // namespace @@ -302,7 +337,10 @@ void SetTraceStream(TraceStream * stream) void InitTrace() { void * context = &gTraceHandlerContext; - RegisterTraceHandler(TraceDefaultHandler, context); + RegisterTraceHandler(SecureMessageSentHandler, context); + RegisterTraceHandler(SecureMessageReceivedHandler, context); + RegisterTraceHandler(PreparedMessageSentHandler, context); + RegisterTraceHandler(PreparedMessageReceivedHandler, context); } void DeInitTrace() diff --git a/src/transport/SessionManager.cpp b/src/transport/SessionManager.cpp index 6dcbbdb5275613..db83898ca00ffb 100644 --- a/src/transport/SessionManager.cpp +++ b/src/transport/SessionManager.cpp @@ -318,6 +318,7 @@ CHIP_ERROR SessionManager::SendPreparedMessage(const SessionHandle & sessionHand if (mTransportMgr != nullptr) { + CHIP_TRACE_PREPARED_MESSAGE_SENT(destination, &msgBuf); return mTransportMgr->SendMessage(*destination, std::move(msgBuf)); } @@ -414,6 +415,7 @@ void SessionManager::CancelExpiryTimer() void SessionManager::OnMessageReceived(const PeerAddress & peerAddress, System::PacketBufferHandle && msg) { + CHIP_TRACE_PREPARED_MESSAGE_RECEIVED(&peerAddress, &msg); PacketHeader packetHeader; ReturnOnFailure(packetHeader.DecodeAndConsume(msg)); diff --git a/src/transport/TraceMessage.h b/src/transport/TraceMessage.h index 0863bf0cc9cec8..93cdfa6dd77927 100644 --- a/src/transport/TraceMessage.h +++ b/src/transport/TraceMessage.h @@ -19,6 +19,7 @@ #pragma once #include +#include #include #include #include @@ -30,7 +31,7 @@ do \ { \ const ::chip::trace::TraceSecureMessageSentData _trace_data{ &payloadHeader, &packetHeader, data, dataLen }; \ - PW_TRACE_INSTANT_DATA("SecureMsg", ::chip::trace::kTraceMessageSentDataFormat, \ + PW_TRACE_INSTANT_DATA(::chip::trace::kTraceMessageEvent, ::chip::trace::kTraceMessageSentDataFormat, \ reinterpret_cast(&_trace_data), sizeof(_trace_data)); \ } while (0) @@ -39,7 +40,23 @@ { \ const ::chip::trace::TraceSecureMessageReceivedData _trace_data{ &payloadHeader, &packetHeader, session, \ &peerAddress, data, dataLen }; \ - PW_TRACE_INSTANT_DATA("SecureMsg", ::chip::trace::kTraceMessageReceivedDataFormat, \ + PW_TRACE_INSTANT_DATA(::chip::trace::kTraceMessageEvent, ::chip::trace::kTraceMessageReceivedDataFormat, \ + reinterpret_cast(&_trace_data), sizeof(_trace_data)); \ + } while (0) + +#define CHIP_TRACE_PREPARED_MESSAGE_SENT(destination, packetBuffer) \ + do \ + { \ + const ::chip::trace::TracePreparedSecureMessageData _trace_data{ destination, packetBuffer }; \ + PW_TRACE_INSTANT_DATA(::chip::trace::kTraceMessageEvent, ::chip::trace::kTracePreparedMessageSentDataFormat, \ + reinterpret_cast(&_trace_data), sizeof(_trace_data)); \ + } while (0) + +#define CHIP_TRACE_PREPARED_MESSAGE_RECEIVED(source, packetBuffer) \ + do \ + { \ + const ::chip::trace::TracePreparedSecureMessageData _trace_data{ source, packetBuffer }; \ + PW_TRACE_INSTANT_DATA(::chip::trace::kTraceMessageEvent, ::chip::trace::kTracePreparedMessageReceivedDataFormat, \ reinterpret_cast(&_trace_data), sizeof(_trace_data)); \ } while (0) @@ -54,14 +71,25 @@ { \ } while (0) +#define CHIP_TRACE_PREPARED_MESSAGE_SENT(destination, packetBuffer) \ + do \ + { \ + } while (0) + +#define CHIP_TRACE_PREPARED_MESSAGE_RECEIVED(source, packetBuffer) \ + do \ + { \ + } while (0) #endif // CHIP_CONFIG_TRANSPORT_TRACE_ENABLED namespace chip { namespace trace { -constexpr const char * kTraceMessageEvent = "SecureMsg"; -constexpr const char * kTraceMessageSentDataFormat = "SecMsgSent"; -constexpr const char * kTraceMessageReceivedDataFormat = "SecMsgReceived"; +constexpr const char * kTraceMessageEvent = "SecureMsg"; +constexpr const char * kTraceMessageSentDataFormat = "SecMsgSent"; +constexpr const char * kTraceMessageReceivedDataFormat = "SecMsgReceived"; +constexpr const char * kTracePreparedMessageSentDataFormat = "PreparedMsgSent"; +constexpr const char * kTracePreparedMessageReceivedDataFormat = "PreparedMsgReceived"; struct TraceSecureMessageSentData { @@ -81,5 +109,11 @@ struct TraceSecureMessageReceivedData size_t packetSize; }; +struct TracePreparedSecureMessageData +{ + const Transport::PeerAddress * peerAddress; + const System::PacketBufferHandle * packetBuffer; +}; + } // namespace trace } // namespace chip