From fdb3d0ef58fb21d0b6a3d5507c4e8dd37e2ad3af Mon Sep 17 00:00:00 2001 From: Abtin Keshavarzian Date: Fri, 29 Jun 2018 11:00:53 -0700 Subject: [PATCH] [mesh-forwarder] update `LogMessage` to use NOTE level for failure/error cases (#2836) This commit also contains - Adding `Instance::GetLogLevel()` to get current log level on device. - Adding new `otLogMac()` macro to log at MAC region with a run-time given log level. --- include/openthread/platform/logging-windows.h | 5 ++ src/core/common/instance.hpp | 17 +++++ src/core/common/logging.cpp | 34 +++++++++ src/core/common/logging.hpp | 45 ++++++++++-- src/core/thread/mesh_forwarder.cpp | 71 +++++++++++++------ src/core/thread/mesh_forwarder.hpp | 27 +++++-- src/core/thread/mesh_forwarder_ftd.cpp | 32 +++++---- 7 files changed, 182 insertions(+), 49 deletions(-) diff --git a/include/openthread/platform/logging-windows.h b/include/openthread/platform/logging-windows.h index 7f94a505e..6269a7b0e 100644 --- a/include/openthread/platform/logging-windows.h +++ b/include/openthread/platform/logging-windows.h @@ -442,6 +442,11 @@ // USESUFFIX(otLogDebgMacErr, ", %!otError!", EXP); // end_wpp +// begin_wpp config +// USEPREFIX (otLogMac, "[%p]MAC%!SPACE!", &CTX); +// otLogMac{LEVEL=TRACE_LEVEL_INFORMATION,FLAGS=OT_MAC}(CTX, EXP, MSG, ...); +// end_wpp + // ==CORE== // begin_wpp config diff --git a/src/core/common/instance.hpp b/src/core/common/instance.hpp index 2c48f6c34..250396598 100644 --- a/src/core/common/instance.hpp +++ b/src/core/common/instance.hpp @@ -194,6 +194,23 @@ public: void SetDynamicLogLevel(otLogLevel aLogLevel) { mLogLevel = aLogLevel; } #endif + /** + * This method returns the active log level. + * + * @returns The log level. + * + */ + otLogLevel GetLogLevel(void) const +#if OPENTHREAD_CONFIG_ENABLE_DYNAMIC_LOG_LEVEL + { + return GetDynamicLogLevel(); + } +#else + { + return static_cast(OPENTHREAD_CONFIG_LOG_LEVEL); + } +#endif + #if OPENTHREAD_MTD || OPENTHREAD_FTD /** * This method finalizes the OpenThread instance. diff --git a/src/core/common/logging.cpp b/src/core/common/logging.cpp index 3f429429e..3521beacf 100644 --- a/src/core/common/logging.cpp +++ b/src/core/common/logging.cpp @@ -327,6 +327,40 @@ const char *otThreadErrorToString(otError aError) return retval; } +const char *otLogLevelToPrefixString(otLogLevel aLogLevel) +{ + const char *retval = ""; + + switch (aLogLevel) + { + case OT_LOG_LEVEL_NONE: + retval = _OT_LEVEL_NONE_PREFIX; + break; + + case OT_LOG_LEVEL_CRIT: + retval = _OT_LEVEL_CRIT_PREFIX; + break; + + case OT_LOG_LEVEL_WARN: + retval = _OT_LEVEL_WARN_PREFIX; + break; + + case OT_LOG_LEVEL_NOTE: + retval = _OT_LEVEL_NOTE_PREFIX; + break; + + case OT_LOG_LEVEL_INFO: + retval = _OT_LEVEL_INFO_PREFIX; + break; + + case OT_LOG_LEVEL_DEBG: + retval = _OT_LEVEL_DEBG_PREFIX; + break; + } + + return retval; +} + #if OPENTHREAD_CONFIG_LOG_OUTPUT == OPENTHREAD_CONFIG_LOG_OUTPUT_NONE /* this provides a stub, incase something uses the function */ void otPlatLog(otLogLevel aLogLevel, otLogRegion aLogRegion, const char *aFormat, ...) diff --git a/src/core/common/logging.hpp b/src/core/common/logging.hpp index 63120d77a..afa747f4c 100644 --- a/src/core/common/logging.hpp +++ b/src/core/common/logging.hpp @@ -71,12 +71,12 @@ extern "C" { #define _OT_LEVEL_DEBG_PREFIX "[DEBG]" #define _OT_REGION_SUFFIX ": " #else -#define _OT_LEVEL_NONE_PREFIX -#define _OT_LEVEL_CRIT_PREFIX -#define _OT_LEVEL_WARN_PREFIX -#define _OT_LEVEL_NOTE_PREFIX -#define _OT_LEVEL_INFO_PREFIX -#define _OT_LEVEL_DEBG_PREFIX +#define _OT_LEVEL_NONE_PREFIX "" +#define _OT_LEVEL_CRIT_PREFIX "" +#define _OT_LEVEL_WARN_PREFIX "" +#define _OT_LEVEL_NOTE_PREFIX "" +#define _OT_LEVEL_INFO_PREFIX "" +#define _OT_LEVEL_DEBG_PREFIX "" #define _OT_REGION_SUFFIX #endif @@ -789,6 +789,18 @@ extern "C" { * @param[in] ... Arguments for the format specification. * */ + +/** + * @def otLogMac + * + * This method generates a log with a given log level for the MAC region. + * + * @param[in] aInstance A reference to the OpenThread instance. + * @param[in] aLogLevel A log level. + * @param[in] aFormat A pointer to the format string. + * @param[in] ... Arguments for the format specification. + * + */ #if OPENTHREAD_CONFIG_LOG_MAC == 1 #define otLogCritMac(aInstance, aFormat, ...) \ otLogCrit(&aInstance, OT_LOG_REGION_MAC, _OT_REGION_MAC_PREFIX aFormat, ##__VA_ARGS__) @@ -803,6 +815,16 @@ extern "C" { #define otLogDebgMacErr(aInstance, aError, aFormat, ...) \ otLogWarn(aInstance, OT_LOG_REGION_MAC, _OT_REGION_MAC_PREFIX "Error %s: " aFormat, otThreadErrorToString(aError), \ ##__VA_ARGS__) +#define otLogMac(aInstance, aLogLevel, aFormat, ...) \ + do \ + { \ + if (aInstance.GetLogLevel() >= aLogLevel) \ + { \ + _otLogFormatter(&aInstance, aLogLevel, OT_LOG_REGION_MAC, "%s" _OT_REGION_MAC_PREFIX aFormat, \ + otLogLevelToPrefixString(aLogLevel), ##__VA_ARGS__); \ + } \ + } while (false) + #else #define otLogCritMac(aInstance, aFormat, ...) #define otLogWarnMac(aInstance, aFormat, ...) @@ -810,6 +832,7 @@ extern "C" { #define otLogInfoMac(aInstance, aFormat, ...) #define otLogDebgMac(aInstance, aFormat, ...) #define otLogDebgMacErr(aInstance, aError, aFormat, ...) +#define otLogMac(aInstance, aLogLevel, aFormat, ...) #endif /** @@ -2072,6 +2095,16 @@ void otDump(otInstance * aIntsance, const void * aBuf, const size_t aLength); +/** + * This function converts a log level to a prefix string for appending to log message. + * + * @param[in] aLogLevel A log level. + * + * @returns A C string representing the log level. + * + */ +const char *otLogLevelToPrefixString(otLogLevel aLogLevel); + /** * Local/private macro to format the log message */ diff --git a/src/core/thread/mesh_forwarder.cpp b/src/core/thread/mesh_forwarder.cpp index 572795e32..dea115d3a 100644 --- a/src/core/thread/mesh_forwarder.cpp +++ b/src/core/thread/mesh_forwarder.cpp @@ -1486,7 +1486,7 @@ void MeshForwarder::HandleDataPollTimeout(Mac::Receiver &aReceiver) aReceiver.GetOwner().GetDataPollManager().HandlePollTimeout(); } -#if (OPENTHREAD_CONFIG_LOG_LEVEL >= OT_LOG_LEVEL_INFO) && (OPENTHREAD_CONFIG_LOG_MAC == 1) +#if (OPENTHREAD_CONFIG_LOG_LEVEL >= OT_LOG_LEVEL_NOTE) && (OPENTHREAD_CONFIG_LOG_MAC == 1) otError MeshForwarder::ParseIp6UdpTcpHeader(const Message &aMessage, Ip6::Header & aIp6Header, @@ -1595,28 +1595,32 @@ const char *MeshForwarder::MessagePriorityToString(const Message &aMessage) } #if OPENTHREAD_CONFIG_LOG_SRC_DST_IP_ADDRESSES -void MeshForwarder::LogIp6SourceDestAddresses(Ip6::Header &aIp6Header, uint16_t aSourcePort, uint16_t aDestPort) +void MeshForwarder::LogIp6SourceDestAddresses(Ip6::Header &aIp6Header, + uint16_t aSourcePort, + uint16_t aDestPort, + otLogLevel aLogLevel) { if (aSourcePort != 0) { - otLogInfoMac(GetInstance(), "\tsrc:[%s]:%d", aIp6Header.GetSource().ToString().AsCString(), aSourcePort); + otLogMac(GetInstance(), aLogLevel, "\tsrc:[%s]:%d", aIp6Header.GetSource().ToString().AsCString(), aSourcePort); } else { - otLogInfoMac(GetInstance(), "\tsrc:[%s]", aIp6Header.GetSource().ToString().AsCString()); + otLogMac(GetInstance(), aLogLevel, "\tsrc:[%s]", aIp6Header.GetSource().ToString().AsCString()); } if (aDestPort != 0) { - otLogInfoMac(GetInstance(), "\tdst:[%s]:%d", aIp6Header.GetDestination().ToString().AsCString(), aDestPort); + otLogMac(GetInstance(), aLogLevel, "\tdst:[%s]:%d", aIp6Header.GetDestination().ToString().AsCString(), + aDestPort); } else { - otLogInfoMac(GetInstance(), "\tdst:[%s]", aIp6Header.GetDestination().ToString().AsCString()); + otLogMac(GetInstance(), aLogLevel, "\tdst:[%s]", aIp6Header.GetDestination().ToString().AsCString()); } } #else -void MeshForwarder::LogIp6SourceDestAddresses(Ip6::Header &, uint16_t, uint16_t) +void MeshForwarder::LogIp6SourceDestAddresses(Ip6::Header &, uint16_t, uint16_t, otLogLevel) { } #endif @@ -1624,7 +1628,8 @@ void MeshForwarder::LogIp6SourceDestAddresses(Ip6::Header &, uint16_t, uint16_t) void MeshForwarder::LogIp6Message(MessageAction aAction, const Message & aMessage, const Mac::Address *aMacAddress, - otError aError) + otError aError, + otLogLevel aLogLevel) { Ip6::Header ip6Header; uint16_t checksum; @@ -1636,18 +1641,18 @@ void MeshForwarder::LogIp6Message(MessageAction aAction, shouldLogRss = (aAction == kMessageReceive) || (aAction == kMessageReassemblyDrop); - otLogInfoMac(GetInstance(), "%s IPv6 %s msg, len:%d, chksum:%04x%s%s, sec:%s%s%s, prio:%s%s%s", - MessageActionToString(aAction, aError), Ip6::Ip6::IpProtoToString(ip6Header.GetNextHeader()), - aMessage.GetLength(), checksum, - (aMacAddress == NULL) ? "" : ((aAction == kMessageReceive) ? ", from:" : ", to:"), - (aMacAddress == NULL) ? "" : aMacAddress->ToString().AsCString(), - aMessage.IsLinkSecurityEnabled() ? "yes" : "no", (aError == OT_ERROR_NONE) ? "" : ", error:", - (aError == OT_ERROR_NONE) ? "" : otThreadErrorToString(aError), MessagePriorityToString(aMessage), - shouldLogRss ? ", rss:" : "", shouldLogRss ? aMessage.GetRssAverager().ToString().AsCString() : ""); + otLogMac(GetInstance(), aLogLevel, "%s IPv6 %s msg, len:%d, chksum:%04x%s%s, sec:%s%s%s, prio:%s%s%s", + MessageActionToString(aAction, aError), Ip6::Ip6::IpProtoToString(ip6Header.GetNextHeader()), + aMessage.GetLength(), checksum, + (aMacAddress == NULL) ? "" : ((aAction == kMessageReceive) ? ", from:" : ", to:"), + (aMacAddress == NULL) ? "" : aMacAddress->ToString().AsCString(), + aMessage.IsLinkSecurityEnabled() ? "yes" : "no", (aError == OT_ERROR_NONE) ? "" : ", error:", + (aError == OT_ERROR_NONE) ? "" : otThreadErrorToString(aError), MessagePriorityToString(aMessage), + shouldLogRss ? ", rss:" : "", shouldLogRss ? aMessage.GetRssAverager().ToString().AsCString() : ""); if (aAction != kMessagePrepareIndirect) { - LogIp6SourceDestAddresses(ip6Header, sourcePort, destPort); + LogIp6SourceDestAddresses(ip6Header, sourcePort, destPort, aLogLevel); } exit: @@ -1659,28 +1664,50 @@ void MeshForwarder::LogMessage(MessageAction aAction, const Mac::Address *aMacAddress, otError aError) { + otLogLevel logLevel = OT_LOG_LEVEL_INFO; + + switch (aAction) + { + case kMessageReceive: + case kMessageTransmit: + case kMessagePrepareIndirect: + logLevel = (aError == OT_ERROR_NONE) ? OT_LOG_LEVEL_INFO : OT_LOG_LEVEL_NOTE; + break; + + case kMessageDrop: + case kMessageReassemblyDrop: + case kMessageEvict: + logLevel = OT_LOG_LEVEL_NOTE; + break; + } + + VerifyOrExit(GetInstance().GetLogLevel() >= logLevel); + switch (aMessage.GetType()) { case Message::kTypeIp6: - LogIp6Message(aAction, aMessage, aMacAddress, aError); + LogIp6Message(aAction, aMessage, aMacAddress, aError, logLevel); break; #if OPENTHREAD_FTD case Message::kType6lowpan: - LogMeshMessage(aAction, aMessage, aMacAddress, aError); + LogMeshMessage(aAction, aMessage, aMacAddress, aError, logLevel); break; #endif default: break; } + +exit: + return; } void MeshForwarder::LogFrame(const char *aActionText, const Mac::Frame &aFrame, otError aError) { if (aError != OT_ERROR_NONE) { - otLogInfoMac(GetInstance(), "%s, aError:%s, %s", aActionText, otThreadErrorToString(aError), + otLogNoteMac(GetInstance(), "%s, aError:%s, %s", aActionText, otThreadErrorToString(aError), aFrame.ToInfoString().AsCString()); } else @@ -1696,7 +1723,7 @@ void MeshForwarder::LogFragmentFrameDrop(otError aError, const Lowpan::FragmentHeader &aFragmentHeader, bool aIsSecure) { - otLogInfoMac(GetInstance(), + otLogNoteMac(GetInstance(), "Dropping rx frag frame, error:%s, len:%d, src:%s, dst:%s, tag:%d, offset:%d, dglen:%d, sec:%s", otThreadErrorToString(aError), aFrameLength, aMacSource.ToString().AsCString(), aMacDest.ToString().AsCString(), aFragmentHeader.GetDatagramTag(), aFragmentHeader.GetDatagramOffset(), @@ -1709,7 +1736,7 @@ void MeshForwarder::LogLowpanHcFrameDrop(otError aError, const Mac::Address &aMacDest, bool aIsSecure) { - otLogInfoMac(GetInstance(), "Dropping rx lowpan HC frame, error:%s, len:%d, src:%s, dst:%s, sec:%s", + otLogNoteMac(GetInstance(), "Dropping rx lowpan HC frame, error:%s, len:%d, src:%s, dst:%s, sec:%s", otThreadErrorToString(aError), aFrameLength, aMacSource.ToString().AsCString(), aMacDest.ToString().AsCString(), aIsSecure ? "yes" : "no"); } diff --git a/src/core/thread/mesh_forwarder.hpp b/src/core/thread/mesh_forwarder.hpp index 873648266..f6728f55c 100644 --- a/src/core/thread/mesh_forwarder.hpp +++ b/src/core/thread/mesh_forwarder.hpp @@ -340,7 +340,7 @@ private: const Mac::Address &aMacDest, bool aIsSecure); -#if (OPENTHREAD_CONFIG_LOG_LEVEL >= OT_LOG_LEVEL_INFO) && (OPENTHREAD_CONFIG_LOG_MAC == 1) +#if (OPENTHREAD_CONFIG_LOG_LEVEL >= OT_LOG_LEVEL_NOTE) && (OPENTHREAD_CONFIG_LOG_MAC == 1) const char *MessageActionToString(MessageAction aAction, otError aError); const char *MessagePriorityToString(const Message &aMessage); @@ -364,16 +364,29 @@ private: otError aError, uint16_t & aOffset, Mac::Address & aMeshSource, - Mac::Address & aMeshDest); + Mac::Address & aMeshDest, + otLogLevel aLogLevel); void LogMeshIpHeader(const Message & aMessage, uint16_t aOffset, const Mac::Address &aMeshSource, - const Mac::Address &aMeshDest); - void LogMeshMessage(MessageAction aAction, const Message &aMessage, const Mac::Address *aAddress, otError aError); + const Mac::Address &aMeshDest, + otLogLevel aLogLevel); + void LogMeshMessage(MessageAction aAction, + const Message & aMessage, + const Mac::Address *aAddress, + otError aError, + otLogLevel aLogLevel); #endif - void LogIp6SourceDestAddresses(Ip6::Header &aIp6Header, uint16_t aSourcePort, uint16_t aDestPort); - void LogIp6Message(MessageAction aAction, const Message &aMessage, const Mac::Address *aAddress, otError aError); -#endif // #if (OPENTHREAD_CONFIG_LOG_LEVEL >= OT_LOG_LEVEL_INFO) && (OPENTHREAD_CONFIG_LOG_MAC == 1) + void LogIp6SourceDestAddresses(Ip6::Header &aIp6Header, + uint16_t aSourcePort, + uint16_t aDestPort, + otLogLevel aLogLevel); + void LogIp6Message(MessageAction aAction, + const Message & aMessage, + const Mac::Address *aAddress, + otError aError, + otLogLevel aLogLevel); +#endif // #if (OPENTHREAD_CONFIG_LOG_LEVEL >= OT_LOG_LEVEL_NOTE) && (OPENTHREAD_CONFIG_LOG_MAC == 1) Mac::Receiver mMacReceiver; Mac::Sender mMacSender; diff --git a/src/core/thread/mesh_forwarder_ftd.cpp b/src/core/thread/mesh_forwarder_ftd.cpp index 051a3021d..48bafccf8 100644 --- a/src/core/thread/mesh_forwarder_ftd.cpp +++ b/src/core/thread/mesh_forwarder_ftd.cpp @@ -1051,7 +1051,7 @@ exit: } #endif // OPENTHREAD_ENABLE_SERVICE -#if (OPENTHREAD_CONFIG_LOG_LEVEL >= OT_LOG_LEVEL_INFO) && (OPENTHREAD_CONFIG_LOG_MAC == 1) +#if (OPENTHREAD_CONFIG_LOG_LEVEL >= OT_LOG_LEVEL_NOTE) && (OPENTHREAD_CONFIG_LOG_MAC == 1) otError MeshForwarder::LogMeshFragmentHeader(MessageAction aAction, const Message & aMessage, @@ -1059,7 +1059,8 @@ otError MeshForwarder::LogMeshFragmentHeader(MessageAction aAction, otError aError, uint16_t & aOffset, Mac::Address & aMeshSource, - Mac::Address & aMeshDest) + Mac::Address & aMeshDest, + otLogLevel aLogLevel) { otError error = OT_ERROR_FAILED; bool hasFragmentHeader = false; @@ -1083,8 +1084,8 @@ otError MeshForwarder::LogMeshFragmentHeader(MessageAction aAction, shouldLogRss = (aAction == kMessageReceive) || (aAction == kMessageReassemblyDrop); - otLogInfoMac( - GetInstance(), "%s mesh frame, len:%d%s%s, msrc:%s, mdst:%s, hops:%d, frag:%s, sec:%s%s%s%s%s", + otLogMac( + GetInstance(), aLogLevel, "%s mesh frame, len:%d%s%s, msrc:%s, mdst:%s, hops:%d, frag:%s, sec:%s%s%s%s%s", MessageActionToString(aAction, aError), aMessage.GetLength(), (aMacAddress == NULL) ? "" : ((aAction == kMessageReceive) ? ", from:" : ", to:"), (aMacAddress == NULL) ? "" : aMacAddress->ToString().AsCString(), aMeshSource.ToString().AsCString(), @@ -1095,8 +1096,8 @@ otError MeshForwarder::LogMeshFragmentHeader(MessageAction aAction, if (hasFragmentHeader) { - otLogInfoMac(GetInstance(), "\tFrag tag:%04x, offset:%d, size:%d", fragmentHeader.GetDatagramTag(), - fragmentHeader.GetDatagramOffset(), fragmentHeader.GetDatagramSize()); + otLogMac(GetInstance(), aLogLevel, "\tFrag tag:%04x, offset:%d, size:%d", fragmentHeader.GetDatagramTag(), + fragmentHeader.GetDatagramOffset(), fragmentHeader.GetDatagramSize()); VerifyOrExit(fragmentHeader.GetDatagramOffset() == 0); } @@ -1183,7 +1184,8 @@ exit: void MeshForwarder::LogMeshIpHeader(const Message & aMessage, uint16_t aOffset, const Mac::Address &aMeshSource, - const Mac::Address &aMeshDest) + const Mac::Address &aMeshDest, + otLogLevel aLogLevel) { uint16_t checksum; uint16_t sourcePort; @@ -1193,10 +1195,10 @@ void MeshForwarder::LogMeshIpHeader(const Message & aMessage, SuccessOrExit(DecompressIp6UdpTcpHeader(aMessage, aOffset, aMeshSource, aMeshDest, ip6Header, checksum, sourcePort, destPort)); - otLogInfoMac(GetInstance(), "\tIPv6 %s msg, chksum:%04x, prio:%s", - Ip6::Ip6::IpProtoToString(ip6Header.GetNextHeader()), checksum, MessagePriorityToString(aMessage)); + otLogMac(GetInstance(), aLogLevel, "\tIPv6 %s msg, chksum:%04x, prio:%s", + Ip6::Ip6::IpProtoToString(ip6Header.GetNextHeader()), checksum, MessagePriorityToString(aMessage)); - LogIp6SourceDestAddresses(ip6Header, sourcePort, destPort); + LogIp6SourceDestAddresses(ip6Header, sourcePort, destPort, aLogLevel); exit: return; @@ -1205,13 +1207,15 @@ exit: void MeshForwarder::LogMeshMessage(MessageAction aAction, const Message & aMessage, const Mac::Address *aMacAddress, - otError aError) + otError aError, + otLogLevel aLogLevel) { uint16_t offset; Mac::Address meshSource; Mac::Address meshDest; - SuccessOrExit(LogMeshFragmentHeader(aAction, aMessage, aMacAddress, aError, offset, meshSource, meshDest)); + SuccessOrExit( + LogMeshFragmentHeader(aAction, aMessage, aMacAddress, aError, offset, meshSource, meshDest, aLogLevel)); // When log action is `kMessageTransmit` we do not include // the IPv6 header info in the logs, as the same info is @@ -1220,13 +1224,13 @@ void MeshForwarder::LogMeshMessage(MessageAction aAction, VerifyOrExit(aAction != kMessageTransmit); - LogMeshIpHeader(aMessage, offset, meshSource, meshDest); + LogMeshIpHeader(aMessage, offset, meshSource, meshDest, aLogLevel); exit: return; } -#endif // #if (OPENTHREAD_CONFIG_LOG_LEVEL >= OT_LOG_LEVEL_INFO) && (OPENTHREAD_CONFIG_LOG_MAC == 1) +#endif // #if (OPENTHREAD_CONFIG_LOG_LEVEL >= OT_LOG_LEVEL_NOTE) && (OPENTHREAD_CONFIG_LOG_MAC == 1) } // namespace ot