search

openthread / ot-br-posix

OpenThread Border Router, a Thread border router for POSIX-based platforms.
https://openthread.io/
BSD 3-Clause "New" or "Revised" License
420 stars 232 forks source link

Problem with otbr-agent status. Init() at spinel_driver.cpp:82: Failure. #2412

Open cvfabian opened 3 months ago

cvfabian commented 3 months ago

Hi,

I've come across with a problem regarding the connection of my nRF52840-DK board to my Raspberry Pi 4B to start the otbr-agent service. I followed the instructions indicated here: https://openthread.io/codelabs/openthread-border-router#1, but to no avail.

Are there any solutions to this? I can't run the succeeding commands, e.g., "sudo ot-ctl dataset init new".

Thanks!

superwhd commented 3 months ago

Have you flashed the latest ot-rcp firmware for your nRF52840-DK? I think it may be an incompatibility between the host and the RCP.

cc @zhanglongxia @Irving-cl

cvfabian commented 3 months ago

Yes, I followed the same steps here in flashing the device. Is there a much newer version than this?

Thanks!

zhanglongxia commented 3 months ago

Could you provide logs of the otbr-agent? You can see the log via tail -f /var/log/syslog | grep otbr.

scratchclaggy commented 3 months ago

I'm getting the same error message, looking at the line the error message is referencing my best guess is there's a version mismatch between the border router and the RCP?

scratchclaggy commented 3 months ago

Here are the logs too:

Aug 05 21:15:47 apollo otbr-agent[2373]: [NOTE]-AGENT---: Thread interface: wpan0
Aug 05 21:15:47 apollo otbr-agent[2373]: [NOTE]-AGENT---: Radio URL: spinel+hdlc+uart:///dev/ttyACM0
Aug 05 21:15:47 apollo otbr-agent[2373]: [NOTE]-AGENT---: Radio URL: trel://eth0
Aug 05 21:15:47 apollo otbr-agent[2373]: [NOTE]-ILS-----: Infra link selected: eth0
Aug 05 21:15:47 apollo otbr-agent[2373]: [INFO]-RCP_HOS-: OpenThread log level changed to 4
Aug 05 21:15:49 apollo otbr-agent[2373]: 49d.17:06:09.397 [W] P-SpinelDrive-: Wait for response timeout
Aug 05 21:15:49 apollo otbr-agent[2373]: 49d.17:06:09.397 [I] P-SpinelDrive-: co-processor self reset successfully
Aug 05 21:15:51 apollo otbr-agent[2373]: 49d.17:06:11.399 [W] P-SpinelDrive-: Wait for response timeout
Aug 05 21:15:53 apollo otbr-agent[2373]: 49d.17:06:13.401 [W] P-SpinelDrive-: Wait for response timeout
Aug 05 21:15:53 apollo otbr-agent[2373]: 49d.17:06:13.401 [C] Platform------: Init() at spinel_driver.cpp:82: Failure
tdzt commented 3 months ago

Hello, Seems to be the same issue for us.

Here is our setup :

ot-agent are crashing and daemon isn't running.

Logs : 

Aug  5 20:48:22 2a45fc7d7e9e mDNSResponder: Default: mDNSResponder (Engineering Build) (Aug  2 2024 16:28:17) starting
Aug  5 20:48:23 2a45fc7d7e9e rsyslogd: rsyslogd's groupid changed to 101
Aug  5 20:48:23 2a45fc7d7e9e rsyslogd: rsyslogd's userid changed to 101
Aug  5 20:48:23 2a45fc7d7e9e rsyslogd:  [origin software="rsyslogd" swVersion="8.32.0" x-pid="98" x-info="http://www.rsyslog.com"] start
Aug  5 20:48:24 2a45fc7d7e9e otbr-web[172]: [INFO]-WEB-----: Running 0.3.0-da1f867
Aug  5 20:48:24 2a45fc7d7e9e otbr-web[172]: [INFO]-WEB-----: Border router web started on wpan0
Aug  5 20:48:24 2a45fc7d7e9e otbr-web[172]: [ERR ]-WEB-----: OpenThread daemon is not running.
Aug  5 20:48:24 2a45fc7d7e9e otbr-agent: [NOTE]-AGENT---: Backbone interface: eth0
Aug  5 20:48:24 2a45fc7d7e9e otbr-agent[199]: [NOTE]-AGENT---: Running 0.3.0-da1f867
Aug  5 20:48:24 2a45fc7d7e9e otbr-agent[199]: [NOTE]-AGENT---: Thread version: 1.3.0
Aug  5 20:48:24 2a45fc7d7e9e otbr-agent[199]: [NOTE]-AGENT---: Thread interface: wpan0
Aug  5 20:48:24 2a45fc7d7e9e otbr-agent[199]: [NOTE]-AGENT---: Radio URL: spinel+hdlc+uart:///dev/ttyACM1
Aug  5 20:48:24 2a45fc7d7e9e otbr-agent[199]: [NOTE]-ILS-----: Infra link selected: eth0
Aug  5 20:48:24 2a45fc7d7e9e otbr-agent[199]: [INFO]-RCP_HOS-: OpenThread log level changed to 5
Aug  5 20:48:24 2a45fc7d7e9e otbr-agent[199]: 58d.21:22:42.935 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:0, cmd:RESET
Aug  5 20:48:24 2a45fc7d7e9e otbr-agent[199]: 58d.21:22:42.935 [D] P-SpinelDrive-: Waiting response: key=0
Aug  5 20:48:26 2a45fc7d7e9e otbr-agent[199]: 58d.21:22:44.937 [W] P-SpinelDrive-: Wait for response timeout
Aug  5 20:48:26 2a45fc7d7e9e otbr-agent[199]: 58d.21:22:44.937 [I] P-SpinelDrive-: co-processor self reset successfully
Aug  5 20:48:26 2a45fc7d7e9e otbr-agent[199]: 58d.21:22:44.937 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:1, cmd:PROP_VALUE_GET, key:PROTOCOL_VERSION
Aug  5 20:48:26 2a45fc7d7e9e otbr-agent[199]: 58d.21:22:44.938 [D] P-SpinelDrive-: Waiting response: key=1
Aug  5 20:48:28 2a45fc7d7e9e otbr-agent[199]: 58d.21:22:46.940 [W] P-SpinelDrive-: Wait for response timeout
Aug  5 20:48:28 2a45fc7d7e9e otbr-agent[199]: 58d.21:22:46.940 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:1, cmd:PROP_VALUE_GET, key:PROTOCOL_VERSION
Aug  5 20:48:28 2a45fc7d7e9e otbr-agent[199]: 58d.21:22:46.940 [D] P-SpinelDrive-: Waiting response: key=1
Aug  5 20:48:30 2a45fc7d7e9e otbr-agent[199]: 58d.21:22:48.942 [W] P-SpinelDrive-: Wait for response timeout
Aug  5 20:48:30 2a45fc7d7e9e otbr-agent[199]: 58d.21:22:48.942 [C] Platform------: Init() at spinel_driver.cpp:82: Failure
Aug  5 20:48:30 2a45fc7d7e9e otbr-agent[199]: 58d.21:22:48.943 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:1, cmd:PROP_VALUE_GET, key:PROTOCOL_VERSION
Aug  5 20:48:30 2a45fc7d7e9e otbr-agent[199]: 58d.21:22:48.943 [D] P-SpinelDrive-: Waiting response: key=1
Aug  5 20:48:32 2a45fc7d7e9e otbr-agent[199]: 58d.21:22:50.945 [W] P-SpinelDrive-: Wait for response timeout
lukeotto commented 3 months ago

I do have the same problem while using a ESP32-C6 with the most recent rcp image connected via USB ot_rcp

2024-08-05T22:33:06.572147+01:00 otbr2 otbr-agent: [NOTE]-AGENT---: Backbone interface: wlan0
2024-08-05T22:33:06.572485+01:00 otbr2 otbr-agent[9110]: [NOTE]-AGENT---: Running 0.3.0-thread-reference-20230710-339-gda1f867030
2024-08-05T22:33:06.572623+01:00 otbr2 otbr-agent[9110]: [NOTE]-AGENT---: Thread version: 1.3.0
2024-08-05T22:33:06.572718+01:00 otbr2 otbr-agent[9110]: [NOTE]-AGENT---: Thread interface: wpan0
2024-08-05T22:33:06.572795+01:00 otbr2 otbr-agent[9110]: [NOTE]-AGENT---: Radio URL: spinel+hdlc+uart:///dev/ttyACM0?uart-baudrate=460800
2024-08-05T22:33:06.572877+01:00 otbr2 otbr-agent[9110]: [NOTE]-AGENT---: Radio URL: trel://wlan0
2024-08-05T22:33:06.572948+01:00 otbr2 otbr-agent[9110]: [NOTE]-ILS-----: Infra link selected: wlan0
2024-08-05T22:33:06.573046+01:00 otbr2 otbr-agent[9110]: [INFO]-RCP_HOS-: OpenThread log level changed to 4
2024-08-05T22:33:08.576571+01:00 otbr2 otbr-agent[9110]: 49d.19:00:21.954 [W] P-SpinelDrive-: Wait for response timeout
2024-08-05T22:33:08.576760+01:00 otbr2 otbr-agent[9110]: 49d.19:00:21.954 [I] P-SpinelDrive-: co-processor self reset successfully
2024-08-05T22:33:10.578648+01:00 otbr2 otbr-agent[9110]: 49d.19:00:23.956 [W] P-SpinelDrive-: Wait for response timeout
2024-08-05T22:33:12.581322+01:00 otbr2 otbr-agent[9110]: 49d.19:00:25.958 [W] P-SpinelDrive-: Wait for response timeout
2024-08-05T22:33:12.581681+01:00 otbr2 otbr-agent[9110]: 49d.19:00:25.958 [C] Platform------: Init() at spinel_driver.cpp:82: Failure
2024-08-05T22:33:14.583655+01:00 otbr2 otbr-agent[9110]: 49d.19:00:27.960 [W] P-SpinelDrive-: Wait for response timeout
ihidchaos commented 3 months ago

Perhaps you can refer to this link to try adding flow control parameters.

scratchclaggy commented 3 months ago

@ihidchaos Thanks, I can confirm that this works! TLDR: edit /etc/default/otbr so that it includes the following or similar:

OTBR_AGENT_OPTS="-I wpan0 -B eth0 spinel+hdlc+uart:///dev/ttyACM0?uart-flow-control trel://eth0"