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

[FrancoisG]

I made some progress on this and sent a more specific question on the `openthread` side.

I'm still unsure but it might be the expected behavior. Even though at least in my case it surely is not optimal.

The question on `openthread` is here if somebody from nordic would have something to add:  github.com/.../7822

[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].