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

[Dehart, John]

All:

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)

HERE    Mar 12 00:50:10 insula nfd[1565]: 1552348210.739609 DEBUG: [nfd.Forwarder] onIncomingInterest face=292 interest=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B
HERE    Mar 12 00:50:10 insula nfd[1565]: 1552348210.739677 DEBUG: [nfd.Forwarder] onOutgoingInterest face=278 interest=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B
HERE    Mar 12 00:50:10 insula nfd[1565]: 1552348210.873764 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
HERE    Mar 12 00:50:10 insula nfd[1565]: 1552348210.873781 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

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?

Below I will attach a snippet from the nfd.log file that includes a little before the messages above and then up to the
onDataUnsolicited message. I can include more from before this if needed.

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.

Thanks,
John


-------------- next part --------------
A non-text attachment was scrubbed...
Name: nfd.log.nlsr.snip_2
Type: application/octet-stream
Size: 105865 bytes
Desc: nfd.log.nlsr.snip_2
URL: <http://www.lists.cs.ucla.edu/pipermail/nfd-dev/attachments/20190312/70c7fa52/attachment-0001.obj>