Skip to content

Commit

Permalink
mgmt+rib: improve logging
Browse files Browse the repository at this point in the history 
Change-Id: I2c8470831a9f9cbd5c06681f69783c4b442420f9
  • Loading branch information
@Pesa
Pesa committed Jan 11, 2025
1 parent b065768 commit 21e24f9
Show file tree
Hide file tree
Showing 11 changed files with 146 additions and 155 deletions.
24 changes: 12 additions & 12 deletions daemon/mgmt/fib-manager.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -65,24 +65,24 @@ FibManager::addNextHop(const Interest& interest, ControlParameters parameters,
uint64_t cost = parameters.getCost();

if (prefix.size() > Fib::getMaxDepth()) {
NFD_LOG_DEBUG("fib/add-nexthop(" << prefix << ',' << faceId << ',' << cost <<
"): FAIL prefix-too-long");
NFD_LOG_DEBUG("add-nexthop(" << prefix << ',' << faceId << ',' << cost <<
") -> FAIL prefix-too-long");
return done(ControlResponse(414, "FIB entry prefix cannot exceed " +
std::to_string(Fib::getMaxDepth()) + " components"));
}

Face* face = m_faceTable.get(faceId);
if (face == nullptr) {
NFD_LOG_DEBUG("fib/add-nexthop(" << prefix << ',' << faceId << ',' << cost <<
"): FAIL unknown-faceid");
NFD_LOG_DEBUG("add-nexthop(" << prefix << ',' << faceId << ',' << cost <<
") -> FAIL unknown-faceid");
return done(ControlResponse(410, "Face not found"));
}

fib::Entry* entry = m_fib.insert(prefix).first;
m_fib.addOrUpdateNextHop(*entry, *face, cost);

NFD_LOG_TRACE("fib/add-nexthop(" << prefix << ',' << faceId << ',' << cost << "): OK");
return done(ControlResponse(200, "Success").setBody(parameters.wireEncode()));
NFD_LOG_TRACE("add-nexthop(" << prefix << ',' << faceId << ',' << cost << ") -> OK");
return done(ControlResponse(200, "OK").setBody(parameters.wireEncode()));
}

void
Expand All @@ -93,30 +93,30 @@ FibManager::removeNextHop(const Interest& interest, ControlParameters parameters
const Name& prefix = parameters.getName();
FaceId faceId = parameters.getFaceId();

done(ControlResponse(200, "Success").setBody(parameters.wireEncode()));
done(ControlResponse(200, "OK").setBody(parameters.wireEncode()));

Face* face = m_faceTable.get(faceId);
if (face == nullptr) {
NFD_LOG_TRACE("fib/remove-nexthop(" << prefix << ',' << faceId << "): OK no-face");
NFD_LOG_TRACE("remove-nexthop(" << prefix << ',' << faceId << ") -> OK no-face");
return;
}

fib::Entry* entry = m_fib.findExactMatch(parameters.getName());
if (entry == nullptr) {
NFD_LOG_TRACE("fib/remove-nexthop(" << prefix << ',' << faceId << "): OK no-entry");
NFD_LOG_TRACE("remove-nexthop(" << prefix << ',' << faceId << ") -> OK no-entry");
return;
}

auto status = m_fib.removeNextHop(*entry, *face);
switch (status) {
case Fib::RemoveNextHopResult::NO_SUCH_NEXTHOP:
NFD_LOG_TRACE("fib/remove-nexthop(" << prefix << ',' << faceId << "): OK no-nexthop");
NFD_LOG_TRACE("remove-nexthop(" << prefix << ',' << faceId << ") -> OK no-nexthop");
break;
case Fib::RemoveNextHopResult::FIB_ENTRY_REMOVED:
NFD_LOG_TRACE("fib/remove-nexthop(" << prefix << ',' << faceId << "): OK entry-erased");
NFD_LOG_TRACE("remove-nexthop(" << prefix << ',' << faceId << ") -> OK entry-erased");
break;
case Fib::RemoveNextHopResult::NEXTHOP_REMOVED:
NFD_LOG_TRACE("fib/remove-nexthop(" << prefix << ',' << faceId << "): OK nexthop-removed");
NFD_LOG_TRACE("remove-nexthop(" << prefix << ',' << faceId << ") -> OK nexthop-removed");
break;
}
}
Expand Down
114 changes: 55 additions & 59 deletions daemon/mgmt/rib-manager.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -31,6 +31,7 @@
#include "table/fib.hpp"

#include <boost/asio/defer.hpp>
#include <boost/lexical_cast.hpp>

#include <ndn-cxx/lp/tags.hpp>
#include <ndn-cxx/mgmt/nfd/rib-entry.hpp>
Expand Down Expand Up @@ -122,11 +123,11 @@ RibManager::enableLocalFields()
m_nfdController.start<ndn::nfd::FaceUpdateCommand>(
ControlParameters().setFlagBit(ndn::nfd::BIT_LOCAL_FIELDS_ENABLED, true),
[] (const ControlParameters&) {
NFD_LOG_DEBUG("Local fields enabled");
NFD_LOG_TRACE("Local fields enabled");
},
[] (const ControlResponse& res) {
NDN_THROW(Error("Couldn't enable local fields (" + std::to_string(res.getCode()) +
" " + res.getText() + ")"));
NDN_THROW(Error("Could not enable local fields (error " +
std::to_string(res.getCode()) + ": " + res.getText() + ")"));
});
}

Expand Down Expand Up @@ -182,11 +183,11 @@ RibManager::beginRibUpdate(const RibUpdate& update,
{
m_rib.beginApplyUpdate(update,
[=] {
NFD_LOG_DEBUG("RIB update succeeded for " << update);
NFD_LOG_DEBUG(update << " -> OK");
done(RibUpdateResult::OK);
},
[=] (uint32_t code, const std::string& error) {
NFD_LOG_DEBUG("RIB update failed for " << update << " (" << code << " " << error << ")");
NFD_LOG_DEBUG(update << " -> error " << code << ": " << error);

// Since the FIB rejected the update, clean up invalid routes
scheduleActiveFaceFetch(1_s);
Expand All @@ -200,10 +201,9 @@ RibManager::registerTopPrefix(const Name& topPrefix)
{
// add FIB nexthop
m_nfdController.start<ndn::nfd::FibAddNextHopCommand>(
ControlParameters().setName(Name(topPrefix).append(MGMT_MODULE_NAME))
.setFaceId(0),
ControlParameters().setName(Name(topPrefix).append(MGMT_MODULE_NAME)).setFaceId(0),
[=] (const ControlParameters& res) {
NFD_LOG_DEBUG("Successfully registered " << topPrefix << " with NFD");
NFD_LOG_DEBUG("Successfully registered " << topPrefix << " with the forwarder");

// Routes must be inserted into the RIB so route flags can be applied
Route route;
Expand All @@ -214,14 +214,25 @@ RibManager::registerTopPrefix(const Name& topPrefix)
m_rib.insert(topPrefix, route);
},
[=] (const ControlResponse& res) {
NDN_THROW(Error("Cannot add FIB entry " + topPrefix.toUri() + " (" +
std::to_string(res.getCode()) + " " + res.getText() + ")"));
NDN_THROW(Error("Could not add FIB entry " + topPrefix.toUri() + " (error " +
std::to_string(res.getCode()) + ": " + res.getText() + ")"));
});

// add top prefix to the dispatcher without prefix registration
m_dispatcher.addTopPrefix(topPrefix, false);
}

static uint64_t
getIncomingFaceId(const Interest& request)
{
auto incomingFaceIdTag = request.getTag<lp::IncomingFaceIdTag>();
// NDNLPv2 says "application MUST be prepared to receive a packet without IncomingFaceId field",
// but it's fine to assert IncomingFaceId is available, because InternalFace lives inside NFD
// and is initialized synchronously with IncomingFaceId field enabled.
BOOST_ASSERT(incomingFaceIdTag != nullptr);
return incomingFaceIdTag->get();
}

void
RibManager::registerEntry(const Interest& interest, ControlParameters parameters,
const CommandContinuation& done)
Expand All @@ -232,10 +243,12 @@ RibManager::registerEntry(const Interest& interest, ControlParameters parameters
return;
}

setFaceForSelfRegistration(interest, parameters);
if (parameters.getFaceId() == 0) { // self registration
parameters.setFaceId(getIncomingFaceId(interest));
}

// Respond since command is valid and authorized
done(ControlResponse(200, "Success").setBody(parameters.wireEncode()));
done(ControlResponse(200, "OK").setBody(parameters.wireEncode()));

Route route;
route.faceId = parameters.getFaceId();
Expand All @@ -256,10 +269,12 @@ void
RibManager::unregisterEntry(const Interest& interest, ControlParameters parameters,
const CommandContinuation& done)
{
setFaceForSelfRegistration(interest, parameters);
if (parameters.getFaceId() == 0) { // self unregistration
parameters.setFaceId(getIncomingFaceId(interest));
}

// Respond since command is valid and authorized
done(ControlResponse(200, "Success").setBody(parameters.wireEncode()));
done(ControlResponse(200, "OK").setBody(parameters.wireEncode()));

Route route;
route.faceId = parameters.getFaceId();
Expand All @@ -273,37 +288,38 @@ RibManager::announceEntry(const Interest& interest, const ndn::nfd::RibAnnounceP
const CommandContinuation& done)
{
const auto& announcement = parameters.getPrefixAnnouncement();
if (announcement.getAnnouncedName().size() > Fib::getMaxDepth()) {
const auto& name = announcement.getAnnouncedName();
if (name.size() > Fib::getMaxDepth()) {
done(ControlResponse(414, "Route prefix cannot exceed " + std::to_string(Fib::getMaxDepth()) +
" components"));
return;
}

Route route(announcement, getIncomingFaceId(interest));

// Prepare parameters for response
ControlParameters responseParams;
responseParams.setFaceId(0);
setFaceForSelfRegistration(interest, responseParams);

Route route(announcement, responseParams.getFaceId());

responseParams
.setName(announcement.getAnnouncedName())
.setName(name)
.setFaceId(route.faceId)
.setOrigin(route.origin)
.setCost(route.cost)
.setFlags(route.flags)
.setExpirationPeriod(time::duration_cast<time::milliseconds>(route.annExpires - time::steady_clock::now()));

NDN_LOG_TRACE("Validating announcement " << announcement);
BOOST_ASSERT(announcement.getData());
m_paValidator.validate(*announcement.getData(),
[=, name = announcement.getAnnouncedName(), route = std::move(route)] (const Data&) {
[=, route = std::move(route)] (const Data&) {
// Respond since command is valid and authorized
done(ControlResponse(200, "Success").setBody(responseParams.wireEncode()));
done(ControlResponse(200, "OK").setBody(responseParams.wireEncode()));
beginAddRoute(name, std::move(route), std::nullopt, [] (RibUpdateResult) {});
},
[=] (const Data&, ndn::security::ValidationError err) {
done(ControlResponse(403, "Validation error: " + err.getInfo()));
}
);
[=] (const Data&, const ndn::security::ValidationError& err) {
NDN_LOG_DEBUG("announce " << name << " -> " << err);
done(ControlResponse(403, "Prefix announcement rejected: " +
boost::lexical_cast<std::string>(err.getCode())));
});
}

void
Expand All @@ -330,20 +346,6 @@ RibManager::listEntries(ndn::mgmt::StatusDatasetContext& context)
context.end();
}

void
RibManager::setFaceForSelfRegistration(const Interest& request, ControlParameters& parameters)
{
bool isSelfRegistration = (parameters.getFaceId() == 0);
if (isSelfRegistration) {
shared_ptr<lp::IncomingFaceIdTag> incomingFaceIdTag = request.getTag<lp::IncomingFaceIdTag>();
// NDNLPv2 says "application MUST be prepared to receive a packet without IncomingFaceId field",
// but it's fine to assert IncomingFaceId is available, because InternalFace lives inside NFD
// and is initialized synchronously with IncomingFaceId field enabled.
BOOST_ASSERT(incomingFaceIdTag != nullptr);
parameters.setFaceId(*incomingFaceIdTag);
}
}

ndn::mgmt::Authorization
RibManager::makeAuthorization(const std::string&)
{
Expand Down Expand Up @@ -408,16 +410,15 @@ RibManager::slAnnounce(const ndn::PrefixAnnouncement& pa, uint64_t faceId,
beginAddRoute(pa.getAnnouncedName(), route, std::nullopt,
[=] (RibUpdateResult ribRes) {
auto res = getSlAnnounceResultFromRibUpdateResult(ribRes);
NFD_LOG_INFO("slAnnounce " << pa.getAnnouncedName() << " " << faceId << ": " << res);
NFD_LOG_INFO("slAnnounce " << pa.getAnnouncedName() << " " << faceId << " -> " << res);
cb(res);
});
},
[=] (const Data&, ndn::security::ValidationError err) {
[=] (const Data&, const ndn::security::ValidationError& err) {
NFD_LOG_INFO("slAnnounce " << pa.getAnnouncedName() << " " << faceId <<
" validation error: " << err);
" -> validation error: " << err);
cb(SlAnnounceResult::VALIDATION_FAILURE);
}
);
});
}

void
Expand All @@ -430,7 +431,7 @@ RibManager::slRenew(const Name& name, uint64_t faceId, time::milliseconds maxLif
Route* oldRoute = m_rib.findLongestPrefix(name, routeQuery);

if (oldRoute == nullptr || !oldRoute->announcement) {
NFD_LOG_DEBUG("slRenew " << name << " " << faceId << ": not found");
NFD_LOG_DEBUG("slRenew " << name << " " << faceId << " -> not found");
return cb(SlAnnounceResult::NOT_FOUND);
}
Name routeName = oldRoute->announcement->getAnnouncedName();
Expand All @@ -440,7 +441,7 @@ RibManager::slRenew(const Name& name, uint64_t faceId, time::milliseconds maxLif
beginAddRoute(routeName, route, std::nullopt,
[=] (RibUpdateResult ribRes) {
auto res = getSlAnnounceResultFromRibUpdateResult(ribRes);
NFD_LOG_INFO("slRenew " << name << " " << faceId << ": " << res << " " << routeName);
NFD_LOG_INFO("slRenew " << name << " " << faceId << " -> " << res << " " << routeName);
cb(res);
});
}
Expand Down Expand Up @@ -472,18 +473,14 @@ RibManager::fetchActiveFaces()

m_nfdController.fetch<ndn::nfd::FaceDataset>(
[this] (auto&&... args) { removeInvalidFaces(std::forward<decltype(args)>(args)...); },
[this] (auto&&... args) { onFetchActiveFacesFailure(std::forward<decltype(args)>(args)...); });
}

void
RibManager::onFetchActiveFacesFailure(uint32_t code, const std::string& reason)
{
NFD_LOG_DEBUG("Face Status Dataset request failure " << code << " " << reason);
scheduleActiveFaceFetch(ACTIVE_FACE_FETCH_INTERVAL);
[this] (uint32_t code, const std::string& reason) {
NFD_LOG_WARN("Failed to fetch face dataset (error " << code << ": " << reason << ")");
scheduleActiveFaceFetch(ACTIVE_FACE_FETCH_INTERVAL);
});
}

void
RibManager::scheduleActiveFaceFetch(const time::seconds& timeToWait)
RibManager::scheduleActiveFaceFetch(time::seconds timeToWait)
{
m_activeFaceFetchEvent = getScheduler().schedule(timeToWait, [this] { fetchActiveFaces(); });
}
Expand All @@ -507,10 +504,9 @@ RibManager::removeInvalidFaces(const std::vector<ndn::nfd::FaceStatus>& activeFa
void
RibManager::onNotification(const ndn::nfd::FaceEventNotification& notification)
{
NFD_LOG_TRACE("onNotification: " << notification);
NFD_LOG_TRACE("Received notification " << notification);

if (notification.getKind() == ndn::nfd::FACE_EVENT_DESTROYED) {
NFD_LOG_DEBUG("Received notification for destroyed FaceId " << notification.getFaceId());
boost::asio::defer(getGlobalIoService(),
[this, id = notification.getFaceId()] { m_rib.beginRemoveFace(id); });
}
Expand Down
8 changes: 1 addition & 7 deletions daemon/mgmt/rib-manager.hpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -224,22 +224,16 @@ class RibManager final : public ManagerBase
void
listEntries(ndn::mgmt::StatusDatasetContext& context);

void
setFaceForSelfRegistration(const Interest& request, ControlParameters& parameters);

ndn::mgmt::Authorization
makeAuthorization(const std::string& verb) final;

private: // Face monitor
void
fetchActiveFaces();

void
onFetchActiveFacesFailure(uint32_t code, const std::string& reason);

NFD_PUBLIC_WITH_TESTS_ELSE_PRIVATE:
void
scheduleActiveFaceFetch(const time::seconds& timeToWait);
scheduleActiveFaceFetch(time::seconds timeToWait);

void
removeInvalidFaces(const std::vector<ndn::nfd::FaceStatus>& activeFaces);
Expand Down
27 changes: 13 additions & 14 deletions daemon/rib/fib-updater.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -64,24 +64,23 @@ FibUpdater::computeAndSendFibUpdates(const RibUpdateBatch& batch,
void
FibUpdater::computeUpdates(const RibUpdateBatch& batch)
{
NFD_LOG_DEBUG("Computing updates for batch with faceID: " << batch.getFaceId());
NFD_LOG_TRACE("Computing updates for batch with faceid=" << batch.getFaceId());

// Compute updates and add to m_fibUpdates
for (const RibUpdate& update : batch) {
switch (update.getAction()) {
case RibUpdate::REGISTER:
computeUpdatesForRegistration(update);
break;
case RibUpdate::UNREGISTER:
computeUpdatesForUnregistration(update);
break;
case RibUpdate::REMOVE_FACE:
computeUpdatesForUnregistration(update);

// Do not apply updates with the same face ID as the destroyed face
// since they will be rejected by the FIB
m_updatesForBatchFaceId.clear();
break;
case RibUpdate::REGISTER:
computeUpdatesForRegistration(update);
break;
case RibUpdate::UNREGISTER:
computeUpdatesForUnregistration(update);
break;
case RibUpdate::REMOVE_FACE:
computeUpdatesForUnregistration(update);
// Do not apply updates with the same face ID as the destroyed face
// since they will be rejected by the FIB
m_updatesForBatchFaceId.clear();
break;
}
}
}
Expand Down
Loading

0 comments on commit 21e24f9

Please sign in to comment.