nlsr: Improve logging throughout lsdb.cpp and others
refs: #3934
Change-Id: I2365c88b795316c83dbeac2eab82f371c0275f88
diff --git a/src/hello-protocol.cpp b/src/hello-protocol.cpp
index b10afb0..684009d 100644
--- a/src/hello-protocol.cpp
+++ b/src/hello-protocol.cpp
@@ -66,6 +66,7 @@
interestName.append(m_nlsr.getConfParameter().getRouterPrefix().wireEncode());
expressInterest(interestName,
m_nlsr.getConfParameter().getInterestResendTime());
+ _LOG_DEBUG("Sending scheduled interest: " << interestName);
}
// If it does not have a Face, we need to give it one. A
// successful registration prompts a callback that sends the hello
@@ -95,6 +96,8 @@
const ndn::Name interestName = interest.getName();
_LOG_DEBUG("Interest Received for Name: " << interestName);
if (interestName.get(-2).toUri() != INFO_COMPONENT) {
+ _LOG_DEBUG("INFO_COMPONENT not found or interestName: " << interestName
+ << " does not match expression");
return;
}
ndn::Name neighbor;
@@ -109,7 +112,7 @@
m_nlsr.getKeyChain().sign(*data, m_nlsr.getDefaultCertName());
_LOG_DEBUG("Sending out data for name: " << interest.getName());
m_nlsr.getNlsrFace().put(*data);
- Adjacent *adjacent = m_nlsr.getAdjacencyList().findAdjacent(neighbor);
+ Adjacent* adjacent = m_nlsr.getAdjacencyList().findAdjacent(neighbor);
// If this neighbor was previously inactive, send our own hello interest, too
if (adjacent->getStatus() == Adjacent::STATUS_INACTIVE) {
// We can only do that if the neighbor currently has a face.
@@ -157,6 +160,7 @@
interestName.append(NLSR_COMPONENT);
interestName.append(INFO_COMPONENT);
interestName.append(m_nlsr.getConfParameter().getRouterPrefix().wireEncode());
+ _LOG_DEBUG("Resending interest: " << interestName);
expressInterest(interestName,
m_nlsr.getConfParameter().getInterestResendTime());
}
@@ -164,6 +168,8 @@
(infoIntTimedOutCount == m_nlsr.getConfParameter().getInterestRetryNumber())) {
m_nlsr.getAdjacencyList().setStatusOfNeighbor(neighbor, Adjacent::STATUS_INACTIVE);
+ _LOG_DEBUG("Neighbor: " << neighbor << " status changed to INACTIVE");
+
m_nlsr.getLsdb().scheduleAdjLsaBuild();
}
}
@@ -250,7 +256,7 @@
HelloProtocol::onRegistrationSuccess(const ndn::nfd::ControlParameters& commandSuccessResult,
const ndn::Name& neighbor,const ndn::time::milliseconds& timeout)
{
- Adjacent *adjacent = m_nlsr.getAdjacencyList().findAdjacent(neighbor);
+ Adjacent* adjacent = m_nlsr.getAdjacencyList().findAdjacent(neighbor);
if (adjacent != 0) {
adjacent->setFaceId(commandSuccessResult.getFaceId());
ndn::Name broadcastKeyPrefix = DEFAULT_BROADCAST_PREFIX;
@@ -290,7 +296,7 @@
* Lsa unless all the neighbors are ACTIVE or DEAD. For considering the
* missconfigured(link) neighbour dead this is required.
*/
- Adjacent *adjacent = m_nlsr.getAdjacencyList().findAdjacent(name);
+ Adjacent* adjacent = m_nlsr.getAdjacencyList().findAdjacent(name);
if (adjacent != 0) {
adjacent->setInterestTimedOutNo(adjacent->getInterestTimedOutNo() + 1);
Adjacent::Status status = adjacent->getStatus();
diff --git a/src/lsdb.cpp b/src/lsdb.cpp
index 1d20d72..8468947 100644
--- a/src/lsdb.cpp
+++ b/src/lsdb.cpp
@@ -120,6 +120,7 @@
}
else if (seqNo > m_highestSeqNo[lsaName]) {
m_highestSeqNo[lsaName] = seqNo;
+ _LOG_TRACE("SeqNo for LSA(name): " << data->getName() << " updated");
}
else if (seqNo < m_highestSeqNo[lsaName]) {
return;
@@ -266,6 +267,7 @@
std::inserter(nameToRemove, nameToRemove.begin()));
for (std::list<ndn::Name>::iterator it = nameToRemove.begin();
it != nameToRemove.end(); ++it) {
+ _LOG_DEBUG("Removing name LSA no longer advertised: " << (*it).toUri());
chkNameLsa->removeName((*it));
if (nlsa.getOrigRouter() != m_nlsr.getConfParameter().getRouterPrefix()) {
if ((*it) != m_nlsr.getConfParameter().getRouterPrefix()) {
@@ -273,6 +275,7 @@
}
}
}
+
if (nlsa.getOrigRouter() != m_nlsr.getConfParameter().getRouterPrefix()) {
ndn::time::system_clock::Duration duration = nlsa.getExpirationTimePoint() -
ndn::time::system_clock::now();
@@ -578,6 +581,7 @@
if (m_nlsr.getConfParameter().getHyperbolicState() == HYPERBOLIC_STATE_ON) {
// Don't build adjacency LSAs in hyperbolic routing
+ _LOG_DEBUG("Adjacency LSA not built. Currently in hyperbolic routing state.");
return;
}
@@ -842,7 +846,7 @@
}
// Since we cannot refresh other router's LSAs, our only choice is to expire.
else {
- _LOG_DEBUG("Other's Name LSA, so removing form LSDB");
+ _LOG_DEBUG("Other's Name LSA, so removing from LSDB");
removeNameLsa(lsaKey);
}
}
@@ -860,7 +864,7 @@
Lsdb::exprireOrRefreshAdjLsa(const ndn::Name& lsaKey, uint64_t seqNo)
{
_LOG_DEBUG("Lsdb::exprireOrRefreshAdjLsa Called");
- _LOG_DEBUG("LSA Key : " << lsaKey << " Seq No: " << seqNo);
+ _LOG_DEBUG("LSA Key: " << lsaKey << " Seq No: " << seqNo);
AdjLsa* chkAdjLsa = findAdjLsa(lsaKey);
// If this is a valid LSA
if (chkAdjLsa != 0) {
@@ -885,7 +889,7 @@
}
// An LSA from another router is expiring
else {
- _LOG_DEBUG("Other's Adj LSA, so removing form LSDB");
+ _LOG_DEBUG("Other's Adj LSA, so removing from LSDB");
removeAdjLsa(lsaKey);
}
// We have changed the contents of the LSDB, so we have to
@@ -938,7 +942,7 @@
}
// We can't refresh other router's LSAs, so we remove it.
else {
- _LOG_DEBUG("Other's Cor LSA, so removing form LSDB");
+ _LOG_DEBUG("Other's Cor LSA, so removing from LSDB");
removeCoordinateLsa(lsaKey);
}
if (m_nlsr.getConfParameter().getHyperbolicState() == HYPERBOLIC_STATE_ON) {
@@ -1031,6 +1035,8 @@
m_nlsr.getKeyChain(),
m_lsaRefreshTime,
content);
+ _LOG_DEBUG("Sending requested data ( " << content << ") for interest (" << interest
+ << ") to be published and added to face.");
publisher.publish(interest.getName(),
ndn::security::signingByCertificate(m_nlsr.getDefaultCertName()));
}
@@ -1045,12 +1051,20 @@
const ndn::Name& lsaKey,
uint64_t seqNo)
{
+
+ _LOG_DEBUG("nameLsa interest " << interest << " received");
NameLsa* nameLsa = m_nlsr.getLsdb().findNameLsa(lsaKey);
if (nameLsa != 0) {
if (nameLsa->getLsSeqNo() == seqNo) {
std::string content = nameLsa->getData();
putLsaData(interest,content);
}
+ else {
+ _LOG_TRACE("SeqNo for nameLsa does not match");
+ }
+ }
+ else {
+ _LOG_TRACE(interest << " was not found in this lsdb");
}
}
@@ -1065,15 +1079,22 @@
uint64_t seqNo)
{
if (m_nlsr.getConfParameter().getHyperbolicState() == HYPERBOLIC_STATE_ON) {
- _LOG_ERROR("Received interest for an adjacency LSA when hyperbolic routing is enabled.");
+ _LOG_ERROR("Received interest for an adjacency LSA when hyperbolic routing is enabled");
}
+ _LOG_DEBUG("AdjLsa interest " << interest << " received");
AdjLsa* adjLsa = m_nlsr.getLsdb().findAdjLsa(lsaKey);
if (adjLsa != 0) {
if (adjLsa->getLsSeqNo() == seqNo) {
std::string content = adjLsa->getData();
putLsaData(interest,content);
}
+ else {
+ _LOG_TRACE("SeqNo for AdjLsa does not match");
+ }
+ }
+ else {
+ _LOG_TRACE(interest << " was not found in this lsdb");
}
}
@@ -1088,15 +1109,22 @@
uint64_t seqNo)
{
if (m_nlsr.getConfParameter().getHyperbolicState() == HYPERBOLIC_STATE_OFF) {
- _LOG_ERROR("Received Interest for a coordinate LSA when link-state routing is enabled.");
+ _LOG_ERROR("Received Interest for a coordinate LSA when link-state routing is enabled");
}
+ _LOG_DEBUG("CoordinateLsa interest " << interest << " received");
CoordinateLsa* corLsa = m_nlsr.getLsdb().findCoordinateLsa(lsaKey);
if (corLsa != 0) {
if (corLsa->getLsSeqNo() == seqNo) {
std::string content = corLsa->getData();
putLsaData(interest,content);
}
+ else {
+ _LOG_TRACE("SeqNo for CoordinateLsa does not match");
+ }
+ }
+ else {
+ _LOG_TRACE(interest << " was not found in this lsdb");
}
}
diff --git a/src/nlsr.cpp b/src/nlsr.cpp
index 58d5cf7..26276d7 100644
--- a/src/nlsr.cpp
+++ b/src/nlsr.cpp
@@ -312,12 +312,19 @@
certName = certName.getPrefix(-1);
}
else if (certName[-1].toUri() != "ID-CERT")
- return; //Wrong key interest.
+ {
+ _LOG_DEBUG("certName for interest " << interest << " is malformed,"
+ << " contains incorrect namespace syntax");
+ return;
+ }
std::shared_ptr<const ndn::IdentityCertificate> cert = getCertificate(certName);
if (!static_cast<bool>(cert))
- return; // cert is not found
+ {
+ _LOG_DEBUG("cert is not found for " << interest);
+ return; // cert is not found
+ }
std::shared_ptr<ndn::Data> data = std::make_shared<ndn::Data>();
data->setName(interestName);
diff --git a/src/route/fib.cpp b/src/route/fib.cpp
index 7c14d78..777ab1b 100644
--- a/src/route/fib.cpp
+++ b/src/route/fib.cpp
@@ -320,6 +320,7 @@
const std::string& faceUri,
uint8_t times)
{
+ _LOG_DEBUG("Registering prefix: " << parameters.getName() << " faceUri: " << faceUri);
m_controller.start<ndn::nfd::RibRegisterCommand>(parameters,
std::bind(&Fib::onRegistrationSuccess, this, _1,
"Successful in name registration",