Skip to content

[CC2652R RCP] OTBR crashes when trying to add a device #7

@samuliHeikkinen

Description

@samuliHeikkinen

Hello!

To start of massive thank you, for the work you've done!

There is something funny with the RCP firmware for CC2652R. I can setup OTBR completely fine and get a Thread network running and all is good on HA side as well, but once I try to add a device to the network, otbr-agent fails panics and shuts down. Any ideas?

otbr  | 00:00:37.307 [I] MeshForwarder-:     src:[fe80:0:0:0:1498:9f0e:d3b3:9cfd]:19788
otbr  | 00:00:37.307 [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
otbr  | 00:00:37.324 [I] P-Netif-------: Message dropped by Thread
otbr  | 00:00:37.325 [I] P-Netif-------: ADD [M] ff03::2 (already subscribed, ignored)
otbr  | 00:00:37.325 [I] P-Netif-------: ADD [M] ff02::2 (already subscribed, ignored)
otbr  | 00:00:37.325 [I] P-Netif-------: ADD [M] ff33:40:fd79:7580:4ee6:18a0:0:1 (already subscribed, ignored)
otbr  | 00:00:37.325 [I] P-Netif-------: ADD [M] ff32:40:fd79:7580:4ee6:18a0:0:1 (already subscribed, ignored)
otbr  | 00:00:37.325 [I] P-Netif-------: ADD [M] ff03::fc (already subscribed, ignored)
otbr  | 00:00:37.325 [I] P-Netif-------: ADD [M] ff03::1 (already subscribed, ignored)
otbr  | 00:00:37.325 [I] P-Netif-------: ADD [M] ff02::16 (already subscribed, ignored)
otbr  | 00:00:37.325 [I] P-Netif-------: ADD [M] ff03::2 (already subscribed, ignored)
otbr  | 00:00:37.325 [I] P-Netif-------: ADD [M] ff02::2 (already subscribed, ignored)
otbr  | 00:00:37.325 [I] P-Netif-------: ADD [M] ff33:40:fd79:7580:4ee6:18a0:0:1 (already subscribed, ignored)
otbr  | 00:00:37.325 [I] P-Netif-------: ADD [M] ff32:40:fd79:7580:4ee6:18a0:0:1 (already subscribed, ignored)
otbr  | 00:00:37.325 [I] P-Netif-------: ADD [M] ff03::fc (already subscribed, ignored)
otbr  | 00:00:37.325 [I] P-Netif-------: ADD [M] ff03::1 (already subscribed, ignored)
otbr  | 00:00:37.325 [I] P-Netif-------: ADD [M] ff02::16 (already subscribed, ignored)
otbr  | 00:00:38.467 [I] BorderRouting-: RsSender: Sent RS 2/3
otbr  | 00:00:38.716 [I] MlrManager----: MLR Reregister!
otbr  | 00:00:39.228 [I] BorderRouting-: Evaluating routing policy
otbr  | 00:00:39.228 [I] BorderRouting-: Evaluating NAT64 prefix
otbr  | 00:00:39.228 [I] BorderRouting-: Will evaluate routing policy in 00:14.244 (14244 msec)
otbr  | 00:00:40.556 [I] Mle-----------: Send Advertisement (ff02:0:0:0:0:0:0:1)
otbr  | 00:00:40.557 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:2, cmd:PROP_VALUE_SET, key:STREAM_RAW, len:69, channel:15, maxbackoffs:4, maxretries:15 ...
otbr  | 00:00:40.557 [D] P-SpinelDrive-: ... csmaCaEnabled:1, isHeaderUpdated:0, isARetx:0, skipAes:0, txDelay:0, txDelayBase:0
otbr  | 00:00:40.566 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:2, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
otbr  | 00:00:40.566 [I] MeshForwarder-: Sent IPv6 UDP msg, len:90, chksum:9bf4, ecn:no, to:0xffff, sec:no, prio:net, radio:all
otbr  | 00:00:40.566 [I] MeshForwarder-:     src:[fe80:0:0:0:1498:9f0e:d3b3:9cfd]:19788
otbr  | 00:00:40.567 [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
otbr  | 00:00:42.467 [I] BorderRouting-: RsSender: Sent RS 3/3
otbr  | 00:00:43.467 [I] BorderRouting-: RsSender: Finished sending RS msgs and waiting for RAs
otbr  | 00:00:43.467 [I] BorderRouting-: Will evaluate routing policy immediately
otbr  | 00:00:43.467 [I] BorderRouting-: Evaluating routing policy
otbr  | 00:00:43.467 [I] BorderRouting-: Local on-link prefix state: Deprecating -> Publishing (fd0e:ed26:2c78:7769::/64)
otbr  | 00:00:43.467 [I] BorderRouting-: Local on-link prefix state: Publishing -> Advertising (fd0e:ed26:2c78:7769::/64)
otbr  | 00:00:43.467 [I] BorderRouting-: Favored on-link prefix: ::/0 -> fd0e:ed26:2c78:7769::/64
otbr  | 00:00:43.467 [I] BorderRouting-: Evaluating NAT64 prefix
otbr  | 00:00:43.467 [I] BorderRouting-: Preparing RA
otbr  | 00:00:43.467 [I] BorderRouting-: - RA Header - flags - M:0 O:0 S:1
otbr  | 00:00:43.467 [I] BorderRouting-: - RA Header - default route - lifetime:0
otbr  | 00:00:43.468 [I] BorderRouting-: - PIO fd0e:ed26:2c78:7769::/64 (valid:1800, preferred:1800, flags - L:1 A:1 P:0)
otbr  | 00:00:43.468 [I] BorderRouting-: - RIO fd08:58c9:6c2e:1::/64 (lifetime:1800, prf:medium)
otbr  | 00:00:43.468 [I] BorderRouting-: Sent RA on infra netif 2
otbr  | 00:00:43.468 [I] SrpServer-----: Selected port 53536
otbr  | 00:00:43.468 [I] NetDataPublshr: Publishing DNS/SRP service unicast (ml-eid, port:53536, ver:0)
otbr  | 00:00:43.468 [I] NetDataPublshr: DNS/SRP service - State: NoEntry -> ToAdd
otbr  | 00:00:43.468 [I] NetDataPublshr: DNS/SRP service (state:ToAdd) in netdata - total:0, preferred:0, desired:2
otbr  | 00:00:43.468 [I] NetDataPublshr: DNS/SRP service - State: ToAdd -> Adding
otbr  | 00:00:43.468 [I] NetDataPublshr: DNS/SRP service (state:Adding) - update in 3208 msec
otbr  | 00:00:43.468 [I] BorderRouting-: Will evaluate routing policy in 00:15.729 (15729 msec)
otbr  | 00:00:43.469 [I] BorderRouting-: Received RA from fe80:0:0:0:e65f:1ff:fe46:f8f0 on infra netif 2 (this BR routing-manager)
otbr  | 00:00:44.115 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:63, rssi:-36 ...
otbr  | 00:00:44.115 [D] P-SpinelDrive-: ... noise:-128, flags:0x0000, channel:15, lqi:187, timestamp:47184007, rxerr:0
otbr  | 00:00:44.116 [I] MeshForwarder-: Received IPv6 UDP msg, len:84, chksum:060b, ecn:no, from:7efbd53be1e72377, sec:no, prio:net, rss:-36.0, radio:15.4
otbr  | 00:00:44.116 [I] MeshForwarder-:     src:[fe80:0:0:0:7cfb:d53b:e1e7:2377]:19788
otbr  | 00:00:44.116 [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:2]:19788
otbr  | 00:00:44.116 [I] RadioSelector-: RadioSelector: NewRadio(OnRx) 15.4 - neighbor:[7efbd53be1e72377 rloc16:0x8001 radio-pref:{15.4:200} state:Restored]
otbr  | 00:00:44.116 [I] Mle-----------: Receive Parent Request (fe80:0:0:0:7cfb:d53b:e1e7:2377)
otbr  | 00:00:44.116 [I] Mle-----------: Delay Parent Response (fe80:0:0:0:7cfb:d53b:e1e7:2377)
otbr  | 00:00:44.217 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:3, cmd:PROP_VALUE_SET, key:RCP_MAC_FRAME_COUNTER, counter:8002
otbr  | 00:00:44.217 [D] P-RadioSpinel-: Wait response: tid=3 key=2049
otbr  | 00:00:44.220 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:3, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
otbr  | 00:00:44.220 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:4, cmd:PROP_VALUE_GET, key:CSL_ACCURACY
otbr  | 00:00:44.220 [D] P-RadioSpinel-: Wait response: tid=4 key=2052
otbr  | 00:00:44.223 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:4, cmd:PROP_VALUE_IS, key:CSL_ACCURACY, accuracy:10
otbr  | 00:00:44.223 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:5, cmd:PROP_VALUE_GET, key:CSL_UNCERTAINTY
otbr  | 00:00:44.223 [D] P-RadioSpinel-: Wait response: tid=5 key=2053
otbr  | 00:00:44.226 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:5, cmd:PROP_VALUE_IS, key:CSL_UNCERTAINTY, uncertainty:80
otbr  | 00:00:44.226 [I] Mle-----------: Send Parent Response (fe80:0:0:0:7cfb:d53b:e1e7:2377)
otbr  | 00:00:44.227 [D] RadioSelector-: RadioSelector: SelectRadio 15.4 - neighbor:[7efbd53be1e72377 rloc16:0x8001 radio-pref:{15.4:200} state:Restored]
otbr  | 00:00:44.228 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:6, cmd:PROP_VALUE_SET, key:STREAM_RAW, len:117, channel:15, maxbackoffs:4, maxretries:15 ...
otbr  | 00:00:44.228 [D] P-SpinelDrive-: ... csmaCaEnabled:1, isHeaderUpdated:0, isARetx:0, skipAes:0, txDelay:0, txDelayBase:0
otbr  | 00:00:44.241 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:6, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
otbr  | 00:00:44.241 [I] RadioSelector-: RadioSelector: UpdateOnTxSucc 15.4 - neighbor:[7efbd53be1e72377 rloc16:0x8001 radio-pref:{15.4:225} state:Restored]
otbr  | 00:00:44.241 [I] MeshForwarder-: Sent IPv6 UDP msg, len:133, chksum:5121, ecn:no, to:7efbd53be1e72377, sec:no, prio:net, radio:15.4
otbr  | 00:00:44.241 [I] MeshForwarder-:     src:[fe80:0:0:0:1498:9f0e:d3b3:9cfd]:19788
otbr  | 00:00:44.241 [I] MeshForwarder-:     dst:[fe80:0:0:0:7cfb:d53b:e1e7:2377]:19788
otbr  | 00:00:44.876 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:112, rssi:-36 ...
otbr  | 00:00:44.876 [D] P-SpinelDrive-: ... noise:-128, flags:0x0000, channel:15, lqi:187, timestamp:47941498, rxerr:0
otbr  | 00:00:44.877 [I] MeshForwarder-: Received IPv6 UDP msg, len:128, chksum:e517, ecn:no, from:7efbd53be1e72377, sec:no, prio:net, rss:-36.0, radio:15.4
otbr  | 00:00:44.877 [I] MeshForwarder-:     src:[fe80:0:0:0:7cfb:d53b:e1e7:2377]:19788
otbr  | 00:00:44.877 [I] MeshForwarder-:     dst:[fe80:0:0:0:1498:9f0e:d3b3:9cfd]:19788
otbr  | 00:00:44.877 [D] RadioSelector-: RadioSelector: UpdateOnRx 15.4 - neighbor:[7efbd53be1e72377 rloc16:0x8001 radio-pref:{15.4:240} state:Restored]
otbr  | 00:00:44.877 [I] Mle-----------: Receive Child ID Request (fe80:0:0:0:7cfb:d53b:e1e7:2377)
otbr  | 00:00:44.877 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:7, cmd:PROP_VALUE_REMOVE, key:MAC_SRC_MATCH_SHORT_ADDRESSES, saddr:0x8001
otbr  | 00:00:44.877 [D] P-RadioSpinel-: Wait response: tid=7 key=4868
otbr  | 00:00:44.880 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:7, cmd:PROP_VALUE_REMOVED, key:MAC_SRC_MATCH_SHORT_ADDRESSES, saddr:0x8001
otbr  | 00:00:44.880 [I] Mle-----------: Child 0x8001 IPv6 address[1]=fd79:7580:4ee6:18a0:d8a1:a4e7:e1d0:6f13
otbr  | 00:00:44.881 [I] Mle-----------: Child 0x8001 has 1 registered IPv6 address, 1 address stored
otbr  | 00:00:44.881 [I] Settings------: Read ChildInfo {rloc:0x8001, extaddr:7efbd53be1e72377, timeout:240, mode:0x04, version:4}
otbr  | 00:00:44.889 [I] Settings------: Removed ChildInfo {rloc:0x8001, extaddr:7efbd53be1e72377, timeout:240, mode:0x04, version:4}
otbr  | 00:00:44.896 [I] Settings------: Added ChildInfo {rloc:0x8001, extaddr:7efbd53be1e72377, timeout:240, mode:0x04, version:4}
otbr  | 00:00:44.897 [I] Mle-----------: Send Child ID Response (fe80:0:0:0:7cfb:d53b:e1e7:2377,0x8001)
otbr  | 00:00:44.897 [I] Notifier------: StateChanged (0x00000400) [Child+]
otbr  | 00:00:44.897 [I] ChildSupervsn-: Starting Child Supervision
otbr  | 00:00:44.897 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:8, cmd:PROP_VALUE_INSERT, key:MAC_SRC_MATCH_EXTENDED_ADDRESSES, extaddr:7efbd53be1e72377
otbr  | 00:00:44.897 [D] P-RadioSpinel-: Wait response: tid=8 key=4869
otbr  | 00:00:44.900 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:8, cmd:PROP_VALUE_INSERTED, key:MAC_SRC_MATCH_EXTENDED_ADDRESSES, extaddr:7efbd53be1e72377
otbr  | 00:00:44.901 [I] MeshForwarder-: Prepping indir tx IPv6 UDP msg, len:169, chksum:03d6, ecn:no, to:7efbd53be1e72377, sec:no, prio:net, radio:all
otbr  | 00:00:44.982 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:34, rssi:-35 ...
otbr  | 00:00:44.982 [D] P-SpinelDrive-: ... noise:-128, flags:0x0010, channel:15, lqi:191, timestamp:48051673, rxerr:0
otbr  | 00:00:44.982 [D] RadioSelector-: RadioSelector: UpdateOnRx 15.4 - neighbor:[7efbd53be1e72377 rloc16:0x8001 radio-pref:{15.4:255} state:Valid]
otbr  | 00:00:44.982 [I] DataPollHandlr: Rx data poll, src:0x8001, qed_msgs:1, rss:-35, ack-fp:1
otbr  | 00:00:44.982 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:9, cmd:PROP_VALUE_SET, key:STREAM_RAW, len:126, channel:15, maxbackoffs:4, maxretries:0 ...
otbr  | 00:00:44.982 [D] P-SpinelDrive-: ... csmaCaEnabled:1, isHeaderUpdated:0, isARetx:0, skipAes:0, txDelay:0, txDelayBase:0
otbr  | 00:00:44.998 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:9, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
otbr  | 00:00:44.998 [D] RadioSelector-: RadioSelector: UpdateOnTxSucc 15.4 - neighbor:[7efbd53be1e72377 rloc16:0x8001 radio-pref:{15.4:255} state:Valid]
otbr  | 00:00:45.005 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:34, rssi:-35 ...
otbr  | 00:00:45.005 [D] P-SpinelDrive-: ... noise:-128, flags:0x0010, channel:15, lqi:191, timestamp:48075130, rxerr:0
otbr  | 00:00:45.005 [D] RadioSelector-: RadioSelector: UpdateOnRx 15.4 - neighbor:[7efbd53be1e72377 rloc16:0x8001 radio-pref:{15.4:255} state:Valid]
otbr  | 00:00:45.005 [I] DataPollHandlr: Rx data poll, src:0x8001, qed_msgs:1, rss:-35, ack-fp:1
otbr  | 00:00:45.006 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:10, cmd:PROP_VALUE_SET, key:STREAM_RAW, len:79, channel:15, maxbackoffs:4, maxretries:0 ...
otbr  | 00:00:45.006 [D] P-SpinelDrive-: ... csmaCaEnabled:1, isHeaderUpdated:0, isARetx:0, skipAes:0, txDelay:0, txDelayBase:0
otbr  | 00:00:45.018 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:10, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
otbr  | 00:00:45.018 [D] RadioSelector-: RadioSelector: UpdateOnTxSucc 15.4 - neighbor:[7efbd53be1e72377 rloc16:0x8001 radio-pref:{15.4:255} state:Valid]
otbr  | 00:00:45.018 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:11, cmd:PROP_VALUE_REMOVE, key:MAC_SRC_MATCH_EXTENDED_ADDRESSES, extaddr:7efbd53be1e72377
otbr  | 00:00:45.018 [D] P-RadioSpinel-: Wait response: tid=11 key=4869
otbr  | 00:00:47.020 [W] P-RadioSpinel-: Wait for response timeout
otbr  | 00:00:47.028 [C] P-RadioSpinel-: Failed to communicate with RCP - no response from RCP during initialization
otbr  | 00:00:47.028 [C] P-RadioSpinel-: This is not a bug and typically due a config error (wrong URL parameters) or bad RCP image:
otbr  | 00:00:47.028 [C] P-RadioSpinel-: - Make sure RCP is running the correct firmware
otbr  | 00:00:47.028 [C] P-RadioSpinel-: - Double check the config parameters passed as `RadioURL` input
otbr  | 00:00:47.028 [C] Platform------: HandleRcpTimeout() at radio_spinel.cpp:2013: RadioSpinelNoResponse
otbr  | otbr-agent exited with code 6 (by signal 0).
otbr  | Chain OT_FORWARD_INGRESS (0 references)
otbr  | target     prot opt source               destination
otbr  | DROP       all  --  anywhere             anywhere             PKTTYPE = unicast
otbr  | DROP       all  --  anywhere             anywhere             match-set otbr-ingress-deny-src src
otbr  | ACCEPT     all  --  anywhere             anywhere             match-set otbr-ingress-allow-dst dst
otbr  | DROP       all  --  anywhere             anywhere             PKTTYPE = unicast
otbr  | ACCEPT     all  --  anywhere             anywhere
otbr  | otbr-ingress-deny-src
otbr  | otbr-ingress-deny-src-swap
otbr  | otbr-ingress-allow-dst
otbr  | otbr-ingress-allow-dst-swap
otbr  | OpenThread firewall rules removed.
otbr  | s6-rc: info: service legacy-services: stopping
otbr  | s6-rc: info: service legacy-services successfully stopped
otbr  | s6-rc: info: service otbr-web: stopping
otbr  | [CRIT]-WEB-----: Stopping web server
otbr  | otbr-web ended with exit code 0 (signal 0).
otbr  | s6-rc: info: service otbr-web successfully stopped
otbr  | s6-rc: info: service otbr-agent: stopping
otbr  | s6-rc: info: service otbr-agent successfully stopped
otbr  | s6-rc: info: service legacy-cont-init: stopping
otbr  | s6-rc: info: service legacy-cont-init successfully stopped
otbr  | s6-rc: info: service fix-attrs: stopping
otbr  | s6-rc: info: service fix-attrs successfully stopped
otbr  | s6-rc: info: service s6rc-oneshot-runner: stopping
otbr  | s6-rc: info: service s6rc-oneshot-runner successfully stopped
otbr exited with code 6

Here is the docker compose just for reference

services:
  otbr:
    image: openthread/border-router:latest
    container_name: otbr
    restart: unless-stopped
    network_mode: host

    # OTBR needs to configure interfaces/routes
    cap_add:
      - NET_ADMIN

    devices:
      - /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0
      - /dev/net/tun:/dev/net/tun

    volumes:
      - /var/lib/otbr:/data
      - /etc/localtime:/etc/localtime:ro

    environment:
      # RCP connection (your stick)
      OT_RCP_DEVICE: "spinel+hdlc+uart:///dev/serial/by-id/usb-1a86_USB_Serial-if00-port0?uart-baudrate=460800"

      # Pi uplink
      OT_INFRA_IF: "eth0"

After the crash the dongle needs to be plugged in again. Nothing else works.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions