Thread device won't fetch reply before retrying

[FrancoisG]

I found my thread device to have quite a large latency so I analysed the communication and found out that the device is actually timeouting and retrying before listening for a reply.

Here is what I see on the border router for a TCP socket open (SYN, SYN/ACK)

un 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.329 [DEBG]-MAC-----: =========================[RX seqno=005 len=069]=========================
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.329 [DEBG]-MAC-----: | 69 98 05 CD AB 00 08 03 | 08 0D 79 19 00 00 03 7A | i..M+.....y....z
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.329 [DEBG]-MAC-----: | D0 10 06 24 7A 85 C8 82 | 7B 6A DC FD 00 00 64 00 | P..$z.H.{j\}..d.
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.329 [DEBG]-MAC-----: | 00 00 00 00 00 00 00 C0 | A8 02 9F CC 9E 07 5B 10 | .......@(..L..[.
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.330 [DEBG]-MAC-----: | 6F BD 12 00 00 00 00 50 | 02 05 00 B3 EC 00 00 0C | o=.....P...3l...
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.330 [DEBG]-MAC-----: | 2D 11 F8 26 53 .. .. .. | .. .. .. .. .. .. .. .. | -.x&S...........
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.330 [DEBG]-MAC-----: ------------------------------------------------------------------------
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.330 [INFO]-MAC-----: Received IPv6 TCP msg, len:60, chksum:b3ec, from:0x0803, sec:yes, prio:normal, rss:-54.0
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.330 [INFO]-MAC-----:     src:[fd11:22:0:0:247a:85c8:827b:6adc]:52382
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.330 [INFO]-MAC-----:     dst:[fd00:64:0:0:0:0:c0a8:29f]:1883
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.332 [INFO]-MAC-----: Prepping indir tx IPv6 TCP msg, len:64, chksum:bda8, to:0x0803, sec:yes, prio:low

Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.529 [DEBG]-MAC-----: =========================[RX seqno=006 len=069]=========================
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.529 [DEBG]-MAC-----: | 69 98 06 CD AB 00 08 03 | 08 0D 7A 19 00 00 03 7A | i..M+.....z....z
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.529 [DEBG]-MAC-----: | D0 10 06 24 7A 85 C8 82 | 7B 6A DC FD 00 00 64 00 | P..$z.H.{j\}..d.
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.529 [DEBG]-MAC-----: | 00 00 00 00 00 00 00 C0 | A8 02 9F CC 9E 07 5B 10 | .......@(..L..[.
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.529 [DEBG]-MAC-----: | 6F BD 12 00 00 00 00 50 | 02 05 00 B3 EC 00 00 FA | o=.....P...3l..z
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.529 [DEBG]-MAC-----: | 74 E3 AB 26 2E .. .. .. | .. .. .. .. .. .. .. .. | tc+&............
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.529 [DEBG]-MAC-----: ------------------------------------------------------------------------
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.530 [INFO]-MAC-----: Received IPv6 TCP msg, len:60, chksum:b3ec, from:0x0803, sec:yes, prio:normal, rss:-54.0
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.530 [INFO]-MAC-----:     src:[fd11:22:0:0:247a:85c8:827b:6adc]:52382
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.530 [INFO]-MAC-----:     dst:[fd00:64:0:0:0:0:c0a8:29f]:1883

Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.532 [INFO]-MAC-----: Rx data poll, src:0x0803, qed_msgs:2, rss:-54, ack-fp:1

Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.538 [DEBG]-MAC-----: =========================[TX seqno=042 len=074]=========================
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.539 [DEBG]-MAC-----: | 79 98 2A CD AB 03 08 00 | 08 0D 8B 0F 00 00 03 78 | y.*M+..........x
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.539 [DEBG]-MAC-----: | 85 01 06 3B FD 00 00 64 | 00 00 00 00 00 00 00 00 | ...;}..d........
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.539 [DEBG]-MAC-----: | C0 A8 02 9F 24 7A 85 C8 | 82 7B 6A DC 07 5B CC 9E | @(..$z.H.{j\.[L.
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.539 [DEBG]-MAC-----: | B6 44 32 41 10 6F BD 13 | 60 12 FA F0 BD A8 00 00 | 6D2A.o=.`.zp=(..
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.539 [DEBG]-MAC-----: | 02 04 05 B4 6E 07 5F 64 | A1 1E .. .. .. .. .. .. | ...4n._d!.......
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.539 [DEBG]-MAC-----: ------------------------------------------------------------------------
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.539 [INFO]-MAC-----: Sent IPv6 TCP msg, len:64, chksum:bda8, to:0x0803, sec:yes, prio:low
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.539 [INFO]-MAC-----:     src:[fd00:64:0:0:0:0:c0a8:29f]:1883
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.539 [INFO]-MAC-----:     dst:[fd11:22:0:0:247a:85c8:827b:6adc]:52382
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.539 [INFO]-MAC-----: Prepping indir tx IPv6 TCP msg, len:64, chksum:bda8, to:0x0803, sec:yes, prio:low

Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.543 [INFO]-MAC-----: Rx data poll, src:0x0803, qed_msgs:1, rss:-54, ack-fp:1

Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.549 [DEBG]-MAC-----: =========================[TX seqno=043 len=074]=========================
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.549 [DEBG]-MAC-----: | 69 98 2B CD AB 03 08 00 | 08 0D 8C 0F 00 00 03 78 | i.+M+..........x
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.549 [DEBG]-MAC-----: | 85 01 06 3B FD 00 00 64 | 00 00 00 00 00 00 00 00 | ...;}..d........
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.549 [DEBG]-MAC-----: | C0 A8 02 9F 24 7A 85 C8 | 82 7B 6A DC 07 5B CC 9E | @(..$z.H.{j\.[L.
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.549 [DEBG]-MAC-----: | B6 44 32 41 10 6F BD 13 | 60 12 FA F0 BD A8 00 00 | 6D2A.o=.`.zp=(..
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.549 [DEBG]-MAC-----: | 02 04 05 B4 6E 07 5F 64 | A1 1E .. .. .. .. .. .. | ...4n._d!.......
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.549 [DEBG]-MAC-----: ------------------------------------------------------------------------
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.549 [INFO]-MAC-----: Sent IPv6 TCP msg, len:64, chksum:bda8, to:0x0803, sec:yes, prio:low
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.549 [INFO]-MAC-----:     src:[fd00:64:0:0:0:0:c0a8:29f]:1883
Jun 17 13:17:00 3b31dc0359e9 otbr-agent[176]: 5d.22:01:40.549 [INFO]-MAC-----:     dst:[fd11:22:0:0:247a:85c8:827b:6adc]:52382

As you can see, the device

1. sends its first packet (SYN)
2. waits 200ms (I'm assuming a timeout)
3. sends the same first packet again (SYN)
4. only then does the RX data poll

At this point, there is 2 packets waiting (the 2 SYN/ACKs) and the device lost 200ms and transmitted twice the information for nothing.

I'm running SDK 1.8 and all the code and instruction on how to run is available here:

github.com/.../f79bec18f90014a30279d8307f818e6d8a755e5a

[Edvin]

Hello,

So this is a Sleepy End Device (SED). How often do you wake up? Do you go to sleep before receiving your ACKs? Can you try to extend the "awake period" and not go to sleep until you have received the ACKs?

I am not sure exactly where to look in your project. Where do you receive the acks?

Best regards,

Edvin

[FrancoisG]

Hi Edvin,

I wake up only on button press to send the event and at the poll period (236 seconds).

The acks are received by the tcp/ip stack, this is transparent to my application code.

[Edvin]

Ok, I am struggling a bit to understand this issue. Can you point me to where in your application you are sending the SYN message, what ACK you are not getting (if that is the case, or perhaps I misunderstand?) And from where is the retransmit triggered?

[FrancoisG]

When I connect to the MQTT server here https://github.com/fgervais/project-nrf-thread-switch/blob/b0dcef3b4292b6e716625568dfe844519e6a419f/app/src/main.c#L232  it will open a tcp socket (SYN/SYN-ACK/ACK).

This is all then managed by the tcp stack of the nrf sdk.

You can have a look at the wireshark screenshot here you will see a complete transaction: https://github.com/openthread/openthread/discussions/7822

The problem are the black lines (retries). I am not getting the first [SYN, ACK] before the tcp stack retries sending a new [SYN].

[FrancoisG]

I'm also available for a call if you want, maybe this could help get in sync. Today I'm free mostly anything reasonable EST.

[Edvin]

So what you are saying is that the nRF goes to sleep before it receives the ack in the first transmission? Or is this the connection to the network, so all this is before you actually enter the sleepy state (as this is a&nbsp;<span>CONFIG_OPENTHREAD_MTD_SED=y)

I will have to forward this question to our Thread team. I will keep you posted. 

Best regards,

Edvin

[FrancoisG]

Yes exactly that, the nRF goes to sleep before it receives the ack in the first transmission.

Thank you.

[Edvin]

Hello,

Sorry for the late reply. I was out of office (vacation) the last week.

Our Thread team noticed that you got an answer in the github issue, which seemed to solve your problem. I suggest that we close this ticket for now.

Best regards,

Edvin