RCP fails on Nordic nRF52840 DK about ot-nrf528xx HOT 4 CLOSED

Hello @marcorussi

I followed all the steps you described on the same commits, and unfortunately, I am not able to reproduce this issue.

Could you please run ot-deamon with verbose logging?
sudo ./build/posix/src/posix/ot-daemon -v -d 5 'spinel+hdlc+uart:///dev/ttyACM0?uart-baudrate=115200'

I've looked at the code, and as far as I can see, this specific log Unexpected RCP reset: RESET_POWER_ON is visible when RCP gets the SPINEL_CMD_RESET command from the host, and replies with RESET_POWER_ON status.

The only place, where ot-daemon sends the SPINEL_CMD_RESET command is on its initialization. And actually, I see the same logs, when i execute this command in two Linux consolas.
sudo ./build/posix/src/posix/ot-daemon -v 'spinel+hdlc+uart:///dev/ttyACM0?uart-baudrate=115200'

Maybe you have some process in the background that tries to access the serial port (e.g. another ot-daemon or ot-br-posix)?

from ot-nrf528xx.

Hello @LuDuda , thank you for investigating. Here the output of 2 consecutive attempts.

Attempt no.1
sudo ./build/posix/src/posix/ot-daemon -v -d 5 'spinel+hdlc+uart:///dev/ttyACM0?uart-baudrate=115200' [sudo] password for marco: ./build/posix/src/posix/ot-daemon[3669]: Running OPENTHREAD/thread-reference-20200818-1740-g33cc75ed3; POSIX; Jun 2 2022 10:50:13 ./build/posix/src/posix/ot-daemon[3669]: Thread version: 4 ./build/posix/src/posix/ot-daemon[3669]: 49d.17:05:46.374 [D] Platform------: Wait response: tid=0 key=0 ./build/posix/src/posix/ot-daemon[3669]: 49d.17:05:46.385 [I] Platform------: RCP reset: RESET_POWER_ON ./build/posix/src/posix/ot-daemon[3669]: 49d.17:05:46.385 [D] Platform------: Wait response: tid=1 key=1 ./build/posix/src/posix/ot-daemon[3669]: 49d.17:05:46.385 [D] Platform------: Wait response: tid=2 key=2 ./build/posix/src/posix/ot-daemon[3669]: 49d.17:05:46.386 [D] Platform------: Wait response: tid=3 key=8 ./build/posix/src/posix/ot-daemon[3669]: 49d.17:05:46.387 [D] Platform------: Wait response: tid=4 key=5 ./build/posix/src/posix/ot-daemon[3669]: 49d.17:05:46.387 [D] Platform------: Wait response: tid=5 key=176 ./build/posix/src/posix/ot-daemon[3669]: 49d.17:05:46.388 [N] Platform------: RCP API Version: 6 ./build/posix/src/posix/ot-daemon[3669]: 49d.17:05:46.388 [D] Platform------: Wait response: tid=6 key=4619 ./build/posix/src/posix/ot-daemon[3669]: 00:00:00.000 [D] Platform------: Wait response: tid=7 key=34 ./build/posix/src/posix/ot-daemon[3669]: 00:00:00.001 [D] Platform------: Wait response: tid=8 key=32 ./build/posix/src/posix/ot-daemon[3669]: 00:00:00.001 [D] Platform------: Wait response: tid=9 key=54 ./build/posix/src/posix/ot-daemon[3669]: 00:00:00.001 [D] Platform------: Wait response: tid=10 key=53 ./build/posix/src/posix/ot-daemon[3669]: 00:00:00.001 [D] Platform------: Wait response: tid=11 key=39 ./build/posix/src/posix/ot-daemon[3669]: 00:00:00.002 [D] SubMac--------: RadioState: Disabled -> Sleep ./build/posix/src/posix/ot-daemon[3669]: 00:00:00.002 [D] Platform------: Wait response: tid=12 key=2048 ./build/posix/src/posix/ot-daemon[3669]: 00:00:00.002 [D] Platform------: Wait response: tid=13 key=52 ./build/posix/src/posix/ot-daemon[3669]: 00:00:00.003 [D] SubMac--------: RadioExtAddress: 22a0e6830ff77b76 ./build/posix/src/posix/ot-daemon[3669]: 00:00:00.003 [D] Platform------: Wait response: tid=14 key=53 ./build/posix/src/posix/ot-daemon[3669]: 00:00:00.003 [D] SubMac--------: RadioShortAddress: 0xfffe ./build/posix/src/posix/ot-daemon[3669]: 00:00:00.003 [D] Platform------: Wait response: tid=15 key=4868 ./build/posix/src/posix/ot-daemon[3669]: 00:00:00.003 [D] Platform------: Wait response: tid=1 key=4869 ./build/posix/src/posix/ot-daemon[3669]: 00:00:00.003 [D] SrcMatchCtrl--: Cleared all entries ./build/posix/src/posix/ot-daemon[3669]: Thread interface: wpan0 ./build/posix/src/posix/ot-daemon[3669]: RCP version: OPENTHREAD/thread-reference-20200818-1740-g33cc75ed3; NRF52840; Jun 2 2022 14:25:49 ./build/posix/src/posix/ot-daemon[3669]: 00:00:00.005 [I] Notifier------: StateChanged (0x00038200) [NetData PanId NetName ExtPanId] ./build/posix/src/posix/ot-daemon[3669]: 00:00:00.005 [D] Platform------: Trying to get RCP time offset ./build/posix/src/posix/ot-daemon[3669]: 00:00:00.005 [D] Platform------: Wait response: tid=2 key=2050 ./build/posix/src/posix/ot-daemon[3669]: 00:00:00.005 [I] Platform------: [netif] Host netif is down ./build/posix/src/posix/ot-daemon[3669]: 00:00:03.167 [W] Platform------: Unexpected Spinel transaction message: 1 ./build/posix/src/posix/ot-daemon[3669]: 00:00:03.167 [W] Platform------: Error processing response: Drop

Attempt no.2
sudo ./build/posix/src/posix/ot-daemon -v -d 5 'spinel+hdlc+uart:///dev/ttyACM0?uart-baudrate=115200' ./build/posix/src/posix/ot-daemon[4017]: Running OPENTHREAD/thread-reference-20200818-1740-g33cc75ed3; POSIX; Jun 2 2022 10:50:13 ./build/posix/src/posix/ot-daemon[4017]: Thread version: 4 ./build/posix/src/posix/ot-daemon[4017]: 49d.17:07:48.093 [D] Platform------: Wait response: tid=0 key=0 ./build/posix/src/posix/ot-daemon[4017]: 49d.17:07:48.103 [I] Platform------: RCP reset: RESET_POWER_ON ./build/posix/src/posix/ot-daemon[4017]: 49d.17:07:48.103 [D] Platform------: Wait response: tid=1 key=1 ./build/posix/src/posix/ot-daemon[4017]: 49d.17:07:48.103 [D] Platform------: Wait response: tid=2 key=2 ./build/posix/src/posix/ot-daemon[4017]: 49d.17:07:48.104 [D] Platform------: Wait response: tid=3 key=8 ./build/posix/src/posix/ot-daemon[4017]: 49d.17:07:48.105 [D] Platform------: Wait response: tid=4 key=5 ./build/posix/src/posix/ot-daemon[4017]: 49d.17:07:48.105 [D] Platform------: Wait response: tid=5 key=176 ./build/posix/src/posix/ot-daemon[4017]: 49d.17:07:48.106 [N] Platform------: RCP API Version: 6 ./build/posix/src/posix/ot-daemon[4017]: 49d.17:07:48.106 [D] Platform------: Wait response: tid=6 key=4619 ./build/posix/src/posix/ot-daemon[4017]: 00:00:00.001 [D] Platform------: Wait response: tid=7 key=34 ./build/posix/src/posix/ot-daemon[4017]: 00:00:00.002 [D] Platform------: Wait response: tid=8 key=32 ./build/posix/src/posix/ot-daemon[4017]: 00:00:00.002 [D] Platform------: Wait response: tid=9 key=54 ./build/posix/src/posix/ot-daemon[4017]: 00:00:00.003 [D] Platform------: Wait response: tid=10 key=53 ./build/posix/src/posix/ot-daemon[4017]: 00:00:00.003 [D] Platform------: Wait response: tid=11 key=39 ./build/posix/src/posix/ot-daemon[4017]: 00:00:00.004 [D] SubMac--------: RadioState: Disabled -> Sleep ./build/posix/src/posix/ot-daemon[4017]: 00:00:00.004 [D] Platform------: Wait response: tid=12 key=2048 ./build/posix/src/posix/ot-daemon[4017]: 00:00:00.004 [D] Platform------: Wait response: tid=13 key=52 ./build/posix/src/posix/ot-daemon[4017]: 00:00:00.005 [D] SubMac--------: RadioExtAddress: 2a6af97848f8f3ee ./build/posix/src/posix/ot-daemon[4017]: 00:00:00.005 [D] Platform------: Wait response: tid=14 key=53 ./build/posix/src/posix/ot-daemon[4017]: 00:00:00.005 [D] SubMac--------: RadioShortAddress: 0xfffe ./build/posix/src/posix/ot-daemon[4017]: 00:00:00.005 [D] Platform------: Wait response: tid=15 key=4868 ./build/posix/src/posix/ot-daemon[4017]: 00:00:00.005 [D] Platform------: Wait response: tid=1 key=4869 ./build/posix/src/posix/ot-daemon[4017]: 00:00:00.005 [D] SrcMatchCtrl--: Cleared all entries ./build/posix/src/posix/ot-daemon[4017]: Thread interface: wpan0 ./build/posix/src/posix/ot-daemon[4017]: RCP version: OPENTHREAD/thread-reference-20200818-1740-g33cc75ed3; NRF52840; Jun 2 2022 14:25:49 ./build/posix/src/posix/ot-daemon[4017]: 00:00:00.006 [I] Notifier------: StateChanged (0x00038200) [NetData PanId NetName ExtPanId] ./build/posix/src/posix/ot-daemon[4017]: 00:00:00.006 [D] Platform------: Trying to get RCP time offset ./build/posix/src/posix/ot-daemon[4017]: 00:00:00.006 [D] Platform------: Wait response: tid=2 key=2050 ./build/posix/src/posix/ot-daemon[4017]: 00:00:00.006 [I] Platform------: [netif] Host netif is down ./build/posix/src/posix/ot-daemon[4017]: 00:00:07.433 [C] Platform------: Unexpected RCP reset: RESET_POWER_ON ./build/posix/src/posix/ot-daemon[4017]: 00:00:07.433 [W] Platform------: RCP failure detected ./build/posix/src/posix/ot-daemon[4017]: 00:00:07.433 [W] Platform------: Trying to recover (1/2) ./build/posix/src/posix/ot-daemon[4017]: 00:00:07.433 [D] Platform------: Wait response: tid=0 key=0 ./build/posix/src/posix/ot-daemon[4017]: 00:00:07.434 [I] Platform------: RCP reset: RESET_POWER_ON ./build/posix/src/posix/ot-daemon[4017]: 00:00:07.434 [D] Platform------: Wait response: tid=1 key=32 ./build/posix/src/posix/ot-daemon[4017]: 00:00:07.434 [D] Platform------: Wait response: tid=2 key=54 ./build/posix/src/posix/ot-daemon[4017]: 00:00:07.434 [D] Platform------: Wait response: tid=3 key=53 ./build/posix/src/posix/ot-daemon[4017]: 00:00:07.435 [D] Platform------: Wait response: tid=4 key=52 ./build/posix/src/posix/ot-daemon[4017]: 00:00:07.435 [D] Platform------: Wait response: tid=5 key=33 ./build/posix/src/posix/ot-daemon[4017]: 00:00:07.435 [D] Platform------: Wait response: tid=6 key=2048 ./build/posix/src/posix/ot-daemon[4017]: 00:00:07.436 [C] Platform------: RestoreProperties() at radio_spinel_impl.hpp:2340: Failure

How can I check if there is anything running in the background?
Thank you.

from ot-nrf528xx.

Hello again @LuDuda . Yes, I think I have an ot-br-posix service running all the time. As I stopped it, the RCP became stable: both ot-daemon and ot-ctl do not crash. I then found that my ot-br-posix was built from an old commit (8aa5377 of https://github.com/openthread/ot-br-posix.git). So it could have to do with a sort of "incompatibility" between the RCP (built from latest main) and the ot-br-posix.
I am going to re-build the ot-br-posix with the latest main and try again. I'll keep you updated.
Thank you.

from ot-nrf528xx.

So, after rebuilding the ot-br-posix service, it seems that it gets in active (running) state. I think this means that the RPC is fine.
I might come across into another problem soon but I'd say that the initial issue raised here is gone.
Thank you for your help.
Cheers.

from ot-nrf528xx.