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;