search

openthread / openthread

OpenThread released by Google is an open-source implementation of the Thread networking protocol
https://openthread.io
BSD 3-Clause "New" or "Revised" License
3.54k stars 1.08k forks source link

What situations may cause otPlatSettingsGet Failure? #10673

Closed lancersky2017 closed 1 month ago

lancersky2017 commented 2 months ago

Describe the bug A clear and concise description of what the bug is. When otPlatSettingsGet Failure occurs, otbr-agent will restart. We don't know what situations will cause otPlatSettingsGet Failure.

Thu Sep  5 13:57:25 2024 user.warn otbr-agent[2911]: 1d.00:11:43.738 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 13:57:27 2024 user.warn otbr-agent[2911]: 1d.00:11:46.191 [W] P-Daemon------: Daemon read: Connection reset by peer
Thu Sep  5 13:57:27 2024 user.warn otbr-agent[2911]: 1d.00:11:46.211 [W] P-Daemon------: Daemon read: Connection reset by peer
Thu Sep  5 13:57:27 2024 user.warn otbr-agent[2911]: 1d.00:11:46.238 [W] P-Daemon------: Daemon read: Connection reset by peer
Thu Sep  5 13:57:34 2024 user.warn otbr-agent[2911]: 1d.00:11:53.303 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 13:57:48 2024 user.warn otbr-agent[2911]: 1d.00:12:07.191 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 13:58:03 2024 user.warn otbr-agent[2911]: 1d.00:12:21.592 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 13:58:15 2024 user.warn otbr-agent[2911]: 1d.00:12:34.406 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 13:58:16 2024 user.warn otbr-agent[2911]: 1d.00:12:35.327 [W] Mle-----------: Failed to process UDP: Duplicated
Thu Sep  5 13:58:17 2024 user.warn otbr-agent[2911]: 1d.00:12:36.383 [W] Mle-----------: Failed to process UDP: Duplicated
Thu Sep  5 13:58:26 2024 user.warn otbr-agent[2911]: 1d.00:12:45.014 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 13:58:36 2024 user.warn otbr-agent[2911]: 1d.00:12:55.167 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 13:58:47 2024 user.warn otbr-agent[2911]: 1d.00:13:06.443 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 13:59:03 2024 user.warn otbr-agent[2911]: 1d.00:13:22.240 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 13:59:15 2024 user.warn otbr-agent[2911]: 1d.00:13:34.335 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 13:59:25 2024 user.warn otbr-agent[2911]: 1d.00:13:44.330 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 13:59:34 2024 user.warn otbr-agent[2911]: 1d.00:13:52.860 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 13:59:50 2024 user.warn otbr-agent[2911]: 1d.00:14:09.522 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 13:59:59 2024 user.warn otbr-agent[2911]: 1d.00:14:18.290 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 14:00:13 2024 user.warn otbr-agent[2911]: 1d.00:14:31.821 [W] P-RadioSpinel-: Handle transmit done failed: ChannelAccessFailure
Thu Sep  5 14:00:15 2024 user.warn otbr-agent[2911]: 1d.00:14:34.030 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 14:00:25 2024 user.warn otbr-agent[2911]: 1d.00:14:44.156 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 14:00:35 2024 user.warn otbr-agent[2911]: 1d.00:14:53.705 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 14:00:46 2024 user.warn otbr-agent[2911]: 1d.00:15:04.732 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 14:00:58 2024 user.warn otbr-agent[2911]: 1d.00:15:16.852 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 14:01:10 2024 user.warn otbr-agent[2911]: 1d.00:15:29.408 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 14:01:22 2024 user.warn otbr-agent[2911]: 1d.00:15:41.452 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 14:01:34 2024 user.warn otbr-agent[2911]: 1d.00:15:53.461 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 14:01:46 2024 user.warn otbr-agent[2911]: 1d.00:16:05.017 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 14:02:02 2024 user.warn otbr-agent[2911]: 1d.00:16:21.238 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 14:02:13 2024 user.warn otbr-agent[2911]: 1d.00:16:32.371 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 14:02:24 2024 user.warn otbr-agent[2911]: 1d.00:16:43.302 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 14:02:35 2024 user.warn otbr-agent[2911]: 1d.00:16:53.798 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 14:02:49 2024 user.warn otbr-agent[2911]: 1d.00:17:07.788 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 14:03:02 2024 user.warn otbr-agent[2911]: 1d.00:17:21.457 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 14:03:10 2024 user.warn otbr-agent[2911]: 1d.00:17:29.108 [W] Mle-----------: Failed to process UDP: Security
Thu Sep  5 14:03:17 2024 user.warn otbr-agent[2911]: 1d.00:17:36.198 [W] P-Netif-------: ADD [U] fd36:ff76:692:a2ba:0:ff:fe00:fc37 failed (InvalidArgs)
Thu Sep  5 14:03:17 2024 user.warn otbr-agent[2911]: 1d.00:17:36.198 [W] P-Netif-------: Failed to process event, error:InvalidArgs
Thu Sep  5 14:03:17 2024 user.err otbr-agent[2911]: [ERR ]-MDNS----: Failed to register service OpenThread BorderRouter #A858 (51733)._meshcop._udp: Name Conflict
Thu Sep  5 14:03:17 2024 user.warn otbr-agent[2911]: [WARN]-BA------: Result of publish meshcop service OpenThread BorderRouter #A858 (51733)._meshcop._udp.local: Duplicated
Thu Sep  5 14:03:17 2024 user.crit otbr-agent[2911]: 1d.00:17:36.257 [C] Platform------: otPlatSettingsGet() at settings.cpp:259: Failure
Thu Sep  5 14:03:17 2024 user.crit otbr-agent[2911]: 1d.00:17:36.257 [C] Platform------: otPlatSettingsGet() at settings.cpp:259: Failure

To Reproduce Information to reproduce the behavior, including: No exact steps

  1. Git commit id simplicity_sdk v2024.6.1
  2. IEEE 802.15.4 hardware platform EFR32MG21F768
  3. Build steps
  4. Network topology
bukepo commented 2 months ago

From the code, it can happen when the settings file was corrupted.

lancersky2017 commented 2 months ago

Thank you for your reply. I will continue to observe what API call causes the file to be corrupted.

lancersky2017 commented 2 months ago

Hi @bukepo How to interpret OT_POSIX_SETTINGS? I would add some debug logs to see what is failing to read.

jwhui commented 2 months ago

Hi @bukepo How to interpret OT_POSIX_SETTINGS? I would add some debug logs to see what is failing to read.

The process dies whenever ot::Posix::PlatformSettingsGet() returns an OT_ERROR_PARSE error: https://github.com/openthread/openthread/blob/07a1b7bd985d8d1cd9fab5d45bc62ae8fc1358c9/src/posix/platform/settings.cpp#L260

I would try to understand why PlatformSettingsGet() is returning OT_ERROR_PARSE: https://github.com/openthread/openthread/blob/07a1b7bd985d8d1cd9fab5d45bc62ae8fc1358c9/src/posix/platform/settings.cpp#L333

lancersky2017 commented 2 months ago

Hi @jwhui We haven't found the steps to reproduce it yet. After otbr-agent is restarted, otPlatSettingsGet failure does not occur immediately again. We want to understand what information is stored in OT_POSIX_SETTINGS, which may help us locate the problem.

Sep 09 05:51:44 192.168.251.18 Sep  9 05:51:26 KNBA5F00001E otbr-agent[7878]: 2d.08:30:50.877 [W] SrpServer-----: Name conflict: host name knx-00fd10f1c763.default.service.arpa. has already been allocated
Sep 09 05:51:44 192.168.251.18 Sep  9 05:51:26 KNBA5F00001E otbr-agent[7878]: 2d.08:30:50.877 [W] SrpServer-----: Failed to Process DNS Update section: Duplicated
Sep 09 05:51:44 192.168.251.18 Sep  9 05:51:26 KNBA5F00001E otbr-agent[7878]: 2d.08:30:50.878 [W] SrpServer-----: Send fail response: 6
Sep 09 05:51:45 192.168.251.18 Sep  9 05:51:26 KNBA5F00001E otbr-agent[7878]: 2d.08:30:51.349 [W] P-Daemon------: Daemon read: Connection reset by peer
Sep 09 05:51:48 192.168.251.18 Sep  9 05:51:30 KNBA5F00001E otbr-agent[7878]: 2d.08:30:54.693 [W] SrpServer-----: Name conflict: service name 00FD10F1C763._knx._udp.default.service.arpa. has already been allocated
Sep 09 05:51:48 192.168.251.18 Sep  9 05:51:30 KNBA5F00001E otbr-agent[7878]: 2d.08:30:54.693 [W] SrpServer-----: Failed to Process DNS Update section: Duplicated
Sep 09 05:51:48 192.168.251.18 Sep  9 05:51:30 KNBA5F00001E otbr-agent[7878]: 2d.08:30:54.694 [W] SrpServer-----: Send fail response: 6
Sep 09 05:51:55 192.168.251.18 Sep  9 05:51:37 KNBA5F00001E otbr-agent[7878]: 2d.08:31:01.896 [W] Mle-----------: Failed to process UDP: Security
Sep 09 05:51:59 192.168.251.18 Sep  9 05:51:41 KNBA5F00001E otbr-agent[7878]: 2d.08:31:06.308 [W] SrpServer-----: Name conflict: service name 00FD10F1C763._knx._udp.default.service.arpa. has already been allocated
Sep 09 05:51:59 192.168.251.18 Sep  9 05:51:41 KNBA5F00001E otbr-agent[7878]: 2d.08:31:06.308 [W] SrpServer-----: Failed to Process DNS Update section: Duplicated
Sep 09 05:51:59 192.168.251.18 Sep  9 05:51:41 KNBA5F00001E otbr-agent[7878]: 2d.08:31:06.309 [W] SrpServer-----: Send fail response: 6
Sep 09 05:52:06 192.168.251.18 Sep  9 05:51:48 KNBA5F00001E otbr-agent[7878]: 2d.08:31:13.229 [W] Mle-----------: Failed to process UDP: Security
Sep 09 05:52:11 192.168.251.18 Sep  9 05:51:53 KNBA5F00001E otbr-agent[7878]: 2d.08:31:17.945 [W] SrpServer-----: Name conflict: service name 00FD10F1C763._knx._udp.default.service.arpa. has already been allocated
Sep 09 05:52:11 192.168.251.18 Sep  9 05:51:53 KNBA5F00001E otbr-agent[7878]: 2d.08:31:17.945 [W] SrpServer-----: Failed to Process DNS Update section: Duplicated
Sep 09 05:52:11 192.168.251.18 Sep  9 05:51:53 KNBA5F00001E otbr-agent[7878]: 2d.08:31:17.946 [W] SrpServer-----: Send fail response: 6
Sep 09 05:52:17 192.168.251.18 Sep  9 05:51:59 KNBA5F00001E otbr-agent[7878]: 2d.08:31:23.773 [W] Mle-----------: Failed to process UDP: Security
Sep 09 05:52:23 192.168.251.18 Sep  9 05:52:05 KNBA5F00001E otbr-agent[7878]: 2d.08:31:29.599 [W] SrpServer-----: Name conflict: service name 00FD10F1C763._knx._udp.default.service.arpa. has already been allocated
Sep 09 05:52:23 192.168.251.18 Sep  9 05:52:05 KNBA5F00001E otbr-agent[7878]: 2d.08:31:29.600 [W] SrpServer-----: Failed to Process DNS Update section: Duplicated
Sep 09 05:52:23 192.168.251.18 Sep  9 05:52:05 KNBA5F00001E otbr-agent[7878]: 2d.08:31:29.601 [W] SrpServer-----: Send fail response: 6
Sep 09 05:52:31 192.168.251.18 Sep  9 05:52:13 KNBA5F00001E otbr-agent[7878]: 2d.08:31:38.016 [W] Mle-----------: Failed to process UDP: Security
Sep 09 05:52:34 192.168.251.18 Sep  9 05:52:16 KNBA5F00001E otbr-agent[7878]: 2d.08:31:41.201 [W] SrpServer-----: Name conflict: service name 00FD10F1C763._knx._udp.default.service.arpa. has already been allocated
Sep 09 05:52:34 192.168.251.18 Sep  9 05:52:16 KNBA5F00001E otbr-agent[7878]: 2d.08:31:41.204 [W] SrpServer-----: Failed to Process DNS Update section: Duplicated
Sep 09 05:52:34 192.168.251.18 Sep  9 05:52:16 KNBA5F00001E otbr-agent[7878]: 2d.08:31:41.205 [W] SrpServer-----: Send fail response: 6
Sep 09 05:52:35 192.168.251.18 Sep  9 05:52:16 KNBA5F00001E otbr-agent[7878]: 2d.08:31:41.342 [C] Platform------: otPlatSettingsGet() at settings.cpp:259: Failure
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: [NOTE]-AGENT---: Running 0.3.0-v19.07.7-45-gc4b47c59e4-dirty
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: [NOTE]-AGENT---: Thread version: 1.3.0
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: [NOTE]-AGENT---: Thread interface: wpan0
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: [NOTE]-AGENT---: Radio URL: spinel+hdlc+uart:///dev/ttyCH343USB0?uart-baudrate=1000000&uart-flow-control
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: [NOTE]-AGENT---: Radio URL: trel://eth0
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: [NOTE]-ILS-----: Infra link selected: eth0
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: [INFO]-NCP-----: OpenThread log level changed to 5
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.574 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:0, cmd:RESET
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.574 [D] P-SpinelDrive-: Waiting response: key=0
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.576 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:7, log:[D] LinkRaw-------: ReceiveDone(22 bytes), error:OK
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.576 [W] P-SpinelDrive-: Error processing frame: Drop
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.577 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:22, rssi:-39 ...
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.577 [D] P-SpinelDrive-: ... noise:-128, flags:0x0000, channel:24, lqi:255, timestamp:610556880, rxerr:0
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.577 [W] P-SpinelDrive-: Error processing frame: Drop
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.579 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:RESET_POWER_ON
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.579 [I] P-SpinelDrive-: co-processor reset: RESET_POWER_ON
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.579 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:NOMEM
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.580 [I] P-SpinelDrive-: co-processor last status: NOMEM
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.580 [C] P-SpinelDrive-: Software reset co-processor successfully
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.580 [D] P-SpinelDrive-: Waiting response: key=1
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.583 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:1, cmd:PROP_VALUE_IS, key:PROTOCOL_VERSION, major:4, minor:3
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.583 [D] P-SpinelDrive-: Waiting response: key=2
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.589 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:1, cmd:PROP_VALUE_IS, key:NCP_VERSION, version:SL-OPENTHREAD/2.5.1.0_GitHub-1fceb225b-v2024.242.09761-b994a40; EFR32; Aug 30 2024 15:30:10
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.589 [D] P-SpinelDrive-: Waiting response: key=5
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.598 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:1, cmd:PROP_VALUE_IS, key:CAPS, caps:COUNTERS UNSOL_UPDATE_FILTER 802_15_4_2450MHZ_OQPSK CONFIG_RADIO MAC_RAW RCP_API_VERSION RCP_MIN_HOST_API_VERSION RCP_RESET_TO_BOOTLOADER RCP_LOG_CRASH_DUMP OPENTHREAD_LOG_METADATA
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.600 [D] P-RadioSpinel-: Wait response: tid=1 key=8
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.610 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:1, cmd:PROP_VALUE_IS, key:HWADDR, eui64:94deb8fffef12db9
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.613 [D] P-RadioSpinel-: RCP supports crash dump logging. Requesting crash dump.
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.613 [D] P-RadioSpinel-: Wait response: tid=2 key=178
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.615 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:2, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.616 [D] P-RadioSpinel-: Wait response: tid=3 key=176
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.616 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:2, log:[C] Platform------: Reset info: 0x3 (EXT)
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.616 [C] P-RadioSpinel-: RCP => [C] Platform------: Reset info: 0x3 (EXT)
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.619 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:2, log:[C] Platform------: Extended Reset info: 0x301 (PIN)
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.620 [C] P-RadioSpinel-: RCP => [C] Platform------: Extended Reset info: 0x301 (PIN)
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.620 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:3, cmd:PROP_VALUE_IS, key:RCP_API_VERSION, version:10
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.620 [D] P-RadioSpinel-: Wait response: tid=4 key=4619
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.623 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:4, cmd:PROP_VALUE_IS, key:RADIO_CAPS, caps:255
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.624 [D] P-Trel--------: platformTrelInit(aTrelUrl:"trel://eth0")
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: [DEBG]-TrelDns-: Initialized on netif "eth0"
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: [DEBG]-TrelDns-: Netif eth0 is ready: index = 3
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 52d.03:41:42.642 [I] P-Netif-------: Sent request#1 to set addr_gen_mode to 1
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.001 [D] P-RadioSpinel-: Wait response: tid=5 key=34
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.005 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:5, cmd:PROP_VALUE_IS, key:PHY_CHAN_SUPPORTED, channelMask:0x07fff800
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.006 [D] P-RadioSpinel-: Wait response: tid=6 key=32
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.008 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:6, cmd:PROP_VALUE_IS, key:PHY_ENABLED, enabled:1
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.009 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:7, log:[D] LinkRaw-------: Enabled(true)
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.009 [D] P-RadioSpinel-: RCP => [D] LinkRaw-------: Enabled(true)
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.009 [D] P-RadioSpinel-: Wait response: tid=7 key=54
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.009 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:6, log:[I] Platform------: State=OT_RADIO_STATE_SLEEP
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.009 [I] P-RadioSpinel-: RCP => [I] Platform------: State=OT_RADIO_STATE_SLEEP
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.012 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:7, log:[D] SubMac--------: RadioState: Disabled -> Sleep
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.012 [D] P-RadioSpinel-: RCP => [D] SubMac--------: RadioState: Disabled -> Sleep
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.012 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:7, cmd:PROP_VALUE_IS, key:MAC_15_4_PANID, panid:0xffff
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.013 [D] P-RadioSpinel-: Wait response: tid=8 key=53
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.014 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:6, log:[I] Platform------: PANID=FFFF index=0 IID=0
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.015 [I] P-RadioSpinel-: RCP => [I] Platform------: PANID=FFFF index=0 IID=0
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.015 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:6, log:[I] Platform------: Setting panIndex=0 to 0xffff
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.016 [I] P-RadioSpinel-: RCP => [I] Platform------: Setting panIndex=0 to 0xffff
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.017 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:7, log:[D] SubMac--------: RadioPanId: 0xffff
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.017 [D] P-RadioSpinel-: RCP => [D] SubMac--------: RadioPanId: 0xffff
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.017 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:8, cmd:PROP_VALUE_IS, key:MAC_15_4_SADDR, saddr:0x0000
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.019 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:6, log:[I] Platform------: ShortAddr=0 index=0
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.019 [I] P-RadioSpinel-: RCP => [I] Platform------: ShortAddr=0 index=0
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.019 [D] P-RadioSpinel-: Wait response: tid=9 key=39
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.021 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:7, log:[D] SubMac--------: RadioShortAddress: 0x0000
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.021 [D] P-RadioSpinel-: RCP => [D] SubMac--------: RadioShortAddress: 0x0000
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.024 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:9, cmd:PROP_VALUE_IS, key:PHY_RX_SENSITIVITY, sensitivity:-100
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.024 [D] P-RadioSpinel-: Wait response: tid=10 key=2048
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.026 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:10, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.027 [D] P-RadioSpinel-: Wait response: tid=11 key=52
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.029 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:11, cmd:PROP_VALUE_IS, key:MAC_15_4_LADDR, laddr:ded3c5f0713f93e9
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.030 [D] P-RadioSpinel-: Wait response: tid=12 key=53
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.031 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:6, log:[I] Platform------: ExtAddr=DED3C5F0713F93E9 index=0
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.031 [I] P-RadioSpinel-: RCP => [I] Platform------: ExtAddr=DED3C5F0713F93E9 index=0
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.033 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:7, log:[D] SubMac--------: RadioExtAddress: ded3c5f0713f93e9
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.033 [D] P-RadioSpinel-: RCP => [D] SubMac--------: RadioExtAddress: ded3c5f0713f93e9
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.033 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:12, cmd:PROP_VALUE_IS, key:MAC_15_4_SADDR, saddr:0xfffe
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.033 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:6, log:[I] Platform------: ShortAddr=FFFE index=0
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.033 [I] P-RadioSpinel-: RCP => [I] Platform------: ShortAddr=FFFE index=0
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.033 [D] P-RadioSpinel-: Wait response: tid=13 key=4868
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.036 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:7, log:[D] SubMac--------: RadioShortAddress: 0xfffe
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.036 [D] P-RadioSpinel-: RCP => [D] SubMac--------: RadioShortAddress: 0xfffe
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.036 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:13, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.036 [D] P-RadioSpinel-: Wait response: tid=14 key=4869
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.038 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:7, log:[D] Platform------: Clear ShortAddr entries (iid: 0)
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.039 [D] P-RadioSpinel-: RCP => [D] Platform------: Clear ShortAddr entries (iid: 0)
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.040 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:14, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.041 [I] ChildSupervsn-: Timeout: 0 -> 190
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.042 [D] P-RadioSpinel-: Wait response: tid=15 key=2048
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.042 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:7, log:[D] Platform------: Clear ExtAddr entries (iid: 0)
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.043 [D] P-RadioSpinel-: RCP => [D] Platform------: Clear ExtAddr entries (iid: 0)
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.046 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:15, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.047 [D] P-RadioSpinel-: Wait response: tid=1 key=54
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.049 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:1, cmd:PROP_VALUE_IS, key:MAC_15_4_PANID, panid:0xc336
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.050 [I] Settings------: Read NetworkInfo {rloc:0xbc00, extaddr:b27af56e066b4c53, role:leader, mode:0x0f, version:4, keyseq:0x5, ...
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.050 [I] Settings------: ... pid:0x53062f0f, mlecntr:0x73f6, maccntr:0x2cd81, mliid:2e9a8f407fa494db}
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.050 [D] P-RadioSpinel-: Wait response: tid=2 key=2048
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.051 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:6, log:[I] Platform------: PANID=C336 index=0 IID=0
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.051 [I] P-RadioSpinel-: RCP => [I] Platform------: PANID=C336 index=0 IID=0
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.051 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:6, log:[I] Platform------: Setting panIndex=0 to 0xc336
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.051 [I] P-RadioSpinel-: RCP => [I] Platform------: Setting panIndex=0 to 0xc336
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.055 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:7, log:[D] SubMac--------: RadioPanId: 0xc336
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.056 [D] P-RadioSpinel-: RCP => [D] SubMac--------: RadioPanId: 0xc336
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.056 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:2, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.056 [D] P-RadioSpinel-: Wait response: tid=3 key=2049
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.060 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:3, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.060 [D] P-RadioSpinel-: Wait response: tid=4 key=2049
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.062 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:4, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.063 [D] P-RadioSpinel-: Wait response: tid=5 key=53
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.065 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:5, cmd:PROP_VALUE_IS, key:MAC_15_4_SADDR, saddr:0xbc00
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.066 [D] P-RadioSpinel-: Wait response: tid=6 key=52
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.066 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:6, log:[I] Platform------: ShortAddr=BC00 index=0
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.066 [I] P-RadioSpinel-: RCP => [I] Platform------: ShortAddr=BC00 index=0
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.068 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:STREAM_LOG, level:7, log:[D] SubMac--------: RadioShortAddress: 0xbc00
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.069 [D] P-RadioSpinel-: RCP => [D] SubMac--------: RadioShortAddress: 0xbc00
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.069 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:6, cmd:PROP_VALUE_IS, key:MAC_15_4_LADDR, laddr:b27af56e066b4c53
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.069 [I] Settings------: Read ChildInfo {rloc:0xbc08, extaddr:7acd4c467c48e9e9, timeout:5400, mode:0x04, version:2}
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.069 [I] Settings------: Read ChildInfo {rloc:0xbc19, extaddr:4e77a9b61ff57db0, timeout:5400, mode:0x04, version:2}
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.069 [I] Settings------: Read ChildInfo {rloc:0xbc03, extaddr:4286d9c1b0ff723b, timeout:5400, mode:0x04, version:2}
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.069 [I] Settings------: Read ChildInfo {rloc:0xbc18, extaddr:4e8949f0dc0b4194, timeout:528, mode:0x05, version:4}
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.070 [I] Settings------: Read ChildInfo {rloc:0xbc01, extaddr:aeb6de2a2c93b28c, timeout:528, mode:0x05, version:2}
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.070 [I] Settings------: Read ChildInfo {rloc:0xbc07, extaddr:4ae5edb506a20ee8, timeout:528, mode:0x05, version:2}
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.070 [I] Settings------: Read ChildInfo {rloc:0xbc0e, extaddr:12b3389f6391a404, timeout:528, mode:0x05, version:2}
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.070 [I] Settings------: Read ChildInfo {rloc:0xbc06, extaddr:46fee020d144cd25, timeout:528, mode:0x05, version:2}
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.071 [I] Settings------: Read ChildInfo {rloc:0xbc05, extaddr:92ca27eedb45d9bd, timeout:528, mode:0x05, version:2}
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.071 [I] Settings------: Read ChildInfo {rloc:0xbc04, extaddr:62cd58705b162a4e, timeout:528, mode:0x05, version:2}
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.071 [I] Settings------: Read ChildInfo {rloc:0xbc11, extaddr:ee9955e928e1c6ac, timeout:528, mode:0x0d, version:2}
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.072 [D] P-Trel--------: PrepareSocket()
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: [DEBG]-TrelDns-: Start browsing _trel._udp services ...
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.072 [I] TrelInterface-: Enabled interface, local port:35611
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.073 [I] RoutingManager: Initializing - InfraIfIndex:3
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.073 [I] InfraIf-------: Init infra netif 3
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.073 [I] Settings------: Read BrUlaPrefix fd1e:7de5:351b::/48
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.073 [N] RoutingManager: BR ULA prefix: fd1e:7de5:351b::/48 (loaded)
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.073 [I] RoutingManager: Generated local OMR prefix: fd1e:7de5:351b:1::/64
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.073 [I] RoutingManager: Generated local NAT64 prefix: fd1e:7de5:351b:2:0:0::/96
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.073 [N] RoutingManager: Local on-link prefix: fd50:7751:2a10:1786::/64
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.073 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.073 [I] RoutingManager: Enabling
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.074 [I] Nat64---------: IPv4 CIDR for NAT64: 192.168.255.0/24 (actual address pool: 192.168.255.1 - 192.168.255.254, 254 addresses)
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.074 [I] Nat64---------: NAT64 translator is now Disabled
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: [INFO]-UTILS---: Set state callback: OK
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.075 [I] Nat64---------: NAT64 translator is now NotRunning
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: [DEBG]-TrelDns-: mDNS Publisher is Ready
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: [INFO]-TrelDns-: TREL DNS-SD Is Now Ready: Netif=eth0(3), SubscriberId=1, Register=!
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: [INFO]-MDNS----: Subscribe service ._trel._udp (total 1)
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: [INFO]-MDNS----: DNSServiceBrowse _trel._udp
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: [INFO]-BA------: Start Thread Border Agent
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: [INFO]-BA------: Publish meshcop service OpenThread BorderRouter #4C53._meshcop._udp.local.
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.076 [I] Settings------: Read BorderAgentId {id:eba5054c74ee080a6601b7ece24ebbbc}
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: [INFO]-MDNS----: Registering service OpenThread BorderRouter #4C53._meshcop._udp
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.077 [I] BbrLocal------: Add Domain Prefix: ::/0, NotFound
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: 00:00:00.078 [I] BbrLocal------: Add BBR Service: seqno (3), delay (5s), timeout (3600s), InvalidState
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: [INFO]-ADPROXY-: Started
Sep 09 05:52:40 192.168.251.18 Sep  9 05:52:22 KNBA5F00001E otbr-agent[12884]: [INFO]-DPROXY--: Started
jwhui commented 2 months ago

All of the non-volatile settings are defined here:

https://github.com/openthread/openthread/blob/main/src/core/common/settings.hpp

lancersky2017 commented 2 months ago

Hi @jwhui The left side shows the hexdump data of OT_POSIX_SETTINGS during normal operation, and the right side shows the hexdump data after otbr-agent exits when otPlatSettingsGet Failure occurs. Can you help explain the differences? image

jinpeng1989 commented 2 months ago

This issue is the same issue as the following. https://github.com/openthread/ot-br-posix/issues/2477

bukepo commented 2 months ago

@lancersky2017 could you attach the file?

jinpeng1989 commented 2 months ago

Hi @bukepo , The screenshot of OT_POSIX_SETTINGS @lancersky2017 provided is not from the time this issue occurred. We will try to reproduce the issue and record the OT_POSIX_SETTINGS before and after it occurred.

jinpeng1989 commented 2 months ago

It is worth mentioning that after switching back to GSDK 4.4.3. The issue will still come up. So please give priority to this issue.

lancersky2017 commented 2 months ago

Hi @bukepo This is OT_POSIX_SETTINGS after otPlatSettingsGet Failure occurs. 0_94deb8fffef12db9.zip

bukepo commented 2 months ago

I use the file you provided to overwrite my node's settings file, it started successfully and the network is established successfully as KNBA5F000043. No crashes occurred. Could you double check whether this is the settings file after otPlatSettingsGet failed?

jinpeng1989 commented 2 months ago

According to the log, otbr-agent has been restarted. So the above Settings file is not the content of the process crash. Because it has been overwritten by the otbr-agent settings file after the restart. We will disable the automatic restart function of otbr-agent, reproduce the issue again.

jinpeng1989 commented 2 months ago

@bukepo We reproduced the otbr-agent crash again.

This is the settings file that was backed up before the otbr-agent crash. 0_94deb8fffef12db9_before_crash.zip This is the settings file that was backed up after the otbr-agent crash. Can you check if this file will cause otbr-agent crash? 0_94deb8fffef12db9_after_crash.zip

Unfortunately, the remote logging system crashed. I can't confirm whether this crash is the same as the crash we are concerned about.

jinpeng1989 commented 2 months ago

@bukepo Have you checked the 0_94deb8fffef12db9_after_crash.zip file?

bukepo commented 1 month ago

I tried loading the settings file after crashing. I saw it loaded successfully.

bukepo commented 1 month ago

@jinpeng1989 is there any modification to the otbr-agent?

jwhui commented 1 month ago

This is the settings file that was backed up before the otbr-agent crash.

@jinpeng1989 , can you share how you backed up the settings file before the crash?

jinpeng1989 commented 1 month ago

This is the settings file that was backed up before the otbr-agent crash.

@jinpeng1989 , can you share how you backed up the settings file before the crash? What's wrong with this file? The tester should have copied the file directly to the local computer using "scp".

jinpeng1989 commented 1 month ago

@jinpeng1989 is there any modification to the otbr-agent?

Yes, there are some modifications. @lancersky2017 is the developer of this otbr-agent module.

bukepo commented 1 month ago

Could you check whether the modifications can cause multiple threads to access OpenThread instance? OpenThread core stack is designed to run in single thread. I suspect the error occurs in some race conditions.

jinpeng1989 commented 1 month ago

@bukepo Thanks for the reminder, there is a modification that call the otDatasetGetActiveTlvs(). @lancersky2017 has removed it. We'll verify the fix. It will take about a week. I will get back to you with the results.

jinpeng1989 commented 1 month ago

@bukepo There are two new pieces of information: 1 It's not the part of the ot-br-posix code that we changed that caused this issue. Because after removing the code, the issue can still be reproduced. 2 These few commands can easily reproduce the issue. ubus call otbr commissioner start, ubus call otbr commissioner stop, ubus call otbr status

bukepo commented 1 month ago

I think this is caused by ubus is running in a separate thread. The ubus implementation is not well maintained. To address this issue, we have to post all OpenThread API calls to the main thread from the ubus thread.

jinpeng1989 commented 1 month ago

The settings file seems to be designed for single-thread access. Problems may occur if multiple threads access the API of the Settings file. Since the swap file will be renamed to the data file. If thread 1 is traversing the settings (data) file and the contents of the file are modified by thread 2, offset may not point to the position of Key. In this case, the Key, Lenth, and Value will not be resolved correctly. https://github.com/openthread/openthread/blob/2bc86850606601db0d565cd958540a2790c08f62/src/posix/platform/settings.cpp#L135-L148 Is there a case that multiple threads are accessing the settings API at the same time?

jinpeng1989 commented 1 month ago

Do you have any plans to fix this issue?

jwhui commented 1 month ago

OpenThread APIs are not thread safe - they need to be called from a single execution context.

jinpeng1989 commented 1 month ago

There is progress on this issue. Our extended ubus method of otbr calls the otDatasetGetActive and otDatasetGetActiveTlvs APIs. We've removed them and started a new round of tests. Thank you for your support. I will update if there is any progress.

jinpeng1989 commented 1 month ago

After verification, the issue has been solved. I think we can close the issue.