From 9483553c44d92d70800ddc6cb4a299334c3eca84 Mon Sep 17 00:00:00 2001 From: Abtin Keshavarzian Date: Thu, 20 Nov 2025 21:52:55 -0800 Subject: [PATCH] [border-agent] improve logging and add session index (#12171) This commit introduces a session index tracked by each session (`CoapDtlsSession`) to uniquely identify sessions in log messages. The `Manager` now maintains a counter to assign a new index to each session upon allocation. Logs are added to track the lifecycle of a session (allocation, connection, disconnection, deletion, and timeout), with each event including the session's unique index. A new templated helper, `Log()`, is added to standardize logging for TMF messages, including response handling. The session index is included in such logs to provide clearer insight into the processing of specific TMF commands by Border Agent sessions. --- src/core/meshcop/border_agent.cpp | 123 ++++++++++++++++++++++++++---- src/core/meshcop/border_agent.hpp | 22 ++++++ 2 files changed, 130 insertions(+), 15 deletions(-) diff --git a/src/core/meshcop/border_agent.cpp b/src/core/meshcop/border_agent.cpp index 3cd750598..3c9c4187b 100644 --- a/src/core/meshcop/border_agent.cpp +++ b/src/core/meshcop/border_agent.cpp @@ -56,6 +56,7 @@ Manager::Manager(Instance &aInstance) : InstanceLocator(aInstance) , mEnabled(true) , mIsRunning(false) + , mSessionIndex(0) , mDtlsTransport(aInstance, kNoLinkSecurity) , mCommissionerSession(nullptr) , mCommissionerUdpReceiver(HandleUdpReceive, this) @@ -249,6 +250,8 @@ void Manager::HandleRemoveSession(SecureSession &aSession) { CoapDtlsSession &coapSession = static_cast(aSession); + LogInfo("Deleting session %u", coapSession.GetIndex()); + coapSession.Cleanup(); coapSession.Free(); } @@ -302,7 +305,7 @@ void Manager::HandleCommissionerPetitionAccepted(CoapDtlsSession &aSession, uint IgnoreError(Get().AddReceiver(mCommissionerUdpReceiver)); - LogInfo("Commissioner accepted - SessionId:%u ALOC:%s", aSessionId, + LogInfo("Session %u accepted as active commissioner - Id:0x%04x ALOC:%s", aSession.GetIndex(), aSessionId, mCommissionerAloc.GetAddress().ToString().AsCString()); #if OPENTHREAD_CONFIG_BORDER_AGENT_EPHEMERAL_KEY_ENABLE @@ -321,7 +324,7 @@ void Manager::RevokeRoleIfActiveCommissioner(CoapDtlsSession &aSession) { VerifyOrExit(IsCommissionerSession(aSession)); - LogInfo("Commissioner role revoked"); + LogInfo("Revoked active commissioner role from session %u", aSession.GetIndex()); IgnoreError(Get().RemoveReceiver(mCommissionerUdpReceiver)); Get().RemoveUnicastAddress(mCommissionerAloc); @@ -361,6 +364,8 @@ template <> void Manager::HandleTmf(Coap::Message &aMessage, const VerifyOrExit(aMessage.IsNonConfirmablePostRequest()); + LogInfo("Received %s from %s", UriToString(), aMessageInfo.GetPeerAddr().ToString().AsCString()); + VerifyOrExit(mCommissionerSession != nullptr); mCommissionerSession->ForwardUdpRelayToCommissioner(aMessage); @@ -505,9 +510,12 @@ Manager::CoapDtlsSession::CoapDtlsSession(Instance &aInstance, Dtls::Transport & : Coap::SecureSession(aInstance, aDtlsTransport) , mTimer(aInstance, HandleTimer, this) , mAllocationTime(aInstance.Get().GetUptime()) + , mIndex(aInstance.Get().GetNextSessionIndex()) { SetResourceHandler(&HandleResource); SetConnectCallback(&HandleConnected, this); + + LogInfo("Allocating session %u", mIndex); } Error Manager::CoapDtlsSession::SendMessage(OwnedPtr aMessage) @@ -558,6 +566,7 @@ bool Manager::CoapDtlsSession::HandleResource(const char *aUriPath, switch (uri) { case kUriCommissionerPetition: + Log(kReceive); IgnoreError(ForwardToLeader(aMessage, aMessageInfo, kUriLeaderPetition)); break; case kUriCommissionerKeepAlive: @@ -591,13 +600,13 @@ void Manager::CoapDtlsSession::HandleConnected(ConnectEvent aEvent) { if (aEvent == kConnected) { - LogInfo("SecureSession connected"); + LogInfo("Session %u connected", mIndex); mTimer.Start(kKeepAliveTimeout); Get().HandleSessionConnected(*this); } else { - LogInfo("SecureSession disconnected"); + LogInfo("Session %u disconnected", mIndex); Get().HandleSessionDisconnected(*this, aEvent); } } @@ -607,6 +616,8 @@ void Manager::CoapDtlsSession::HandleTmfCommissionerKeepAlive(Coap::Message { VerifyOrExit(IsActiveCommissioner()); + Log(kReceive); + SuccessOrExit(ForwardToLeader(aMessage, aMessageInfo, kUriLeaderKeepAlive)); mTimer.Start(kKeepAliveTimeout); #if OPENTHREAD_CONFIG_BORDER_AGENT_EPHEMERAL_KEY_ENABLE && OPENTHREAD_CONFIG_HISTORY_TRACKER_ENABLE @@ -664,7 +675,17 @@ Error Manager::CoapDtlsSession::ForwardToLeader(const Coap::Message &aMessage mForwardContexts.Push(*forwardContext.Release()); - LogInfo("Forwarded request to leader on %s", PathForUri(aUri)); + switch (aUri) + { + case kUriLeaderPetition: + Log(kForward, " to leader"); + break; + case kUriLeaderKeepAlive: + Log(kForward, " to leader"); + break; + default: + break; + } exit: LogWarnOnError(error, "forward to leader"); @@ -698,6 +719,18 @@ void Manager::CoapDtlsSession::HandleLeaderResponseToFwdTmf(const ForwardContext IgnoreError(mForwardContexts.Remove(aForwardContext)); + switch (aForwardContext.mUri) + { + case kUriLeaderPetition: + Log(kReceive, " response from leader"); + break; + case kUriLeaderKeepAlive: + Log(kReceive, " response from leader"); + break; + default: + break; + } + SuccessOrExit(error = aResult); forwardMessage.Reset(NewPriorityMessage()); @@ -745,7 +778,23 @@ void Manager::CoapDtlsSession::HandleLeaderResponseToFwdTmf(const ForwardContext exit: if (error != kErrorNone) { - LogWarn("Commissioner request failed: %s", ErrorToString(error)); +#if OT_SHOULD_LOG_AT(OT_LOG_LEVEL_WARN) + const char *uriString = "Unknown"; + + switch (aForwardContext.mUri) + { + case kUriLeaderPetition: + uriString = UriToString(); + break; + case kUriLeaderKeepAlive: + uriString = UriToString(); + break; + default: + break; + } + + LogWarn("Forwarded %s failed - session %u, error:%s", uriString, mIndex, ErrorToString(error)); +#endif SendErrorMessage(error, aForwardContext.mToken, aForwardContext.mTokenLength); } @@ -781,10 +830,10 @@ void Manager::CoapDtlsSession::ForwardUdpProxyToCommissioner(const Message SuccessOrExit(error = SendMessage(message.PassOwnership())); - LogInfo("Sent ProxyRx (c/ur) to commissioner"); + Log(kForward); exit: - LogWarnOnError(error, "send ProxyRx (c/ur)"); + LogWarnOnError(error, "forward UDP proxy"); } void Manager::CoapDtlsSession::ForwardUdpRelayToCommissioner(const Message &aMessage) @@ -797,10 +846,10 @@ void Manager::CoapDtlsSession::ForwardUdpRelayToCommissioner(const Message &aMes SuccessOrExit(error = ForwardToCommissioner(forwardMessage.PassOwnership(), aMessage)); - LogInfo("Sent RelayRx (c/rx) to commissioner"); + Log(kForward); exit: - LogWarnOnError(error, "send RelayRx (c/rx)"); + LogWarnOnError(error, "forward UDP relay"); } Error Manager::CoapDtlsSession::ForwardToCommissioner(OwnedPtr aForwardMessage, const Message &aMessage) @@ -845,6 +894,8 @@ void Manager::CoapDtlsSession::HandleTmfProxyTx(Coap::Message &aMessage) OffsetRange offsetRange; UdpEncapsulationTlvHeader udpEncapHeader; + Log(kReceive); + VerifyOrExit(IsActiveCommissioner(), error = kErrorInvalidState); SuccessOrExit(error = Tlv::FindTlvValueOffsetRange(aMessage, Tlv::kUdpEncapsulation, offsetRange)); @@ -869,7 +920,7 @@ void Manager::CoapDtlsSession::HandleTmfProxyTx(Coap::Message &aMessage) SuccessOrExit(error = Get().SendDatagram(*message, messageInfo)); message.Release(); - LogInfo("Proxy transmit sent to %s", messageInfo.GetPeerAddr().ToString().AsCString()); + LogInfo("Sent proxy UDP to %s", messageInfo.GetPeerAddr().ToString().AsCString()); exit: LogWarnOnError(error, "send proxy stream"); @@ -887,6 +938,8 @@ void Manager::CoapDtlsSession::HandleTmfRelayTx(Coap::Message &aMessage) VerifyOrExit(IsActiveCommissioner(), error = kErrorInvalidState); + Log(kReceive); + SuccessOrExit(error = Tlv::Find(aMessage, joinerRouterRloc)); message.Reset(Get().NewPriorityNonConfirmablePostMessage(kUriRelayTx)); @@ -902,10 +955,10 @@ void Manager::CoapDtlsSession::HandleTmfRelayTx(Coap::Message &aMessage) SuccessOrExit(error = Get().SendMessage(*message, messageInfo)); message.Release(); - LogInfo("Sent to joiner router request on RelayTx (c/tx)"); + LogInfo("Forward %s to joiner router 0x%04x", UriToString(), joinerRouterRloc); exit: - LogWarnOnError(error, "send to joiner router request RelayTx (c/tx)"); + LogWarnOnError(error, "forward to joiner router"); } void Manager::CoapDtlsSession::HandleTmfDatasetGet(Coap::Message &aMessage, Uri aUri) @@ -920,6 +973,7 @@ void Manager::CoapDtlsSession::HandleTmfDatasetGet(Coap::Message &aMessage, Uri switch (aUri) { case kUriActiveGet: + Log(kReceive); response.Reset( Get().ProcessGetRequest(aMessage, DatasetManager::kIgnoreSecurityPolicyFlags)); Get().mCounters.mMgmtActiveGets++; @@ -932,6 +986,7 @@ void Manager::CoapDtlsSession::HandleTmfDatasetGet(Coap::Message &aMessage, Uri break; case kUriPendingGet: + Log(kReceive); response.Reset( Get().ProcessGetRequest(aMessage, DatasetManager::kIgnoreSecurityPolicyFlags)); Get().mCounters.mMgmtPendingGets++; @@ -944,6 +999,7 @@ void Manager::CoapDtlsSession::HandleTmfDatasetGet(Coap::Message &aMessage, Uri break; case kUriCommissionerGet: + Log(kReceive); response.Reset(Get().ProcessCommissionerGetRequest(aMessage)); break; @@ -955,7 +1011,20 @@ void Manager::CoapDtlsSession::HandleTmfDatasetGet(Coap::Message &aMessage, Uri SuccessOrExit(error = SendMessage(response.PassOwnership())); - LogInfo("Sent %s response to non-active commissioner", PathForUri(aUri)); + switch (aUri) + { + case kUriActiveGet: + Log(kSend, " response"); + break; + case kUriPendingGet: + Log(kSend, " response"); + break; + case kUriCommissionerGet: + Log(kSend, " response"); + break; + default: + break; + } exit: LogWarnOnError(error, "send Active/Pending/CommissionerGet response"); @@ -970,11 +1039,35 @@ void Manager::CoapDtlsSession::HandleTimer(void) { if (IsConnected()) { - LogInfo("Session timed out - disconnecting"); + LogInfo("Session %u timed out - disconnecting", mIndex); DisconnectTimeout(); } } +#if OT_SHOULD_LOG_AT(OT_LOG_LEVEL_INFO) + +void Manager::CoapDtlsSession::LogUri(Action aAction, const char *aUriString, const char *aTxt) +{ + static const char *const kActionStrings[] = { + "Receive", // kReceive + "Send", // kSend + "Forward", // kForward, + }; + + struct EnumChecker + { + InitEnumValidatorCounter(); + + ValidateNextEnum(kReceive); + ValidateNextEnum(kSend); + ValidateNextEnum(kForward); + }; + + LogInfo("%s %s%s - session %u", kActionStrings[aAction], aUriString, aTxt, mIndex); +} + +#endif + //---------------------------------------------------------------------------------------------------------------------- // `Manager::CoapDtlsSession::ForwardContext` diff --git a/src/core/meshcop/border_agent.hpp b/src/core/meshcop/border_agent.hpp index dacca854e..ec1ab8274 100644 --- a/src/core/meshcop/border_agent.hpp +++ b/src/core/meshcop/border_agent.hpp @@ -47,6 +47,7 @@ #include "common/heap_allocatable.hpp" #include "common/linked_list.hpp" #include "common/locator.hpp" +#include "common/log.hpp" #include "common/non_copyable.hpp" #include "common/notifier.hpp" #include "common/owned_ptr.hpp" @@ -261,8 +262,16 @@ private: void Cleanup(void); bool IsActiveCommissioner(void) const; uint64_t GetAllocationTime(void) const { return mAllocationTime; } + uint16_t GetIndex(void) const { return mIndex; } private: + enum Action : uint8_t + { + kReceive, + kSend, + kForward, + }; + struct ForwardContext : public ot::LinkedListEntry, public Heap::Allocatable, private ot::NonCopyable @@ -303,9 +312,20 @@ private: static void HandleTimer(Timer &aTimer); void HandleTimer(void); +#if OT_SHOULD_LOG_AT(OT_LOG_LEVEL_INFO) + void LogUri(Action aAction, const char *aUriString, const char *aTxt); + + template void Log(Action aAction) { Log(aAction, ""); } + template void Log(Action aAction, const char *aTxt) { LogUri(aAction, UriToString(), aTxt); } +#else + template void Log(Action) {} + template void Log(Action, const char *) {} +#endif + LinkedList mForwardContexts; TimerMilliContext mTimer; uint64_t mAllocationTime; + uint16_t mIndex; }; void UpdateState(void); @@ -323,6 +343,7 @@ private: static void HandleRemoveSession(void *aContext, SecureSession &aSession); void HandleRemoveSession(SecureSession &aSession); + uint16_t GetNextSessionIndex(void) { return ++mSessionIndex; } const Ip6::Address &GetCommissionerAloc(void) const { return mCommissionerAloc.GetAddress(); } CoapDtlsSession *GetCommissionerSession(void) { return mCommissionerSession; } @@ -356,6 +377,7 @@ private: bool mEnabled; bool mIsRunning; + uint16_t mSessionIndex; Dtls::Transport mDtlsTransport; CoapDtlsSession *mCommissionerSession; Ip6::Udp::Receiver mCommissionerUdpReceiver;