otbr-agent with NRF52840 (RCP) is exiting

[saumildmehta]

I am using custom linux board and taken latest code of otbr-agent. Also taken latest code of ot-nrf528xx for NRF52840.

otbr-agent is able to communicate with RCP successfully and my openthread network is created as well. But randomly it files following error and exits:

otbr-agent[14116]: 00:35:22.736 [WARN]-PLAT----: radio tx timeout otbr-agent[14116]: 00:35:22.736 [CRIT]-PLAT----: HandleRcpTimeout() at /usr/src/debug/otbr/git-r0/ot-br-posix/third_party/openthread/repo/src/lib/spinel /radio_spinel_impl.hpp:2218: RadioSpinelNoResponse

Full logs of otbr-agent from start are attached and it was exited without any activity. Once I was able to commission and communicate with device and after it got exited with same error. Is it issue from otbr? or rcp?

otbr_agent_rcp_timeout.log

[jwhui]

@saumildmehta , can you provide more information on your setup?

• What git commit(s) are you using?
• Are you using an nRF52840-DK or USB dongle?
• How are you connecting the nRF52840 - UART, USB, I2C?

[saumildmehta]

@jwhui Thanks for response.

- What git commit(s) are you using?

I am using following commits:
RCP: ot-nrf528xx - ad3b3c0
OTBR: otbr - 83babaf236cad8471be28185d8d4351d37564919

- Are you using an nRF52840-DK or USB dongle?
- How are you connecting the nRF52840 - UART, USB, I2C?
I am using custom board with i.Mx6ull as host and NRF52840 module connected over UART.
UART between them is hardware flow control enabled.
Note: iMx6ull and NRF52840 connectivity is good as I have validated it by flashing different binary for BLE.

Let me know if you need any more logs or different trials.

[jwhui]

@edmont @MarekPorwisz @LuDuda , have you seen this issue before?

[saumildmehta]

@jwhui @edmont @MarekPorwisz @LuDuda
FYI. If I flash image first time, it runs for long time may be for couple of hours and able to add and ping child devices.
But after words it exits in seconds. Majority times I have seen this "radio tx timeout" error after applying command "ot-ctl thread start".

[LuDuda]

@saumildmehta are you able to connect debugger to the nRF52840 SoC after this error happens? It would be interesting to see what is the state of the device (maybe it hangs in some assert).

Could you verify if you can see the same problem with nRF52840 DK that acts as RCP? (If you use J-Link USB, remember to turn off the MSD as it is described in the platform's README.md).

[lancersky]

We are developing OTBR base on OpenWrt. And I also got the same exception in version openthread/ot-br-posix@5be3594.
The EFR32MG21 RCP firmware version was built from openthread/ot-efr32@31e9fc8.
The end device firmware version was built from ot-nrf52840 - 6533ff7

Thu May 12 05:47:09 2022 user.info otbr-agent[3232]: 00:06:24.745 [INFO]-MAC-----: Received IPv6 HopOpts msg, len:83, chksum:0000, from:0x7000, sec:yes, prio:normal, rss:-40.0
Thu May 12 05:47:09 2022 user.info otbr-agent[3232]: 00:06:24.745 [INFO]-MAC-----:     src:[fdd2:b178:8ba5:0:6600:5182:e6dd:13f6]
Thu May 12 05:47:09 2022 user.info otbr-agent[3232]: 00:06:24.745 [INFO]-MAC-----:     dst:[ff03:0:0:0:0:0:0:1]
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:24.991 [DEBG]-MAC-----: Received frame from short address 0x7000
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:24.992 [DEBG]-MAC-----: Rx security - frame counter 37487
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:24.992 [DEBG]-MAC-----: =========================[RX seqno=189 len=078]=========================
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:24.992 [DEBG]-MAC-----: | 49 98 BD 32 3D FF FF 00 | 70 0D 6F 92 00 00 01 7C | I.=2=...p.o....|
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:24.992 [DEBG]-MAC-----: | 5A 3F 50 F1 D7 EF 43 C2 | 4D D3 03 00 00 01 E1 06 | Z?PqWoCBMS....a.
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:24.992 [DEBG]-MAC-----: | 6D 04 40 E2 70 01 F0 9C | 95 16 33 D8 2C 58 03 82 | m.@bp.p...3X,X..
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:24.993 [DEBG]-MAC-----: | 0B 76 12 4A 10 5F 73 2C | FC BC 6E 65 74 77 6F 72 | .v.J._s,|<networ
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:24.993 [DEBG]-MAC-----: | 6B 5F 74 65 73 74 FF 14 | AB DD 77 4F 66 10 .. .. | k_test..+]wOf...
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:24.993 [DEBG]-MAC-----: ------------------------------------------------------------------------
Thu May 12 05:47:10 2022 user.info otbr-agent[3232]: 00:06:24.993 [INFO]-MAC-----: Received IPv6 HopOpts msg, len:83, chksum:0000, from:0x7000, sec:yes, prio:normal, rss:-40.0
Thu May 12 05:47:10 2022 user.info otbr-agent[3232]: 00:06:24.993 [INFO]-MAC-----:     src:[fdd2:b178:8ba5:0:50f1:d7ef:43c2:4dd3]
Thu May 12 05:47:10 2022 user.info otbr-agent[3232]: 00:06:24.993 [INFO]-MAC-----:     dst:[ff03:0:0:0:0:0:0:1]
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:25.038 [DEBG]-MAC-----: Received frame from short address 0x7000
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:25.039 [DEBG]-MAC-----: Rx security - frame counter 37488
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:25.041 [DEBG]-MAC-----: =========================[RX seqno=190 len=078]=========================
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:25.041 [DEBG]-MAC-----: | 49 98 BE 32 3D FF FF 00 | 70 0D 70 92 00 00 01 7C | I.>2=...p.p....|
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:25.041 [DEBG]-MAC-----: | 5A 3F 50 F1 D7 EF 43 C2 | 4D D3 03 00 00 01 E1 06 | Z?PqWoCBMS....a.
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:25.043 [DEBG]-MAC-----: | 6D 04 40 E2 70 01 F0 9C | 95 16 33 D8 2C 58 03 82 | m.@bp.p...3X,X..
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:25.043 [DEBG]-MAC-----: | 0B 76 12 4A 10 5F 73 2C | FC BC 6E 65 74 77 6F 72 | .v.J._s,|<networ
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:25.043 [DEBG]-MAC-----: | 6B 5F 74 65 73 74 FF 14 | 2E B2 9B 6F 66 10 .. .. | k_test...2.of...
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:25.044 [DEBG]-MAC-----: ------------------------------------------------------------------------
Thu May 12 05:47:10 2022 user.info otbr-agent[3232]: 00:06:25.044 [INFO]-MAC-----: Received IPv6 HopOpts msg, len:83, chksum:0000, from:0x7000, sec:yes, prio:normal, rss:-40.0
Thu May 12 05:47:10 2022 user.info otbr-agent[3232]: 00:06:25.045 [INFO]-MAC-----:     src:[fdd2:b178:8ba5:0:50f1:d7ef:43c2:4dd3]
Thu May 12 05:47:10 2022 user.info otbr-agent[3232]: 00:06:25.045 [INFO]-MAC-----:     dst:[ff03:0:0:0:0:0:0:1]
Thu May 12 05:47:10 2022 user.warn otbr-agent[3232]: 00:06:25.046 [WARN]-PLAT----: radio tx timeout
Thu May 12 05:47:10 2022 user.warn otbr-agent[3232]: 00:06:25.046 [WARN]-PLAT----: RCP failure detected
Thu May 12 05:47:10 2022 user.warn otbr-agent[3232]: 00:06:25.046 [WARN]-PLAT----: Trying to recover (1/5)
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:25.047 [DEBG]-PLAT----: Wait response: tid=0 key=0
Thu May 12 05:47:10 2022 user.info otbr-agent[3232]: 00:06:25.083 [INFO]-PLAT----: RCP reset: RESET_POWER_ON
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:25.083 [DEBG]-PLAT----: Wait response: tid=1 key=32
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:25.084 [DEBG]-PLAT----: Wait response: tid=2 key=54
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:25.120 [DEBG]-PLAT----: Wait response: tid=3 key=53
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:25.125 [DEBG]-PLAT----: Wait response: tid=4 key=52
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:25.160 [DEBG]-PLAT----: Wait response: tid=5 key=33
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:25.195 [DEBG]-PLAT----: Wait response: tid=6 key=2048
Thu May 12 05:47:10 2022 user.info otbr-agent[3232]: 00:06:25.199 [INFO]-CORE----: [settings] Read NetworkInfo {rloc:0xa000, extaddr:869fb174c86af38f, role:router, mode:0x0f, version:3, keyseq:0x0, ...
Thu May 12 05:47:10 2022 user.info otbr-agent[3232]: 00:06:25.204 [INFO]-CORE----: [settings] ... pid:0x6b0e75b9, mlecntr:0x3f7, maccntr:0x7d3, mliid:2641fdfb46d32fc6}
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:25.205 [DEBG]-PLAT----: Wait response: tid=7 key=2049
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:25.239 [DEBG]-PLAT----: Wait response: tid=8 key=37
Thu May 12 05:47:10 2022 user.debug otbr-agent[3232]: 00:06:25.241 [DEBG]-PLAT----: Wait response: tid=9 key=43
Thu May 12 05:47:10 2022 user.warn otbr-agent[3232]: 00:06:25.243 [WARN]-PLAT----: Error processing result: NotImplemented
Thu May 12 05:47:10 2022 user.warn otbr-agent[3232]: 00:06:25.245 [WARN]-PLAT----: Error waiting response: NotImplemented
Thu May 12 05:47:10 2022 user.crit otbr-agent[3232]: 00:06:25.248 [CRIT]-PLAT----: BSD TCP function() at radio_spinel_impl.hpp:2378: Failure
Thu May 12 05:47:15 2022 user.info otbr-agent[11593]: [INFO]-UTILS---: Running thread-reference-20200818-1510-g3b79cb0d0
Thu May 12 05:47:15 2022 user.info otbr-agent[11593]: [INFO]-UTILS---: Thread version: 1.2.0
Thu May 12 05:47:15 2022 user.info otbr-agent[11593]: [INFO]-UTILS---: Thread interface: wpan0
Thu May 12 05:47:15 2022 user.info otbr-agent[11593]: [INFO]-UTILS---: Backbone interface:
Thu May 12 05:47:15 2022 user.info otbr-agent[11593]: [INFO]-UTILS---: Radio URL: spinel+hdlc+uart:///dev/ttyUSB0?uart-baudrate=460800
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 49d.17:10:21.241 [DEBG]-PLAT----: Wait response: tid=0 key=0
Thu May 12 05:47:15 2022 user.info otbr-agent[11593]: 49d.17:10:21.276 [INFO]-PLAT----: RCP reset: RESET_POWER_ON
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 49d.17:10:21.276 [DEBG]-PLAT----: Wait response: tid=1 key=1
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 49d.17:10:21.311 [DEBG]-PLAT----: Wait response: tid=2 key=2
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 49d.17:10:21.313 [DEBG]-PLAT----: Wait response: tid=3 key=8
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 49d.17:10:21.349 [DEBG]-PLAT----: Wait response: tid=4 key=5
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 49d.17:10:21.384 [DEBG]-PLAT----: Wait response: tid=5 key=176
Thu May 12 05:47:15 2022 user.notice otbr-agent[11593]: 49d.17:10:21.419 [NOTE]-PLAT----: RCP API Version: 5
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 49d.17:10:21.419 [DEBG]-PLAT----: Wait response: tid=6 key=4619
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 00:00:00.001 [DEBG]-PLAT----: Wait response: tid=7 key=34
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 00:00:00.037 [DEBG]-PLAT----: Wait response: tid=8 key=32
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 00:00:00.071 [DEBG]-PLAT----: Wait response: tid=9 key=54
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 00:00:00.106 [DEBG]-PLAT----: Wait response: tid=10 key=53
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 00:00:00.140 [DEBG]-PLAT----: Wait response: tid=11 key=39
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 00:00:00.175 [DEBG]-MAC-----: RadioState: Disabled -> Sleep
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 00:00:00.175 [DEBG]-PLAT----: Wait response: tid=12 key=2048
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 00:00:00.211 [DEBG]-PLAT----: Wait response: tid=13 key=52
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 00:00:00.246 [DEBG]-MAC-----: RadioExtAddress: ee6ea886d34a1f22
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 00:00:00.246 [DEBG]-PLAT----: Wait response: tid=14 key=53
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 00:00:00.281 [DEBG]-MAC-----: RadioShortAddress: 0xfffe
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 00:00:00.283 [DEBG]-PLAT----: Wait response: tid=15 key=4868
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 00:00:00.318 [DEBG]-PLAT----: Wait response: tid=1 key=4869
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 00:00:00.319 [DEBG]-MAC-----: SrcAddrMatch - Cleared all entries
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 00:00:00.320 [DEBG]-PLAT----: Wait response: tid=2 key=2048
Thu May 12 05:47:15 2022 user.debug otbr-agent[11593]: 00:00:00.322 [DEBG]-PLAT----: Wait response: tid=3 key=54
Thu May 12 05:47:16 2022 user.debug otbr-agent[11593]: 00:00:00.356 [DEBG]-MAC-----: RadioPanId: 0x3d32
Thu May 12 05:47:16 2022 user.info otbr-agent[11593]: 00:00:00.357 [INFO]-CORE----: [settings] Read NetworkInfo {rloc:0xa000, extaddr:869fb174c86af38f, role:router, mode:0x0f, version:3, keyseq:0x0, ...
Thu May 12 05:47:16 2022 user.info otbr-agent[11593]: 00:00:00.357 [INFO]-CORE----: [settings] ... pid:0x6b0e75b9, mlecntr:0x3f7, maccntr:0x7d3, mliid:2641fdfb46d32fc6}
Thu May 12 05:47:16 2022 user.debug otbr-agent[11593]: 00:00:00.357 [DEBG]-PLAT----: Wait response: tid=4 key=2049
Thu May 12 05:47:16 2022 user.debug otbr-agent[11593]: 00:00:00.393 [DEBG]-PLAT----: Wait response: tid=5 key=53
Thu May 12 05:47:16 2022 user.debug otbr-agent[11593]: 00:00:00.428 [DEBG]-MAC-----: RadioShortAddress: 0xa000
Thu May 12 05:47:16 2022 user.debug otbr-agent[11593]: 00:00:00.430 [DEBG]-PLAT----: Wait response: tid=6 key=52
Thu May 12 05:47:16 2022 user.debug otbr-agent[11593]: 00:00:00.465 [DEBG]-MAC-----: RadioExtAddress: 869fb174c86af38f
Thu May 12 05:47:16 2022 user.info otbr-agent[11593]: [INFO]-UTILS---: Set state callback: OK
Thu May 12 05:47:16 2022 user.info otbr-agent[11593]: 00:00:00.465 [INFO]-SRP-----: [server] selected port 53535
Thu May 12 05:47:16 2022 user.info otbr-agent[11593]: 00:00:00.466 [INFO]-N-DATA--: Publisher: Publishing DNS/SRP service unicast (ml-eid, port:53535)
Thu May 12 05:47:16 2022 user.info otbr-agent[11593]: 00:00:00.466 [INFO]-N-DATA--: Publisher: DNS/SRP service - State: NoEntry -> ToAdd
Thu May 12 05:47:16 2022 user.info otbr-agent[11593]: [INFO]-BA------: Publish meshcop service OpenThread BorderRouter._meshcop._udp.local.
Thu May 12 05:47:16 2022 user.info otbr-agent[11593]: [INFO]-MDNS----: Add service: OpenThread BorderRouter._meshcop._udp (ref: 0xb6f3eeb0)
Thu May 12 05:47:16 2022 user.info otbr-agent[11593]: [INFO]-ADPROXY-: Publish all hosts and services
Thu May 12 05:47:16 2022 user.info otbr-agent[11593]: [INFO]-ADPROXY-: Started
Thu May 12 05:47:16 2022 user.info otbr-agent[11593]: [INFO]-DPROXY--: started
Thu May 12 05:47:16 2022 user.info otbr-agent[11593]: [INFO]-BA------: Start Thread Border Agent: OK
Thu May 12 05:47:16 2022 user.info otbr-agent[11593]: [INFO]-UBUS----: Connected as 81469bc6
Thu May 12 05:47:16 2022 user.info otbr-agent[11593]: [INFO]-UBUS----: Uloop run
Thu May 12 05:47:16 2022 user.info otbr-agent[11593]: [INFO]-APP-----: Border router agent started.

[kroa38]

Hello,
My OTBR is based on the Silabs Image for Raspberry-Pi 4 here and when i attache the nRF52840 DK to Rpi the service
"otbr-agent" return an error because the RCP is in version 8 and not in the range of [4-6] (Spinel issue i think)
Is there a way to downgrade to a RCP version 4 to 6 ?

[jwhui]

Hello, My OTBR is based on the Silabs Image for Raspberry-Pi 4 here and when i attache the nRF52840 DK to Rpi the service "otbr-agent" return an error because the RCP is in version 8 and not in the range of [4-6] (Spinel issue i think) Is there a way to downgrade to a RCP version 4 to 6 ?

@kroa38 , you can move to an earlier commit. The easiest is to match the same commit as what's used on the OTBR host.

[kroa38]

Any idea how to know the right commit with a RCP API version in the range of [4-6]
Thanks

[jwhui]

Any idea how to know the right commit with a RCP API version in the range of [4-6] Thanks

As mentioned above, one method is to simply use the same git commit on both OTBR host and RCP.

Alternatively, you can walk back the git blame history to find when SPINEL_RCP_API_VERSION was set to 6.

https://github.com/openthread/openthread/blob/9af0bfa60e373d81a5576b298d6664045870a375/src/lib/spinel/spinel.h#L420

[MonicaisHer]

Any idea how to know the right commit with a RCP API version in the range of [4-6] Thanks

Here is my solution: Building and flashing the RCP using main repo commit (00ac6cd) and submodule commit (9af0bfa60e373d81a5576b298d6664045870a375). By doing this, the RCP and OT-BR will be compatible using the same API version 6.