[Nfd-dev] NLSR/NFD Issue on the Testbed

Tue Mar 12 08:09:19 PDT 2019

Junxiao,

Interesting, thanks for the added details.
face=276 is BASEL, just to add to the info.

John

On Mar 12, 2019, at 10:04 AM, Junxiao Shi <shijunxiao at email.arizona.edu<mailto:shijunxiao at email.arizona.edu>> wrote:

Hi John

The log entries related to this Interest are: (timestamp changed to relative in microseconds)
0      DEBUG: [nfd.Forwarder] onIncomingInterest face=292 interest=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B
29     DEBUG: [nfd.ContentStore] find /ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B L
53     DEBUG: [nfd.Forwarder] onContentStoreMiss interest=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B
63     DEBUG: [nfd.Forwarder] onContentStoreMiss interest=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B nexthop-faceid=278
68     DEBUG: [nfd.Forwarder] onOutgoingInterest face=278 interet=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B
100    DEBUG: [nfd.Forwarder] onIncomingInterest face=292 interest=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B
115    DEBUG: [nfd.Forwarder] onContentStoreMiss interest=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B
128    DEBUG: [nfd.AsfStrategy] /ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B?ndn.Nonce=3346098500 from=292 suppressed
36064  DEBUG: [nfd.Forwarder] onIncomingInterest face=276 interest=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B
36086  DEBUG: [nfd.Forwarder] onContentStoreMiss interest=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B
36104  DEBUG: [nfd.AsfStrategy] /ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B?ndn.Nonce=3569453214 from=276 noNextHop
36113  DEBUG: [nfd.Forwarder] onOutgoingNack face=276 nack=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B~NoRoute OK
36155  DEBUG: [nfd.Forwarder] onInterestFinalize interest=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B unsatisfied
134155 DEBUG: [nfd.Forwarder] onIncomingData face=278 data=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B/NA/%FD%00%00%01in%84%2Ff
134172 DEBUG: [nfd.Forwarder] onDataUnsolicited face=278 data=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B/NA/%FD%00%00%01in%84%2Ff decision=drop

Events happened:

  1.  Interest arrives from face 292. It goes out to face 278.
  2.  100us later, retransmission arrives from face 292. Strategy suppresses it.
  3.  36ms later, another Interest with same name arrives from face 276. Strategy determines there's no available nexthop so it responds with a Nack, and then deletes the PIT entry.
  4.  134ms later, Data arrives and is dropped because there's no PIT entry.

ASF strategy has two code path that can lead to Nack, both in AsfStrategy::afterReceiveInterest function<https://github.com/named-data/NFD/blob/NFD-0.6.5/daemon/fw/asf-strategy.cpp#L125-L140>:
  const fib::Entry& fibEntry = this->lookupFib(*pitEntry);
  const fib::NextHopList& nexthops = fibEntry.getNextHops();
  if (nexthops.size() == 0) {
    sendNoRouteNack(ingress, interest, pitEntry);
    this->rejectPendingInterest(pitEntry);
    return;
  }

  Face* faceToUse = getBestFaceForForwarding(fibEntry, interest, ingress.face);
  if (faceToUse == nullptr) {
    sendNoRouteNack(ingress, interest, pitEntry);
    this->rejectPendingInterest(pitEntry);
    return;
  }

The first condition, nexthops.size() == 0 , is not possible here.
The second condition AsfStrategy::getBestFaceForForwarding<https://github.com/named-data/NFD/blob/c70794810592a90847656a97caf27f0326668240/daemon/fw/asf-strategy.cpp#L264> returning nullptr, only happens if the ingress face is the only nexthop, but ingress face 276 is not nexthop 278.
Thus, I do not understand which condition is triggering the Nack.

After sending a Nack, ASF strategy invokes Strategy::rejectPendingInterest<https://github.com/named-data/NFD/blob/NFD-0.6.5/daemon/fw/strategy.hpp#L266-L276> that schedules the PIT entry for immediate deletion. A strategy should invoke this function when it concludes that the Interest cannot be forwarded and it does not want to wait for responses from existing upstream nodes.
Since the Interest is already forwarded to face 278, I do not understand why ASF believes it would not be satisfied and the PIT entry should be deleted.

Also, I do not understand why NLSR decides to retransmit its Interest just 100us after the initial transmission. It should know that the response would not come this fast.
However, rapid retransmission would not cause "the first one not registered in PIT" because the forwarder is single threaded.

Yours, Junxiao

On Tue, Mar 12, 2019 at 10:16 AM Dehart, John <jdd at wustl.edu<mailto:jdd at wustl.edu>> wrote:

I have upgraded 6 nodes on the NDN Testbed to NFD 0.6.5 and NLSR 0.5.0 with PSync.
I had an issue yesterday where it took a very long time for NLSR to sync the default routes
for all 6 nodes. The nodes involved are: MEMPHIS, WU, URJC, BASEL, BERN and AAU.
The connectivity is like this:
MEMPHIS--WU--URJC--BASEL and then BASEL, AAU and BERN are all connected to each other.

After 2-3 hours, URJC, BASEL, BERN and AAU had not learned MEMPHIS’s default route yet.
All other routes had been updated.
What I found was that they were having trouble validating because they were not able to retrieve
MEMPHIS’s KEY. One example of what I am seeing is illustrated by these four NFD log messages
from URJC (I’ve manually added the ‘HERE’ to the nfd.log file to give myself something easy to grep on)

I believe face=292 is NLSR and face=278 is WU. So, we see NLSR sending an interest to NFD for /ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B,
NFD forwards that interest to WU. About 130ms later, data from WU returns that should satisfy that Interest but NFD indicates that
it is unsolicted data and drops it.

So, why would NFD not have a PIT entry for the interest it forwarded 130ms earlier?

About 6 hours after the above messages, NLSR on URJC finally did get the KEY data it needed an validated
the route update. I will be processing the log files around that event to see if there is anything telling that is different there.

On Tue, Mar 12, 2019 at 10:48 AM Dehart, John <jdd at wustl.edu<mailto:jdd at wustl.edu>> wrote:

It appears that 100us after an interest arrives from NLSR another one arrives for the same data.
This second one AsfStrategy suppresses.
Is this rapid succession of interests and suppression causing the first one to not be registered in the PIT?

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.lists.cs.ucla.edu/pipermail/nfd-dev/attachments/20190312/461af142/attachment-0001.html>