[ndnSIM] ConsumerCbr scheduling SendPacket when it reaches maxSeq

[Thiago Teixeira]

Hi all,

I'm using ndnSIM 2.5 with one consumer (n0) plus three other nodes in a line topology, where n3 is the producer. The topology looks like this:

n0 ----- n1 ----- n2 ----- n3
|
dummy face

The consumer node has a ConsumerCbr App installed, requesting 5 Interest/s, from Seq # 0 through 9 (set maxSeq = 10). I also configured the RTO to be of maximum 500 ms and InterestLifetime to be 0.5 s. I purposely make the first Interest to not return (by sending it to a dummy face) and later retransmit to n1.

The consumer retrieves Seq # 0 through 8 successfully. The issue is when it sends the first request to Seq #9 to the dummy face at 8.6 s (this request is set to expire at 9.1 s), but the application sends another request at 8.8 s (following the 5 Int/s or 1 Int/200 ms rule). This request ends up increasing the "m_seq" count, so when request for Seq # 9 times out at 9.1 s, the method "Consumer::SendPacket()" enters in the control loop on Line 176<http://ndnsim.net/current/doxygen/ndn-consumer_8cpp_source.html#l00176> and the application never returns Seq #9.

Please find below the logs with comments that explain this behavior.

Shouldn't the consumer application in this case only send a request if there are pending Interests that are not in flight?

Thank you,
Thiago


# sequence numbers 0 through 8 are retrieved successfully.
# here, the consumer retransmits Seq #8 from the dummy face to n1
+8.400000000s 0 ndn.Consumer:SendPacket()
+8.400000000s 0 ndn.Consumer:SendPacket(): [INFO ] > Interest for 8
+8.400000000s 0 ndn.Consumer:WillSendOutInterest(): [DEBUG] Trying to add 8 with +8400000000.0ns. already 1 items
+8.400000000s 0 nfd.Forwarder:onIncomingInterest(): [DEBUG] onIncomingInterest face=259 interest=/ndn/prefix/%FE%08
+8.400000000s 0 nfd.Forwarder:onContentStoreMiss(): [DEBUG] onContentStoreMiss interest=/ndn/prefix/%FE%08
+8.400000000s 0 nfd.CustomStrategy:afterReceiveInterest(): [DEBUG] Node Id: 0 Retx Tag is: 1
+8.400000000s 0 nfd.CustomStrategy:afterReceiveInterest(): [DEBUG] OutFace is: netdev://[00:00:00:00:00:06]
+8.400000000s 0 nfd.Forwarder:onOutgoingInterest(): [DEBUG] onOutgoingInterest face=257 interest=/ndn/prefix/%FE%08

# here's when the Consumer requests Seq #9 to the dummy face, following one Interest every 200 ms
+8.600000000s 0 ndn.Consumer:SendPacket()
+8.600000000s 0 ndn.Consumer:SendPacket(): [INFO ] > Interest for 9
+8.600000000s 0 ndn.Consumer:WillSendOutInterest(): [DEBUG] Trying to add 9 with +8600000000.0ns. already 1 items
+8.600000000s 0 nfd.Forwarder:onIncomingInterest(): [DEBUG] onIncomingInterest face=259 interest=/ndn/prefix/%FE%09
+8.600000000s 0 nfd.Forwarder:onContentStoreMiss(): [DEBUG] onContentStoreMiss interest=/ndn/prefix/%FE%09
+8.600000000s 0 nfd.CustomStrategy:afterReceiveInterest(): [DEBUG] Node Id: 0 Retx Tag is: 0
+8.600000000s 0 nfd.CustomStrategy:afterReceiveInterest(): [DEBUG] OutFace is: netdev://[00:00:00:00:00:01]
+8.600000000s 0 nfd.Forwarder:onOutgoingInterest(): [DEBUG] onOutgoingInterest face=256 interest=/ndn/prefix/%FE%09

# Consumer gets Data for 8
+8.733265748s 0 nfd.Forwarder:onIncomingData(): [DEBUG] onIncomingData face=257 data=/ndn/prefix/%FE%08
+8.733265748s 0 nfd.Forwarder:onIncomingData(): [DEBUG] onIncomingData matching=/ndn/prefix/%FE%08
+8.733265748s 0 nfd.Forwarder:onOutgoingData(): [DEBUG] onOutgoingData face=259 data=/ndn/prefix/%FE%08
+8.733265748s 0 ndn.Consumer:OnData(0x1808630, 0x183b1e0)
+8.733265748s 0 ndn.Consumer:OnData(): [INFO ] < DATA for 8
+8.733265748s 0 ndn.Consumer:OnData(): [DEBUG] Hop count: 3

# Here is where things get interest
# at 8.8 seconds, the Consumer calls SendPacket, even though Interest for 9 only expires at 9.1s (8.6 + 0.5 ms of RTO)
+8.800000000s 0 ndn.Consumer:SendPacket()

# this extra call (above) ends up increasing "m_seq" to 10, which makes the code enter the control statements on Line 176<http://ndnsim.net/current/doxygen/ndn-consumer_8cpp_source.html#l00176>

# at 9.1 s the Interest for 9 times out, as expected
+9.100000000s 0 nfd.Forwarder:onInterestUnsatisfied(): [DEBUG] onInterestUnsatisfied interest=/ndn/prefix/%FE%09
+9.100000000s 0 nfd.Forwarder:onInterestFinalize(): [DEBUG] onInterestFinalize interest=/ndn/prefix/%FE%09 unsatisfied
+9.100000000s -1 ndn.Consumer:OnTimeout(9)

# Then, this call never gets out and requests continue until the "Simulator::Stop()" is called.
+9.300000000s -1 ndn.Consumer:SendPacket()
+9.300000000s -1 ndn.Consumer:SendPacket(): [INFO ] > Interest for 9

+9.500000000s -1 ndn.Consumer:SendPacket()

+10.000000000s -1 ndn.Consumer:SendPacket()
+10.000000000s -1 ndn.Consumer:SendPacket(): [INFO ] > Interest for 9

+10.200000000s -1 ndn.Consumer:SendPacket()
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.lists.cs.ucla.edu/pipermail/ndnsim/attachments/20180717/46b03ef9/attachment-0001.html>