<div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr">Hi John<div><br></div><div>The log entries related to this Interest are: (timestamp changed to relative in microseconds)</div><div><div><div><font face="monospace, monospace">0 DEBUG: [nfd.Forwarder] onIncomingInterest face=292 interest=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B</font></div><div><font face="monospace, monospace">29 DEBUG: [nfd.ContentStore] find /ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B L</font></div><div><font face="monospace, monospace">53 DEBUG: [nfd.Forwarder] onContentStoreMiss interest=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B</font></div><div><font face="monospace, monospace">63 DEBUG: [nfd.Forwarder] onContentStoreMiss interest=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B nexthop-faceid=278</font></div><div><font face="monospace, monospace">68 DEBUG: [nfd.Forwarder] onOutgoingInterest face=278 interet=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B</font></div><div><font face="monospace, monospace">100 DEBUG: [nfd.Forwarder] onIncomingInterest face=292 interest=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B</font></div><div><font face="monospace, monospace">115 DEBUG: [nfd.Forwarder] onContentStoreMiss interest=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B</font></div><div><font face="monospace, monospace">128 DEBUG: [nfd.AsfStrategy] /ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B?ndn.Nonce=3346098500 from=292 suppressed</font></div><div><font face="monospace, monospace">36064 DEBUG: [nfd.Forwarder] onIncomingInterest face=276 interest=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B</font></div><div><font face="monospace, monospace">36086 DEBUG: [nfd.Forwarder] onContentStoreMiss interest=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B</font></div><div><font face="monospace, monospace">36104 DEBUG: [nfd.AsfStrategy] /ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B?ndn.Nonce=3569453214 from=276 noNextHop</font></div><div><font face="monospace, monospace">36113 DEBUG: [nfd.Forwarder] onOutgoingNack face=276 nack=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B~NoRoute OK</font></div><div><font face="monospace, monospace">36155 DEBUG: [nfd.Forwarder] onInterestFinalize interest=/ndn/edu/memphis/%C1.Router/titan/nlsr/KEY/%C96%5B%D6%03Y%C2B unsatisfied</font></div><div><font face="monospace, monospace">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</font></div><div><font face="monospace, monospace">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</font></div></div></div><div><br></div><div>Events happened:</div><div><ol><li>Interest arrives from face 292. It goes out to face 278.</li><li>100us later, retransmission arrives from face 292. Strategy suppresses it.</li><li>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.</li><li>134ms later, Data arrives and is dropped because there's no PIT entry.</li></ol></div><div><br></div><div>ASF strategy has two code path that can lead to Nack, both in <a href="https://github.com/named-data/NFD/blob/NFD-0.6.5/daemon/fw/asf-strategy.cpp#L125-L140">AsfStrategy::afterReceiveInterest function</a>:</div><div><div><font face="monospace, monospace"> const fib::Entry& fibEntry = this->lookupFib(*pitEntry);</font></div><div><font face="monospace, monospace"> const fib::NextHopList& nexthops = fibEntry.getNextHops();</font></div><div><font face="monospace, monospace"> if (nexthops.size() == 0) {</font></div><div><font face="monospace, monospace"> sendNoRouteNack(ingress, interest, pitEntry);</font></div><div><font face="monospace, monospace"> this->rejectPendingInterest(pitEntry);</font></div><div><font face="monospace, monospace"> return;</font></div><div><font face="monospace, monospace"> }</font></div><div><font face="monospace, monospace"><br></font></div><div><font face="monospace, monospace"> Face* faceToUse = getBestFaceForForwarding(fibEntry, interest, ingress.face);</font></div><div><font face="monospace, monospace"> if (faceToUse == nullptr) {</font></div><div><font face="monospace, monospace"> sendNoRouteNack(ingress, interest, pitEntry);</font></div><div><font face="monospace, monospace"> this->rejectPendingInterest(pitEntry);</font></div><div><font face="monospace, monospace"> return;</font></div><div><font face="monospace, monospace"> }</font></div></div><div><br></div><div>The first condition, <span style="font-family:monospace,monospace">nexthops.size() == 0</span> , is not possible here.</div><div>The second condition <a href="https://github.com/named-data/NFD/blob/c70794810592a90847656a97caf27f0326668240/daemon/fw/asf-strategy.cpp#L264">AsfStrategy::getBestFaceForForwarding</a> returning nullptr, only happens if the ingress face is the only nexthop, but ingress face 276 is not nexthop 278.</div><div>Thus, I do not understand which condition is triggering the Nack.</div><div><br></div><div>After sending a Nack, ASF strategy invokes <a href="https://github.com/named-data/NFD/blob/NFD-0.6.5/daemon/fw/strategy.hpp#L266-L276">Strategy::rejectPendingInterest</a> 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.</div><div>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.</div><div><br></div><div>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.</div><div>However, rapid retransmission would not cause "the first one not registered in PIT" because the forwarder is single threaded.</div><div><br></div><div>Yours, Junxiao</div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Tue, Mar 12, 2019 at 10:16 AM Dehart, John <<a href="mailto:jdd@wustl.edu">jdd@wustl.edu</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><br>I have upgraded 6 nodes on the NDN Testbed to NFD 0.6.5 and NLSR 0.5.0 with PSync.<br>
I had an issue yesterday where it took a very long time for NLSR to sync the default routes<br>
for all 6 nodes. The nodes involved are: MEMPHIS, WU, URJC, BASEL, BERN and AAU.<br>
The connectivity is like this: <br>
MEMPHIS--WU--URJC--BASEL and then BASEL, AAU and BERN are all connected to each other.<br>
<br>
After 2-3 hours, URJC, BASEL, BERN and AAU had not learned MEMPHIS’s default route yet.<br>
All other routes had been updated.<br>
What I found was that they were having trouble validating because they were not able to retrieve<br>
MEMPHIS’s KEY. One example of what I am seeing is illustrated by these four NFD log messages<br>
from URJC (I’ve manually added the ‘HERE’ to the nfd.log file to give myself something easy to grep on)<br><br>
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,<br>
NFD forwards that interest to WU. About 130ms later, data from WU returns that should satisfy that Interest but NFD indicates that<br>
it is unsolicted data and drops it.<br>
<br>
So, why would NFD not have a PIT entry for the interest it forwarded 130ms earlier?<br><br>
About 6 hours after the above messages, NLSR on URJC finally did get the KEY data it needed an validated<br>
the route update. I will be processing the log files around that event to see if there is anything telling that is different there.<br><br></blockquote><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Tue, Mar 12, 2019 at 10:48 AM Dehart, John <<a href="mailto:jdd@wustl.edu">jdd@wustl.edu</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><br>It appears that 100us after an interest arrives from NLSR another one arrives for the same data.<br>This second one AsfStrategy suppresses.<br>Is this rapid succession of interests and suppression causing the first one to not be registered in the PIT?<br></blockquote></div><div> </div></div></div></div></div></div></div></div>