Debug logging for OTBR
[19:53:53] INFO: Web UI and REST API port are exposed, starting otbr-web.
[19:53:53] INFO: Enabled socat-otbr-tcp.
s6-rc: info: service socat-otbr-tcp: starting
s6-rc: info: service mdns: starting
s6-rc: info: service s6rc-oneshot-runner: starting
s6-rc: info: service mdns successfully started
s6-rc: info: service s6rc-oneshot-runner successfully started
s6-rc: info: service fix-attrs: starting
s6-rc: info: service banner: starting
s6-rc: info: service fix-attrs successfully started
s6-rc: info: service legacy-cont-init: starting
s6-rc: info: service legacy-cont-init successfully started
[19:53:53] INFO: Starting mDNS Responder...
Default: mDNSResponder (Engineering Build) (Jan 14 2025 21:04:03) starting
[19:53:53] INFO: Starting socat TCP client for OTBR daemon...
-----------------------------------------------------------
Add-on: OpenThread Border Router
OpenThread Border Router add-on
-----------------------------------------------------------
Add-on version: 2.13.0
You are running the latest version of this add-on.
System: Home Assistant OS 15.2 (amd64 / qemux86-64)
Home Assistant Core: 2025.6.1
Home Assistant Supervisor: 2025.06.1
-----------------------------------------------------------
Please, share the above information when looking for help
or support in, e.g., GitHub, forums or the Discord chat.
-----------------------------------------------------------
s6-rc: info: service banner successfully started
s6-rc: info: service universal-silabs-flasher: starting
[19:53:53] INFO: Flashing firmware is disabled
s6-rc: info: service universal-silabs-flasher successfully started
s6-rc: info: service socat-otbr-tcp successfully started
s6-rc: info: service otbr-agent: starting
[19:53:53] INFO: Setup OTBR firewall...
[19:53:53] INFO: Starting otbr-agent...
[NOTE]-AGENT---: Running 0.3.0-b067e5ac-dirty
[NOTE]-AGENT---: Thread version: 1.3.0
[NOTE]-AGENT---: Thread interface: wpan0
[NOTE]-AGENT---: Radio URL: spinel+hdlc+uart:///tmp/ttyOTBR?uart-baudrate=460800&uart-init-deassert
[NOTE]-AGENT---: Radio URL: trel://enp0s18
tiocmbic: Inappropriate ioctl for device
[NOTE]-ILS-----: Infra link selected: enp0s18
[INFO]-RCP_HOS-: OpenThread log level changed to 5
73d.00:38:33.096 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:0, cmd:RESET
73d.00:38:33.096 [D] P-SpinelDrive-: Waiting response: key=0
73d.00:38:34.012 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:0, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:RESET_POWER_ON
73d.00:38:34.012 [I] P-SpinelDrive-: co-processor reset: RESET_POWER_ON
73d.00:38:34.012 [C] P-SpinelDrive-: Software reset co-processor successfully
73d.00:38:34.012 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:1, cmd:PROP_VALUE_GET, key:PROTOCOL_VERSION
73d.00:38:34.012 [D] P-SpinelDrive-: Waiting response: key=1
73d.00:38:34.022 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:1, cmd:PROP_VALUE_IS, key:PROTOCOL_VERSION, major:4, minor:3
73d.00:38:34.022 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:1, cmd:PROP_VALUE_GET, key:NCP_VERSION
73d.00:38:34.022 [D] P-SpinelDrive-: Waiting response: key=2
73d.00:38:34.033 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:1, cmd:PROP_VALUE_IS, key:NCP_VERSION, version:SL-OPENTHREAD/2.5.2.0_GitHub-1fceb225b; EFR32; Feb 12 2025 08:21:10
73d.00:38:34.033 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:1, cmd:PROP_VALUE_GET, key:CAPS
73d.00:38:34.033 [D] P-SpinelDrive-: Waiting response: key=5
73d.00:38:34.044 [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
[INFO]-BA------: Ephemeral Key is: disabled during initialization
73d.00:38:34.044 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:1, cmd:PROP_VALUE_GET, key:HWADDR
73d.00:38:34.044 [D] P-RadioSpinel-: Wait response: tid=1 key=8
73d.00:38:34.055 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:1, cmd:PROP_VALUE_IS, key:HWADDR, eui64:bc8d7efffe239a33
73d.00:38:34.055 [D] P-RadioSpinel-: RCP supports crash dump logging. Requesting crash dump.
73d.00:38:34.055 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:2, cmd:PROP_VALUE_SET, key:RCP_LOG_CRASH_DUMP, log-crash-dump
73d.00:38:34.055 [D] P-RadioSpinel-: Wait response: tid=2 key=178
73d.00:38:34.066 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:2, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
73d.00:38:34.066 [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)
73d.00:38:34.066 [C] P-RadioSpinel-: RCP => [C] Platform------: Reset info: 0x3 (EXT)
73d.00:38:34.066 [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)
73d.00:38:34.066 [C] P-RadioSpinel-: RCP => [C] Platform------: Extended Reset info: 0x301 (PIN)
73d.00:38:34.066 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:3, cmd:PROP_VALUE_GET, key:RCP_API_VERSION
73d.00:38:34.066 [D] P-RadioSpinel-: Wait response: tid=3 key=176
73d.00:38:34.077 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:3, cmd:PROP_VALUE_IS, key:RCP_API_VERSION, version:10
73d.00:38:34.077 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:4, cmd:PROP_VALUE_GET, key:RCP_MIN_HOST_API_VERSION
73d.00:38:34.077 [D] P-RadioSpinel-: Wait response: tid=4 key=177
73d.00:38:34.088 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:4, cmd:PROP_VALUE_IS, key:RCP_MIN_HOST_API_VERSION, min-host-version:4
73d.00:38:34.088 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:5, cmd:PROP_VALUE_GET, key:RADIO_CAPS
73d.00:38:34.088 [D] P-RadioSpinel-: Wait response: tid=5 key=4619
73d.00:38:34.099 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:5, cmd:PROP_VALUE_IS, key:RADIO_CAPS, caps:255
73d.00:38:34.099 [D] P-Trel--------: platformTrelInit(aTrelUrl:"trel://enp0s18")
73d.00:38:34.099 [D] P-Trel--------: otSysTrelInit(aInterfaceName:"enp0s18")
[DEBG]-TrelDns-: Initialized on netif "enp0s18"
[DEBG]-TrelDns-: Netif enp0s18 is ready: index = 2
73d.00:38:34.099 [I] P-Netif-------: Sent request#1 to set addr_gen_mode to 1
73d.00:38:34.099 [I] P-Resolver----: Got nameserver #0: 172.30.32.3
00:00:00.001 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:6, cmd:PROP_VALUE_GET, key:PHY_CHAN_SUPPORTED
00:00:00.001 [D] P-RadioSpinel-: Wait response: tid=6 key=34
00:00:00.011 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:6, cmd:PROP_VALUE_IS, key:PHY_CHAN_SUPPORTED, channelMask:0x07fff800
00:00:00.011 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:7, cmd:PROP_VALUE_SET, key:PHY_ENABLED, enabled:1
00:00:00.011 [D] P-RadioSpinel-: Wait response: tid=7 key=32
00:00:00.022 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:7, cmd:PROP_VALUE_IS, key:PHY_ENABLED, enabled:1
00:00:00.022 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:8, cmd:PROP_VALUE_SET, key:MAC_15_4_PANID, panid:0xffff
00:00:00.022 [D] P-RadioSpinel-: Wait response: tid=8 key=54
00:00:00.033 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:8, cmd:PROP_VALUE_IS, key:MAC_15_4_PANID, panid:0xffff
00:00:00.033 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:9, cmd:PROP_VALUE_SET, key:MAC_15_4_SADDR, saddr:0x0000
00:00:00.033 [D] P-RadioSpinel-: Wait response: tid=9 key=53
00:00:00.044 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:9, cmd:PROP_VALUE_IS, key:MAC_15_4_SADDR, saddr:0x0000
00:00:00.044 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:10, cmd:PROP_VALUE_GET, key:PHY_RX_SENSITIVITY
00:00:00.044 [D] P-RadioSpinel-: Wait response: tid=10 key=39
00:00:00.055 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:10, cmd:PROP_VALUE_IS, key:PHY_RX_SENSITIVITY, sensitivity:-100
00:00:00.055 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:11, cmd:PROP_VALUE_SET, key:RCP_MAC_KEY, keyIdMode:8, keyId:1, prevKey:***, currKey:***, nextKey:***
00:00:00.055 [D] P-RadioSpinel-: Wait response: tid=11 key=2048
00:00:00.066 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:11, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
00:00:00.066 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:12, cmd:PROP_VALUE_SET, key:MAC_15_4_LADDR, laddr:b2f7b20b2c68118c
00:00:00.066 [D] P-RadioSpinel-: Wait response: tid=12 key=52
00:00:00.077 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:12, cmd:PROP_VALUE_IS, key:MAC_15_4_LADDR, laddr:b2f7b20b2c68118c
00:00:00.077 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:13, cmd:PROP_VALUE_SET, key:MAC_15_4_SADDR, saddr:0xfffe
00:00:00.077 [D] P-RadioSpinel-: Wait response: tid=13 key=53
00:00:00.088 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:13, cmd:PROP_VALUE_IS, key:MAC_15_4_SADDR, saddr:0xfffe
00:00:00.088 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:14, cmd:PROP_VALUE_SET, key:MAC_SRC_MATCH_SHORT_ADDRESSES, saddr:none
00:00:00.088 [D] P-RadioSpinel-: Wait response: tid=14 key=4868
00:00:00.099 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:14, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
00:00:00.099 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:15, cmd:PROP_VALUE_SET, key:MAC_SRC_MATCH_EXTENDED_ADDRESSES, extaddr:none
00:00:00.099 [D] P-RadioSpinel-: Wait response: tid=15 key=4869
00:00:00.110 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:15, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
00:00:00.110 [I] CslTxScheduler: Set frame request ahead: 7605 usec
00:00:00.110 [I] ChildSupervsn-: Timeout: 0 -> 190
00:00:00.110 [D] P-Trel--------: PrepareSocket()
[DEBG]-TrelDns-: Start browsing _trel._udp services ...
00:00:00.110 [I] TrelInterface-: Enabled interface, local port:48117
00:00:00.110 [I] RoutingManager: Initializing - InfraIfIndex:2
00:00:00.110 [I] InfraIf-------: Init infra netif 2
00:00:00.110 [I] Settings------: Read BrUlaPrefix fdd8:1204:d2c1::/48
00:00:00.110 [N] RoutingManager: BR ULA prefix: fdd8:1204:d2c1::/48 (loaded)
00:00:00.110 [I] RoutingManager: Generated local OMR prefix: fdd8:1204:d2c1:1::/64
00:00:00.110 [I] RoutingManager: Generated local NAT64 prefix: fdd8:1204:d2c1:2:0:0::/96
00:00:00.110 [N] RoutingManager: Local on-link prefix: fdde:ad00:beef:cafe::/64
00:00:00.110 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING
00:00:00.110 [I] RoutingManager: Enabling
00:00:00.110 [I] Nat64---------: IPv4 CIDR for NAT64: 192.168.255.0/24 (actual address pool: 192.168.255.1 - 192.168.255.254, 254 addresses)
[INFO]-UTILS---: Set state callback: OK
[DEBG]-TrelDns-: Stop browsing _trel._udp service.
[DEBG]-TrelDns-: mDNS Publisher is Ready
[INFO]-TrelDns-: TREL DNS-SD Is Now Ready: Netif=enp0s18(2), SubscriberId=0, Register=!
[INFO]-BA------: Start Thread Border Agent
[INFO]-BA------: Publish meshcop service Home Assistant OpenThread Border Router #118C._meshcop._udp.local.
00:00:00.110 [I] Settings------: Read BorderAgentId {id:f6815df411f02ab1061973e844c15b97}
[INFO]-MDNS----: Registering service Home Assistant OpenThread Border Router #118C._meshcop._udp
00:00:00.111 [I] BbrLocal------: Add Domain Prefix: ::/0, NotFound
00:00:00.111 [I] BbrLocal------: Add BBR Service: seqno (65), delay (5s), timeout (3600s), InvalidState
[INFO]-ADPROXY-: Started
[INFO]-DPROXY--: Started
[INFO]-APP-----: Co-processor version: SL-OPENTHREAD/2.5.2.0_GitHub-1fceb225b; EFR32; Feb 12 2025 08:21:10
00:00:00.111 [I] Notifier------: StateChanged (0x42038210) [MLAddr NetData PanId NetName ExtPanId BbrState Nat64]
00:00:00.111 [I] Bbr-----------: Start listening on port 61631
00:00:00.111 [I] Bbr-----------: Backbone TMF subscribes ff32:40:fdde:ad00:beef:0:0:3: OK
00:00:00.111 [I] BbrManager----: Start Backbone TMF agent: OK
00:00:00.114 [I] Platform------: Execute command `ipset flush otbr-ingress-allow-dst-swap` = 0
00:00:00.115 [I] Platform------: Execute command `ipset flush otbr-ingress-deny-src-swap` = 0
00:00:00.117 [I] Platform------: Execute command `ipset add otbr-ingress-deny-src-swap fdde:ad00:beef:0::/64 -exist` = 0
00:00:00.118 [I] Platform------: Execute command `ipset swap otbr-ingress-deny-src-swap otbr-ingress-deny-src` = 0
00:00:00.119 [I] Platform------: Execute command `ipset swap otbr-ingress-allow-dst-swap otbr-ingress-allow-dst` = 0
00:00:00.119 [I] P-Netif-------: NAT64 CIDR updated to 192.168.255.0/24.
00:00:00.119 [I] P-Netif-------: Sent request#2 to delete route 192.168.255.0/24
00:00:00.119 [I] P-Netif-------: Deleting route for NAT64
00:00:00.119 [I] P-McastRtMgr--: Disable: OK
[INFO]-BA------: Publish meshcop service Home Assistant OpenThread Border Router #118C._meshcop._udp.local.
[DEBG]-BBA-----: BackboneAgent: HandleBackboneRouterState: state=1, mBackboneRouterState=0
00:00:00.119 [I] RouterTable---: Route table
00:00:00.119 [I] P-Netif-------: Host netif is down
00:00:00.120 [I] P-Netif-------: Succeeded to process request#1
00:00:00.120 [W] P-Netif-------: Failed to process request#2: No such process
s6-rc: info: service otbr-agent successfully started
s6-rc: info: service otbr-agent-configure: starting
s6-rc: info: service otbr-web: starting
s6-rc: info: service otbr-web successfully started
[19:53:55] INFO: Starting otbr-web...
[INFO]-WEB-----: Running 0.3.0-b067e5ac-dirty
listenAddr not specified, using default ::
[INFO]-WEB-----: Border router web started on wpan0
00:00:00.221 [I] P-Daemon------: Session socket is ready
00:00:00.221 [D] Cli-----------: Input: state
00:00:00.221 [D] Cli-----------: Output: disabled
00:00:00.221 [D] Cli-----------: Output: Done
00:00:00.241 [I] P-Daemon------: Session socket is ready
00:00:00.241 [D] Cli-----------: Input: txpower 6
00:00:00.241 [D] P-SpinelDrive-: Sent spinel frame, flg:0x2, iid:0, tid:1, cmd:PROP_VALUE_SET, key:PHY_TX_POWER, power:6
00:00:00.241 [D] P-RadioSpinel-: Wait response: tid=1 key=37
00:00:00.251 [D] P-SpinelDrive-: Received spinel frame, flg:0x2, iid:0, tid:1, cmd:PROP_VALUE_IS, key:PHY_TX_POWER, power:5
00:00:00.251 [D] Cli-----------: Output: Done
Done
s6-rc: info: service otbr-agent-configure successfully started
s6-rc: info: service otbr-agent-rest-discovery: starting
00:00:00.306 [I] P-Daemon------: Session socket is ready
00:00:00.306 [D] Cli-----------: Input: rcp version
00:00:00.306 [D] Cli-----------: Output: SL-OPENTHREAD/2.5.2.0_GitHub-1fceb225b; EFR32; Feb 12 2025 08:21:10
00:00:00.306 [D] Cli-----------: Output: Done
00:00:00.306 [W] P-Daemon------: Failed to write CLI output: Broken pipe
[19:53:55] INFO: Successfully sent discovery information to Home Assistant.
s6-rc: info: service otbr-agent-rest-discovery successfully started
s6-rc: info: service legacy-services: starting
s6-rc: info: service legacy-services successfully started
[INFO]-MDNS----: Successfully registered service Home Assistant OpenThread Border Router #118C._meshcop._udp
[INFO]-BA------: Result of publish meshcop service Home Assistant OpenThread Border Router #118C._meshcop._udp.local: OK
[INFO]-BA------: Result of publish meshcop service Home Assistant OpenThread Border Router #118C._meshcop._udp.local: OK