Data poll delayed when receiving fragmented packets about openthread HOT 8 OPEN

It is been a while since I last read the DataPollSender and Mac code, but checking the code I dont see anything obvious that would lead to such a behavior.

• The DataPollSender should immediately SendDataPoll() from ProcessRxFrame() if it sees aFrame.GetFramePending() on the received frames.
• Mac should finish kOperationWaitingForData from HandleReceivedFrame()

Unable to obtain due to messages overriding each other when logging at level 5. Logging at level 4 does not trigger the bug.

Gotta love a Heisenbug 😄

from openthread.

@CodingRays , can you attach the pcap file?

from openthread.

So heres a minimal setup to reproduce the issue i found. This uses only dongles:

From a fresh clone of the nrf52840:
Build using ./script/build nrf52840 USB_trans -DOT_BOOTLOADER=USB -DOT_LOG_LEVEL_DYNAMIC=ON
On the mtd following commands:

log level 5
mode -
pollperiod 10000

On the ftd to test

udp send <mleid> 5000 -s 512

Since the bug appears ~50% of the time a few transmission might be required but it should trigger very reliably.

I sadly lost the pcap file from the image but here is a capture from a test using the above setup.
The bug appears between packet 172 and 173. Network key: 6ce43b5b088aa1a10db563e803d1a28b
data_poll_dongle.zip

from openthread.

Looking at the packet trace again, it appears that the ACK was sent with the Frame Pending bit set, but no data frame transmission followed. The default Data Poll Timeout is set to 100ms:

The Data Sequence Number jumps from 125 in frame 169 to 127 in frame 175. So it appears that it tried to send a data frame. But without more logging from the sender, it is difficult to determine exactly the root cause. It could be due to CCA failures. It could be that the frame was transmitted but a collision occurred. Both of which would be legitimate reasons for packet loss.

Can you provide detailed logs from the parent?

from openthread.

I can try to get the logs.

But its hard to believe its completely unrelated to the logging due to just how consistent it is. I have not had a single such failure during all my testing while logging was disabled while with it enabled its 50% of all ip packets / ~16% of all fragments.

from openthread.

I'm hoping the logs can provide some visibility into why data frames are not being transmitted following an ACK with the Frame Pending bit set.

from openthread.

Ok so ive spent a while testing and i was no longer able to reproduce the bug. It did occur once and as previously when it did happen it was reliable until i changed the configuration. Here 10s after the change i continued testing and it immediately stopped. However without knowing any conditions to trigger it its hard to investigate. I also couldnt get logs from that test. One thing to note though is that now the wireshark logs show the data poll being sent but no response from the parent.

I am using different hardware (newer chip revisions) now though and will try and test with the original hardware hopefully soon and get back after i do that.

from openthread.

Alright i cant reproduce the bug anymore event with different hardware. I have no idea what changed.
I guess the issue can be closed then.

from openthread.