From f05f222b44c912e787afa0841fe54456f57779ed Mon Sep 17 00:00:00 2001 From: Abtin Keshavarzian Date: Tue, 30 May 2023 13:26:08 -0700 Subject: [PATCH] [routing-manager] update logs (#9095) This commit updates logs in the `RoutingManager` module: - The log module name is changed to "RoutingManager". - State changes are logged (enabling, disabling, starting, etc.). - The `ScheduleRoutingPolicyEvaluation()` log will show the delay in both milliseconds and ":." format(e.g. `05:15.234`). - Logging of PIOs and RIOs are harmonized (when preparing RA to send or processing a received RA). - Local on-link prefix logs are harmonized in `OnLinkPrefixManager`. - `RsSender` logs are simplified. --- src/core/border_router/routing_manager.cpp | 102 ++++++++++++++------- src/core/border_router/routing_manager.hpp | 3 + src/core/common/uptime.hpp | 2 + 3 files changed, 76 insertions(+), 31 deletions(-) diff --git a/src/core/border_router/routing_manager.cpp b/src/core/border_router/routing_manager.cpp index e713ec69e..0a19027f6 100644 --- a/src/core/border_router/routing_manager.cpp +++ b/src/core/border_router/routing_manager.cpp @@ -60,7 +60,7 @@ namespace ot { namespace BorderRouter { -RegisterLogModule("BorderRouter"); +RegisterLogModule("RoutingManager"); RoutingManager::RoutingManager(Instance &aInstance) : InstanceLocator(aInstance) @@ -87,6 +87,8 @@ Error RoutingManager::Init(uint32_t aInfraIfIndex, bool aInfraIfIsRunning) { Error error; + LogInfo("Initializing - InfraIfIndex:%u", aInfraIfIndex); + SuccessOrExit(error = mInfraIf.Init(aInfraIfIndex)); SuccessOrExit(error = LoadOrGenerateRandomBrUlaPrefix()); @@ -116,6 +118,7 @@ Error RoutingManager::SetEnabled(bool aEnabled) VerifyOrExit(aEnabled != mIsEnabled); mIsEnabled = aEnabled; + LogInfo("%s", mIsEnabled ? "Enabling" : "Disabling"); EvaluateState(); exit: @@ -304,7 +307,7 @@ void RoutingManager::Start(void) { if (!mIsRunning) { - LogInfo("Border Routing manager started"); + LogInfo("Starting"); mIsRunning = true; UpdateDiscoveredPrefixTableOnNetDataChange(); @@ -344,7 +347,7 @@ void RoutingManager::Stop(void) mRoutePublisher.Stop(); - LogInfo("Border Routing manager stopped"); + LogInfo("Stopped"); mIsRunning = false; @@ -535,9 +538,25 @@ void RoutingManager::ScheduleRoutingPolicyEvaluation(ScheduleMode aMode) // Ensure we wait a min delay after last RA tx evaluateTime = Max(now + delay, mRaInfo.mLastTxTime + kMinDelayBetweenRtrAdvs); - LogInfo("Start evaluating routing policy, scheduled in %lu milliseconds", ToUlong(evaluateTime - now)); - mRoutingPolicyTimer.FireAtIfEarlier(evaluateTime); + +#if OT_SHOULD_LOG_AT(OT_LOG_LEVEL_INFO) + { + uint32_t duration = evaluateTime - now; + + if (duration == 0) + { + LogInfo("Will evaluate routing policy immediately"); + } + else + { + String string; + + Uptime::UptimeToString(duration, string, /* aIncludeMsec */ true); + LogInfo("Will evaluate routing policy in %s (%lu msec)", string.AsCString() + 3, ToUlong(duration)); + } + } +#endif } void RoutingManager::SendRouterAdvertisement(RouterAdvTxMode aRaTxMode) @@ -561,6 +580,8 @@ void RoutingManager::SendRouterAdvertisement(RouterAdvTxMode aRaTxMode) NetworkData::Iterator iterator; NetworkData::OnMeshPrefixConfig prefixConfig; + LogInfo("Preparing RA"); + // Append PIO for local on-link prefix if is either being // advertised or deprecated and for old prefix if is being // deprecated. @@ -603,7 +624,7 @@ void RoutingManager::SendRouterAdvertisement(RouterAdvTxMode aRaTxMode) if (prefix.GetLength() != 0) { SuccessOrAssert(raMsg.AppendRouteInfoOption(prefix, /* aRouteLifetime */ 0, mRioPreference)); - LogInfo("RouterAdvert: Added RIO for %s (lifetime=0)", prefix.ToString().AsCString()); + LogRouteInfoOption(prefix, 0, mRioPreference); } } @@ -678,8 +699,7 @@ void RoutingManager::SendRouterAdvertisement(RouterAdvTxMode aRaTxMode) for (const OnMeshPrefix &prefix : mAdvertisedPrefixes) { SuccessOrAssert(raMsg.AppendRouteInfoOption(prefix, kDefaultOmrPrefixLifetime, mRioPreference)); - LogInfo("RouterAdvert: Added RIO for %s (lifetime=%lu)", prefix.ToString().AsCString(), - ToUlong(kDefaultOmrPrefixLifetime)); + LogRouteInfoOption(prefix, kDefaultOmrPrefixLifetime, mRioPreference); } } @@ -698,15 +718,14 @@ void RoutingManager::SendRouterAdvertisement(RouterAdvTxMode aRaTxMode) { mRaInfo.mLastTxTime = TimerMilli::GetNow(); Get().GetBorderRoutingCounters().mRaTxSuccess++; - LogInfo("Sent Router Advertisement on %s", mInfraIf.ToString().AsCString()); + LogInfo("Sent RA on %s", mInfraIf.ToString().AsCString()); DumpDebg("[BR-CERT] direction=send | type=RA |", raMsg.GetAsPacket().GetBytes(), raMsg.GetAsPacket().GetLength()); } else { Get().GetBorderRoutingCounters().mRaTxFailure++; - LogWarn("Failed to send Router Advertisement on %s: %s", mInfraIf.ToString().AsCString(), - ErrorToString(error)); + LogWarn("Failed to send RA on %s: %s", mInfraIf.ToString().AsCString(), ErrorToString(error)); } } } @@ -843,8 +862,7 @@ void RoutingManager::HandleRouterSolicit(const InfraIf::Icmp6Packet &aPacket, co OT_UNUSED_VARIABLE(aSrcAddress); Get().GetBorderRoutingCounters().mRsRx++; - LogInfo("Received Router Solicitation from %s on %s", aSrcAddress.ToString().AsCString(), - mInfraIf.ToString().AsCString()); + LogInfo("Received RS from %s on %s", aSrcAddress.ToString().AsCString(), mInfraIf.ToString().AsCString()); ScheduleRoutingPolicyEvaluation(kToReplyToRs); } @@ -871,8 +889,8 @@ void RoutingManager::HandleRouterAdvertisement(const InfraIf::Icmp6Packet &aPack VerifyOrExit(routerAdvMessage.IsValid()); Get().GetBorderRoutingCounters().mRaRx++; - LogInfo("Received Router Advertisement from %s on %s", aSrcAddress.ToString().AsCString(), - mInfraIf.ToString().AsCString()); + + LogInfo("Received RA from %s on %s", aSrcAddress.ToString().AsCString(), mInfraIf.ToString().AsCString()); DumpDebg("[BR-CERT] direction=recv | type=RA |", aPacket.GetBytes(), aPacket.GetLength()); mDiscoveredPrefixTable.ProcessRouterAdvertMessage(routerAdvMessage, aSrcAddress); @@ -899,7 +917,7 @@ bool RoutingManager::ShouldProcessPrefixInfoOption(const Ip6::Nd::PrefixInfoOpti if (!IsValidOnLinkPrefix(aPio)) { - LogInfo("Ignore invalid on-link prefix in PIO: %s", aPrefix.ToString().AsCString()); + LogInfo("- PIO %s - ignore since not a valid on-link prefix", aPrefix.ToString().AsCString()); ExitNow(); } @@ -933,7 +951,7 @@ bool RoutingManager::ShouldProcessRouteInfoOption(const Ip6::Nd::RouteInfoOption if (!IsValidOmrPrefix(aPrefix)) { - LogInfo("Ignore RIO prefix %s since not a valid OMR prefix", aPrefix.ToString().AsCString()); + LogInfo("- RIO %s - ignore since not a valid OMR prefix", aPrefix.ToString().AsCString()); ExitNow(); } @@ -1097,6 +1115,25 @@ void RoutingManager::ResetDiscoveredPrefixStaleTimer(void) } } +#if OT_SHOULD_LOG_AT(OT_LOG_LEVEL_INFO) +void RoutingManager::LogPrefixInfoOption(const Ip6::Prefix &aPrefix, + uint32_t aValidLifetime, + uint32_t aPreferredLifetime) +{ + LogInfo("- PIO %s (valid:%lu, preferred:%lu)", aPrefix.ToString().AsCString(), ToUlong(aValidLifetime), + ToUlong(aPreferredLifetime)); +} + +void RoutingManager::LogRouteInfoOption(const Ip6::Prefix &aPrefix, uint32_t aLifetime, RoutePreference aPreference) +{ + LogInfo("- RIO %s (lifetime:%lu, prf:%s)", aPrefix.ToString().AsCString(), ToUlong(aLifetime), + RoutePreferenceToString(aPreference)); +} +#else +void RoutingManager::LogPrefixInfoOption(const Ip6::Prefix &, uint32_t, uint32_t) {} +void RoutingManager::LogRouteInfoOption(const Ip6::Prefix &, uint32_t, RoutePreference) {} +#endif + //--------------------------------------------------------------------------------------------------------------------- // DiscoveredPrefixTable @@ -1171,6 +1208,8 @@ void RoutingManager::DiscoveredPrefixTable::ProcessDefaultRoute(const Ip6::Nd::R prefix.Clear(); entry = aRouter.mEntries.FindMatching(Entry::Matcher(prefix, Entry::kTypeRoute)); + LogInfo("- RA Header - default route - lifetime:%u", aRaHeader.GetRouterLifetime()); + if (entry == nullptr) { VerifyOrExit(aRaHeader.GetRouterLifetime() != 0); @@ -1210,7 +1249,7 @@ void RoutingManager::DiscoveredPrefixTable::ProcessPrefixInfoOption(const Ip6::N VerifyOrExit(Get().ShouldProcessPrefixInfoOption(aPio, prefix)); - LogInfo("Processing PIO (%s, %lu seconds)", prefix.ToString().AsCString(), ToUlong(aPio.GetValidLifetime())); + LogPrefixInfoOption(prefix, aPio.GetValidLifetime(), aPio.GetPreferredLifetime()); entry = aRouter.mEntries.FindMatching(Entry::Matcher(prefix, Entry::kTypeOnLink)); @@ -1256,7 +1295,7 @@ void RoutingManager::DiscoveredPrefixTable::ProcessRouteInfoOption(const Ip6::Nd VerifyOrExit(Get().ShouldProcessRouteInfoOption(aRio, prefix)); - LogInfo("Processing RIO (%s, %lu seconds)", prefix.ToString().AsCString(), ToUlong(aRio.GetRouteLifetime())); + LogRouteInfoOption(prefix, aRio.GetRouteLifetime(), aRio.GetPreference()); entry = aRouter.mEntries.FindMatching(Entry::Matcher(prefix, Entry::kTypeRoute)); @@ -2238,8 +2277,7 @@ void RoutingManager::OnLinkPrefixManager::Evaluate(void) if (!(mLocalPrefix < mFavoredDiscoveredPrefix)) { - LogInfo("EvaluateOnLinkPrefix: There is already favored on-link prefix %s", - mFavoredDiscoveredPrefix.ToString().AsCString()); + LogInfo("Found a favored on-link prefix %s", mFavoredDiscoveredPrefix.ToString().AsCString()); Deprecate(); } } @@ -2295,6 +2333,8 @@ void RoutingManager::OnLinkPrefixManager::PublishAndAdvertise(void) mState = kPublishing; ResetExpireTime(TimerMilli::GetNow()); + LogInfo("Publishing route for local on-link prefix %s", mLocalPrefix.ToString().AsCString()); + // We wait for the ULA `fc00::/7` route or a sub-prefix of it (e.g., // default route) to be added in Network Data before // starting to advertise the local on-link prefix in RAs. @@ -2325,7 +2365,7 @@ void RoutingManager::OnLinkPrefixManager::Deprecate(void) case kPublishing: case kAdvertising: mState = kDeprecating; - LogInfo("Deprecate local on-link prefix %s", mLocalPrefix.ToString().AsCString()); + LogInfo("Deprecating local on-link prefix %s", mLocalPrefix.ToString().AsCString()); break; case kIdle: @@ -2354,7 +2394,7 @@ void RoutingManager::OnLinkPrefixManager::ResetExpireTime(TimeMilli aNow) void RoutingManager::OnLinkPrefixManager::EnterAdvertisingState(void) { mState = kAdvertising; - LogInfo("Start advertising local on-link prefix %s", mLocalPrefix.ToString().AsCString()); + LogInfo("Advertising local on-link prefix %s", mLocalPrefix.ToString().AsCString()); } bool RoutingManager::OnLinkPrefixManager::IsPublishingOrAdvertising(void) const @@ -2400,8 +2440,7 @@ void RoutingManager::OnLinkPrefixManager::AppendCurPrefix(Ip6::Nd::RouterAdvertM SuccessOrAssert(aRaMessage.AppendPrefixInfoOption(mLocalPrefix, validLifetime, preferredLifetime)); - LogInfo("RouterAdvert: Added PIO for %s (valid=%lu, preferred=%lu)", mLocalPrefix.ToString().AsCString(), - ToUlong(validLifetime), ToUlong(preferredLifetime)); + LogPrefixInfoOption(mLocalPrefix, validLifetime, preferredLifetime); exit: return; @@ -2422,8 +2461,7 @@ void RoutingManager::OnLinkPrefixManager::AppendOldPrefixes(Ip6::Nd::RouterAdver validLifetime = TimeMilli::MsecToSec(oldPrefix.mExpireTime - now); SuccessOrAssert(aRaMessage.AppendPrefixInfoOption(oldPrefix.mPrefix, validLifetime, 0)); - LogInfo("RouterAdvert: Added PIO for %s (valid=%lu, preferred=0)", oldPrefix.mPrefix.ToString().AsCString(), - ToUlong(validLifetime)); + LogPrefixInfoOption(oldPrefix.mPrefix, validLifetime, 0); } } @@ -2548,7 +2586,7 @@ void RoutingManager::OnLinkPrefixManager::HandleTimer(void) case kDeprecating: if (now >= mExpireTime) { - LogInfo("Local on-link prefix %s expired", mLocalPrefix.ToString().AsCString()); + LogInfo("Removing expired local on-link prefix %s", mLocalPrefix.ToString().AsCString()); IgnoreError(Get().RemoveBrOnLinkPrefix(mLocalPrefix)); mState = kIdle; } @@ -3041,7 +3079,8 @@ void RoutingManager::RsSender::Start(void) VerifyOrExit(!IsInProgress()); delay = Random::NonCrypto::GetUint32InRange(0, kMaxStartDelay); - LogInfo("Scheduled Router Solicitation in %lu milliseconds", ToUlong(delay)); + + LogInfo("RsSender: Starting - will send first RS in %lu msec", ToUlong(delay)); mTxCount = 0; mStartTime = TimerMilli::GetNow(); @@ -3083,6 +3122,7 @@ void RoutingManager::RsSender::HandleTimer(void) if (mTxCount >= kMaxTxCount) { + LogInfo("RsSender: Finished sending RS msgs and waiting for RAs"); Get().HandleRsSenderFinished(mStartTime); ExitNow(); } @@ -3092,12 +3132,12 @@ void RoutingManager::RsSender::HandleTimer(void) if (error == kErrorNone) { mTxCount++; - LogInfo("Successfully sent RS %u/%u", mTxCount, kMaxTxCount); delay = (mTxCount == kMaxTxCount) ? kWaitOnLastAttempt : kTxInterval; + LogInfo("RsSender: Sent RS %u/%u", mTxCount, kMaxTxCount); } else { - LogCrit("Failed to send RS %u, error:%s", mTxCount + 1, ErrorToString(error)); + LogCrit("RsSender: Failed to send RS %u/%u: %s", mTxCount + 1, kMaxTxCount, ErrorToString(error)); // Note that `mTxCount` is intentionally not incremented // if the tx fails. diff --git a/src/core/border_router/routing_manager.hpp b/src/core/border_router/routing_manager.hpp index db73497cf..17fcd2f7d 100644 --- a/src/core/border_router/routing_manager.hpp +++ b/src/core/border_router/routing_manager.hpp @@ -999,6 +999,9 @@ private: static bool IsValidOnLinkPrefix(const Ip6::Nd::PrefixInfoOption &aPio); static bool IsValidOnLinkPrefix(const Ip6::Prefix &aOnLinkPrefix); + static void LogPrefixInfoOption(const Ip6::Prefix &aPrefix, uint32_t aValidLifetime, uint32_t aPreferredLifetime); + static void LogRouteInfoOption(const Ip6::Prefix &aPrefix, uint32_t aLifetime, RoutePreference aPreference); + using RoutingPolicyTimer = TimerMilliIn; using DiscoveredPrefixStaleTimer = TimerMilliIn; diff --git a/src/core/common/uptime.hpp b/src/core/common/uptime.hpp index 0e9a4aac0..0a2b77008 100644 --- a/src/core/common/uptime.hpp +++ b/src/core/common/uptime.hpp @@ -57,6 +57,8 @@ namespace ot { class Uptime : public InstanceLocator, private NonCopyable { public: + static constexpr uint16_t kStringSize = OT_UPTIME_STRING_SIZE; ///< Recommended string size to represent uptime. + /** * Initializes an `Uptime` instance. *