<div dir="ltr"><div><div><div><div>Hello all,<br><br></div>I am working with NFD on the raspberry pi 3 model B system. Lately, however, I have had a very strange issue. While using ndnping over 1 hop in an adhoc environment over ethernet multicast faces, the round trip time can be upwards of 10 minutes. I was working with a modified version when I encountered this issue, however, after reinstalling the clean version from github, the problem persisted. So, I used the trace level logging to see what could be going on, but I am unable to find the issue. Does anyone have an idea what could be causing this issue?<br><br></div>Below is the trace from each side, organized into the order that I believe the events took place, however, I am unsure if this is actually the case, as there is a chance that the producer responded to the interest after the timeout took place on the consumer.<br><br></div>Thanks for your time,<br></div>Anthony Dowling<br><div><div><br>// first ping sent by consumer<br>1511037635.119663 DEBUG: [Forwarder] onIncomingInterest face=260 interest=/ping/ping/10324781016848213197<br>1511037635.119735 TRACE: [NameTree] lookup /ping/ping/10324781016848213197<br>1511037635.119793 TRACE: [NameTreeHashtable] found / hash=0 bucket=0<br>1511037635.119836 TRACE: [NameTreeHashtable] found /ping hash=3225558032 bucket=16<br>1511037635.119891 TRACE: [NameTreeHashtable] insert /ping/ping hash=0 bucket=0<br>1511037635.119943 TRACE: [NameTreeHashtable] insert /ping/ping/10324781016848213197 hash=97694297 bucket=601<br>1511037635.120008 DEBUG: [ContentStore] find /ping/ping/10324781016848213197 L<br>1511037635.120137 DEBUG: [ContentStore]   no-match<br>1511037635.120174 DEBUG: [Forwarder] onContentStoreMiss interest=/ping/ping/10324781016848213197<br>1511037635.120251 TRACE: [Strategy] lookupFib noForwardingHint found=/ping<br>1511037635.120415 DEBUG: [Forwarder] onOutgoingInterest face=257 interest=/ping/ping/10324781016848213197<br>1511037635.120474 TRACE: [LinkService] [id=257,local=dev://wlan0,remote=ether://[01:00:5e:00:17:aa]] sendInterest<br>1511037635.120562 TRACE: [EthernetTransport] [id=257,local=dev://wlan0,remote=ether://[01:00:5e:00:17:aa]] doSend<br>1511037635.120759 TRACE: [EthernetTransport] [id=257,local=dev://wlan0,remote=ether://[01:00:5e:00:17:aa]] Successfully sent: 52 bytes<br>1511037635.120828 DEBUG: [BestRouteStrategy2] /ping/ping/10324781016848213197?ndn.MustBeFresh=1&ndn.InterestLifetime=10000&ndn.Nonce=1869174386 from=260 newPitEntry-to=257<br><br>// producer responding to data<br>1511037711.976099 TRACE: [EthernetTransport] [id=257,local=dev://wlan0,remote=ether://[01:00:5e:00:17:aa]] Received: 52 bytes from b8:27:eb:03:30:1a<br>1511037711.976325 TRACE: [LinkService] [id=257,local=dev://wlan0,remote=ether://[01:00:5e:00:17:aa]] receiveInterest<br>1511037711.976387 DEBUG: [Forwarder] onIncomingInterest face=257 interest=/ping/ping/10324781016848213197<br>1511037711.976470 TRACE: [NameTree] lookup /ping/ping/10324781016848213197<br>1511037711.976532 TRACE: [NameTreeHashtable] found / hash=0 bucket=0<br>1511037711.976578 TRACE: [NameTreeHashtable] found /ping hash=3225558032 bucket=16<br>1511037711.976626 TRACE: [NameTreeHashtable] found /ping/ping hash=0 bucket=0<br>1511037711.976682 TRACE: [NameTreeHashtable] insert /ping/ping/10324781016848213197 hash=97694297 bucket=601<br>1511037711.976757 DEBUG: [ContentStore] find /ping/ping/10324781016848213197 L<br>1511037711.976896 DEBUG: [ContentStore]   no-match<br>1511037711.976934 DEBUG: [Forwarder] onContentStoreMiss interest=/ping/ping/10324781016848213197<br>1511037711.977005 TRACE: [Strategy] lookupFib noForwardingHint found=/ping/ping<br>1511037711.977164 DEBUG: [Forwarder] onOutgoingInterest face=261 interest=/ping/ping/10324781016848213197<br>1511037711.977221 TRACE: [LinkService] [id=261,local=unix:///run/nfd.sock,remote=fd://30] sendInterest<br>1511037711.977303 TRACE: [UnixStreamTransport] [id=261,local=unix:///run/nfd.sock,remote=fd://30] doSend<br>1511037711.977448 DEBUG: [BestRouteStrategy2] /ping/ping/10324781016848213197?ndn.MustBeFresh=1&ndn.InterestLifetime=10000&ndn.Nonce=1869174386 from=257 newPitEntry-to=261<br>1511037711.977635 TRACE: [UnixStreamTransport] [id=261,local=unix:///run/nfd.sock,remote=fd://30] Successfully sent: 52 bytes<br>1511037711.978420 TRACE: [UnixStreamTransport] [id=261,local=unix:///run/nfd.sock,remote=fd://30] Received: 85 bytes<br>1511037711.978583 TRACE: [LinkService] [id=261,local=unix:///run/nfd.sock,remote=fd://30] receiveData<br>1511037711.978640 DEBUG: [Forwarder] onIncomingData face=261 data=/ping/ping/10324781016848213197<br>1511037711.978713 TRACE: [NameTreeHashtable] found /ping/ping/10324781016848213197 hash=97694297 bucket=601<br>1511037711.978783 TRACE: [NameTreeIterator] initialized entry=/ping/ping/10324781016848213197 ref=/ping/ping/10324781016848213197 state=0<br>1511037711.978865 TRACE: [NameTreeIterator] advanced end<br>1511037711.978912 DEBUG: [ContentStore] insert /ping/ping/10324781016848213197<br>1511037711.979000 DEBUG: [Forwarder] onIncomingData matching=/ping/ping/10324781016848213197<br>1511037711.979084 DEBUG: [Strategy] beforeSatisfyInterest pitEntry=/ping/ping/10324781016848213197 inFace=261 data=/ping/ping/10324781016848213197<br>1511037711.979193 DEBUG: [Forwarder] onOutgoingData face=257 data=/ping/ping/10324781016848213197<br>1511037711.979248 TRACE: [LinkService] [id=257,local=dev://wlan0,remote=ether://[01:00:5e:00:17:aa]] sendData<br>1511037711.979334 TRACE: [EthernetTransport] [id=257,local=dev://wlan0,remote=ether://[01:00:5e:00:17:aa]] doSend<br>1511037711.979523 TRACE: [EthernetTransport] [id=257,local=dev://wlan0,remote=ether://[01:00:5e:00:17:aa]] Successfully sent: 85 bytes<br>1511037712.079333 DEBUG: [Forwarder] onInterestFinalize interest=/ping/ping/10324781016848213197 satisfied<br>1511037712.079457 TRACE: [NameTreeHashtable] erase /ping/ping/10324781016848213197 hash=97694297 bucket=601<br>1511037712.314525 TRACE: [DeadNonceList] mark nMarks=48<br><br>// timeout event on consumer<br>1511037645.123436 DEBUG: [Forwarder] onInterestUnsatisfied interest=/ping/ping/10324781016848213197<br>1511037645.123563 DEBUG: [Strategy] beforeExpirePendingInterest pitEntry=/ping/ping/10324781016848213197<br>1511037645.123683 DEBUG: [Forwarder] onInterestFinalize interest=/ping/ping/10324781016848213197 unsatisfied<br>1511037645.123821 TRACE: [NameTreeHashtable] erase /ping/ping/10324781016848213197 hash=97694297 bucket=601<br><br>// data for interest after it wasn't recieved on consumer<br>1511037720.599789 DEBUG: [Forwarder] onIncomingData face=257 data=/ping/ping/10324781016848213197<br>1511037720.599938 TRACE: [NameTreeHashtable] not-found /ping/ping/10324781016848213197 hash=97694297 bucket=601<br>1511037720.600082 TRACE: [NameTreeHashtable] found /ping/ping hash=0 bucket=0<br>1511037720.600205 TRACE: [NameTreeHashtable] found /ping hash=3225558032 bucket=16<br>1511037720.600326 TRACE: [NameTreeHashtable] found / hash=0 bucket=0<br>1511037720.600476 TRACE: [NameTreeIterator] initialized end<br>1511037720.600588 DEBUG: [Forwarder] onDataUnsolicited face=257 data=/ping/ping/10324781016848213197 decision=drop<br><br></div></div></div>