diff --git a/examples/common/tracing/TraceHandlers.cpp b/examples/common/tracing/TraceHandlers.cpp index ea40e285df3844..f798d517c7d609 100644 --- a/examples/common/tracing/TraceHandlers.cpp +++ b/examples/common/tracing/TraceHandlers.cpp @@ -199,7 +199,7 @@ std::string PayloadHeaderToJson(const PayloadHeader * payloadHeader) std::string jsonBody; - uint8_t exchangeFlags = payloadHeader->GetExhangeFlags(); + uint8_t exchangeFlags = payloadHeader->GetExchangeFlags(); jsonBody += AsFirstJsonKey("exchange_flags", std::to_string(exchangeFlags)); uint16_t exchangeId = payloadHeader->GetExchangeID(); diff --git a/src/tracing/backend.h b/src/tracing/backend.h index bc6501dbf6b4be..adf6b75a97828e 100644 --- a/src/tracing/backend.h +++ b/src/tracing/backend.h @@ -58,7 +58,7 @@ class Backend : public ::chip::IntrusiveListNodeBase<> virtual void TraceInstant(Instant instant) = 0; virtual void LogMessageSend(MessageSendInfo &) { TraceInstant(Instant::Log_MessageSend); } - virtual void LogMessageReceived(MessageReceiveInfo &) { TraceInstant(Instant::Log_MessageReceived); } + virtual void LogMessageReceived(MessageReceivedInfo &) { TraceInstant(Instant::Log_MessageReceived); } virtual void LogNodeLookup(NodeLookupInfo &) { TraceInstant(Instant::Log_NodeLookup); } virtual void LogNodeDiscovered(NodeDiscoveredInfo &) { TraceInstant(Instant::Log_NodeDiscovered); } diff --git a/src/tracing/log_declares.h b/src/tracing/log_declares.h index 8cc4e11a7e2cb3..5e502d0c93af6c 100644 --- a/src/tracing/log_declares.h +++ b/src/tracing/log_declares.h @@ -23,7 +23,7 @@ namespace Tracing { // on actual types. This allows tracing to be used anywhere lib/support could be used. struct MessageSendInfo; -struct MessageReceiveInfo; +struct MessageReceivedInfo; struct NodeLookupInfo; struct NodeDiscoveredInfo; struct NodeDiscoveryFailedInfo; diff --git a/src/tracing/log_json/BUILD.gn b/src/tracing/log_json/BUILD.gn index 1b8a3c8efdbbd4..655fda8e6a2c97 100644 --- a/src/tracing/log_json/BUILD.gn +++ b/src/tracing/log_json/BUILD.gn @@ -26,6 +26,7 @@ static_library("log_json") { public_deps = [ "${chip_root}/src/lib/address_resolve", "${chip_root}/src/tracing", + "${chip_root}/src/transport", "${chip_root}/third_party/jsoncpp", ] } diff --git a/src/tracing/log_json/log_json_tracing.cpp b/src/tracing/log_json/log_json_tracing.cpp index 2a89300f0eced6..933009d67bea94 100644 --- a/src/tracing/log_json/log_json_tracing.cpp +++ b/src/tracing/log_json/log_json_tracing.cpp @@ -21,6 +21,7 @@ #include #include #include +#include #include @@ -219,6 +220,63 @@ void LogJsonValue(Json::Value const & value) ChipLogProgress(Automation, "%s", output.str().c_str()); } +void DecodePayloadHeader(Json::Value & value, const PayloadHeader * payloadHeader) +{ + + value["exchangeFlags"] = payloadHeader->GetExchangeFlags(); + value["exchangeId"] = payloadHeader->GetExchangeID(); + value["protocolId"] = payloadHeader->GetProtocolID().ToFullyQualifiedSpecForm(); + value["messageType"] = payloadHeader->GetMessageType(); + value["initiator"] = payloadHeader->IsInitiator(); + value["needsAck"] = payloadHeader->NeedsAck(); + + const Optional & acknowledgedMessageCounter = payloadHeader->GetAckMessageCounter(); + if (acknowledgedMessageCounter.HasValue()) + { + value["ackMessageCounter"] = acknowledgedMessageCounter.Value(); + } +} + +void DecodePacketHeader(Json::Value & value, const PacketHeader * packetHeader) +{ + value["msgCounter"] = packetHeader->GetMessageCounter(); + value["sessionId"] = packetHeader->GetSessionId(); + value["flags"] = packetHeader->GetMessageFlags(); + value["securityFlags"] = packetHeader->GetSecurityFlags(); + + { + const Optional & nodeId = packetHeader->GetSourceNodeId(); + if (nodeId.HasValue()) + { + value["sourceNodeId"] = nodeId.Value(); + } + } + + { + const Optional & nodeId = packetHeader->GetDestinationNodeId(); + if (nodeId.HasValue()) + { + value["destinationNodeId"] = nodeId.Value(); + } + } + + { + const Optional & groupId = packetHeader->GetDestinationGroupId(); + if (groupId.HasValue()) + { + value["groupId"] = groupId.Value(); + } + } +} + +void DecodePayloadData(Json::Value & value, chip::ByteSpan payload) +{ + value["payloadSize"] = static_cast(payload.size()); + + // TODO: a decode would be useful however it likely requires more decode + // metadata +} + } // namespace void LogJsonBackend::TraceBegin(Scope scope) @@ -245,17 +303,54 @@ void LogJsonBackend::TraceInstant(Instant instant) LogJsonValue(value); } -void LogJsonBackend::LogMessageSend(MessageSendInfo &) +void LogJsonBackend::LogMessageSend(MessageSendInfo & info) { Json::Value value; - value["TODO"] = "LogMessageSend"; + value["event"] = "MessageSend"; + + switch (info.messageType) + { + case OutgoingMessageType::kGroupMessage: + value["messageType"] = "Group"; + break; + case OutgoingMessageType::kSecureSession: + value["messageType"] = "Secure"; + break; + case OutgoingMessageType::kUnauthenticated: + value["messageType"] = "Unauthenticated"; + break; + } + + DecodePayloadHeader(value["payloadHeader"], info.payloadHeader); + DecodePacketHeader(value["packetHeader"], info.packetHeader); + DecodePayloadData(value["payload"], info.payload); + LogJsonValue(value); } -void LogJsonBackend::LogMessageReceived(MessageReceiveInfo &) +void LogJsonBackend::LogMessageReceived(MessageReceivedInfo & info) { Json::Value value; - value["TODO"] = "LogMessageReceived"; + + value["event"] = "MessageReceived"; + + switch (info.messageType) + { + case IncomingMessageType::kGroupMessage: + value["messageType"] = "Group"; + break; + case IncomingMessageType::kSecureUnicast: + value["messageType"] = "Secure"; + break; + case IncomingMessageType::kUnauthenticated: + value["messageType"] = "Unauthenticated"; + break; + } + + DecodePayloadHeader(value["payloadHeader"], info.payloadHeader); + DecodePacketHeader(value["packetHeader"], info.packetHeader); + DecodePayloadData(value["payload"], info.payload); + LogJsonValue(value); } diff --git a/src/tracing/log_json/log_json_tracing.h b/src/tracing/log_json/log_json_tracing.h index ca15c8f27e6448..ef462c9c37be95 100644 --- a/src/tracing/log_json/log_json_tracing.h +++ b/src/tracing/log_json/log_json_tracing.h @@ -35,7 +35,7 @@ class LogJsonBackend : public ::chip::Tracing::Backend void TraceEnd(Scope scope) override; void TraceInstant(Instant instant) override; void LogMessageSend(MessageSendInfo &) override; - void LogMessageReceived(MessageReceiveInfo &) override; + void LogMessageReceived(MessageReceivedInfo &) override; void LogNodeLookup(NodeLookupInfo &) override; void LogNodeDiscovered(NodeDiscoveredInfo &) override; void LogNodeDiscoveryFailed(NodeDiscoveryFailedInfo &) override; diff --git a/src/tracing/registry.cpp b/src/tracing/registry.cpp index f3497a27f2643f..bb9862383f2857 100644 --- a/src/tracing/registry.cpp +++ b/src/tracing/registry.cpp @@ -74,7 +74,7 @@ void LogMessageSend(::chip::Tracing::MessageSendInfo & info) } } -void LogMessageReceived(::chip::Tracing::MessageReceiveInfo & info) +void LogMessageReceived(::chip::Tracing::MessageReceivedInfo & info) { for (auto & backend : gTracingBackends) { diff --git a/src/tracing/registry.h b/src/tracing/registry.h index b1596144dbc00f..b3a5a6aaf1564f 100644 --- a/src/tracing/registry.h +++ b/src/tracing/registry.h @@ -64,7 +64,7 @@ void End(::chip::Tracing::Scope scope); void Instant(::chip::Tracing::Instant instant); void LogMessageSend(::chip::Tracing::MessageSendInfo & info); -void LogMessageReceived(::chip::Tracing::MessageReceiveInfo & info); +void LogMessageReceived(::chip::Tracing::MessageReceivedInfo & info); void LogNodeLookup(::chip::Tracing::NodeLookupInfo & info); void LogNodeDiscovered(::chip::Tracing::NodeDiscoveredInfo & info); void LogNodeDiscoveryFailed(::chip::Tracing::NodeDiscoveryFailedInfo & info); diff --git a/src/transport/BUILD.gn b/src/transport/BUILD.gn index a632f41af3a3d3..70168e64cb5924 100644 --- a/src/transport/BUILD.gn +++ b/src/transport/BUILD.gn @@ -45,6 +45,7 @@ static_library("transport") { "SessionManager.h", "SessionMessageCounter.h", "SessionMessageDelegate.h", + "TracingStructs.h", "TransportMgr.h", "TransportMgrBase.cpp", "TransportMgrBase.h", @@ -64,6 +65,7 @@ static_library("transport") { "${chip_root}/src/lib/support", "${chip_root}/src/platform", "${chip_root}/src/setup_payload", + "${chip_root}/src/tracing", "${chip_root}/src/transport/raw", "${nlio_root}:nlio", ] diff --git a/src/transport/SessionManager.cpp b/src/transport/SessionManager.cpp index e3c424fee20dc0..2b060cb78b3210 100644 --- a/src/transport/SessionManager.cpp +++ b/src/transport/SessionManager.cpp @@ -40,9 +40,11 @@ #include #include #include +#include #include #include #include +#include #include // Global object @@ -178,6 +180,9 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P } // Trace before any encryption + MATTER_LOG_MESSAGE_SEND(chip::Tracing::OutgoingMessageType::kGroupMessage, &payloadHeader, &packetHeader, + chip::ByteSpan(message->Start(), message->TotalLength())); + CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, message->Start(), message->TotalLength()); Crypto::SymmetricKeyContext * keyContext = @@ -213,6 +218,8 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P .SetSessionType(Header::SessionType::kUnicastSession); // Trace before any encryption + MATTER_LOG_MESSAGE_SEND(chip::Tracing::OutgoingMessageType::kSecureSession, &payloadHeader, &packetHeader, + chip::ByteSpan(message->Start(), message->TotalLength())); CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, message->Start(), message->TotalLength()); CryptoContext::NonceStorage nonce; @@ -244,6 +251,8 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P } // Trace after all headers are settled. + MATTER_LOG_MESSAGE_SEND(chip::Tracing::OutgoingMessageType::kUnauthenticated, &payloadHeader, &packetHeader, + chip::ByteSpan(message->Start(), message->TotalLength())); CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, message->Start(), message->TotalLength()); ReturnErrorOnFailure(payloadHeader.EncodeBeforeData(message)); @@ -644,12 +653,18 @@ void SessionManager::UnauthenticatedMessageDispatch(const PacketHeader & partial // CHIP_ERROR_DUPLICATE_MESSAGE_RECEIVED. unsecuredSession->GetPeerMessageCounter().CommitUnencrypted(packetHeader.GetMessageCounter()); } - if (mCB != nullptr) { + MATTER_LOG_MESSAGE_RECEIVED(chip::Tracing::IncomingMessageType::kUnauthenticated, &payloadHeader, &packetHeader, + unsecuredSession, &peerAddress, chip::ByteSpan(msg->Start(), msg->TotalLength())); + CHIP_TRACE_MESSAGE_RECEIVED(payloadHeader, packetHeader, unsecuredSession, peerAddress, msg->Start(), msg->TotalLength()); mCB->OnMessageReceived(packetHeader, payloadHeader, session, isDuplicate, std::move(msg)); } + else + { + ChipLogError(Inet, "Received UNSECURED message was not processed."); + } } void SessionManager::SecureUnicastMessageDispatch(const PacketHeader & partialPacketHeader, @@ -754,9 +769,15 @@ void SessionManager::SecureUnicastMessageDispatch(const PacketHeader & partialPa if (mCB != nullptr) { + MATTER_LOG_MESSAGE_RECEIVED(chip::Tracing::IncomingMessageType::kSecureUnicast, &payloadHeader, &packetHeader, + secureSession, &peerAddress, chip::ByteSpan(msg->Start(), msg->TotalLength())); CHIP_TRACE_MESSAGE_RECEIVED(payloadHeader, packetHeader, secureSession, peerAddress, msg->Start(), msg->TotalLength()); mCB->OnMessageReceived(packetHeader, payloadHeader, session.Value(), isDuplicate, std::move(msg)); } + else + { + ChipLogError(Inet, "Received SECURED message was not processed."); + } } /** @@ -961,10 +982,18 @@ void SessionManager::SecureGroupMessageDispatch(const PacketHeader & partialPack // TODO : When MCSP is done, clean up session creation logic Transport::IncomingGroupSession groupSession(groupContext.group_id, groupContext.fabric_index, packetHeaderCopy.GetSourceNodeId().Value()); + + MATTER_LOG_MESSAGE_RECEIVED(chip::Tracing::IncomingMessageType::kGroupMessage, &payloadHeader, &packetHeaderCopy, + &groupSession, &peerAddress, chip::ByteSpan(msg->Start(), msg->TotalLength())); + CHIP_TRACE_MESSAGE_RECEIVED(payloadHeader, packetHeaderCopy, &groupSession, peerAddress, msg->Start(), msg->TotalLength()); mCB->OnMessageReceived(packetHeaderCopy, payloadHeader, SessionHandle(groupSession), SessionMessageDelegate::DuplicateMessage::No, std::move(msg)); } + else + { + ChipLogError(Inet, "Received GROUP message was not processed."); + } } Optional SessionManager::FindSecureSessionForNode(ScopedNodeId peerNodeId, diff --git a/src/transport/TracingStructs.h b/src/transport/TracingStructs.h new file mode 100644 index 00000000000000..5f57663e46dba2 --- /dev/null +++ b/src/transport/TracingStructs.h @@ -0,0 +1,64 @@ +/* + * Copyright (c) 2023 Project CHIP Authors + * All rights reserved. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +#pragma once + +#include +#include +#include + +namespace chip { +namespace Tracing { + +/// Concrete definitions of the message tracing info that session managers +/// report + +enum class OutgoingMessageType +{ + kGroupMessage, + kSecureSession, + kUnauthenticated, +}; + +/// A message is about to be sent +struct MessageSendInfo +{ + OutgoingMessageType messageType; + const PayloadHeader * payloadHeader; + const PacketHeader * packetHeader; + const chip::ByteSpan payload; +}; + +enum class IncomingMessageType +{ + kGroupMessage, + kSecureUnicast, + kUnauthenticated, +}; + +/// A message has been received +struct MessageReceivedInfo +{ + const IncomingMessageType messageType; + const PayloadHeader * payloadHeader; + const PacketHeader * packetHeader; + const Transport::Session * session; + const Transport::PeerAddress * peerAddress; + const chip::ByteSpan payload; +}; + +} // namespace Tracing +} // namespace chip diff --git a/src/transport/raw/MessageHeader.h b/src/transport/raw/MessageHeader.h index 4f7856232179c5..ec957315714bbb 100644 --- a/src/transport/raw/MessageHeader.h +++ b/src/transport/raw/MessageHeader.h @@ -511,7 +511,7 @@ class PayloadHeader uint8_t GetMessageType() const { return mMessageType; } /** Get the raw exchange flags from this header. */ - uint8_t GetExhangeFlags() const { return mExchangeFlags.Raw(); } + uint8_t GetExchangeFlags() const { return mExchangeFlags.Raw(); } /** Check whether the header has a given secure message type */ bool HasMessageType(uint8_t type) const { return mMessageType == type; }