Bug #2559
closed
ndnSIM loses ALL data packets when payload size is set to a certain number
0%
Description
While testing MTU and payload size features of ndnSIM and a dummy producer, I came across undesired behaviour.
I varied the payload size and in certain situations I just did not receive any reply from the producer.
I managed to check the following things:
- Payload < MTU - check
- OnInterest called in Producer - check
- Interest returns data packet in Producer - check
- data packet is put to content store on producer (if there is a content store) - check
However, the data packet NEVER arrives at the consumer (it is being lost on an intermediate node or on the path for some reason).
This bug is hardly noticeable, as it happens in less than 1% of all possible cases - which makes it very hard to debug.
I've changed several parameters of the simulation (see attached file), the only thing I could come up with that actually causes this behaviour is:
- (obviously) the payload size
- the length of the prefix/interest to request (if you just add one or remove one character, it works)
- the amount of / (slashes) in the interest name
The attached simulation should show the behaviour when you run it with --vis.
If you don't want to use the visualizer, use NS_LOG to double check the behaviour (in debug mode of ndnSIM):
NS_LOG=ndn.Producer:ndn.Consumer ./waf --run ndn-memory-test --vis
Here is some example output from logging:
0s 0 ndn.Consumer:StartApplication()
0s 2 ndn.Producer:StartApplication()
0s 0 ndn.Consumer:SendPacket()
0s 0 ndn.Consumer:SendPacket(): [INFO ] > Interest for 0
0s 0 ndn.Consumer:WillSendOutInterest(): [DEBUG] Trying to add 0 with +0.0ns. already 0 items
0.021488s 2 ndn.Producer:OnInterest(0x10089b0, 0x7f64f000f908)
0.021488s 2 ndn.Producer:OnInterest(): [INFO ] node(2) respodning with Data: /prefix/abcdefghijklmnopqrstuvwxyz/123456789/need/more/somefile.txt/%FE%00
This is it, the request never reaches the consumer.
Files
Updated by Christian Kreuzberger over 9 years ago
Sorry for the messed up log output in the description. I could not find the edit option, so here it is again:
0s 0 ndn.Consumer:StartApplication()
0s 2 ndn.Producer:StartApplication()
0s 0 ndn.Consumer:SendPacket()
0s 0 ndn.Consumer:SendPacket(): [INFO ] > Interest for 0
0s 0 ndn.Consumer:WillSendOutInterest(): [DEBUG] Trying to add 0 with +0.0ns. already 0 items
0.021488s 2 ndn.Producer:OnInterest(0x10089b0, 0x7f64f000f908)
0.021488s 2 ndn.Producer:OnInterest(): [INFO ] node(2) respodning with Data: /prefix/abcdefghijklmnopqrstuvwxyz/123456789/need/more/somefile.txt/%FE%00
Updated by Spyros Mastorakis over 9 years ago
Hello Christian,
thanks for the report. However, the reasons for this behavior can be multiple and it is not a bug necessarily. A reason for that can be a PIT entry timeout that probably causes NFD to drop the data packet. In general, this can be caused by NFD's internal processing. Have you tried to enable logging for the daemon/fw/forwarder.cpp file to see what is going on? Have you tried to enable logging, in general, in NFD? If there is a PIT entry timeout, the method WillEraseTimedOutPendingInterest has to be called.
Updated by Christian Kreuzberger over 9 years ago
I re-run the scenario with the following changes:
consumerHelper.SetAttribute("Frequency", StringValue("1")); // 10 interests a second
and log output:
NS_LOG=nfd.Forwarder:ndn.Consumer:ndn.Producer:ndn.NetDeviceFace ./waf --run ndn-losing-data
Here are the results (node 0 = consumer, node 2 = producer, node 1 = intermediate router)
0s 0 ndn.Consumer:SendPacket()
0s 0 ndn.Consumer:SendPacket(): [INFO ] > Interest for 0
0s 0 ndn.Consumer:WillSendOutInterest(): [DEBUG] Trying to add 0 with +0.0ns. already 0 items
0s 0 nfd.Forwarder:onIncomingInterest(): [DEBUG] onIncomingInterest face=257 interest=/prefix/abcdefghijklmnopqrstuvwxyz/123456789/need/more/somefile.txt/%FE%00
0s 0 nfd.Forwarder:onOutgoingInterest(): [DEBUG] onOutgoingInterest face=256 interest=/prefix/abcdefghijklmnopqrstuvwxyz/123456789/need/more/somefile.txt/%FE%00
0s 0 ndn.NetDeviceFace:sendInterest(0x9e2908, 0x9e6a88)
0.010744s 1 ndn.NetDeviceFace:receiveFromNetDevice(0x9c3aa0, 0x9e6690, 30583, 02-06-00:00:00:00:00:01, 02-06-00:00:00:00:00:02, 1)
0.010744s 1 nfd.Forwarder:onIncomingInterest(): [DEBUG] onIncomingInterest face=256 interest=/prefix/abcdefghijklmnopqrstuvwxyz/123456789/need/more/somefile.txt/%FE%00
0.010744s 1 nfd.Forwarder:onOutgoingInterest(): [DEBUG] onOutgoingInterest face=257 interest=/prefix/abcdefghijklmnopqrstuvwxyz/123456789/need/more/somefile.txt/%FE%00
0.010744s 1 ndn.NetDeviceFace:sendInterest(0x9eff28, 0xa01248)
0.021488s 2 ndn.NetDeviceFace:receiveFromNetDevice(0x9c50b0, 0xa17080, 30583, 02-06-00:00:00:00:00:03, 02-06-00:00:00:00:00:04, 1)
0.021488s 2 nfd.Forwarder:onIncomingInterest(): [DEBUG] onIncomingInterest face=256 interest=/prefix/abcdefghijklmnopqrstuvwxyz/123456789/need/more/somefile.txt/%FE%00
0.021488s 2 nfd.Forwarder:onOutgoingInterest(): [DEBUG] onOutgoingInterest face=257 interest=/prefix/abcdefghijklmnopqrstuvwxyz/123456789/need/more/somefile.txt/%FE%00
0.021488s 2 ndn.Producer:OnInterest(0xa11930, 0xa18448)
0.021488s 2 ndn.Producer:OnInterest(): [INFO ] node(2) respodning with Data: /prefix/abcdefghijklmnopqrstuvwxyz/123456789/need/more/somefile.txt/%FE%00
0.021488s 2 nfd.Forwarder:onIncomingData(): [DEBUG] onIncomingData face=257 data=/prefix/abcdefghijklmnopqrstuvwxyz/123456789/need/more/somefile.txt/%FE%00
0.021488s 2 nfd.Forwarder:onIncomingData(): [DEBUG] onIncomingData matching=/prefix/abcdefghijklmnopqrstuvwxyz/123456789/need/more/somefile.txt/%FE%00
0.021488s 2 nfd.Forwarder:onOutgoingData(): [DEBUG] onOutgoingData face=256 data=/prefix/abcdefghijklmnopqrstuvwxyz/123456789/need/more/somefile.txt/%FE%00
0.021488s 2 ndn.NetDeviceFace:sendData(0xa03868, 0xa1e768)
0.035888s 1 ndn.NetDeviceFace:receiveFromNetDevice(0x9c4230, 0xa009f0, 30583, 02-06-00:00:00:00:00:04, 02-06-00:00:00:00:00:03, 1)
0.035888s 1 ndn.NetDeviceFace:receiveFromNetDevice(): [ERROR] Unrecognized TLV packet
0.121488s 2 nfd.Forwarder:onInterestFinalize(): [DEBUG] onInterestFinalize interest=/prefix/abcdefghijklmnopqrstuvwxyz/123456789/need/more/somefile.txt/%FE%00 satisfied
1s 0 ndn.Consumer:SendPacket()
1s 0 ndn.Consumer:SendPacket(): [INFO ] > Interest for 1
1s 0 ndn.Consumer:WillSendOutInterest(): [DEBUG] Trying to add 1 with +1000000000.0ns. already 1 items
1s 0 nfd.Forwarder:onIncomingInterest(): [DEBUG] onIncomingInterest face=257 interest=/prefix/abcdefghijklmnopqrstuvwxyz/123456789/need/more/somefile.txt/%FE%01
1s 0 nfd.Forwarder:onOutgoingInterest(): [DEBUG] onOutgoingInterest face=256 interest=/prefix/abcdefghijklmnopqrstuvwxyz/123456789/need/more/somefile.txt/%FE%01
1s 0 ndn.NetDeviceFace:sendInterest(0x9e2908, 0xa1de28)
1s -1 ndn.Consumer:OnTimeout(0)
What about this:
0.035888s 1 ndn.NetDeviceFace:receiveFromNetDevice(): [ERROR] Unrecognized TLV packet
Updated by Spyros Mastorakis over 9 years ago
Interesting enough... I will need to check that... :)
Updated by Christian Kreuzberger over 9 years ago
This is as far as I got with some std::cerr in block.cpp (in ndn-cxx):
Value size=544,Totallenght=544
TLVTYpe=7, lenght=77
TLVTYpe=20, lenght=3
TLVTYpe=21, lenght=449
TLVTYpe=22, lenght=3
TLVTYpe=0, lenght=0
The packet seems to be valid at first, but then it is being sent to the intermediate node, and the intermediate node then receives:
Value size=519,Totallenght=519
TLVTYpe=77, lenght=8
TLVTYpe=26, lenght=97
TLVTYpe=0, lenght=0
TLVTYpe=0, lenght=0
TLVTYpe=0, lenght=0
TLVTYpe=0, lenght=0
...
I'm guessing there might be a problem with decode/encode?
Updated by Christian Kreuzberger over 9 years ago
Just to confirm, I've updated ndn-cxx to the latest version, and I've confirmed the problem on two computers (both Ubuntu 14.04, 64 Bit).
Updated by Alex Afanasyev over 9 years ago
- Related to Bug #2728: Block::fromStream decode error when TLV-LENGTH equals whitespace added
Updated by Christian Kreuzberger over 9 years ago
I've tested my original example with payload sizes from 100 to 1500, and I can confirm that they are all working, so the bug has been fixed.
Great work!