From cd5768b89d9f26e35dbda48b806a77188bb976d6 Mon Sep 17 00:00:00 2001 From: Abtin Keshavarzian Date: Tue, 17 Oct 2023 10:42:47 -0700 Subject: [PATCH] [logging] add new `otLogPlat()` APIs with sub-module name (#9516) This commit adds new public OT logging APIs `otLogPlat()` and `otLogPlatArgs()`, which allow the caller to specify a platform sub-module name to be included in the emitted log. This makes it easier to distinguish logs from the platform layer and filter the logs. This commit also updates the `RadioSpinel` class to use the new API, ensuring that its logs use the "P-RadioSpinel" module name. --- include/openthread/instance.h | 2 +- include/openthread/logging.h | 39 +++++++ src/core/api/logging_api.cpp | 33 ++++++ src/lib/spinel/radio_spinel.cpp | 195 ++++++++++++++++++++------------ src/lib/spinel/radio_spinel.hpp | 10 +- 5 files changed, 202 insertions(+), 77 deletions(-) diff --git a/include/openthread/instance.h b/include/openthread/instance.h index b60d8900cff..7f9bc8915eb 100644 --- a/include/openthread/instance.h +++ b/include/openthread/instance.h @@ -53,7 +53,7 @@ extern "C" { * @note This number versions both OpenThread platform and user APIs. * */ -#define OPENTHREAD_API_VERSION (366) +#define OPENTHREAD_API_VERSION (367) /** * @addtogroup api-instance diff --git a/include/openthread/logging.h b/include/openthread/logging.h index 143a0d51118..1f989851aba 100644 --- a/include/openthread/logging.h +++ b/include/openthread/logging.h @@ -201,6 +201,45 @@ void otDumpInfoPlat(const char *aText, const void *aData, uint16_t aDataLength); */ void otDumpDebgPlat(const char *aText, const void *aData, uint16_t aDataLength); +/** + * Emits a log message at given log level using a platform module name. + * + * This is is intended for use by platform. If `OPENTHREAD_CONFIG_LOG_PLATFORM` is not set or the current log + * level is below @p aLogLevel , this function does not emit any log message. + * + * The @p aPlatModuleName name is used to determine the log module name in the emitted log message, following the + * `P-{PlatModuleName}---` format. This means that the prefix string "P-" is added to indicate that this is a platform + * sub-module, followed by the next 12 characters of the @p PlatModuleName string, with padded hyphens `-` at the end + * to ensure that the region name is 14 characters long. + + * @param[in] aLogLevel The log level. + * @param[in] aPlatModuleName The platform sub-module name. + * @param[in] aFormat The format string. + * @param[in] ... Arguments for the format specification. + * + */ +void otLogPlat(otLogLevel aLogLevel, const char *aPlatModuleName, const char *aFormat, ...) + OT_TOOL_PRINTF_STYLE_FORMAT_ARG_CHECK(3, 4); + +/** + * Emits a log message at given log level using a platform module name. + * + * This is is intended for use by platform. If `OPENTHREAD_CONFIG_LOG_PLATFORM` is not set or the current log + * level is below @p aLogLevel , this function does not emit any log message. + * + * The @p aPlatModuleName name is used to determine the log module name in the emitted log message, following the + * `P-{PlatModuleName}---` format. This means that the prefix string "P-" is added to indicate that this is a platform + * sub-module, followed by the next 12 characters of the @p PlatModuleName string, with padded hyphens `-` at the end + * to ensure that the region name is 14 characters long. + * + * @param[in] aLogLevel The log level. + * @param[in] aPlatModuleName The platform sub-module name. + * @param[in] aFormat The format string. + * @param[in] aArgs Arguments for the format specification. + * + */ +void otLogPlatArgs(otLogLevel aLogLevel, const char *aPlatModuleName, const char *aFormat, va_list aArgs); + /** * Emits a log message at a given log level. * diff --git a/src/core/api/logging_api.cpp b/src/core/api/logging_api.cpp index edce6b9201b..0245f5b8905 100644 --- a/src/core/api/logging_api.cpp +++ b/src/core/api/logging_api.cpp @@ -38,6 +38,7 @@ #include "common/instance.hpp" #include "common/locator_getters.hpp" #include "common/log.hpp" +#include "common/string.hpp" using namespace ot; @@ -179,6 +180,38 @@ void otDumpDebgPlat(const char *aText, const void *aData, uint16_t aDataLength) #endif } +void otLogPlat(otLogLevel aLogLevel, const char *aPlatModuleName, const char *aFormat, ...) +{ +#if OPENTHREAD_CONFIG_LOG_PLATFORM + va_list args; + + va_start(args, aFormat); + otLogPlatArgs(aLogLevel, aPlatModuleName, aFormat, args); + va_end(args); +#else + OT_UNUSED_VARIABLE(aLogLevel); + OT_UNUSED_VARIABLE(aPlatModuleName); + OT_UNUSED_VARIABLE(aFormat); +#endif +} + +void otLogPlatArgs(otLogLevel aLogLevel, const char *aPlatModuleName, const char *aFormat, va_list aArgs) +{ +#if OT_SHOULD_LOG && OPENTHREAD_CONFIG_LOG_PLATFORM + String moduleName; + + OT_ASSERT(aLogLevel >= kLogLevelNone && aLogLevel <= kLogLevelDebg); + + moduleName.Append("P-%s", aPlatModuleName); + Logger::LogVarArgs(moduleName.AsCString(), static_cast(aLogLevel), aFormat, aArgs); +#else + OT_UNUSED_VARIABLE(aLogLevel); + OT_UNUSED_VARIABLE(aPlatModuleName); + OT_UNUSED_VARIABLE(aFormat); + OT_UNUSED_VARIABLE(aArgs); +#endif +} + void otLogCli(otLogLevel aLogLevel, const char *aFormat, ...) { #if OT_SHOULD_LOG && OPENTHREAD_CONFIG_LOG_CLI diff --git a/src/lib/spinel/radio_spinel.cpp b/src/lib/spinel/radio_spinel.cpp index e933874e780..9328184d996 100644 --- a/src/lib/spinel/radio_spinel.cpp +++ b/src/lib/spinel/radio_spinel.cpp @@ -143,7 +143,7 @@ void RadioSpinel::ResetRcp(bool aResetRadio) if (aResetRadio && (SendReset(SPINEL_RESET_STACK) == OT_ERROR_NONE) && (WaitResponse(false) == OT_ERROR_NONE)) { - otLogInfoPlat("Software reset RCP successfully"); + LogInfo("Software reset RCP successfully"); ExitNow(resetDone = true); } @@ -158,17 +158,17 @@ void RadioSpinel::ResetRcp(bool aResetRadio) if (hardwareReset) { - otLogInfoPlat("Hardware reset RCP successfully"); + LogInfo("Hardware reset RCP successfully"); } else { - otLogInfoPlat("RCP self reset successfully"); + LogInfo("RCP self reset successfully"); } exit: if (!resetDone) { - otLogCritPlat("Failed to reset RCP!"); + LogCrit("Failed to reset RCP!"); DieNow(OT_EXIT_FAILURE); } } @@ -186,8 +186,8 @@ otError RadioSpinel::CheckSpinelVersion(void) if ((versionMajor != SPINEL_PROTOCOL_VERSION_THREAD_MAJOR) || (versionMinor != SPINEL_PROTOCOL_VERSION_THREAD_MINOR)) { - otLogCritPlat("Spinel version mismatch - Posix:%d.%d, RCP:%d.%d", SPINEL_PROTOCOL_VERSION_THREAD_MAJOR, - SPINEL_PROTOCOL_VERSION_THREAD_MINOR, versionMajor, versionMinor); + LogCrit("Spinel version mismatch - Posix:%d.%d, RCP:%d.%d", SPINEL_PROTOCOL_VERSION_THREAD_MAJOR, + SPINEL_PROTOCOL_VERSION_THREAD_MINOR, versionMajor, versionMinor); DieNow(OT_EXIT_RADIO_SPINEL_INCOMPATIBLE); } @@ -247,7 +247,7 @@ bool RadioSpinel::IsRcp(bool &aSupportsRcpApiVersion, bool &aSupportsRcpMinHostA if (!supportsRawRadio && isRcp) { - otLogCritPlat("RCP capability list does not include support for radio/raw mode"); + LogCrit("RCP capability list does not include support for radio/raw mode"); DieNow(OT_EXIT_RADIO_SPINEL_INCOMPATIBLE); } @@ -272,16 +272,16 @@ otError RadioSpinel::CheckRadioCapabilities(void) { otRadioCaps missingCaps = (mRadioCaps & kRequiredRadioCaps) ^ kRequiredRadioCaps; - // missingCaps may be an unused variable when otLogCritPlat is blank + // missingCaps may be an unused variable when LogCrit is blank // avoid compiler warning in that case OT_UNUSED_VARIABLE(missingCaps); - otLogCritPlat("RCP is missing required capabilities: %s%s%s%s%s", - (missingCaps & OT_RADIO_CAPS_ACK_TIMEOUT) ? "ack-timeout " : "", - (missingCaps & OT_RADIO_CAPS_TRANSMIT_RETRIES) ? "tx-retries " : "", - (missingCaps & OT_RADIO_CAPS_CSMA_BACKOFF) ? "CSMA-backoff " : "", - (missingCaps & OT_RADIO_CAPS_TRANSMIT_SEC) ? "tx-security " : "", - (missingCaps & OT_RADIO_CAPS_TRANSMIT_TIMING) ? "tx-timing " : ""); + LogCrit("RCP is missing required capabilities: %s%s%s%s%s", + (missingCaps & OT_RADIO_CAPS_ACK_TIMEOUT) ? "ack-timeout " : "", + (missingCaps & OT_RADIO_CAPS_TRANSMIT_RETRIES) ? "tx-retries " : "", + (missingCaps & OT_RADIO_CAPS_CSMA_BACKOFF) ? "CSMA-backoff " : "", + (missingCaps & OT_RADIO_CAPS_TRANSMIT_SEC) ? "tx-security " : "", + (missingCaps & OT_RADIO_CAPS_TRANSMIT_TIMING) ? "tx-timing " : ""); DieNow(OT_EXIT_RADIO_SPINEL_INCOMPATIBLE); } @@ -308,9 +308,9 @@ otError RadioSpinel::CheckRcpApiVersion(bool aSupportsRcpApiVersion, bool aSuppo if (rcpApiVersion < SPINEL_MIN_HOST_SUPPORTED_RCP_API_VERSION) { - otLogCritPlat("RCP and host are using incompatible API versions"); - otLogCritPlat("RCP API Version %u is older than min required by host %u", rcpApiVersion, - SPINEL_MIN_HOST_SUPPORTED_RCP_API_VERSION); + LogCrit("RCP and host are using incompatible API versions"); + LogCrit("RCP API Version %u is older than min required by host %u", rcpApiVersion, + SPINEL_MIN_HOST_SUPPORTED_RCP_API_VERSION); DieNow(OT_EXIT_RADIO_SPINEL_INCOMPATIBLE); } } @@ -328,9 +328,9 @@ otError RadioSpinel::CheckRcpApiVersion(bool aSupportsRcpApiVersion, bool aSuppo if (SPINEL_RCP_API_VERSION < minHostRcpApiVersion) { - otLogCritPlat("RCP and host are using incompatible API versions"); - otLogCritPlat("RCP requires min host API version %u but host is older and at version %u", - minHostRcpApiVersion, SPINEL_RCP_API_VERSION); + LogCrit("RCP and host are using incompatible API versions"); + LogCrit("RCP requires min host API version %u but host is older and at version %u", minHostRcpApiVersion, + SPINEL_RCP_API_VERSION); DieNow(OT_EXIT_RADIO_SPINEL_INCOMPATIBLE); } } @@ -380,7 +380,7 @@ void RadioSpinel::HandleReceivedFrame(void) if (error != OT_ERROR_NONE) { mRxFrameBuffer.DiscardFrame(); - otLogWarnPlat("Error handling hdlc frame: %s", otThreadErrorToString(error)); + LogWarn("Error handling hdlc frame: %s", otThreadErrorToString(error)); } UpdateParseErrorCount(error); @@ -419,7 +419,7 @@ void RadioSpinel::HandleNotification(SpinelInterface::RxFrameBuffer &aFrameBuffe case SPINEL_CMD_PROP_VALUE_INSERTED: case SPINEL_CMD_PROP_VALUE_REMOVED: - otLogInfoPlat("Ignored command %lu", ToUlong(cmd)); + LogInfo("Ignored command %lu", ToUlong(cmd)); break; default: @@ -433,7 +433,7 @@ void RadioSpinel::HandleNotification(SpinelInterface::RxFrameBuffer &aFrameBuffe if (shouldSaveFrame) { - otLogCritPlat("RX Spinel buffer full, dropped incoming frame"); + LogCrit("RX Spinel buffer full, dropped incoming frame"); } } @@ -494,7 +494,7 @@ void RadioSpinel::HandleResponse(const uint8_t *aBuffer, uint16_t aLength) } else { - otLogWarnPlat("Unexpected Spinel transaction message: %u", SPINEL_HEADER_GET_TID(header)); + LogWarn("Unexpected Spinel transaction message: %u", SPINEL_HEADER_GET_TID(header)); error = OT_ERROR_DROP; } @@ -596,12 +596,12 @@ void RadioSpinel::HandleValueIs(spinel_prop_key_t aKey, const uint8_t *aBuffer, ExitNow(); } - otLogInfoPlat("RCP reset: %s", spinel_status_to_cstr(status)); + LogInfo("RCP reset: %s", spinel_status_to_cstr(status)); mIsReady = true; } else { - otLogInfoPlat("RCP last status: %s", spinel_status_to_cstr(status)); + LogInfo("RCP last status: %s", spinel_status_to_cstr(status)); } } else if (aKey == SPINEL_PROP_MAC_ENERGY_SCAN_RESULT) @@ -628,7 +628,7 @@ void RadioSpinel::HandleValueIs(spinel_prop_key_t aKey, const uint8_t *aBuffer, assert(len < sizeof(logStream)); VerifyOrExit(unpacked > 0, error = OT_ERROR_PARSE); logStream[len] = '\0'; - otLogDebgPlat("RCP => %s", logStream); + LogDebg("RCP => %s", logStream); } else if ((aKey == SPINEL_PROP_STREAM_LOG) && mSupportsLogStream) { @@ -648,25 +648,25 @@ void RadioSpinel::HandleValueIs(spinel_prop_key_t aKey, const uint8_t *aBuffer, case SPINEL_NCP_LOG_LEVEL_EMERG: case SPINEL_NCP_LOG_LEVEL_ALERT: case SPINEL_NCP_LOG_LEVEL_CRIT: - otLogCritPlat("RCP => %s", logString); + LogCrit("RCP => %s", logString); break; case SPINEL_NCP_LOG_LEVEL_ERR: case SPINEL_NCP_LOG_LEVEL_WARN: - otLogWarnPlat("RCP => %s", logString); + LogWarn("RCP => %s", logString); break; case SPINEL_NCP_LOG_LEVEL_NOTICE: - otLogNotePlat("RCP => %s", logString); + LogNote("RCP => %s", logString); break; case SPINEL_NCP_LOG_LEVEL_INFO: - otLogInfoPlat("RCP => %s", logString); + LogInfo("RCP => %s", logString); break; case SPINEL_NCP_LOG_LEVEL_DEBUG: default: - otLogDebgPlat("RCP => %s", logString); + LogDebg("RCP => %s", logString); break; } } @@ -827,7 +827,7 @@ void RadioSpinel::ProcessRadioStateMachine(void) else if (mState == kStateTransmitting && otPlatTimeGet() >= mTxRadioEndUs) { // Frame has been successfully passed to radio, but no `TransmitDone` event received within kTxWaitUs. - otLogWarnPlat("radio tx timeout"); + LogWarn("radio tx timeout"); HandleRcpTimeout(); } } @@ -1378,7 +1378,7 @@ otError RadioSpinel::WaitResponse(bool aHandleRcpTimeout) { uint64_t end = otPlatTimeGet() + kMaxWaitTime * kUsPerMs; - otLogDebgPlat("Wait response: tid=%u key=%lu", mWaitingTid, ToUlong(mWaitingKey)); + LogDebg("Wait response: tid=%u key=%lu", mWaitingTid, ToUlong(mWaitingKey)); do { @@ -1387,7 +1387,7 @@ otError RadioSpinel::WaitResponse(bool aHandleRcpTimeout) now = otPlatTimeGet(); if ((end <= now) || (mSpinelInterface->WaitForFrame(end - now) != OT_ERROR_NONE)) { - otLogWarnPlat("Wait for response timeout"); + LogWarn("Wait for response timeout"); if (aHandleRcpTimeout) { HandleRcpTimeout(); @@ -1751,7 +1751,7 @@ otError RadioSpinel::Enable(otInstance *aInstance) exit: if (error != OT_ERROR_NONE) { - otLogWarnPlat("RadioSpinel enable: %s", otThreadErrorToString(error)); + LogWarn("RadioSpinel enable: %s", otThreadErrorToString(error)); error = OT_ERROR_FAILED; } @@ -1870,7 +1870,7 @@ void RadioSpinel::CalcRcpTimeOffset(void) VerifyOrExit(!mIsTimeSynced || (otPlatTimeGet() >= GetNextRadioTimeRecalcStart())); - otLogDebgPlat("Trying to get RCP time offset"); + LogDebg("Trying to get RCP time offset"); packed = spinel_datatype_pack(buffer, sizeof(buffer), SPINEL_DATATYPE_UINT64_S, remoteTimestamp); VerifyOrExit(packed > 0 && static_cast(packed) <= sizeof(buffer), error = OT_ERROR_NO_BUFS); @@ -1903,7 +1903,7 @@ void RadioSpinel::HandleRcpUnexpectedReset(spinel_status_t aStatus) OT_UNUSED_VARIABLE(aStatus); mRadioSpinelMetrics.mRcpUnexpectedResetCount++; - otLogCritPlat("Unexpected RCP reset: %s", spinel_status_to_cstr(aStatus)); + LogCrit("Unexpected RCP reset: %s", spinel_status_to_cstr(aStatus)); #if OPENTHREAD_SPINEL_CONFIG_RCP_RESTORATION_MAX_COUNT > 0 mRcpFailed = true; @@ -1923,10 +1923,10 @@ void RadioSpinel::HandleRcpTimeout(void) #else if (!mIsReady) { - otLogCritPlat("Failed to communicate with RCP - no response from RCP during initialization"); - otLogCritPlat("This is not a bug and typically due a config error (wrong URL parameters) or bad RCP image:"); - otLogCritPlat("- Make sure RCP is running the correct firmware"); - otLogCritPlat("- Double check the config parameters passed as `RadioURL` input"); + LogCrit("Failed to communicate with RCP - no response from RCP during initialization"); + LogCrit("This is not a bug and typically due a config error (wrong URL parameters) or bad RCP image:"); + LogCrit("- Make sure RCP is running the correct firmware"); + LogCrit("- Double check the config parameters passed as `RadioURL` input"); } DieNow(OT_EXIT_RADIO_SPINEL_NO_RESPONSE); @@ -1945,17 +1945,17 @@ void RadioSpinel::RecoverFromRcpFailure(void) } mRcpFailed = false; - otLogWarnPlat("RCP failure detected"); + LogWarn("RCP failure detected"); ++mRadioSpinelMetrics.mRcpRestorationCount; ++mRcpFailureCount; if (mRcpFailureCount > kMaxFailureCount) { - otLogCritPlat("Too many rcp failures, exiting"); + LogCrit("Too many rcp failures, exiting"); DieNow(OT_EXIT_FAILURE); } - otLogWarnPlat("Trying to recover (%d/%d)", mRcpFailureCount, kMaxFailureCount); + LogWarn("Trying to recover (%d/%d)", mRcpFailureCount, kMaxFailureCount); mState = kStateDisabled; mRxFrameBuffer.Clear(); @@ -1997,7 +1997,7 @@ void RadioSpinel::RecoverFromRcpFailure(void) } --mRcpFailureCount; - otLogNotePlat("RCP recovery is done"); + LogNote("RCP recovery is done"); exit: return; @@ -2112,13 +2112,13 @@ otError RadioSpinel::SetRadioRegion(uint16_t aRegionCode) if (error == OT_ERROR_NONE) { - otLogNotePlat("Set region code \"%c%c\" successfully", static_cast(aRegionCode >> 8), - static_cast(aRegionCode)); + LogNote("Set region code \"%c%c\" successfully", static_cast(aRegionCode >> 8), + static_cast(aRegionCode)); } else { - otLogWarnPlat("Failed to set region code \"%c%c\": %s", static_cast(aRegionCode >> 8), - static_cast(aRegionCode), otThreadErrorToString(error)); + LogWarn("Failed to set region code \"%c%c\": %s", static_cast(aRegionCode >> 8), + static_cast(aRegionCode), otThreadErrorToString(error)); } return error; @@ -2571,7 +2571,7 @@ void RadioSpinel::LogSpinelFrame(const uint8_t *aFrame, uint16_t aLength, bool a start += Snprintf(start, static_cast(end - start), ", len:%u, rssi:%d ...", frame.mLength, frame.mInfo.mRxInfo.mRssi); OT_UNUSED_VARIABLE(start); // Avoid static analysis error - otLogDebgPlat("%s", buf); + LogDebg("%s", buf); start = buf; start += Snprintf(start, static_cast(end - start), @@ -2607,7 +2607,7 @@ void RadioSpinel::LogSpinelFrame(const uint8_t *aFrame, uint16_t aLength, bool a ", len:%u, channel:%u, maxbackoffs:%u, maxretries:%u ...", frame.mLength, frame.mChannel, frame.mInfo.mTxInfo.mMaxCsmaBackoffs, frame.mInfo.mTxInfo.mMaxFrameRetries); OT_UNUSED_VARIABLE(start); // Avoid static analysis error - otLogDebgPlat("%s", buf); + LogDebg("%s", buf); start = buf; start += Snprintf(start, static_cast(end - start), @@ -2757,25 +2757,25 @@ void RadioSpinel::LogSpinelFrame(const uint8_t *aFrame, uint16_t aLength, bool a VerifyOrExit(unpacked > 0, error = OT_ERROR_PARSE); - otLogDebgPlat("%s ...", buf); - otLogDebgPlat(" txRequest:%lu", ToUlong(metrics.mNumTxRequest)); - otLogDebgPlat(" txGrantImmediate:%lu", ToUlong(metrics.mNumTxGrantImmediate)); - otLogDebgPlat(" txGrantWait:%lu", ToUlong(metrics.mNumTxGrantWait)); - otLogDebgPlat(" txGrantWaitActivated:%lu", ToUlong(metrics.mNumTxGrantWaitActivated)); - otLogDebgPlat(" txGrantWaitTimeout:%lu", ToUlong(metrics.mNumTxGrantWaitTimeout)); - otLogDebgPlat(" txGrantDeactivatedDuringRequest:%lu", ToUlong(metrics.mNumTxGrantDeactivatedDuringRequest)); - otLogDebgPlat(" txDelayedGrant:%lu", ToUlong(metrics.mNumTxDelayedGrant)); - otLogDebgPlat(" avgTxRequestToGrantTime:%lu", ToUlong(metrics.mAvgTxRequestToGrantTime)); - otLogDebgPlat(" rxRequest:%lu", ToUlong(metrics.mNumRxRequest)); - otLogDebgPlat(" rxGrantImmediate:%lu", ToUlong(metrics.mNumRxGrantImmediate)); - otLogDebgPlat(" rxGrantWait:%lu", ToUlong(metrics.mNumRxGrantWait)); - otLogDebgPlat(" rxGrantWaitActivated:%lu", ToUlong(metrics.mNumRxGrantWaitActivated)); - otLogDebgPlat(" rxGrantWaitTimeout:%lu", ToUlong(metrics.mNumRxGrantWaitTimeout)); - otLogDebgPlat(" rxGrantDeactivatedDuringRequest:%lu", ToUlong(metrics.mNumRxGrantDeactivatedDuringRequest)); - otLogDebgPlat(" rxDelayedGrant:%lu", ToUlong(metrics.mNumRxDelayedGrant)); - otLogDebgPlat(" avgRxRequestToGrantTime:%lu", ToUlong(metrics.mAvgRxRequestToGrantTime)); - otLogDebgPlat(" rxGrantNone:%lu", ToUlong(metrics.mNumRxGrantNone)); - otLogDebgPlat(" stopped:%u", metrics.mStopped); + LogDebg("%s ...", buf); + LogDebg(" txRequest:%lu", ToUlong(metrics.mNumTxRequest)); + LogDebg(" txGrantImmediate:%lu", ToUlong(metrics.mNumTxGrantImmediate)); + LogDebg(" txGrantWait:%lu", ToUlong(metrics.mNumTxGrantWait)); + LogDebg(" txGrantWaitActivated:%lu", ToUlong(metrics.mNumTxGrantWaitActivated)); + LogDebg(" txGrantWaitTimeout:%lu", ToUlong(metrics.mNumTxGrantWaitTimeout)); + LogDebg(" txGrantDeactivatedDuringRequest:%lu", ToUlong(metrics.mNumTxGrantDeactivatedDuringRequest)); + LogDebg(" txDelayedGrant:%lu", ToUlong(metrics.mNumTxDelayedGrant)); + LogDebg(" avgTxRequestToGrantTime:%lu", ToUlong(metrics.mAvgTxRequestToGrantTime)); + LogDebg(" rxRequest:%lu", ToUlong(metrics.mNumRxRequest)); + LogDebg(" rxGrantImmediate:%lu", ToUlong(metrics.mNumRxGrantImmediate)); + LogDebg(" rxGrantWait:%lu", ToUlong(metrics.mNumRxGrantWait)); + LogDebg(" rxGrantWaitActivated:%lu", ToUlong(metrics.mNumRxGrantWaitActivated)); + LogDebg(" rxGrantWaitTimeout:%lu", ToUlong(metrics.mNumRxGrantWaitTimeout)); + LogDebg(" rxGrantDeactivatedDuringRequest:%lu", ToUlong(metrics.mNumRxGrantDeactivatedDuringRequest)); + LogDebg(" rxDelayedGrant:%lu", ToUlong(metrics.mNumRxDelayedGrant)); + LogDebg(" avgRxRequestToGrantTime:%lu", ToUlong(metrics.mAvgRxRequestToGrantTime)); + LogDebg(" rxGrantNone:%lu", ToUlong(metrics.mNumRxGrantNone)); + LogDebg(" stopped:%u", metrics.mStopped); start = buf; start += Snprintf(start, static_cast(end - start), " grantGlitch:%u", metrics.mNumGrantGlitch); @@ -2856,11 +2856,11 @@ void RadioSpinel::LogSpinelFrame(const uint8_t *aFrame, uint16_t aLength, bool a OT_UNUSED_VARIABLE(start); // Avoid static analysis error if (error == OT_ERROR_NONE) { - otLogDebgPlat("%s", buf); + LogDebg("%s", buf); } else if (prefix != nullptr) { - otLogDebgPlat("%s, failed to parse spinel frame !", prefix); + LogDebg("%s, failed to parse spinel frame !", prefix); } } @@ -2947,9 +2947,56 @@ void RadioSpinel::LogIfFail(const char *aText, otError aError) if (aError != OT_ERROR_NONE && aError != OT_ERROR_NO_ACK) { - otLogWarnPlat("%s: %s", aText, otThreadErrorToString(aError)); + LogWarn("%s: %s", aText, otThreadErrorToString(aError)); } } +static const char kModuleName[] = "RadioSpinel"; + +void RadioSpinel::LogCrit(const char *aFormat, ...) +{ + va_list args; + + va_start(args, aFormat); + otLogPlatArgs(OT_LOG_LEVEL_CRIT, kModuleName, aFormat, args); + va_end(args); +} + +void RadioSpinel::LogWarn(const char *aFormat, ...) +{ + va_list args; + + va_start(args, aFormat); + otLogPlatArgs(OT_LOG_LEVEL_WARN, kModuleName, aFormat, args); + va_end(args); +} + +void RadioSpinel::LogNote(const char *aFormat, ...) +{ + va_list args; + + va_start(args, aFormat); + otLogPlatArgs(OT_LOG_LEVEL_NOTE, kModuleName, aFormat, args); + va_end(args); +} + +void RadioSpinel::LogInfo(const char *aFormat, ...) +{ + va_list args; + + va_start(args, aFormat); + otLogPlatArgs(OT_LOG_LEVEL_INFO, kModuleName, aFormat, args); + va_end(args); +} + +void RadioSpinel::LogDebg(const char *aFormat, ...) +{ + va_list args; + + va_start(args, aFormat); + otLogPlatArgs(OT_LOG_LEVEL_DEBG, kModuleName, aFormat, args); + va_end(args); +} + } // namespace Spinel } // namespace ot diff --git a/src/lib/spinel/radio_spinel.hpp b/src/lib/spinel/radio_spinel.hpp index dac40d5c006..05df2115348 100644 --- a/src/lib/spinel/radio_spinel.hpp +++ b/src/lib/spinel/radio_spinel.hpp @@ -1011,11 +1011,17 @@ class RadioSpinel mRadioSpinelMetrics.mSpinelParseErrorCount += (aError == OT_ERROR_PARSE) ? 1 : 0; } + static void LogIfFail(const char *aText, otError aError); + + static void LogCrit(const char *aFormat, ...) OT_TOOL_PRINTF_STYLE_FORMAT_ARG_CHECK(1, 2); + static void LogWarn(const char *aFormat, ...) OT_TOOL_PRINTF_STYLE_FORMAT_ARG_CHECK(1, 2); + static void LogNote(const char *aFormat, ...) OT_TOOL_PRINTF_STYLE_FORMAT_ARG_CHECK(1, 2); + static void LogInfo(const char *aFormat, ...) OT_TOOL_PRINTF_STYLE_FORMAT_ARG_CHECK(1, 2); + static void LogDebg(const char *aFormat, ...) OT_TOOL_PRINTF_STYLE_FORMAT_ARG_CHECK(1, 2); + uint32_t Snprintf(char *aDest, uint32_t aSize, const char *aFormat, ...); void LogSpinelFrame(const uint8_t *aFrame, uint16_t aLength, bool aTx); - void LogIfFail(const char *aText, otError aError); - otInstance *mInstance; SpinelInterface::RxFrameBuffer mRxFrameBuffer;