Open thedevleon opened 11 months ago
Just had another crash after 3 days. Before the crash, we were sending a good amount of big packets, as 8 devices were receiving OTAs via CoAP block-wise transfer with a chunk size of 1024.
Nov 6 11:37:29 128f62455490 otbr-agent[200]: 2d.22:10:21.455 [D] P-RadioSpinel-: Received spinel frame, flg:0x2, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:123, rssi:-81 ...
Nov 6 11:37:29 128f62455490 otbr-agent[200]: 2d.22:10:21.455 [D] P-RadioSpinel-: ... noise:-128, flags:0x0000, channel:16, lqi:9, timestamp:938961714397, rxerr:0
Nov 6 11:37:29 128f62455490 otbr-agent[200]: 2d.22:10:21.459 [D] P-RadioSpinel-: Received spinel frame, flg:0x2, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:49, rssi:-80 ...
Nov 6 11:37:29 128f62455490 otbr-agent[200]: 2d.22:10:21.459 [D] P-RadioSpinel-: ... noise:-128, flags:0x0000, channel:16, lqi:11, timestamp:938961720156, rxerr:0
Nov 6 11:37:29 128f62455490 otbr-agent[200]: 2d.22:10:21.459 [I] MeshForwarder-: Received IPv6 UDP msg, len:135, chksum:d068, ecn:no, from:0xd400, sec:yes, prio:normal, rss:-80.5
Nov 6 11:37:29 128f62455490 otbr-agent[200]: 2d.22:10:21.460 [I] MeshForwarder-: src:[fd3a:c703:91ab:1:9ca8:2073:403a:f4bd]:34962
Nov 6 11:37:29 128f62455490 otbr-agent[200]: 2d.22:10:21.460 [I] MeshForwarder-: dst:[fd3a:c703:91ab:2:0:0:34f:5ca3]:5683
Nov 6 11:37:29 128f62455490 otbr-agent[200]: 2d.22:10:21.466 [D] P-RadioSpinel-: Received spinel frame, flg:0x2, tid:9, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
Nov 6 11:37:29 128f62455490 otbr-agent[200]: 2d.22:10:21.466 [W] P-RadioSpinel-: Handle radio frame failed: Parse
Nov 6 11:37:29 128f62455490 otbr-agent[200]: 2d.22:10:21.466 [W] P-RadioSpinel-: Handle transmit done failed: Parse
Nov 6 11:37:29 128f62455490 otbr-agent[200]: 2d.22:10:21.467 [C] Platform------: ------------------ BEGINNING OF CRASH -------------
Nov 6 11:37:29 128f62455490 otbr-agent[200]: 2d.22:10:21.467 [C] Platform------: *** FATAL ERROR: Caught signal: 6 (Aborted)
Nov 6 11:37:29 128f62455490 otbr-agent[200]: 2d.22:10:21.469 [C] Platform------: # 0: /usr/sbin/otbr-agent(+0x2bc6e0) [0x555b07c6e0]
Nov 6 11:37:29 128f62455490 otbr-agent[200]: 2d.22:10:21.469 [C] Platform------: ------------------ END OF CRASH ------------------
Yet another after 5 days:
Nov 8 22:34:43 8826213816e4 otbr-agent[200]: 5d.09:08:12.131 [D] P-RadioSpinel-: Received spinel frame, flg:0x2, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:44, rssi:-67 ...
Nov 8 22:34:43 8826213816e4 otbr-agent[200]: 5d.09:08:12.131 [D] P-RadioSpinel-: ... noise:-128, flags:0x0000, channel:15, lqi:10, timestamp:1154095791000, rxerr:0
Nov 8 22:34:43 8826213816e4 otbr-agent[200]: 5d.09:08:12.131 [I] MeshForwarder-: Received IPv6 UDP msg, len:322, chksum:9057, ecn:no, from:0xac00, sec:yes, prio:normal, rss:-66.625
Nov 8 22:34:43 8826213816e4 otbr-agent[200]: 5d.09:08:12.131 [I] MeshForwarder-: src:[fd9b:4dd6:b34d:1:7e24:5ec4:ecc8:235b]:55369
Nov 8 22:34:43 8826213816e4 otbr-agent[200]: 5d.09:08:12.132 [I] MeshForwarder-: dst:[fd9b:4dd6:b34d:2:0:0:34f:5ca3]:5683
Nov 8 22:34:43 8826213816e4 otbr-agent[200]: 5d.09:08:12.144 [D] P-RadioSpinel-: Received spinel frame, flg:0x2, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:123, rssi:-84 ...
Nov 8 22:34:43 8826213816e4 otbr-agent[200]: 5d.09:08:12.144 [D] P-RadioSpinel-: ... noise:-128, flags:0x0000, channel:15, lqi:10, timestamp:1154095802636, rxerr:0
Nov 8 22:34:43 8826213816e4 otbr-agent[200]: 5d.09:08:12.153 [D] P-RadioSpinel-: Received spinel frame, flg:0x2, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:122, rssi:-86 ...
Nov 8 22:34:43 8826213816e4 otbr-agent[200]: 5d.09:08:12.153 [D] P-RadioSpinel-: ... noise:-128, flags:0x0000, channel:15, lqi:9, timestamp:1154095811165, rxerr:0
Nov 8 22:34:44 8826213816e4 otbr-agent[200]: 5d.09:08:12.162 [D] P-RadioSpinel-: Received spinel frame, flg:0x2, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:122, rssi:-87 ...
Nov 8 22:34:44 8826213816e4 otbr-agent[200]: 5d.09:08:12.163 [D] P-RadioSpinel-: ... noise:-128, flags:0x0000, channel:15, lqi:9, timestamp:1154095820686, rxerr:0
Nov 8 22:34:44 8826213816e4 otbr-agent[200]: 5d.09:08:12.167 [D] P-RadioSpinel-: Received spinel frame, flg:0x2, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:38, rssi:-84 ...
Nov 8 22:34:44 8826213816e4 otbr-agent[200]: 5d.09:08:12.167 [D] P-RadioSpinel-: ... noise:-128, flags:0x0000, channel:15, lqi:9, timestamp:1154095827084, rxerr:0
Nov 8 22:34:44 8826213816e4 otbr-agent[200]: 5d.09:08:12.167 [I] MeshForwarder-: Received IPv6 UDP msg, len:316, chksum:8ef9, ecn:no, from:0xd800, sec:yes, prio:normal, rss:-85.125
Nov 8 22:34:44 8826213816e4 otbr-agent[200]: 5d.09:08:12.168 [I] MeshForwarder-: src:[fd9b:4dd6:b34d:1:3a61:fa47:c2a1:5b93]:61703
Nov 8 22:34:44 8826213816e4 otbr-agent[200]: 5d.09:08:12.168 [I] MeshForwarder-: dst:[fd9b:4dd6:b34d:2:0:0:34f:5ca3]:5683
Nov 8 22:34:44 8826213816e4 otbr-agent[200]: 5d.09:08:12.169 [D] P-RadioSpinel-: Sent spinel frame, flg:0x2, tid:3, cmd:PROP_VALUE_SET, key:STREAM_RAW, len:68, channel:15, maxbackoffs:4, maxretries:15 ...
Nov 8 22:34:44 8826213816e4 otbr-agent[200]: 5d.09:08:12.169 [D] P-RadioSpinel-: ... csmaCaEnabled:1, isHeaderUpdated:0, isARetx:0, skipAes:0, txDelay:0, txDelayBase:0
Nov 8 22:34:44 8826213816e4 otbr-agent[200]: 5d.09:08:12.196 [D] P-RadioSpinel-: Received spinel frame, flg:0x2, tid:3, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
Nov 8 22:34:44 8826213816e4 otbr-agent[200]: 5d.09:08:12.196 [I] MeshForwarder-: Sent IPv6 UDP msg, len:60, chksum:119d, ecn:no, to:0xac00, sec:yes, prio:low
Nov 8 22:34:44 8826213816e4 otbr-agent[200]: 5d.09:08:12.196 [I] MeshForwarder-: src:[fd9b:4dd6:b34d:2:0:0:34f:5ca3]:5683
Nov 8 22:34:44 8826213816e4 otbr-agent[200]: 5d.09:08:12.196 [I] MeshForwarder-: dst:[fd9b:4dd6:b34d:1:7e24:5ec4:ecc8:235b]:55369
Nov 8 22:34:44 8826213816e4 otbr-agent[200]: 5d.09:08:12.204 [D] P-RadioSpinel-: Sent spinel frame, flg:0x2, tid:4, cmd:PROP_VALUE_SET, key:STREAM_RAW, len:68, channel:15, maxbackoffs:4, maxretries:15 ...
Nov 8 22:34:44 8826213816e4 otbr-agent[200]: 5d.09:08:12.204 [D] P-RadioSpinel-: ... csmaCaEnabled:1, isHeaderUpdated:0, isARetx:0, skipAes:0, txDelay:0, txDelayBase:0
Nov 8 22:34:44 8826213816e4 otbr-agent[200]: 5d.09:08:12.226 [D] P-RadioSpinel-: Received spinel frame, flg:0x2, tid:4, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
Nov 8 22:34:44 8826213816e4 otbr-agent[200]: 5d.09:08:12.226 [I] MeshForwarder-: Sent IPv6 UDP msg, len:60, chksum:f45f, ecn:no, to:0xd800, sec:yes, prio:low
Nov 8 22:34:44 8826213816e4 otbr-agent[200]: 5d.09:08:12.226 [I] MeshForwarder-: src:[fd9b:4dd6:b34d:2:0:0:34f:5ca3]:5683
Nov 8 22:34:44 8826213816e4 otbr-agent[200]: 5d.09:08:12.226 [I] MeshForwarder-: dst:[fd9b:4dd6:b34d:1:3a61:fa47:c2a1:5b93]:61703
Nov 8 22:34:45 8826213816e4 otbr-agent[200]: 5d.09:08:14.015 [D] P-RadioSpinel-: Received spinel frame, flg:0x2, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:86, rssi:-93 ...
Nov 8 22:34:45 8826213816e4 otbr-agent[200]: 5d.09:08:14.015 [D] P-RadioSpinel-: ... noise:-128, flags:0x0000, channel:15, lqi:7, timestamp:1154097674122, rxerr:0
Nov 8 22:34:45 8826213816e4 otbr-agent[200]: 5d.09:08:14.015 [I] MeshForwarder-: Received IPv6 UDP msg, len:107, chksum:7bf8, ecn:no, from:c6a22f1a7f6fdac8, sec:no, prio:net, rss:-93.0
Nov 8 22:34:45 8826213816e4 otbr-agent[200]: 5d.09:08:14.016 [I] MeshForwarder-: src:[fe80:0:0:0:c4a2:2f1a:7f6f:dac8]:19788
Nov 8 22:34:45 8826213816e4 otbr-agent[200]: 5d.09:08:14.016 [I] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:1]:19788
Nov 8 22:34:45 8826213816e4 otbr-agent[200]: 5d.09:08:14.016 [I] Mle-----------: Receive Advertisement (fe80:0:0:0:c4a2:2f1a:7f6f:dac8,0xa800)
Nov 8 22:34:46 8826213816e4 otbr-agent[200]: 5d.09:08:15.110 [D] P-RadioSpinel-: Received spinel frame, flg:0x2, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:71, rssi:-72 ...
Nov 8 22:34:46 8826213816e4 otbr-agent[200]: 5d.09:08:15.110 [D] P-RadioSpinel-: ... noise:-128, flags:0x0000, channel:15, lqi:11, timestamp:1154098769603, rxerr:0
Nov 8 22:34:46 8826213816e4 otbr-agent[200]: 5d.09:08:15.111 [I] MeshForwarder-: Received IPv6 UDP msg, len:87, chksum:b475, ecn:no, from:c6fb9ad3cff93e9e, sec:no, prio:net, rss:-72.0
Nov 8 22:34:46 8826213816e4 otbr-agent[200]: 5d.09:08:15.111 [I] MeshForwarder-: src:[fe80:0:0:0:c4fb:9ad3:cff9:3e9e]:19788
Nov 8 22:34:46 8826213816e4 otbr-agent[200]: 5d.09:08:15.111 [I] MeshForwarder-: dst:[fe80:0:0:0:88e:5d5e:8daf:63bf]:19788
Nov 8 22:34:46 8826213816e4 otbr-agent[200]: 5d.09:08:15.111 [I] Mle-----------: Receive Child Update Request from child (fe80:0:0:0:c4fb:9ad3:cff9:3e9e)
Nov 8 22:34:46 8826213816e4 otbr-agent[200]: 5d.09:08:15.112 [I] Mle-----------: Send Child Update Response to child (fe80:0:0:0:c4fb:9ad3:cff9:3e9e,0x9884)
Nov 8 22:34:46 8826213816e4 otbr-agent[200]: 5d.09:08:15.112 [D] P-RadioSpinel-: Sent spinel frame, flg:0x2, tid:5, cmd:PROP_VALUE_SET, key:STREAM_RAW, len:71, channel:15, maxbackoffs:4, maxretries:15 ...
Nov 8 22:34:46 8826213816e4 otbr-agent[200]: 5d.09:08:15.112 [D] P-RadioSpinel-: ... csmaCaEnabled:1, isHeaderUpdated:0, isARetx:0, skipAes:0, txDelay:0, txDelayBase:0
Nov 8 22:34:46 8826213816e4 otbr-agent[200]: 5d.09:08:15.126 [D] P-RadioSpinel-: Received spinel frame, flg:0x2, tid:5, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
Nov 8 22:34:46 8826213816e4 otbr-agent[200]: 5d.09:08:15.126 [I] MeshForwarder-: Sent IPv6 UDP msg, len:87, chksum:f0a6, ecn:no, to:c6fb9ad3cff93e9e, sec:no, prio:net
Nov 8 22:34:46 8826213816e4 otbr-agent[200]: 5d.09:08:15.126 [I] MeshForwarder-: src:[fe80:0:0:0:88e:5d5e:8daf:63bf]:19788
Nov 8 22:34:46 8826213816e4 otbr-agent[200]: 5d.09:08:15.126 [I] MeshForwarder-: dst:[fe80:0:0:0:c4fb:9ad3:cff9:3e9e]:19788
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:15.327 [D] P-RadioSpinel-: Received spinel frame, flg:0x2, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:101, rssi:-88 ...
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:15.327 [D] P-RadioSpinel-: ... noise:-128, flags:0x0000, channel:15, lqi:7, timestamp:1154098985290, rxerr:0
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:15.327 [I] MeshForwarder-: Received IPv6 UDP msg, len:94, chksum:dd0d, ecn:no, from:0x9888, sec:yes, prio:normal, rss:-88.0
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:15.328 [I] MeshForwarder-: src:[fd9b:4dd6:b34d:1:564f:f666:64c0:4c7f]:36395
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:15.328 [I] MeshForwarder-: dst:[fd9b:4dd6:b34d:2:0:0:34f:5ca3]:5683
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:15.360 [D] P-RadioSpinel-: Sent spinel frame, flg:0x2, tid:6, cmd:PROP_VALUE_SET, key:STREAM_RAW, len:69, channel:15, maxbackoffs:4, maxretries:15 ...
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:15.360 [D] P-RadioSpinel-: ... csmaCaEnabled:1, isHeaderUpdated:0, isARetx:0, skipAes:0, txDelay:0, txDelayBase:0
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:15.386 [D] P-RadioSpinel-: Received spinel frame, flg:0x2, tid:6, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:15.386 [I] MeshForwarder-: Sent IPv6 UDP msg, len:61, chksum:125e, ecn:no, to:0x9888, sec:yes, prio:low
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:15.386 [I] MeshForwarder-: src:[fd9b:4dd6:b34d:2:0:0:34f:5ca3]:5683
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:15.386 [I] MeshForwarder-: dst:[fd9b:4dd6:b34d:1:564f:f666:64c0:4c7f]:36395
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:15.943 [D] P-RadioSpinel-: Received spinel frame, flg:0x2, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:121, rssi:-98 ...
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:15.943 [D] P-RadioSpinel-: ... noise:-128, flags:0x0000, channel:15, lqi:7, timestamp:1154099600887, rxerr:0
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:15.952 [I] Mle-----------: Router timeout expired
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:15.952 [I] Mle-----------: Send Link Request (fe80:0:0:0:a038:8ba7:d8ae:4ea5)
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:15.953 [D] P-RadioSpinel-: Sent spinel frame, flg:0x2, tid:7, cmd:PROP_VALUE_SET, key:STREAM_RAW, len:80, channel:15, maxbackoffs:4, maxretries:15 ...
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:15.953 [D] P-RadioSpinel-: ... csmaCaEnabled:1, isHeaderUpdated:0, isARetx:0, skipAes:0, txDelay:0, txDelayBase:0
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.120 [D] P-RadioSpinel-: Received spinel frame, flg:0x2, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:120, rssi:-95 ...
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.120 [D] P-RadioSpinel-: ... noise:-128, flags:0x0000, channel:15, lqi:8, timestamp:1154099777772, rxerr:0
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.120 [I] MeshForwarder-: Received IPv6 UDP msg, len:136, chksum:a83e, ecn:no, from:a2388ba7d8ae4ea5, sec:no, prio:net, rss:-95.0
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.121 [I] MeshForwarder-: src:[fe80:0:0:0:a038:8ba7:d8ae:4ea5]:19788
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.121 [I] MeshForwarder-: dst:[fe80:0:0:0:88e:5d5e:8daf:63bf]:19788
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.121 [I] Mle-----------: Receive Link Accept (fe80:0:0:0:a038:8ba7:d8ae:4ea5,0x1000)
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.122 [I] RouterTable---: Route table
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.122 [I] RouterTable---: 50 0xc800 - nbr{lq[i/o]:3/3 cost:1} - nexthop{62 cost:1}
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.122 [I] RouterTable---: 43 0xac00 - nbr{lq[i/o]:3/3 cost:1} - nexthop{51 cost:1}
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.122 [I] RouterTable---: 14 0x3800 - nexthop{34 cost:1}
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.122 [I] RouterTable---: 51 0xcc00 - nbr{lq[i/o]:3/3 cost:1} - nexthop{43 cost:1}
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.123 [I] RouterTable---: 4 0x1000 - nbr{lq[i/o]:3/2 cost:2} - nexthop{61 cost:1}
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.123 [I] RouterTable---: 17 0x4400 - nbr{lq[i/o]:3/3 cost:1} - nexthop{61 cost:1} - leader
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.123 [I] RouterTable---: 42 0xa800 - nbr{lq[i/o]:3/3 cost:1} - nexthop{59 cost:1}
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.123 [I] RouterTable---: 46 0xb800 - nbr{lq[i/o]:3/3 cost:1} - nexthop{43 cost:1}
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.123 [I] RouterTable---: 38 0x9800 - me
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.124 [I] RouterTable---: 5 0x1400 - nexthop{45 cost:1}
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.124 [I] RouterTable---: 62 0xf800 - nbr{lq[i/o]:3/3 cost:1} - nexthop{50 cost:1}
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.124 [I] RouterTable---: 34 0x8800 - nbr{lq[i/o]:3/3 cost:1} - nexthop{61 cost:1}
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.124 [I] RouterTable---: 58 0xe800 - nbr{lq[i/o]:2/2 cost:2} - nexthop{34 cost:1}
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.124 [I] RouterTable---: 45 0xb400 - nbr{lq[i/o]:2/3 cost:2} - nexthop{51 cost:3}
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.124 [I] RouterTable---: 61 0xf400 - nbr{lq[i/o]:3/3 cost:1} - nexthop{51 cost:1}
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.125 [I] RouterTable---: 60 0xf000 - nbr{lq[i/o]:3/3 cost:1} - nexthop{50 cost:1}
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.125 [I] RouterTable---: 59 0xec00 - nbr{lq[i/o]:3/3 cost:1} - nexthop{42 cost:1}
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.125 [I] RouterTable---: 54 0xd800 - nbr{lq[i/o]:3/3 cost:1} - nexthop{17 cost:2}
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.125 [D] P-RadioSpinel-: Received spinel frame, flg:0x2, tid:7, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.126 [W] P-RadioSpinel-: Handle radio frame failed: Parse
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.126 [W] P-RadioSpinel-: Handle transmit done failed: Parse
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.126 [C] Platform------: ------------------ BEGINNING OF CRASH -------------
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.126 [C] Platform------: *** FATAL ERROR: Caught signal: 6 (Aborted)
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.128 [C] Platform------: # 0: /usr/sbin/otbr-agent(+0x2bc6e0) [0x55802cc6e0]
Nov 8 22:34:47 8826213816e4 otbr-agent[200]: 5d.09:08:16.129 [C] Platform------: ------------------ END OF CRASH ------------------
Nov 8 23:01:50 8826213816e4 avahi-daemon[164]: Withdrawing address record for fd11:1111:1122:2223:42:acff:fe11:2 on eth0.
Nov 8 23:01:50 8826213816e4 avahi-daemon[164]: Leaving mDNS multicast group on interface eth0.IPv6 with address fd11:1111:1122:2223:42:acff:fe11:2.
Nov 8 23:01:50 8826213816e4 avahi-daemon[164]: Joining mDNS multicast group on interface eth0.IPv6 with address fe80::42:acff:fe11:2.
Nov 8 23:01:50 8826213816e4 avahi-daemon[164]: Registering new address record for fe80::42:acff:fe11:2 on eth0.*.
And another one after 3 days, they all seem to be related to this line:
Received spinel frame, flg:0x2, tid:9, cmd:PROP_VALUE_IS, key:LAST_STATUS, stat
Please let me know if I can enable any additional debugging or logging options to figure out the root cause of this crash.
The error Handle transmit done failed: Parse
means that the code has reached to the function HandleTransmitDone() and the error code mTxError
is set to OT_ERROR_PARSE
. The error code OT_ERROR_PARSE
will be finally handled by the function SubMac::HandleTransmitDone. The function SubMac::HandleTransmitDone
is unable to process the error code OT_ERROR_PARSE
, so it calls the OT_ASSERT(false);. The OT_ASSERT()
calls the assert() to make the program crashed.
So the root cause is that the Thread host receives a wrong Spinel frame from the esp32-c6. I think you can add the code to HandleTransmitDone() to print out the raw data of the Spinel message to better understand which field of the Spinel frame is wrong.
I also encountered a similar problem. The platform I used was Silabs SoC + Raspberry Pi 4. Details are in the Silabs Community Discussion.
The following is part of the log:
Sep 27 08:16:01 otbr-4b otbr-agent[200]: 00:58:54.588 [D] Platform------: Process(): Interrupt.
Sep 27 08:16:01 otbr-4b otbr-agent[200]: 00:58:54.589 [D] Platform------: ============================[SPI-TX len=053]============================
Sep 27 08:16:01 otbr-4b otbr-agent[200]: 00:58:54.589 [D] Platform------: | 02 20 00 00 00 8A 03 71 | 55 00 69 98 21 CC CC 00 | . .....qU.i.!LL.
Sep 27 08:16:01 otbr-4b otbr-agent[200]: 00:58:54.589 [D] Platform------: | 94 00 8C 0D F4 6F 02 00 | 08 68 85 01 04 52 B4 06 | ....to...h...R4.
Sep 27 08:16:01 otbr-4b otbr-agent[200]: 00:58:54.589 [D] Platform------: | 3F 24 0E 03 B6 04 AB 03 | 20 52 8D 5C FF FE AC 8F | ?$..6.+. R.\.~,.
Sep 27 08:16:01 otbr-4b otbr-agent[200]: 00:58:54.589 [D] Platform------: | A5 0D 57 64 3A .. .. .. | .. .. .. .. .. .. .. .. | %.Wd:...........
Sep 27 08:16:01 otbr-4b otbr-agent[200]: 00:58:54.589 [D] Platform------: ------------------------------------------------------------------------
Sep 27 08:16:01 otbr-4b otbr-agent[200]: 00:58:54.589 [D] Platform------: ============================[SPI-RX len=053]============================
Sep 27 08:16:01 otbr-4b otbr-agent[200]: 00:58:54.589 [D] Platform------: | 02 FB 01 04 00 8A 06 00 | 04 FF FF FF FF FF FF FF | .{..............
Sep 27 08:16:01 otbr-4b otbr-agent[200]: 00:58:54.589 [D] Platform------: | FF FF FF FF FF FF FF FF | FF FF FF FF FF FF FF FF | ................
Sep 27 08:16:01 otbr-4b otbr-agent[200]: 00:58:54.589 [D] Platform------: | FF FF FF FF FF FF FF FF | FF FF FF FF FF FF FF FF | ................
Sep 27 08:16:01 otbr-4b otbr-agent[200]: 00:58:54.589 [D] Platform------: | FF FF FF FF FF .. .. .. | .. .. .. .. .. .. .. .. | ................
Sep 27 08:16:01 otbr-4b otbr-agent[200]: 00:58:54.589 [D] Platform------: ------------------------------------------------------------------------
Sep 27 08:16:01 otbr-4b otbr-agent[200]: 00:58:54.589 [D] Platform------: spi_transfer TX: H:02 ACCEPT:32 DATA:0
Sep 27 08:16:01 otbr-4b otbr-agent[200]: 00:58:54.589 [D] Platform------: spi_transfer RX: H:02 ACCEPT:507 DATA:4
Sep 27 08:16:01 otbr-4b otbr-agent[200]: 00:58:54.589 [D] Platform------: Received spinel frame, flg:0x2, iid:0, tid:10, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:INVALID_STATE
Sep 27 08:16:01 otbr-4b otbr-agent[200]: 00:58:54.589 [W] Platform------: Handle transmit done failed: Parse
Sep 27 08:16:01 otbr-4b otbr-agent[200]: 00:58:54.590 [C] Platform------: ------------------ BEGINNING OF CRASH -------------
Sep 27 08:16:01 otbr-4b otbr-agent[200]: 00:58:54.590 [C] Platform------: *** FATAL ERROR: Caught signal: 6 (Aborted)
Sep 27 08:16:01 otbr-4b otbr-agent[200]: 00:58:54.590 [C] Platform------: ------------------ END OF CRASH ------------------
Sep 27 08:16:03 otbr-4b mDNSResponder: Default: mDNS_Execute: SendResponses didn't send all its responses; will try again in one second
I'm seeing a similar problem with a Silabs based device. It's usually in the context of an MLE channel announcement. I added some message dumps to the spinel code (this function).
0001-st-add-logging-to-HandleTransmitDone.patch
2024-01-28_18:38:33.050 | silabs-otbr-agent[1661]: 1d.16:11:32.901 [I] Mle-----------: Send Announce on channel 15
2024-01-28_18:38:33.052 | silabs-otbr-agent[1661]: 1d.16:11:32.902 [D] Mac-----------: Request to start operation "TransmitDataDirect"
2024-01-28_18:38:33.052 | silabs-otbr-agent[1661]: 1d.16:11:32.903 [D] Mac-----------: Starting operation "TransmitDataDirect"
2024-01-28_18:38:33.053 | silabs-otbr-agent[1661]: 1d.16:11:32.904 [D] SubMac--------: RadioState: Receive -> CsmaBackoff
2024-01-28_18:38:33.059 | silabs-otbr-agent[1661]: 1d.16:11:32.910 [D] SubMac--------: RadioState: CsmaBackoff -> Transmit
2024-01-28_18:38:33.061 | silabs-otbr-agent[1661]: 1d.16:11:32.911 [D] Platform------: Sent spinel frame, flg:0x2, iid:2, tid:12, cmd:PROP_VALUE_SET, key:STREAM_RAW, len:82, channel:15, maxbackoffs:4, maxretries:15 ...
2024-01-28_18:38:33.061 | silabs-otbr-agent[1661]: 1d.16:11:32.912 [D] Platform------: ... csmaCaEnabled:1, isHeaderUpdated:1, isARetx:0, skipAes:1, txDelay:0, txDelayBase:0
2024-01-28_18:38:33.062 | silabs-otbr-agent[1661]: 1d.16:11:32.912 [D] TrelLink------: State: Receive -> Transmit
2024-01-28_18:38:33.063 | silabs-otbr-agent[1661]: 1d.16:11:32.914 [D] TrelLink------: BeginTransmit() [broadcast ch:15 panid:ffff num:15425 src:02e46158a6cee849 no-ack] plen:80
2024-01-28_18:38:33.065 | silabs-otbr-agent[1661]: 1d.16:11:32.916 [D] TrelLink------: State: Transmit -> Receive
2024-01-28_18:38:33.066 | silabs-otbr-agent[1661]: 1d.16:11:32.916 [D] Platform------: Received spinel frame, flg:0x2, iid:1, tid:12, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
2024-01-28_18:38:33.066 | silabs-otbr-agent[1661]: 1d.16:11:32.917 [D] Platform------: Discarding spinel message with IID=1
2024-01-28_18:38:33.070 | silabs-otbr-agent[1661]: 1d.16:11:32.921 [D] Platform------: Received spinel frame, flg:0x2, iid:2, tid:12, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
2024-01-28_18:38:33.071 | silabs-otbr-agent[1661]: 1d.16:11:32.922 [D] Mac-----------: ==============[HandleTransmitDone: spinel buffer len=031]===============
2024-01-28_18:38:33.072 | silabs-otbr-agent[1661]: 1d.16:11:32.922 [D] Mac-----------: | 00 00 01 00 00 00 80 00 | 00 0A 00 00 00 00 00 00 | ................
2024-01-28_18:38:33.073 | silabs-otbr-agent[1661]: 1d.16:11:32.923 [D] Mac-----------: | 00 00 00 00 00 01 00 00 | 05 00 00 00 00 00 00 .. | ................
2024-01-28_18:38:33.074 | silabs-otbr-agent[1661]: 1d.16:11:32.924 [D] Mac-----------: ------------------------------------------------------------------------
2024-01-28_18:38:33.075 | silabs-otbr-agent[1661]: 1d.16:11:32.925 [D] Mac-----------: ==============[HandleTransmitDone: spinel buffer len=030]===============
2024-01-28_18:38:33.076 | silabs-otbr-agent[1661]: 1d.16:11:32.926 [D] Mac-----------: | 00 01 00 00 00 80 00 00 | 0A 00 00 00 00 00 00 00 | ................
2024-01-28_18:38:33.076 | silabs-otbr-agent[1661]: 1d.16:11:32.927 [D] Mac-----------: | 00 00 00 00 01 00 00 05 | 00 00 00 00 00 00 .. .. | ................
2024-01-28_18:38:33.077 | silabs-otbr-agent[1661]: 1d.16:11:32.927 [D] Mac-----------: ------------------------------------------------------------------------
2024-01-28_18:38:33.077 | silabs-otbr-agent[1661]: 1d.16:11:32.928 [D] Mac-----------: ==============[HandleTransmitDone: spinel buffer len=029]===============
2024-01-28_18:38:33.078 | silabs-otbr-agent[1661]: 1d.16:11:32.928 [D] Mac-----------: | 01 00 00 00 80 00 00 0A | 00 00 00 00 00 00 00 00 | ................
2024-01-28_18:38:33.078 | silabs-otbr-agent[1661]: 1d.16:11:32.929 [D] Mac-----------: | 00 00 00 01 00 00 05 00 | 00 00 00 00 00 .. .. .. | ................
2024-01-28_18:38:33.079 | silabs-otbr-agent[1661]: 1d.16:11:32.929 [D] Mac-----------: ------------------------------------------------------------------------
2024-01-28_18:38:33.079 | silabs-otbr-agent[1661]: 1d.16:11:32.930 [C] Platform------: HandleTransmitDone(): Could not parse keyId (0) and frameCounter (2123311720)
2024-01-28_18:38:33.080 | silabs-otbr-agent[1661]: 1d.16:11:32.930 [C] Platform------: HandleTransmitDone(): unpacked: -1
2024-01-28_18:38:33.080 | silabs-otbr-agent[1661]: 1d.16:11:32.931 [C] Mac-----------: ==============[HandleTransmitDone: spinel buffer len=000]===============
2024-01-28_18:38:33.081 | silabs-otbr-agent[1661]: 1d.16:11:32.931 [C] Mac-----------: ------------------------------------------------------------------------
2024-01-28_18:38:33.081 | silabs-otbr-agent[1661]: 1d.16:11:32.932 [W] Platform------: RCP failure detected
The SIGABRT
can be addressed via the commit in https://github.com/openthread/openthread/pull/9745. However, this doesn't explain the behavior around incorrectly encoded/decoded messages.
These failures are happening around 1-2 times a day on my setup, but I haven't been able to narrow down the exact failure in order to reproduce it. This is the corresponding code for the radio.
@abtink, what data would you recommend logging on the radio? I tried printing the entire buffer, but that looks like its 2048 bytes and I'm running into issues with RTT overwriting data.
Hi @jdswensen ,
My Silabs-based equipment also fails an average of 1-2 times a day.
Under the default build of Silabs, this device will fail dozens of times a day, but after setting the log level to critical, the device will only fail 1-2 times a day. In addition, as the concurrency of the network increases, the number of device failures will also increase.
@jdswensen, some suggestions/questions:
iid=1
and iid=2
from RPC which points to RCP operating as multi-PAN mode.Some observation from the log snipper for things to be investigated:
Here the spinel frame requesting a "Tx" is sent to RCP. It is sent with iid:2
and has tid:12
2024-01-28_18:38:33.061 | silabs-otbr-agent[1661]: 1d.16:11:32.911 [D] Platform------: Sent spinel frame, flg:0x2, iid:2, tid:12, cmd:PROP_VALUE_SET, key:STREAM_RAW, len:82, channel:15, maxbackoffs:4, maxretries:15 ...
2024-01-28_18:38:33.061 | silabs-otbr-agent[1661]: 1d.16:11:32.912 [D] Platform------: ... csmaCaEnabled:1, isHeaderUpdated:1, isARetx:0, skipAes:1, txDelay:0, txDelayBase:0
Later we see this set of spinel messages received from RCP:
iid:1
and one iid:2
for same tid:12
(tid
match indicates it is a response to the command above).iid:1
as well? The response should be using iid:2
same as the request.2024-01-28_18:38:33.066 | silabs-otbr-agent[1661]: 1d.16:11:32.916 [D] Platform------: Received spinel frame, flg:0x2, iid:1, tid:12, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
2024-01-28_18:38:33.066 | silabs-otbr-agent[1661]: 1d.16:11:32.917 [D] Platform------: Discarding spinel message with IID=1
2024-01-28_18:38:33.070 | silabs-otbr-agent[1661]: 1d.16:11:32.921 [D] Platform------: Received spinel frame, flg:0x2, iid:2, tid:12, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
Describe the bug The otbr-agent in the docker container crashes after around a week of uptime.
To Reproduce Information to reproduce the behavior, including:
openthread/otbr@sha256:78543c07c08650044a35e6e938ae787f0bf48b059dd8a82883a14e97ce5c86cd
Expected behavior ot-agent shouldn't crash ;) And even if it does, it should either restart itself, or crash the docker container so that docker automatically restarts the container.
Console/log output
We have 4 pi's running the otbr docker image with around 30 devices each. Here are the 4 logs from each:
Additional context Add any other context about the problem here.