Missing messages in big network (30 nodes+BR)

[YasmineSafi]

Hello People,

We have an issue with messaging in our thread network which is composed of:

• 30 FTDs, each one:

  • MCU: silicon labs MGM210P
  • OpenThread commit : SL-OPENTHREAD/2.0.1.0_GitHub-55af6ce2c
  • Sending 3 periodic messages within 60 seconds to the Border Router only : message payload sizes vary between 24 Bytes and 900ish bytes

• 1 Border router :

  • Using OTBR application ot-br-posix on Beaglebone Black
  • OTBR version OPENTHREAD/0.01.00
  • RCP MCU : silicon labs MGM210P
  • RCP version: SL-OPENTHREAD/1.2.0.0_GitHub-cf21d5760
  • Running a Python application to Receive and transmit the UDP messages over Thread
  • Sending multicast every 15 seconds, around 24 Bytes/message payload

Problems:

• We stopped receiving messages from FTD (in most cases messages with bigger sized payload > 250 bytes).
• After observing the OTBR-Agent Logs, we encountered many logs having error Duplicated almost evry 2minute

Apr 21 14:43:24 beaglebone otbr-agent[27449]: [INFO]-MAC-----: Frame rx failed, error:Duplicated, len:50, seqnum:56, type:Data, src:0xd000, dst:0x2800, sec:yes, ackreq:yes, radio:15.4
Apr 21 14:43:28 beaglebone otbr-agent[27449]: [INFO]-MAC-----: Frame rx failed, error:Duplicated, len:124, seqnum:67, type:Data, src:0xd000, dst:0x2800, sec:yes, ackreq:yes, radio:15.4
Apr 21 14:43:38 beaglebone otbr-agent[27449]: [INFO]-MAC-----: Frame rx failed, error:Duplicated, len:50, seqnum:102, type:Data, src:0xd000, dst:0x2800, sec:yes, ackreq:yes, radio:15.4
Apr 21 14:43:39 beaglebone otbr-agent[27449]: [INFO]-MAC-----: Frame rx failed, error:Duplicated, len:121, seqnum:102, type:Data, src:0x6000, dst:0x2800, sec:yes, ackreq:yes, radio:15.4
Apr 21 14:43:39 beaglebone otbr-agent[27449]: [INFO]-MAC-----: Frame rx failed, error:Duplicated, len:121, seqnum:102, type:Data, src:0x6000, dst:0x2800, sec:yes, ackreq:yes, radio:15.4
Apr 21 14:43:43 beaglebone otbr-agent[27449]: [INFO]-MAC-----: Frame rx failed, error:Duplicated, len:127, seqnum:120, type:Data, src:0x6000, dst:0x2800, sec:yes, ackreq:yes, radio:15.4
Apr 21 14:43:44 beaglebone otbr-agent[27449]: [INFO]-MAC-----: Frame rx failed, error:Duplicated, len:121, seqnum:122, type:Data, src:0x6000, dst:0x2800, sec:yes, ackreq:yes, radio:15.4

• otbr seems to be sending the messages it received from any FTD as we saw here :

Apr 21 13:30:48 beaglebone otbr-agent[27449]: [NOTE]-MAC-----: Failed to send IPv6 UDP msg, len:287, chksum:8c84, sec:yes, error:ReassemblyTimeout, prio:normal, rss:-27.0, radio:15.4
Apr 21 13:33:49 beaglebone otbr-agent[27449]: [NOTE]-MAC-----: Failed to send IPv6 UDP msg, len:954, chksum:9401, sec:yes, error:ReassemblyTimeout, prio:normal, rss:-64.0, radio:15.4
Apr 21 13:35:42 beaglebone otbr-agent[27449]: [NOTE]-MAC-----: Failed to send IPv6 UDP msg, len:248, chksum:16a6, sec:yes, error:ReassemblyTimeout, prio:normal, rss:-78.0, radio:15.4
Apr 21 13:35:43 beaglebone otbr-agent[27449]: [NOTE]-MAC-----: Failed to send IPv6 UDP msg, len:248, chksum:16a6, sec:yes, error:ReassemblyTimeout, prio:normal, rss:-71.0, radio:15.4
Apr 21 13:36:04 beaglebone otbr-agent[27449]: [NOTE]-MAC-----: Failed to send IPv6 UDP msg, len:248, chksum:16a6, sec:yes, error:ReassemblyTimeout, prio:normal, rss:-77.0, radio:15.4
Apr 21 13:36:06 beaglebone otbr-agent[27449]: [NOTE]-MAC-----: Failed to send IPv6 UDP msg, len:248, chksum:16a6, sec:yes, error:ReassemblyTimeout, prio:normal, rss:-79.0, radio:15.4
Apr 21 13:36:33 beaglebone otbr-agent[27449]: [NOTE]-MAC-----: Failed to send IPv6 UDP msg, len:248, chksum:16a6, sec:yes, error:ReassemblyTimeout, prio:normal, rss:-80.0, radio:15.4
Apr 21 13:36:34 beaglebone otbr-agent[27449]: [NOTE]-MAC-----: Failed to send IPv6 UDP msg, len:248, chksum:16a6, sec:yes, error:ReassemblyTimeout, prio:normal, rss:-79.0, radio:15.4

Let me know if there are some missing information.
Any help would be appreciated, Thank you :)

[suveshpratapa]

@YasmineSafi Thanks for raising this issue.

1. Do your devices ever recover after getting into this state, or do you have to reset network state?

2. It seems like there is a high rate of retries and fragment reassembly going on, which the errors indicate. Have you checked the instructions in Silicon Labs AN1256 about increasing the baud rate to improve message reliability in high data rate use cases? Do you mind trying these changes out to see if it improves your use case?

In your /etc/default/otbr-agent file, you can add a parameter to increase the baud rate to 460800, something like:

OTBR_AGENT_OPTS="-I wpan0 -B eth0 spinel+hdlc+uart:///dev/ttyACM0?uart-baudrate=460800"

You can also configure your RCP EFR image / WSTK at this baud rate, by following instructions in Silicon Labs AN1256, Section 4.2

[YasmineSafi]

For now it is not possible to update RCP because we need to update OTBR as well ( not possible now ).
that's the only reason why we are using an older version.

Do think that both RCP and FTD should be using the same version ? or just because SDK 4.0.1 has some improvements/fixes ?

also I would like to ask about the UDP forward feature. what would happen if it is enabled ? for now it is only enabled in FTDs

[suveshpratapa]

Do think that both RCP and FTD should be using the same version ? or just because SDK 4.0.1 has some improvements/fixes ?

Our latest SDKs are in general more stable overall (including various platform stability features). The only reason I'm asking is because the RCP version is old. If you cannot change it however, let us continue investigating this way.

also I would like to ask about the UDP forward feature. what would happen if it is enabled ? for now it is only enabled in FTDs

I assumed you were turning this on because you needed this for your application; it is to set up special UDP forwarding capability on your application. It is NOT required and should not be turned on by default if you're not setting up a forwarding callback.

So please turn off OPENTHREAD_CONFIG_UDP_FORWARD_ENABLE if you're not using it.

[YasmineSafi]

okay, thank you for your answers
so I will do the test tomorrow and share the logs to investigate this more

[YasmineSafi]

logs_otbr.txt

I hope these logs are helpful
so starting from 12:26:48, the FTDs start sending messages at almost the same time.
it resulted in seeing errors more frequently.

I don't understand if this error log is normal or not :

Failed to send IPv6 UDP msg, len:X, chksum:X, sec:yes, error:ReassemblyTimeout, prio:normal, rss:-X, radio:15.4

it seems to me here that the BR couldn't send an IPv6 message
but then I see that the dst address is the BR's address

dst:[fd84:6586:a172:375c:0:ff:fe00:fc11]:1212

Thank you for taking the time to investigate this :)

[suveshpratapa]

@YasmineSafi

1. Is there any particular reason your RCP is on 3.2 and you can't upgrade to latest SiLabs SDK? What commit is your OTBR running against?
2. Is it at all possible for you to modify the OTBR code to add more debugging?

[guerbasc]

Hello @YasmineSafi ,

I apologize for intruding into your discussion without being able to provide you with an answer.

But I saw on your question #7624 that you have configured a border router using silicon labs, I would like to know if you have made another configuration other than what is described in openthread.io.
And if you could do the same configuration with a Nordic nRF52840.

Thank you for having read me

[YasmineSafi]

Hello @guerbasc

No worries :)

for the RCP, we are using silicon labs MCU MGM210P.
To configure and flash the RCP, we used Simplicity Studio ( IDE by Silicon Labs ) .
As for the OTBR build and configuration, we followed these instructions https://openthread.io/guides/border-router/build

Currently we are only using Silicon Labs MCUs, so I can't try anything on Nordic MCUs.

I hope this answered your questions.

[guerbasc]

@YasmineSafi Thank's for your prompt response.

I'm going to take the opportunity to ask you a question about a problem I have to run tests using border router devices.

when I run any test with border router, the test stops at 7%.

for example, when I run BR_1 5.9.11 test, I see the following status on the GRL windows console :

Status --> Starting over the air packet capture.. [7]

Capturing on 2 interfaces

Have you any idea about this issue and how can i fix it ?

[YasmineSafi]

No sorry :/
When I have an issue regarding OpenThread, I ask in OpenThread forums/discussions ( https://github.com/openthread/openthread/discussions/categories/q-a ). They are really helpful
It's always better to do so, so that people with similar issues can find an answer

[guerbasc]

thank's for help @YasmineSafi :)

[dmfiore]

I have been able to try this with 35-50 devices sending at a rate much greater than described as well as the OTBR sending mcast every 5 seconds. Using all mg12 as that is what is available.
I have tried with all 35 devices sending 256byte packets x6 per minute.
Nothing ever 'locks up' or needs recovery. There is certainly loss as we increase traffic rates well beyond what the device can handle and when configured for 115k baud rate which is less than half of the rate that 15.4 OT can reach (~250 kbps).
At silabs, we are using raspberry pi, perhaps this is a beagle board issue. Gathering more data results and runs with all devices sending 1024 byte packets. Will post more results here sometime soon.
@YasmineSafi

[dmfiore]

Here are a series of tests that were executed over a network of 35 SoC MG12 devices running latest OT and the DuT which is also MG12 running OTBR on a raspberry pi and Silicon labs WSTK adapter. These devices are distributed all within ~1500 square foot area in an environment with a lot of other 15.4 and wifi traffic.
The serial interface on the OTBR is configured for only 115k vcom with HWFC.
There is some loss in these charts as the traffic rate is very high for 35 devices sending to 1. The greater the stress (such as all devices sending 1024 bytes packets), the greater the latency and loss. Other than loss of packets, it was not ever observed that a device stops tx'g or rx'g and needed to be reset to recover/resume.
For this testing, the same network was used and stable for hours.
While the 35 devices are transmitting, the OTBR is transmitting a multicast ever 5 seconds.
The 8byte test is running at a faster rate (each tx'd every 7 secs), while the other scenarios are all once per 12 secs (ie x5 per min).

[YasmineSafi]

Thank you very much for sharing these results.

We are planning to carry working on this soon and update the RCP and OTBR.
I will share more information regarding this issue.
thanks again!