Skip to content

Commit

Permalink
Make tracedecoder not stateful and ensure both sent and received mess…
Browse files Browse the repository at this point in the history 
…ages are logged (#27860)

* Make TraceDecoder not stateful, log inbound/outbount

* Restyle

* Ensure sending message data has destination peer address

* Restyle

* Add missing comma

* Restyle

* Remove unused constants

* Restyled by clang-format

* Apply code review comments

* Restyled by clang-format

* Code review fix

* Avoid unused variable errors

* Restyle

---------

Co-authored-by: Restyled.io <[email protected]>
Co-authored-by: Andrei Litvin <[email protected]>
  • Loading branch information
@andy31415 @restyled-commits
@andreilitvin @pull
3 people authored and pull[bot] committed Mar 20, 2024
1 parent 6d77f3b commit 1135459
Show file tree
Hide file tree
Showing 6 changed files with 75 additions and 100 deletions.
137 changes: 49 additions & 88 deletions examples/common/tracing/TraceDecoder.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -30,31 +30,43 @@
constexpr uint16_t kMaxLineLen = 4096;
constexpr const char * jsonPrefix = " json\t";

// Json keys
constexpr const char * kProtocolIdKey = "protocol_id";
constexpr const char * kProtocolCodeKey = "protocol_opcode";
constexpr const char * kSessionIdKey = "session_id";
constexpr const char * kExchangeIdKey = "exchange_id";
constexpr const char * kMessageCounterKey = "msg_counter";
constexpr const char * kSecurityFlagsKey = "security_flags";
constexpr const char * kMessageFlagsKey = "msg_flags";
constexpr const char * kSourceNodeIdKey = "source_node_id";
constexpr const char * kDestinationNodeIdKey = "dest_node_id";
constexpr const char * kDestinationGroupIdKey = "group_id";
constexpr const char * kExchangeFlagsKey = "exchange_flags";
constexpr const char * kIsInitiatorKey = "is_initiator";
constexpr const char * kNeedsAckKey = "is_ack_requested";
constexpr const char * kAckMsgKey = "acknowledged_msg_counter";
constexpr const char * kPayloadDataKey = "payload_hex";
constexpr const char * kPayloadSizeKey = "payload_size";
constexpr const char * kPayloadEncryptedDataKey = "payload_hex_encrypted";
constexpr const char * kPayloadEncryptedSizeKey = "payload_size_encrypted";
constexpr const char * kPayloadEncryptedBufferPtrKey = "buffer_ptr";
constexpr const char * kSourceKey = "source";
constexpr const char * kDestinationKey = "destination";

namespace chip {
namespace trace {
namespace {

// Json keys
constexpr const char * kProtocolIdKey = "protocol_id";
constexpr const char * kProtocolCodeKey = "protocol_opcode";
constexpr const char * kSessionIdKey = "session_id";
constexpr const char * kExchangeIdKey = "exchange_id";
constexpr const char * kMessageCounterKey = "msg_counter";
constexpr const char * kSecurityFlagsKey = "security_flags";
constexpr const char * kMessageFlagsKey = "msg_flags";
constexpr const char * kSourceNodeIdKey = "source_node_id";
constexpr const char * kDestinationNodeIdKey = "dest_node_id";
constexpr const char * kDestinationGroupIdKey = "group_id";
constexpr const char * kExchangeFlagsKey = "exchange_flags";
constexpr const char * kIsInitiatorKey = "is_initiator";
constexpr const char * kNeedsAckKey = "is_ack_requested";
constexpr const char * kAckMsgKey = "acknowledged_msg_counter";
constexpr const char * kPayloadDataKey = "payload_hex";
constexpr const char * kPayloadSizeKey = "payload_size";
constexpr const char * kDirectionKey = "direction";
constexpr const char * kPeerAddress = "peer_address";

bool IsOutbound(const Json::Value & json)
{
VerifyOrReturnValue(json.isMember(kDirectionKey), false);
return strcmp(json[kDirectionKey].asCString(), "outbound") == 0;
}

bool IsInbound(const Json::Value & json)
{
VerifyOrReturnValue(json.isMember(kDirectionKey), false);
return strcmp(json[kDirectionKey].asCString(), "inbound") == 0;
}

} // namespace

using namespace logging;

Expand Down Expand Up @@ -83,45 +95,8 @@ CHIP_ERROR TraceDecoder::ReadString(const char * str)
str += strlen(jsonPrefix);

Json::Reader reader;

if (mJsonBuffer.empty())
{
VerifyOrReturnError(reader.parse(str, mJsonBuffer), CHIP_ERROR_INVALID_ARGUMENT);
VerifyOrReturnError(mJsonBuffer.isMember(kPayloadDataKey) && mJsonBuffer.isMember(kPayloadSizeKey),
CHIP_ERROR_INCORRECT_STATE);
return CHIP_NO_ERROR;
}

Json::Value json;
VerifyOrReturnError(reader.parse(str, json), CHIP_ERROR_INVALID_ARGUMENT);

// If there is a source, then it means the previously saved payload is an encrypted to decode, otherwise
// the previously saved payload is the non encrypted version, and the current decoded one is the encrypted version.
if (mJsonBuffer.isMember(kSourceKey))
{
json[kPayloadEncryptedDataKey] = mJsonBuffer[kPayloadDataKey];
json[kPayloadEncryptedSizeKey] = mJsonBuffer[kPayloadSizeKey];
}
else
{
auto data = json[kPayloadDataKey];
auto size = json[kPayloadSizeKey];
json[kPayloadDataKey] = mJsonBuffer[kPayloadDataKey];
json[kPayloadSizeKey] = mJsonBuffer[kPayloadSizeKey];
json[kPayloadEncryptedDataKey] = data;
json[kPayloadEncryptedSizeKey] = size;
}
mJsonBuffer.removeMember(kPayloadDataKey);
mJsonBuffer.removeMember(kPayloadSizeKey);

// If there is additional data in the previously saved json copy all of it.
for (const auto & key : mJsonBuffer.getMemberNames())
{
json[key] = mJsonBuffer[key];
mJsonBuffer.removeMember(key);
}

VerifyOrReturnError(json.isMember(kSourceKey) || json.isMember(kDestinationKey), CHIP_ERROR_INCORRECT_STATE);
VerifyOrReturnError(json.isMember(kProtocolIdKey), CHIP_ERROR_INCORRECT_STATE);
VerifyOrReturnError(json.isMember(kProtocolCodeKey), CHIP_ERROR_INCORRECT_STATE);

Expand All @@ -138,20 +113,19 @@ CHIP_ERROR TraceDecoder::LogJSON(Json::Value & json)
return CHIP_NO_ERROR;
}

if (!mOptions.mEnableMessageInitiator && json.isMember(kDestinationKey))
if (!mOptions.mEnableMessageInitiator && IsOutbound(json))
{
return CHIP_NO_ERROR;
}

if (!mOptions.mEnableMessageResponder && json.isMember(kSourceKey))
if (!mOptions.mEnableMessageResponder && IsInbound(json))
{
return CHIP_NO_ERROR;
}

bool isResponse = json.isMember(kSourceKey) ? true : false;
bool isResponse = IsInbound(json);
ReturnErrorOnFailure(LogAndConsumeProtocol(json));
ReturnErrorOnFailure(MaybeLogAndConsumeHeaderFlags(json));
ReturnErrorOnFailure(MaybeLogAndConsumeEncryptedPayload(json));
ReturnErrorOnFailure(MaybeLogAndConsumePayload(json, isResponse));
ReturnErrorOnFailure(MaybeLogAndConsumeOthers(json));

Expand All @@ -168,26 +142,6 @@ CHIP_ERROR TraceDecoder::MaybeLogAndConsumeHeaderFlags(Json::Value & json)
return CHIP_NO_ERROR;
}

CHIP_ERROR TraceDecoder::MaybeLogAndConsumeEncryptedPayload(Json::Value & json)
{
if (mOptions.mEnableDataEncryptedPayload)
{
size_t size = static_cast<uint16_t>(json[kPayloadEncryptedSizeKey].asLargestUInt());
if (size)
{
auto payload = json[kPayloadEncryptedDataKey].asString();
auto bufferPtr = json[kPayloadEncryptedBufferPtrKey].asString();
auto scopedIndent = ScopedLogIndentWithSize("Encrypted Payload", size);
Log("data", payload.c_str());
Log("buffer_ptr", bufferPtr.c_str());
}
}
json.removeMember(kPayloadEncryptedSizeKey);
json.removeMember(kPayloadEncryptedDataKey);
json.removeMember(kPayloadEncryptedBufferPtrKey);
return CHIP_NO_ERROR;
}

CHIP_ERROR TraceDecoder::MaybeLogAndConsumeOthers(Json::Value & json)
{
std::vector<std::string> keys = json.getMemberNames();
Expand Down Expand Up @@ -218,8 +172,16 @@ CHIP_ERROR TraceDecoder::LogAndConsumeProtocol(Json::Value & json)

chip::StringBuilderBase builder(protocolInfo, sizeof(protocolInfo));

builder.Add(json.isMember(kSourceKey) ? "<< from " : ">> to ");
builder.Add(json.isMember(kSourceKey) ? json[kSourceKey].asCString() : json[kDestinationKey].asCString());
builder.Add(IsInbound(json) ? "<< from " : ">> to ");

if (json.isMember(kPeerAddress))
{
builder.Add(json[kPeerAddress].asCString());
}
else
{
builder.Add("UNKNOWN");
}

builder.Add(" ");
auto msgCounter = static_cast<uint32_t>(json[kMessageCounterKey].asLargestUInt());
Expand Down Expand Up @@ -258,11 +220,10 @@ CHIP_ERROR TraceDecoder::LogAndConsumeProtocol(Json::Value & json)

ChipLogProgress(DataManagement, "%s", builder.c_str());

json.removeMember(kSourceKey);
json.removeMember(kDestinationKey);
json.removeMember(kSessionIdKey);
json.removeMember(kExchangeIdKey);
json.removeMember(kMessageCounterKey);
json.removeMember(kDirectionKey);

return CHIP_NO_ERROR;
}
Expand Down
9 changes: 6 additions & 3 deletions examples/common/tracing/TraceDecoder.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -42,7 +42,12 @@ class TraceDecoder : public TraceStream
{
char buffer[2048] = {};
snprintf(buffer, sizeof(buffer), " %s\t %s", tag.c_str(), data.c_str());
ReadString(buffer);
CHIP_ERROR err = ReadString(buffer);

if (err != CHIP_NO_ERROR)
{
ChipLogError(Automation, "Failed to add field: %" CHIP_ERROR_FORMAT, err.Format());
}
}

void FinishEvent() override {}
Expand All @@ -55,12 +60,10 @@ class TraceDecoder : public TraceStream
CHIP_ERROR MaybeLogAndConsumeMessageFlags(Json::Value & value);
CHIP_ERROR MaybeLogAndConsumeExchangeFlags(Json::Value & value);
CHIP_ERROR MaybeLogAndConsumePayload(Json::Value & value, bool isResponse);
CHIP_ERROR MaybeLogAndConsumeEncryptedPayload(Json::Value & value);
CHIP_ERROR MaybeLogAndConsumeOthers(Json::Value & value);

private:
TraceDecoderOptions mOptions;
Json::Value mJsonBuffer;
};

} // namespace trace
Expand Down
6 changes: 4 additions & 2 deletions examples/common/tracing/TraceHandlers.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -233,7 +233,9 @@ void SecureMessageSentHandler(const TraceSecureMessageSentData * eventData)
return;
}

std::string jsonBody = "{";
std::string jsonBody = "{ \"direction\": \"outbound\", ";
jsonBody += AsFirstJsonKey("peer_address", AsJsonString(eventData->peerAddress));
jsonBody += ", ";
jsonBody += PacketHeaderToJson(eventData->packetHeader);
jsonBody += ", ";
jsonBody += PayloadHeaderToJson(eventData->payloadHeader);
Expand All @@ -255,7 +257,7 @@ void SecureMessageReceivedHandler(const TraceSecureMessageReceivedData * eventDa
return;
}

std::string jsonBody = "{";
std::string jsonBody = "{ \"direction\": \"inbound\", ";
jsonBody += AsFirstJsonKey("peer_address", AsJsonString(eventData->peerAddress));
jsonBody += ", ";
jsonBody += PacketHeaderToJson(eventData->packetHeader);
Expand Down
1 change: 0 additions & 1 deletion src/transport/Session.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -27,7 +27,6 @@
#include <messaging/ReliableMessageProtocolConfig.h>
#include <platform/LockTracker.h>
#include <transport/SessionDelegate.h>
#include <transport/raw/PeerAddress.h>

namespace chip {
namespace Transport {
Expand Down
13 changes: 10 additions & 3 deletions src/transport/SessionManager.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -181,11 +181,13 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P
return CHIP_ERROR_INTERNAL;
}

PeerAddress destination_address = Transport::PeerAddress::Multicast(fabric->GetFabricId(), groupSession->GetGroupId());

// 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());
CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, destination_address, message->Start(), message->TotalLength());

Crypto::SymmetricKeyContext * keyContext =
groups->GetKeyContext(groupSession->GetFabricIndex(), groupSession->GetGroupId());
Expand Down Expand Up @@ -219,10 +221,12 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P
.SetSessionId(session->GetPeerSessionId()) //
.SetSessionType(Header::SessionType::kUnicastSession);

PeerAddress destination_address = session->GetPeerAddress();

// 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());
CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, destination_address, message->Start(), message->TotalLength());

CryptoContext::NonceStorage nonce;
NodeId sourceNodeId = session->GetLocalScopedNodeId().GetNodeId();
Expand Down Expand Up @@ -252,10 +256,13 @@ CHIP_ERROR SessionManager::PrepareMessage(const SessionHandle & sessionHandle, P
break;
}

auto unauthenticated = sessionHandle->AsUnauthenticatedSession();
PeerAddress destination_address = unauthenticated->GetPeerAddress();

// 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());
CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, destination_address, message->Start(), message->TotalLength());

ReturnErrorOnFailure(payloadHeader.EncodeBeforeData(message));

Expand Down
9 changes: 6 additions & 3 deletions src/transport/TraceMessage.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -40,10 +40,10 @@
#define _CHIP_TRACE_MESSAGE_INTERNAL(type, data, size) PW_TRACE_INSTANT_DATA(::chip::trace::kTraceMessageEvent, type, data, size);
#endif // CHIP_CONFIG_TRANSPORT_TRACE_ENABLED && CHIP_CONFIG_TRANSPORT_PW_TRACE_ENABLED

#define CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, data, dataLen) \
#define CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, peerAddress, data, dataLen) \
do \
{ \
const ::chip::trace::TraceSecureMessageSentData _trace_data{ &payloadHeader, &packetHeader, data, dataLen }; \
const ::chip::trace::TraceSecureMessageSentData _trace_data{ &payloadHeader, &packetHeader, &peerAddress, data, dataLen }; \
_CHIP_TRACE_MESSAGE_INTERNAL(::chip::trace::kTraceMessageSentDataFormat, reinterpret_cast<const char *>(&_trace_data), \
sizeof(_trace_data)); \
} while (0)
Expand All @@ -58,14 +58,16 @@
} while (0)

#else // CHIP_CONFIG_TRANSPORT_TRACE_ENABLED || CHIP_CONFIG_TRANSPORT_PW_TRACE_ENABLED
#define CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, data, dataLen) \
#define CHIP_TRACE_MESSAGE_SENT(payloadHeader, packetHeader, peerAddress, data, dataLen) \
do \
{ \
(void) peerAddress; \
} while (0)

#define CHIP_TRACE_MESSAGE_RECEIVED(payloadHeader, packetHeader, session, peerAddress, data, dataLen) \
do \
{ \
(void) peerAddress; \
} while (0)

#endif // CHIP_CONFIG_TRANSPORT_TRACE_ENABLED || CHIP_CONFIG_TRANSPORT_PW_TRACE_ENABLED
Expand All @@ -81,6 +83,7 @@ struct TraceSecureMessageSentData
{
const PayloadHeader * payloadHeader;
const PacketHeader * packetHeader;
const Transport::PeerAddress * peerAddress;
const uint8_t * packetPayload;
size_t packetSize;
};
Expand Down

0 comments on commit 1135459

Please sign in to comment.