[Nfd-dev] Help needed with debugging duplicate Nonce

Wed Jun 29 13:24:30 PDT 2016

Okay, so I performed a new experiment (i.e. just ran minindn and quit after some time) with FibManager and Forwarder DEBUG logs.

In this experiment, looked at the first Duplicate NACK on localhop prefix (Nonce: 567161547) and found the following:

1) b->a

2) b->c

3) a->c

4) c sends Duplicate NACK

This happens around 1467225861 - I don't see any FibManager messages around this time in NFD logs.

I have attached a sync interest trail where I grepped for the particular sync interest such as:

grep "/localhop/NLSR/sync/e4c858598a526f7f25d42f4da49cb51b7950cf352e26d5092bd35126b509101b?ndn.MustBeFresh=1&ndn.Nonce" */ndndump* | sort -t: -nk2 | awk '{split($NF,a,"Nonce="); $NF=""; print $0 " " a[2]}' > sync-interest-trail

(ndndump* includes localhost as well as interface)

Seems like before the NACK, a sends interests with two different Nonces - one to c (which resulted in the above NACK), one to b (resulted in another NACK).

This time I didn't see any local new interest for the sync on a  (which should be equivalent to b from the previous example).

Ashlesh

________________________________
From: Junxiao Shi <shijunxiao at email.arizona.edu>
Sent: Wednesday, June 29, 2016 11:54:37 AM
To: Ashlesh Gawande (agawande)
Cc: Lan Wang (lanwang); nfd-dev at lists.cs.ucla.edu
Subject: Re: [Nfd-dev] Help needed with debugging duplicate Nonce

Hi Ashlesh

As discussed in 20160628 NFD call, packet timing at B is like:

  1.  fwB receives Interest from appB with nonceB; this Interest is not forwarded
  2.  fwB receives Interest from fwC with nonceC
  3.  Interest is forwarded to fwA with nonceC

This exposes a weakness in outgoing Interest pipeline “pick Interest” step: when fwB forwards the Interest, it picks the latest incoming Interest with nonceC, and thus trigger Nack-Duplicate from fwA. If it picks nonceB instead, there wouldn’t be a Nack-Duplicate from fwA.

But another question is: why fwB did not forward the Interest from appB in the first place? This indicates there might be a FIB update during this process.
Can you provide NFD logs to show whether a FIB update occurred? Log level settings should be FibManager=DEBUG, Forwarder=DEBUG.

Yours, Junxiao

On Jun 28, 2016, at 10:29 AM, Ashlesh Gawande (agawande) <agawande at memphis.edu<mailto:agawande at memphis.edu>> wrote:

Confirmed that this is happening because node b has the same (sync) interest and hence forwards the interest to a resulting in a NACK.

Ashlesh
________________________________
From: Nfd-dev <nfd-dev-bounces at lists.cs.ucla.edu<mailto:nfd-dev-bounces at lists.cs.ucla.edu>> on behalf of Ashlesh Gawande (agawande) <agawande at memphis.edu<mailto:agawande at memphis.edu>>
Sent: Tuesday, June 28, 2016 10:48:35 AM
To: Lan Wang (lanwang); Junxiao Shi
Cc: nfd-dev at lists.cs.ucla.edu<mailto:nfd-dev at lists.cs.ucla.edu>
Subject: Re: [Nfd-dev] Help needed with debugging duplicate Nonce

Have attached proof for the said observation.

tmp-localhost_6_27$ grep --color=always 927845950 */ndndump* | sort -t: -k2
c/ndndump.c-eth0_1.0.0.10.pcap:1467054254.052399 From: 1.0.0.10, To: 1.0.0.9, Tunnel Type: UDP, INTEREST: /localhop/NLSR/sync/e4c858598a526f7f25d42f4da49cb51b7950cf352e26d5092bd35126b509101b?ndn.MustBeFresh=1&ndn.Nonce=927845950
b/ndndump.b-eth1_1.0.0.9.pcap:1467054254.052424 From: 1.0.0.10, To: 1.0.0.9, Tunnel Type: UDP, INTEREST: /localhop/NLSR/sync/e4c858598a526f7f25d42f4da49cb51b7950cf352e26d5092bd35126b509101b?ndn.MustBeFresh=1&ndn.Nonce=927845950
c/ndndump.c-eth1_1.0.0.6.pcap:1467054254.052428 From: 1.0.0.6, To: 1.0.0.5, Tunnel Type: UDP, INTEREST: /localhop/NLSR/sync/e4c858598a526f7f25d42f4da49cb51b7950cf352e26d5092bd35126b509101b?ndn.MustBeFresh=1&ndn.Nonce=927845950
a/ndndump.a-eth1_1.0.0.5.pcap:1467054254.052436 From: 1.0.0.6, To: 1.0.0.5, Tunnel Type: UDP, INTEREST: /localhop/NLSR/sync/e4c858598a526f7f25d42f4da49cb51b7950cf352e26d5092bd35126b509101b?ndn.MustBeFresh=1&ndn.Nonce=927845950
b/ndndump.b-eth0_1.0.0.2.pcap:1467054257.955331 From: 1.0.0.2, To: 1.0.0.1, Tunnel Type: UDP, INTEREST: /localhop/NLSR/sync/e4c858598a526f7f25d42f4da49cb51b7950cf352e26d5092bd35126b509101b?ndn.MustBeFresh=1&ndn.Nonce=927845950
a/ndndump.a-eth0_1.0.0.1.pcap:1467054257.955348 From: 1.0.0.2, To: 1.0.0.1, Tunnel Type: UDP, INTEREST: /localhop/NLSR/sync/e4c858598a526f7f25d42f4da49cb51b7950cf352e26d5092bd35126b509101b?ndn.MustBeFresh=1&ndn.Nonce=927845950
a/ndndump.a-eth0_1.0.0.1.pcap:1467054257.965760 From: 1.0.0.1, To: 1.0.0.2, Tunnel Type: UDP, NACK: Duplicate, /localhop/NLSR/sync/e4c858598a526f7f25d42f4da49cb51b7950cf352e26d5092bd35126b509101b?ndn.MustBeFresh=1&ndn.Nonce=927845950
b/ndndump.b-eth0_1.0.0.2.pcap:1467054257.965760 From: 1.0.0.1, To: 1.0.0.2, Tunnel Type: UDP, NACK: Duplicate, /localhop/NLSR/sync/e4c858598a526f7f25d42f4da49cb51b7950cf352e26d5092bd35126b509101b?ndn.MustBeFresh=1&ndn.Nonce=927845950

1) c to b
2) c to a
3) b to a
4) a responds with duplicate NACK

Meanwhile I will also try to test Junxiao's suggestion by forcing communication over TCP and make sure that this is because of local sync expressing the same interest.

Ashlesh

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.lists.cs.ucla.edu/pipermail/nfd-dev/attachments/20160629/450ace97/attachment.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: nfd_log_localhost_tcp_6_29.tar.gz
Type: application/gzip
Size: 355320 bytes
Desc: nfd_log_localhost_tcp_6_29.tar.gz
URL: <http://www.lists.cs.ucla.edu/pipermail/nfd-dev/attachments/20160629/450ace97/attachment.bin>