Add data logging using the tracing module for message send/receive (#27281)
* Add message loging structures and definitions
* Run clang-format
* Fix a comment
* Restyled by clang-format
* Fix dependencies in build.gn
* Fix compile error for mac .. size_t cannot be easilu converted and we know size fits in a UInt
* Fix typo
---------
Co-authored-by: Andrei Litvin <andreilitvin@google.com>
Co-authored-by: Restyled.io <commits@restyled.io>
diff --git a/examples/common/tracing/TraceHandlers.cpp b/examples/common/tracing/TraceHandlers.cpp
index 373b00c..d595580 100644
--- a/examples/common/tracing/TraceHandlers.cpp
+++ b/examples/common/tracing/TraceHandlers.cpp
@@ -199,7 +199,7 @@
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 bc6501d..adf6b75 100644
--- a/src/tracing/backend.h
+++ b/src/tracing/backend.h
@@ -58,7 +58,7 @@
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 8cc4e11..5e502d0 100644
--- a/src/tracing/log_declares.h
+++ b/src/tracing/log_declares.h
@@ -23,7 +23,7 @@
// 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 1b8a3c8..655fda8 100644
--- a/src/tracing/log_json/BUILD.gn
+++ b/src/tracing/log_json/BUILD.gn
@@ -26,6 +26,7 @@
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 2a89300..933009d 100644
--- a/src/tracing/log_json/log_json_tracing.cpp
+++ b/src/tracing/log_json/log_json_tracing.cpp
@@ -21,6 +21,7 @@
#include <lib/address_resolve/TracingStructs.h>
#include <lib/support/ErrorStr.h>
#include <lib/support/StringBuilder.h>
+#include <transport/TracingStructs.h>
#include <json/json.h>
@@ -219,6 +220,63 @@
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<uint32_t> & 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> & nodeId = packetHeader->GetSourceNodeId();
+ if (nodeId.HasValue())
+ {
+ value["sourceNodeId"] = nodeId.Value();
+ }
+ }
+
+ {
+ const Optional<NodeId> & nodeId = packetHeader->GetDestinationNodeId();
+ if (nodeId.HasValue())
+ {
+ value["destinationNodeId"] = nodeId.Value();
+ }
+ }
+
+ {
+ const Optional<GroupId> & groupId = packetHeader->GetDestinationGroupId();
+ if (groupId.HasValue())
+ {
+ value["groupId"] = groupId.Value();
+ }
+ }
+}
+
+void DecodePayloadData(Json::Value & value, chip::ByteSpan payload)
+{
+ value["payloadSize"] = static_cast<Json::Value::UInt>(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 @@
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 ca15c8f..ef462c9 100644
--- a/src/tracing/log_json/log_json_tracing.h
+++ b/src/tracing/log_json/log_json_tracing.h
@@ -35,7 +35,7 @@
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 f3497a2..bb98623 100644
--- a/src/tracing/registry.cpp
+++ b/src/tracing/registry.cpp
@@ -74,7 +74,7 @@
}
}
-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 b159614..b3a5a6a 100644
--- a/src/tracing/registry.h
+++ b/src/tracing/registry.h
@@ -64,7 +64,7 @@
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 a632f41..70168e6 100644
--- a/src/transport/BUILD.gn
+++ b/src/transport/BUILD.gn
@@ -45,6 +45,7 @@
"SessionManager.h",
"SessionMessageCounter.h",
"SessionMessageDelegate.h",
+ "TracingStructs.h",
"TransportMgr.h",
"TransportMgrBase.cpp",
"TransportMgrBase.h",
@@ -64,6 +65,7 @@
"${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 1aba11a..30494b0 100644
--- a/src/transport/SessionManager.cpp
+++ b/src/transport/SessionManager.cpp
@@ -40,9 +40,11 @@
#include <platform/CHIPDeviceLayer.h>
#include <protocols/Protocols.h>
#include <protocols/secure_channel/Constants.h>
+#include <tracing/macros.h>
#include <transport/GroupPeerMessageCounter.h>
#include <transport/GroupSession.h>
#include <transport/SecureMessageCodec.h>
+#include <transport/TracingStructs.h>
#include <transport/TransportMgr.h>
// Global object
@@ -178,6 +180,9 @@
}
// 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 @@
.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 @@
}
// 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));
@@ -641,12 +650,18 @@
// 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,
@@ -751,9 +766,15 @@
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.");
+ }
}
/**
@@ -958,10 +979,18 @@
// 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<SessionHandle> SessionManager::FindSecureSessionForNode(ScopedNodeId peerNodeId,
diff --git a/src/transport/TracingStructs.h b/src/transport/TracingStructs.h
new file mode 100644
index 0000000..5f57663
--- /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 <lib/support/Span.h>
+#include <transport/Session.h>
+#include <transport/raw/MessageHeader.h>
+
+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 4f78562..ec95731 100644
--- a/src/transport/raw/MessageHeader.h
+++ b/src/transport/raw/MessageHeader.h
@@ -511,7 +511,7 @@
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; }
