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

Junxiao Shi shijunxiao at email.arizona.edu
Tue Mar 12 08:04:16 PDT 2019 

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> 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> 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/55450163/attachment-0001.html>

More information about the Nfd-dev mailing list