From 653eb07e29a4580f09f6749df047370de6135a12 Mon Sep 17 00:00:00 2001 From: Alex Lane Date: Thu, 27 Jul 2023 22:11:46 -0400 Subject: [PATCH] fw: refactor strategy logging and improve ASF probe logging Bring strategy logging in line with format from 6bf94c0. This should also marginally improve performance when log level is raised. Refs: #5262, #5267 Co-authored-by: Davide Pesavento Change-Id: I6493b6476f3d0c6ae5562b66abfa46f6c6f4903d --- daemon/fw/access-strategy.cpp | 41 ++++++++++++++-------------- daemon/fw/asf-strategy.cpp | 33 ++++++++++------------ daemon/fw/best-route-strategy.cpp | 17 ++++++------ daemon/fw/multicast-strategy.cpp | 16 +++++------ daemon/fw/process-nack-traits.cpp | 16 ++++------- daemon/fw/random-strategy.cpp | 5 ++-- daemon/fw/retx-suppression.hpp | 18 +++--------- daemon/fw/self-learning-strategy.cpp | 22 +++++++-------- daemon/fw/strategy.hpp | 28 +++++++++++++++++-- 9 files changed, 96 insertions(+), 100 deletions(-) diff --git a/daemon/fw/access-strategy.cpp b/daemon/fw/access-strategy.cpp index c2b6504c..688867f7 100644 --- a/daemon/fw/access-strategy.cpp +++ b/daemon/fw/access-strategy.cpp @@ -1,6 +1,6 @@ /* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */ /* - * Copyright (c) 2014-2022, Regents of the University of California, + * Copyright (c) 2014-2023, Regents of the University of California, * Arizona Board of Regents, * Colorado State University, * University Pierre & Marie Curie, Sorbonne University, @@ -65,7 +65,7 @@ AccessStrategy::afterReceiveInterest(const Interest& interest, const FaceEndpoin case RetxSuppressionResult::FORWARD: return afterReceiveRetxInterest(interest, ingress, pitEntry); case RetxSuppressionResult::SUPPRESS: - NFD_LOG_DEBUG(interest << " interestFrom " << ingress << " retx-suppress"); + NFD_LOG_INTEREST_FROM(interest, ingress, "suppressed"); return; } } @@ -79,7 +79,7 @@ AccessStrategy::afterReceiveNewInterest(const Interest& interest, const FaceEndp // has measurements for Interest Name? if (mi != nullptr) { - NFD_LOG_DEBUG(interest << " interestFrom " << ingress << " new-interest mi=" << miName); + NFD_LOG_INTEREST_FROM(interest, ingress, "new mi=" << miName); // send to last working nexthop bool isSentToLastNexthop = this->sendToLastNexthop(interest, ingress, pitEntry, *mi, fibEntry); @@ -88,7 +88,7 @@ AccessStrategy::afterReceiveNewInterest(const Interest& interest, const FaceEndp } } else { - NFD_LOG_DEBUG(interest << " interestFrom " << ingress << " new-interest no-mi"); + NFD_LOG_INTEREST_FROM(interest, ingress, "new no-mi"); } // no measurements, or last working nexthop unavailable @@ -105,8 +105,8 @@ void AccessStrategy::afterReceiveRetxInterest(const Interest& interest, const FaceEndpoint& ingress, const shared_ptr& pitEntry) { + NFD_LOG_INTEREST_FROM(interest, ingress, "retx"); const auto& fibEntry = this->lookupFib(*pitEntry); - NFD_LOG_DEBUG(interest << " interestFrom " << ingress << " retx-forward"); this->multicast(interest, ingress.face, pitEntry, fibEntry); } @@ -116,29 +116,29 @@ AccessStrategy::sendToLastNexthop(const Interest& interest, const FaceEndpoint& const fib::Entry& fibEntry) { if (mi.lastNexthop == face::INVALID_FACEID) { - NFD_LOG_DEBUG(pitEntry->getInterest() << " no-last-nexthop"); + NFD_LOG_INTEREST_FROM(interest, ingress, "no-last-nexthop"); return false; } if (mi.lastNexthop == ingress.face.getId()) { - NFD_LOG_DEBUG(pitEntry->getInterest() << " last-nexthop-is-downstream"); + NFD_LOG_INTEREST_FROM(interest, ingress, "last-nexthop-is-downstream"); return false; } Face* outFace = this->getFace(mi.lastNexthop); if (outFace == nullptr || !fibEntry.hasNextHop(*outFace)) { - NFD_LOG_DEBUG(pitEntry->getInterest() << " last-nexthop-gone"); + NFD_LOG_INTEREST_FROM(interest, ingress, "last-nexthop-gone"); return false; } if (wouldViolateScope(ingress.face, interest, *outFace)) { - NFD_LOG_DEBUG(pitEntry->getInterest() << " last-nexthop-violates-scope"); + NFD_LOG_INTEREST_FROM(interest, ingress, "last-nexthop-violates-scope"); return false; } auto rto = mi.rtt.getEstimatedRto(); - NFD_LOG_DEBUG(pitEntry->getInterest() << " interestTo " << mi.lastNexthop - << " last-nexthop rto=" << time::duration_cast(rto).count()); + NFD_LOG_INTEREST_FROM(interest, ingress, "to=" << mi.lastNexthop << " last-nexthop rto=" + << time::duration_cast(rto).count() << "us"); if (!this->sendInterest(interest, *outFace, pitEntry)) { return false; @@ -164,8 +164,8 @@ AccessStrategy::afterRtoTimeout(const weak_ptr& pitWeak, Face* inFace = this->getFace(inFaceId); if (inFace == nullptr) { - NFD_LOG_DEBUG(pitEntry->getInterest() << " timeoutFrom " << firstOutFaceId - << " inFace-gone " << inFaceId); + NFD_LOG_DEBUG(pitEntry->getName() << " timeout from=" << firstOutFaceId + << " in-face-gone=" << inFaceId); return; } @@ -178,8 +178,7 @@ AccessStrategy::afterRtoTimeout(const weak_ptr& pitWeak, const Interest& interest = inRecord->getInterest(); const fib::Entry& fibEntry = this->lookupFib(*pitEntry); - NFD_LOG_DEBUG(pitEntry->getInterest() << " timeoutFrom " << firstOutFaceId - << " multicast-except " << firstOutFaceId); + NFD_LOG_DEBUG(pitEntry->getName() << " timeout from=" << firstOutFaceId << " multicast"); this->multicast(interest, *inFace, pitEntry, fibEntry, firstOutFaceId); } @@ -195,7 +194,8 @@ AccessStrategy::multicast(const Interest& interest, const Face& inFace, wouldViolateScope(inFace, interest, outFace)) { continue; } - NFD_LOG_DEBUG(pitEntry->getInterest() << " interestTo " << outFace.getId() << " multicast"); + NFD_LOG_DEBUG(interest.getName() << " nonce=" << interest.getNonce() + << " multicast to=" << outFace.getId()); if (this->sendInterest(interest, outFace, pitEntry)) { ++nSent; } @@ -213,19 +213,18 @@ AccessStrategy::beforeSatisfyInterest(const Data& data, const FaceEndpoint& ingr } if (!pitEntry->hasInRecords()) { // already satisfied by another upstream - NFD_LOG_DEBUG(pitEntry->getInterest() << " dataFrom " << ingress << " not-fastest"); + NFD_LOG_DATA_FROM(data, ingress, "not-fastest"); return; } auto outRecord = pitEntry->getOutRecord(ingress.face); - if (outRecord == pitEntry->out_end()) { // no out-record - NFD_LOG_DEBUG(pitEntry->getInterest() << " dataFrom " << ingress << " no-out-record"); + if (outRecord == pitEntry->out_end()) { + NFD_LOG_DATA_FROM(data, ingress, "no-out-record"); return; } auto rtt = time::steady_clock::now() - outRecord->getLastRenewed(); - NFD_LOG_DEBUG(pitEntry->getInterest() << " dataFrom " << ingress - << " rtt=" << time::duration_cast(rtt).count()); + NFD_LOG_DATA_FROM(data, ingress, "rtt=" << time::duration_cast(rtt).count() << "us"); this->updateMeasurements(ingress.face, data, rtt); } diff --git a/daemon/fw/asf-strategy.cpp b/daemon/fw/asf-strategy.cpp index d4ea9440..8ff31a2c 100644 --- a/daemon/fw/asf-strategy.cpp +++ b/daemon/fw/asf-strategy.cpp @@ -1,6 +1,6 @@ /* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */ /* - * Copyright (c) 2014-2022, Regents of the University of California, + * Copyright (c) 2014-2023, Regents of the University of California, * Arizona Board of Regents, * Colorado State University, * University Pierre & Marie Curie, Sorbonne University, @@ -25,7 +25,6 @@ #include "asf-strategy.hpp" #include "algorithm.hpp" -#include "common/global.hpp" #include "common/logger.hpp" namespace nfd::fw::asf { @@ -75,11 +74,11 @@ AsfStrategy::afterReceiveInterest(const Interest& interest, const FaceEndpoint& if (!hasPendingOutRecords(*pitEntry)) { auto* faceToUse = getBestFaceForForwarding(interest, ingress.face, fibEntry, pitEntry); if (faceToUse == nullptr) { - NFD_LOG_DEBUG(interest << " new-interest from=" << ingress << " no-nexthop"); + NFD_LOG_INTEREST_FROM(interest, ingress, "new no-nexthop"); sendNoRouteNack(ingress.face, pitEntry); } else { - NFD_LOG_DEBUG(interest << " new-interest from=" << ingress << " forward-to=" << faceToUse->getId()); + NFD_LOG_INTEREST_FROM(interest, ingress, "new forward-to=" << faceToUse->getId()); forwardInterest(interest, *faceToUse, fibEntry, pitEntry); sendProbe(interest, ingress, *faceToUse, fibEntry, pitEntry); } @@ -91,13 +90,12 @@ AsfStrategy::afterReceiveInterest(const Interest& interest, const FaceEndpoint& auto suppressResult = m_retxSuppression->decidePerUpstream(*pitEntry, *faceToUse); if (suppressResult == RetxSuppressionResult::SUPPRESS) { // Cannot be sent on this face, interest was received within the suppression window - NFD_LOG_DEBUG(interest << " retx-interest from=" << ingress - << " forward-to=" << faceToUse->getId() << " suppressed"); + NFD_LOG_INTEREST_FROM(interest, ingress, "retx forward-to=" << faceToUse->getId() << " suppressed"); } else { // The retx arrived after the suppression period: forward it but don't probe, because // probing was done earlier for this interest when it was newly received - NFD_LOG_DEBUG(interest << " retx-interest from=" << ingress << " forward-to=" << faceToUse->getId()); + NFD_LOG_INTEREST_FROM(interest, ingress, "retx forward-to=" << faceToUse->getId()); auto* outRecord = forwardInterest(interest, *faceToUse, fibEntry, pitEntry); if (outRecord && suppressResult == RetxSuppressionResult::FORWARD) { m_retxSuppression->incrementIntervalForOutRecord(*outRecord); @@ -111,17 +109,16 @@ AsfStrategy::afterReceiveInterest(const Interest& interest, const FaceEndpoint& const auto& nexthops = fibEntry.getNextHops(); auto it = findEligibleNextHopWithEarliestOutRecord(ingress.face, interest, nexthops, pitEntry); if (it == nexthops.end()) { - NFD_LOG_DEBUG(interest << " retx-interest from=" << ingress << " no eligible nexthop"); + NFD_LOG_INTEREST_FROM(interest, ingress, "retx no-nexthop"); return; } auto& outFace = it->getFace(); auto suppressResult = m_retxSuppression->decidePerUpstream(*pitEntry, outFace); if (suppressResult == RetxSuppressionResult::SUPPRESS) { - NFD_LOG_DEBUG(interest << " retx-interest from=" << ingress - << " retry-to=" << outFace.getId() << " suppressed"); + NFD_LOG_INTEREST_FROM(interest, ingress, "retx retry-to=" << outFace.getId() << " suppressed"); } else { - NFD_LOG_DEBUG(interest << " retx-interest from=" << ingress << " retry-to=" << outFace.getId()); + NFD_LOG_INTEREST_FROM(interest, ingress, "retx retry-to=" << outFace.getId()); // sendInterest() is used here instead of forwardInterest() because the measurements info // were already attached to this face in the previous forwarding auto* outRecord = sendInterest(interest, outFace, pitEntry); @@ -137,25 +134,24 @@ AsfStrategy::beforeSatisfyInterest(const Data& data, const FaceEndpoint& ingress { NamespaceInfo* namespaceInfo = m_measurements.getNamespaceInfo(pitEntry->getName()); if (namespaceInfo == nullptr) { - NFD_LOG_DEBUG(pitEntry->getName() << " data from=" << ingress << " no-measurements"); + NFD_LOG_DATA_FROM(data, ingress, "no-measurements"); return; } // Record the RTT between the Interest out to Data in FaceInfo* faceInfo = namespaceInfo->getFaceInfo(ingress.face.getId()); if (faceInfo == nullptr) { - NFD_LOG_DEBUG(pitEntry->getName() << " data from=" << ingress << " no-face-info"); + NFD_LOG_DATA_FROM(data, ingress, "no-face-info"); return; } auto outRecord = pitEntry->getOutRecord(ingress.face); if (outRecord == pitEntry->out_end()) { - NFD_LOG_DEBUG(pitEntry->getName() << " data from=" << ingress << " no-out-record"); + NFD_LOG_DATA_FROM(data, ingress, "no-out-record"); } else { faceInfo->recordRtt(time::steady_clock::now() - outRecord->getLastRenewed()); - NFD_LOG_DEBUG(pitEntry->getName() << " data from=" << ingress - << " rtt=" << faceInfo->getLastRtt() << " srtt=" << faceInfo->getSrtt()); + NFD_LOG_DATA_FROM(data, ingress, "rtt=" << faceInfo->getLastRtt() << " srtt=" << faceInfo->getSrtt()); } // Extend lifetime for measurements associated with Face @@ -169,7 +165,7 @@ void AsfStrategy::afterReceiveNack(const lp::Nack& nack, const FaceEndpoint& ingress, const shared_ptr& pitEntry) { - NFD_LOG_DEBUG(nack.getInterest() << " nack from=" << ingress << " reason=" << nack.getReason()); + NFD_LOG_NACK_FROM(nack, ingress, ""); onTimeoutOrNack(pitEntry->getName(), ingress.face.getId(), true); } @@ -213,7 +209,8 @@ AsfStrategy::sendProbe(const Interest& interest, const FaceEndpoint& ingress, co Interest probeInterest(interest); probeInterest.refreshNonce(); - NFD_LOG_TRACE("Sending probe " << probeInterest << " to=" << faceToProbe->getId()); + NFD_LOG_DEBUG("Sending probe " << probeInterest.getName() << " nonce=" << probeInterest.getNonce() + << " to=" << faceToProbe->getId() << " trigger-nonce=" << interest.getNonce()); forwardInterest(probeInterest, *faceToProbe, fibEntry, pitEntry); m_probing.afterForwardingProbe(fibEntry, interest.getName()); diff --git a/daemon/fw/best-route-strategy.cpp b/daemon/fw/best-route-strategy.cpp index 0de6265f..a275b3ac 100644 --- a/daemon/fw/best-route-strategy.cpp +++ b/daemon/fw/best-route-strategy.cpp @@ -1,6 +1,6 @@ /* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */ /* - * Copyright (c) 2014-2022, Regents of the University of California, + * Copyright (c) 2014-2023, Regents of the University of California, * Arizona Board of Regents, * Colorado State University, * University Pierre & Marie Curie, Sorbonne University, @@ -61,9 +61,9 @@ void BestRouteStrategy::afterReceiveInterest(const Interest& interest, const FaceEndpoint& ingress, const shared_ptr& pitEntry) { - RetxSuppressionResult suppression = m_retxSuppression->decidePerPitEntry(*pitEntry); + auto suppression = m_retxSuppression->decidePerPitEntry(*pitEntry); if (suppression == RetxSuppressionResult::SUPPRESS) { - NFD_LOG_DEBUG(interest << " from=" << ingress << " suppressed"); + NFD_LOG_INTEREST_FROM(interest, ingress, "suppressed"); return; } @@ -78,8 +78,7 @@ BestRouteStrategy::afterReceiveInterest(const Interest& interest, const FaceEndp }); if (it == nexthops.end()) { - NFD_LOG_DEBUG(interest << " from=" << ingress << " noNextHop"); - + NFD_LOG_INTEREST_FROM(interest, ingress, "new no-nexthop"); lp::NackHeader nackHeader; nackHeader.setReason(lp::NackReason::NO_ROUTE); this->sendNack(nackHeader, ingress.face, pitEntry); @@ -88,7 +87,7 @@ BestRouteStrategy::afterReceiveInterest(const Interest& interest, const FaceEndp } Face& outFace = it->getFace(); - NFD_LOG_DEBUG(interest << " from=" << ingress << " newPitEntry-to=" << outFace.getId()); + NFD_LOG_INTEREST_FROM(interest, ingress, "new to=" << outFace.getId()); this->sendInterest(interest, outFace, pitEntry); return; } @@ -102,19 +101,19 @@ BestRouteStrategy::afterReceiveInterest(const Interest& interest, const FaceEndp if (it != nexthops.end()) { Face& outFace = it->getFace(); this->sendInterest(interest, outFace, pitEntry); - NFD_LOG_DEBUG(interest << " from=" << ingress << " retransmit-unused-to=" << outFace.getId()); + NFD_LOG_INTEREST_FROM(interest, ingress, "retx unused-to=" << outFace.getId()); return; } // find an eligible upstream that is used earliest it = findEligibleNextHopWithEarliestOutRecord(ingress.face, interest, nexthops, pitEntry); if (it == nexthops.end()) { - NFD_LOG_DEBUG(interest << " from=" << ingress << " retransmitNoNextHop"); + NFD_LOG_INTEREST_FROM(interest, ingress, "retx no-nexthop"); } else { Face& outFace = it->getFace(); this->sendInterest(interest, outFace, pitEntry); - NFD_LOG_DEBUG(interest << " from=" << ingress << " retransmit-retry-to=" << outFace.getId()); + NFD_LOG_INTEREST_FROM(interest, ingress, "retx retry-to=" << outFace.getId()); } } diff --git a/daemon/fw/multicast-strategy.cpp b/daemon/fw/multicast-strategy.cpp index ab8e12a2..678f52a3 100644 --- a/daemon/fw/multicast-strategy.cpp +++ b/daemon/fw/multicast-strategy.cpp @@ -1,6 +1,6 @@ /* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */ /* - * Copyright (c) 2014-2022, Regents of the University of California, + * Copyright (c) 2014-2023, Regents of the University of California, * Arizona Board of Regents, * Colorado State University, * University Pierre & Marie Curie, Sorbonne University, @@ -67,10 +67,9 @@ MulticastStrategy::afterReceiveInterest(const Interest& interest, const FaceEndp for (const auto& nexthop : nexthops) { Face& outFace = nexthop.getFace(); - RetxSuppressionResult suppressResult = m_retxSuppression->decidePerUpstream(*pitEntry, outFace); - + auto suppressResult = m_retxSuppression->decidePerUpstream(*pitEntry, outFace); if (suppressResult == RetxSuppressionResult::SUPPRESS) { - NFD_LOG_DEBUG(interest << " from=" << ingress << " to=" << outFace.getId() << " suppressed"); + NFD_LOG_INTEREST_FROM(interest, ingress, "to=" << outFace.getId() << " suppressed"); continue; } @@ -78,7 +77,7 @@ MulticastStrategy::afterReceiveInterest(const Interest& interest, const FaceEndp continue; } - NFD_LOG_DEBUG(interest << " from=" << ingress << " pitEntry-to=" << outFace.getId()); + NFD_LOG_INTEREST_FROM(interest, ingress, "to=" << outFace.getId()); auto* sentOutRecord = this->sendInterest(interest, outFace, pitEntry); if (sentOutRecord && suppressResult == RetxSuppressionResult::FORWARD) { m_retxSuppression->incrementIntervalForOutRecord(*sentOutRecord); @@ -93,16 +92,15 @@ MulticastStrategy::afterNewNextHop(const fib::NextHop& nextHop, // no need to check for suppression, as it is a new next hop auto nextHopFaceId = nextHop.getFace().getId(); - auto& interest = pitEntry->getInterest(); + const auto& interest = pitEntry->getInterest(); // try to find an incoming face record that doesn't violate scope restrictions for (const auto& r : pitEntry->getInRecords()) { auto& inFace = r.getFace(); - if (isNextHopEligible(inFace, interest, nextHop, pitEntry)) { - NFD_LOG_DEBUG(interest << " from=" << inFace.getId() << " pitEntry-to=" << nextHopFaceId); + if (isNextHopEligible(inFace, interest, nextHop, pitEntry)) { + NFD_LOG_INTEREST_FROM(interest, inFace.getId(), "new-nexthop to=" << nextHopFaceId); this->sendInterest(interest, nextHop.getFace(), pitEntry); - break; // just one eligible incoming face record is enough } } diff --git a/daemon/fw/process-nack-traits.cpp b/daemon/fw/process-nack-traits.cpp index 4b4fbbc1..25b25268 100644 --- a/daemon/fw/process-nack-traits.cpp +++ b/daemon/fw/process-nack-traits.cpp @@ -1,6 +1,6 @@ /* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */ /* - * Copyright (c) 2014-2022, Regents of the University of California, + * Copyright (c) 2014-2023, Regents of the University of California, * Arizona Board of Regents, * Colorado State University, * University Pierre & Marie Curie, Sorbonne University, @@ -58,26 +58,20 @@ ProcessNackTraitsBase::processNack(const lp::Nack& nack, const Face& inFace, auto inR = pitEntry->getInRecord(*lastFaceNotNacked); if (inR != pitEntry->in_end()) { // one out-record not Nacked, which is also a downstream - NFD_LOG_DEBUG(nack.getInterest() << " nack-from=" << inFace.getId() << - " nack=" << nack.getReason() << - " nack-to(bidirectional)=" << lastFaceNotNacked->getId() << - " out-nack=" << outNack.getReason()); + NFD_LOG_NACK_FROM(nack, inFace.getId(), "bidirectional nack-to=" << lastFaceNotNacked->getId() + << " out-nack=" << outNack.getReason()); this->sendNackForProcessNackTraits(pitEntry, *lastFaceNotNacked, outNack); return; } } if (nOutRecordsNotNacked > 0) { - NFD_LOG_DEBUG(nack.getInterest() << " nack-from=" << inFace.getId() << - " nack=" << nack.getReason() << - " waiting=" << nOutRecordsNotNacked); + NFD_LOG_NACK_FROM(nack, inFace.getId(), "waiting=" << nOutRecordsNotNacked); // continue waiting return; } - NFD_LOG_DEBUG(nack.getInterest() << " nack-from=" << inFace.getId() << - " nack=" << nack.getReason() << - " nack-to=all out-nack=" << outNack.getReason()); + NFD_LOG_NACK_FROM(nack, inFace.getId(), "nack-to=all out-nack=" << outNack.getReason()); this->sendNacksForProcessNackTraits(pitEntry, outNack); } diff --git a/daemon/fw/random-strategy.cpp b/daemon/fw/random-strategy.cpp index b4950e70..a7ba2249 100644 --- a/daemon/fw/random-strategy.cpp +++ b/daemon/fw/random-strategy.cpp @@ -1,6 +1,6 @@ /* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */ /* - * Copyright (c) 2014-2022, Regents of the University of California, + * Copyright (c) 2014-2023, Regents of the University of California, * Arizona Board of Regents, * Colorado State University, * University Pierre & Marie Curie, Sorbonne University, @@ -66,8 +66,7 @@ RandomStrategy::afterReceiveInterest(const Interest& interest, const FaceEndpoin [&] (const auto& nh) { return isNextHopEligible(ingress.face, interest, nh, pitEntry); }); if (nhs.empty()) { - NFD_LOG_DEBUG(interest << " from=" << ingress << " no nexthop"); - + NFD_LOG_INTEREST_FROM(interest, ingress, "no-nexthop"); lp::NackHeader nackHeader; nackHeader.setReason(lp::NackReason::NO_ROUTE); this->sendNack(nackHeader, ingress.face, pitEntry); diff --git a/daemon/fw/retx-suppression.hpp b/daemon/fw/retx-suppression.hpp index 7cf6893b..ac658b0b 100644 --- a/daemon/fw/retx-suppression.hpp +++ b/daemon/fw/retx-suppression.hpp @@ -1,6 +1,6 @@ /* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */ /* - * Copyright (c) 2014-2022, Regents of the University of California, + * Copyright (c) 2014-2023, Regents of the University of California, * Arizona Board of Regents, * Colorado State University, * University Pierre & Marie Curie, Sorbonne University, @@ -26,22 +26,12 @@ #ifndef NFD_DAEMON_FW_RETX_SUPPRESSION_HPP #define NFD_DAEMON_FW_RETX_SUPPRESSION_HPP -#include "core/common.hpp" - namespace nfd::fw { enum class RetxSuppressionResult { - /** \brief Interest is new (not a retransmission) - */ - NEW, - - /** \brief Interest is retransmission and should be forwarded - */ - FORWARD, - - /** \brief Interest is retransmission and should be suppressed - */ - SUPPRESS + NEW, ///< Interest is new (not a retransmission). + FORWARD, ///< Interest is a retransmission and should be forwarded. + SUPPRESS, ///< Interest is a retransmission and should be suppressed. }; } // namespace nfd::fw diff --git a/daemon/fw/self-learning-strategy.cpp b/daemon/fw/self-learning-strategy.cpp index 399b9702..19d9d75d 100644 --- a/daemon/fw/self-learning-strategy.cpp +++ b/daemon/fw/self-learning-strategy.cpp @@ -1,6 +1,6 @@ /* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */ /* - * Copyright (c) 2014-2022, Regents of the University of California, + * Copyright (c) 2014-2023, Regents of the University of California, * Arizona Board of Regents, * Colorado State University, * University Pierre & Marie Curie, Sorbonne University, @@ -76,7 +76,7 @@ SelfLearningStrategy::afterReceiveInterest(const Interest& interest, const FaceE if (isNonDiscovery) { // "non-discovery" Interest inRecordInfo->isNonDiscoveryInterest = true; if (nexthops.empty()) { // return NACK if no matching FIB entry exists - NFD_LOG_DEBUG("NACK non-discovery Interest=" << interest << " from=" << ingress << " noNextHop"); + NFD_LOG_INTEREST_FROM(interest, ingress, "non-discovery no-nexthop"); lp::NackHeader nackHeader; nackHeader.setReason(lp::NackReason::NO_ROUTE); this->sendNack(nackHeader, ingress.face, pitEntry); @@ -104,7 +104,7 @@ SelfLearningStrategy::afterReceiveData(const Data& data, const FaceEndpoint& ing { auto outRecord = pitEntry->getOutRecord(ingress.face); if (outRecord == pitEntry->out_end()) { - NFD_LOG_DEBUG("Data " << data.getName() << " from=" << ingress << " no out-record"); + NFD_LOG_DATA_FROM(data, ingress, "no-out-record"); return; } @@ -132,11 +132,11 @@ void SelfLearningStrategy::afterReceiveNack(const lp::Nack& nack, const FaceEndpoint& ingress, const shared_ptr& pitEntry) { - NFD_LOG_DEBUG("Nack for " << nack.getInterest() << " from=" << ingress - << " reason=" << nack.getReason()); + NFD_LOG_NACK_FROM(nack, ingress, ""); + if (nack.getReason() == lp::NackReason::NO_ROUTE) { // remove FIB entries BOOST_ASSERT(this->lookupFib(*pitEntry).hasNextHops()); - NFD_LOG_DEBUG("Send NACK to all downstreams"); + NFD_LOG_DEBUG("Send Nack to all downstreams"); this->sendNacks(nack.getHeader(), pitEntry); renewRoute(nack.getInterest().getName(), ingress.face.getId(), 0_ms); } @@ -153,8 +153,7 @@ SelfLearningStrategy::broadcastInterest(const Interest& interest, const Face& in continue; } - NFD_LOG_DEBUG("send discovery Interest=" << interest << " from=" << inFace.getId() << - " to=" << outFace.getId()); + NFD_LOG_INTEREST_FROM(interest, inFace.getId(), "send discovery to=" << outFace.getId()); auto outRecord = this->sendInterest(interest, outFace, pitEntry); if (outRecord != nullptr) { outRecord->insertStrategyInfo().first->isNonDiscoveryInterest = false; @@ -173,8 +172,7 @@ SelfLearningStrategy::multicastInterest(const Interest& interest, const Face& in } Face& outFace = nexthop.getFace(); - NFD_LOG_DEBUG("send non-discovery Interest=" << interest << " from=" << inFace.getId() << - " to=" << outFace.getId()); + NFD_LOG_INTEREST_FROM(interest, inFace.getId(), "send non-discovery to=" << outFace.getId()); auto outRecord = this->sendInterest(interest, outFace, pitEntry); if (outRecord != nullptr) { outRecord->insertStrategyInfo().first->isNonDiscoveryInterest = true; @@ -198,13 +196,13 @@ SelfLearningStrategy::asyncProcessData(const shared_ptr& pitEntry, c auto pitEntry = pitEntryWeak.lock(); auto inFace = this->getFace(inFaceId); if (pitEntry && inFace) { - NFD_LOG_DEBUG("found PrefixAnnouncement=" << pa.getAnnouncedName()); + NFD_LOG_DEBUG("Found PrefixAnnouncement=" << pa.getAnnouncedName()); data.setTag(make_shared(lp::PrefixAnnouncementHeader(pa))); this->sendDataToAll(data, pitEntry, *inFace); this->setExpiryTimer(pitEntry, 0_ms); } else { - NFD_LOG_DEBUG("PIT entry or Face no longer exists"); + NFD_LOG_DEBUG("PIT entry or face no longer exists"); } }); } diff --git a/daemon/fw/strategy.hpp b/daemon/fw/strategy.hpp index 285e1a80..5e99d6a3 100644 --- a/daemon/fw/strategy.hpp +++ b/daemon/fw/strategy.hpp @@ -1,6 +1,6 @@ /* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */ /* - * Copyright (c) 2014-2022, Regents of the University of California, + * Copyright (c) 2014-2023, Regents of the University of California, * Arizona Board of Regents, * Colorado State University, * University Pierre & Marie Curie, Sorbonne University, @@ -490,9 +490,10 @@ class StrategyParameters : public std::map } // namespace nfd::fw -/** \brief Registers a strategy +/** + * \brief Registers a forwarding strategy. * - * This macro should appear once in .cpp of each strategy. + * This macro should appear once in the `.cpp` of each strategy. */ #define NFD_REGISTER_STRATEGY(S) \ static class NfdAuto ## S ## StrategyRegistrationClass \ @@ -504,4 +505,25 @@ public: \ } \ } g_nfdAuto ## S ## StrategyRegistrationVariable +/// Logs the reception of \p interest on \p ingress, followed by \p msg, at DEBUG level. +#define NFD_LOG_INTEREST_FROM(interest, ingress, msg) \ + NFD_LOG_DEBUG("interest=" << (interest).getName() << \ + " nonce=" << (interest).getNonce() << \ + " from=" << (ingress) << \ + ' ' << msg) + +/// Logs the reception of \p data on \p ingress, followed by \p msg, at DEBUG level. +#define NFD_LOG_DATA_FROM(data, ingress, msg) \ + NFD_LOG_DEBUG("data=" << (data).getName() << \ + " from=" << (ingress) << \ + ' ' << msg) + +/// Logs the reception of \p nack on \p ingress, followed by \p msg, at DEBUG level. +#define NFD_LOG_NACK_FROM(nack, ingress, msg) \ + NFD_LOG_DEBUG("nack=" << (nack).getInterest().getName() << \ + " nonce=" << (nack).getInterest().getNonce() << \ + " reason=" << (nack).getReason() << \ + " from=" << (ingress) << \ + ' ' << msg) + #endif // NFD_DAEMON_FW_STRATEGY_HPP