search

b2un0 / silabs-multipan-docker

A standalone RPC server based on HomeAssistant's Silicon Labs multiprotocol addon
https://hub.docker.com/r/b2un0/silabs-multipan-docker
Apache License 2.0
54 stars 7 forks source link

Docker exiting without reason #10

Closed crystalin closed 7 months ago

crystalin commented 7 months ago

The docker execution exists without showing relevant error. Running on a Ubuntu machine (managing services with nomad, running home assistant, matter server and many other images...)

Command: docker run -it -e 'DEVICE=/dev/ttyUSB0' -e "BAUDRATE=460800" -e "FLOW_CONTROL=true" -e "BACKBONE_IF=enp86s0" -v '/dev/ttyUSB0:/dev/ttyUSB0' -v "/var/run/dbus:/var/run/dbus" -v "/var/run/avahi-daemon/socket:/var/run/avahi-daemon/socket" --privileged --cap-add 'SYS_ADMIN' --cap-add 'NET_ADMIN' --network host -v '/extra/home-assistant/multiplan:/data' b2un0/silabs-multipan-docker:latest 2>&1 | ts | tee docker-multipan.log

Logs:

Jan 18 10:25:48 2024-01-18 10:25:48 [INFO] Web UI and REST API port are exposed, starting otbr-web.
Jan 18 10:25:48 s6-rc-compile: tracing: from s6-rc-compile internals: adding identifier s6rc-oneshot-runner of type longrun
Jan 18 10:25:48 s6-rc-compile: tracing: from s6-rc-compile internals: adding identifier s6rc-fdholder of type longrun
Jan 18 10:25:48 s6-rc-compile: info: parsing /etc/s6-overlay/s6-rc.d/cpcd
Jan 18 10:25:48 s6-rc-compile: info: cpcd has type longrun
Jan 18 10:25:48 s6-rc-compile: tracing: from /etc/s6-overlay/s6-rc.d: adding identifier cpcd of type longrun
Jan 18 10:25:48 s6-rc-compile: tracing: from cpcd: adding identifier universal-silabs-flasher of type unknown
Jan 18 10:25:48 s6-rc-compile: info: parsing /etc/s6-overlay/s6-rc.d/mdns
Jan 18 10:25:48 s6-rc-compile: info: mdns has type longrun
Jan 18 10:25:48 s6-rc-compile: tracing: from /etc/s6-overlay/s6-rc.d: adding identifier mdns of type longrun
Jan 18 10:25:48 s6-rc-compile: info: parsing /etc/s6-overlay/s6-rc.d/otbr-agent
Jan 18 10:25:48 s6-rc-compile: info: otbr-agent has type longrun
Jan 18 10:25:48 s6-rc-compile: tracing: from /etc/s6-overlay/s6-rc.d: adding identifier otbr-agent of type longrun
Jan 18 10:25:48 s6-rc-compile: tracing: from otbr-agent: adding identifier cpcd of type unknown
Jan 18 10:25:48 s6-rc-compile: tracing: identifier cpcd was already declared with type longrun
Jan 18 10:25:48 s6-rc-compile: info: parsing /etc/s6-overlay/s6-rc.d/otbr-web
Jan 18 10:25:48 s6-rc-compile: info: otbr-web has type longrun
Jan 18 10:25:48 s6-rc-compile: tracing: from /etc/s6-overlay/s6-rc.d: adding identifier otbr-web of type longrun
Jan 18 10:25:48 s6-rc-compile: tracing: from otbr-web: adding identifier otbr-agent of type unknown
Jan 18 10:25:48 s6-rc-compile: tracing: identifier otbr-agent was already declared with type longrun
Jan 18 10:25:48 s6-rc-compile: info: parsing /etc/s6-overlay/s6-rc.d/socat-cpcd-tcp
Jan 18 10:25:48 s6-rc-compile: info: socat-cpcd-tcp has type longrun
Jan 18 10:25:48 s6-rc-compile: tracing: from /etc/s6-overlay/s6-rc.d: adding identifier socat-cpcd-tcp of type longrun
Jan 18 10:25:48 s6-rc-compile: info: parsing /etc/s6-overlay/s6-rc.d/universal-silabs-flasher
Jan 18 10:25:48 s6-rc-compile: info: universal-silabs-flasher has type oneshot
Jan 18 10:25:48 s6-rc-compile: tracing: from /etc/s6-overlay/s6-rc.d: adding identifier universal-silabs-flasher of type oneshot
Jan 18 10:25:48 s6-rc-compile: tracing: previously encountered identifier universal-silabs-flasher now has type oneshot
Jan 18 10:25:48 s6-rc-compile: tracing: dependency from universal-silabs-flasher to s6rc-oneshot-runner (0)
Jan 18 10:25:48 s6-rc-compile: info: parsing /etc/s6-overlay/s6-rc.d/user
Jan 18 10:25:48 s6-rc-compile: info: user has type bundle
Jan 18 10:25:48 s6-rc-compile: tracing: from /etc/s6-overlay/s6-rc.d: adding identifier user of type bundle
Jan 18 10:25:48 s6-rc-compile: tracing: from user: adding identifier mdns of type unknown
Jan 18 10:25:48 s6-rc-compile: tracing: identifier mdns was already declared with type longrun
Jan 18 10:25:48 s6-rc-compile: tracing: from user: adding identifier otbr-agent of type unknown
Jan 18 10:25:48 s6-rc-compile: tracing: identifier otbr-agent was already declared with type longrun
Jan 18 10:25:48 s6-rc-compile: tracing: from user: adding identifier zigbeed of type unknown
Jan 18 10:25:48 s6-rc-compile: tracing: from user: adding identifier cpcd of type unknown
Jan 18 10:25:48 s6-rc-compile: tracing: identifier cpcd was already declared with type longrun
Jan 18 10:25:48 s6-rc-compile: tracing: from user: adding identifier otbr-web of type unknown
Jan 18 10:25:48 s6-rc-compile: tracing: identifier otbr-web was already declared with type longrun
Jan 18 10:25:48 s6-rc-compile: info: parsing /etc/s6-overlay/s6-rc.d/user2
Jan 18 10:25:48 s6-rc-compile: info: user2 has type bundle
Jan 18 10:25:48 s6-rc-compile: tracing: from /etc/s6-overlay/s6-rc.d: adding identifier user2 of type bundle
Jan 18 10:25:48 s6-rc-compile: info: parsing /etc/s6-overlay/s6-rc.d/zigbeed
Jan 18 10:25:48 s6-rc-compile: info: zigbeed has type longrun
Jan 18 10:25:48 s6-rc-compile: tracing: from /etc/s6-overlay/s6-rc.d: adding identifier zigbeed of type longrun
Jan 18 10:25:48 s6-rc-compile: tracing: previously encountered identifier zigbeed now has type longrun
Jan 18 10:25:48 s6-rc-compile: tracing: from zigbeed: adding identifier cpcd of type unknown
Jan 18 10:25:48 s6-rc-compile: tracing: identifier cpcd was already declared with type longrun
Jan 18 10:25:48 s6-rc-compile: info: parsing /package/admin/s6-overlay-3.1.6.2/etc/s6-rc/sources/base
Jan 18 10:25:48 s6-rc-compile: info: base has type bundle
Jan 18 10:25:48 s6-rc-compile: tracing: from /package/admin/s6-overlay-3.1.6.2/etc/s6-rc/sources: adding identifier base of type bundle
Jan 18 10:25:48 s6-rc-compile: tracing: from base: adding identifier legacy-cont-init of type unknown
Jan 18 10:25:48 s6-rc-compile: tracing: from base: adding identifier fix-attrs of type unknown
Jan 18 10:25:48 s6-rc-compile: info: parsing /package/admin/s6-overlay-3.1.6.2/etc/s6-rc/sources/fix-attrs
Jan 18 10:25:48 s6-rc-compile: info: fix-attrs has type oneshot
Jan 18 10:25:48 s6-rc-compile: tracing: from /package/admin/s6-overlay-3.1.6.2/etc/s6-rc/sources: adding identifier fix-attrs of type oneshot
Jan 18 10:25:48 s6-rc-compile: tracing: previously encountered identifier fix-attrs now has type oneshot
Jan 18 10:25:48 s6-rc-compile: tracing: dependency from fix-attrs to s6rc-oneshot-runner (0)
Jan 18 10:25:48 s6-rc-compile: info: parsing /package/admin/s6-overlay-3.1.6.2/etc/s6-rc/sources/legacy-cont-init
Jan 18 10:25:48 s6-rc-compile: info: legacy-cont-init has type oneshot
Jan 18 10:25:48 s6-rc-compile: tracing: from /package/admin/s6-overlay-3.1.6.2/etc/s6-rc/sources: adding identifier legacy-cont-init of type oneshot
Jan 18 10:25:48 s6-rc-compile: tracing: previously encountered identifier legacy-cont-init now has type oneshot
Jan 18 10:25:48 s6-rc-compile: tracing: from legacy-cont-init: adding identifier fix-attrs of type unknown
Jan 18 10:25:48 s6-rc-compile: tracing: identifier fix-attrs was already declared with type oneshot
Jan 18 10:25:48 s6-rc-compile: tracing: dependency from legacy-cont-init to fix-attrs (145)
Jan 18 10:25:48 s6-rc-compile: tracing: dependency from legacy-cont-init to s6rc-oneshot-runner (0)
Jan 18 10:25:48 s6-rc-compile: info: parsing /package/admin/s6-overlay-3.1.6.2/etc/s6-rc/sources/legacy-services
Jan 18 10:25:48 s6-rc-compile: info: legacy-services has type oneshot
Jan 18 10:25:48 s6-rc-compile: tracing: from /package/admin/s6-overlay-3.1.6.2/etc/s6-rc/sources: adding identifier legacy-services of type oneshot
Jan 18 10:25:48 s6-rc-compile: tracing: from legacy-services: adding identifier user of type unknown
Jan 18 10:25:48 s6-rc-compile: tracing: identifier user was already declared with type bundle
Jan 18 10:25:48 s6-rc-compile: tracing: from legacy-services: adding identifier base of type unknown
Jan 18 10:25:48 s6-rc-compile: tracing: identifier base was already declared with type bundle
Jan 18 10:25:48 s6-rc-compile: tracing: dependency from legacy-services to user (104)
Jan 18 10:25:48 s6-rc-compile: tracing: dependency from legacy-services to base (123)
Jan 18 10:25:48 s6-rc-compile: tracing: dependency from legacy-services to s6rc-oneshot-runner (0)
Jan 18 10:25:48 s6-rc-compile: info: parsing /package/admin/s6-overlay-3.1.6.2/etc/s6-rc/sources/top
Jan 18 10:25:48 s6-rc-compile: info: top has type bundle
Jan 18 10:25:48 s6-rc-compile: tracing: from /package/admin/s6-overlay-3.1.6.2/etc/s6-rc/sources: adding identifier top of type bundle
Jan 18 10:25:48 s6-rc-compile: tracing: from top: adding identifier user of type unknown
Jan 18 10:25:48 s6-rc-compile: tracing: identifier user was already declared with type bundle
Jan 18 10:25:48 s6-rc-compile: tracing: from top: adding identifier base of type unknown
Jan 18 10:25:48 s6-rc-compile: tracing: identifier base was already declared with type bundle
Jan 18 10:25:48 s6-rc-compile: tracing: from top: adding identifier legacy-services of type unknown
Jan 18 10:25:48 s6-rc-compile: tracing: identifier legacy-services was already declared with type oneshot
Jan 18 10:25:48 s6-rc-compile: tracing: from top: adding identifier user2 of type unknown
Jan 18 10:25:48 s6-rc-compile: tracing: identifier user2 was already declared with type bundle
Jan 18 10:25:48 s6-rc-compile: info: making bundles for pipelines
Jan 18 10:25:48 s6-rc-compile: info: resolving bundle names
Jan 18 10:25:48 s6-rc-compile: info: converting bundle array
Jan 18 10:25:48 s6-rc-compile: info: resolving service names
Jan 18 10:25:48 s6-rc-compile: tracing: cpcd depends on oneshot universal-silabs-flasher (8)
Jan 18 10:25:48 s6-rc-compile: tracing: otbr-agent depends on longrun cpcd (2)
Jan 18 10:25:48 s6-rc-compile: tracing: otbr-web depends on longrun otbr-agent (4)
Jan 18 10:25:48 s6-rc-compile: tracing: zigbeed depends on longrun cpcd (2)
Jan 18 10:25:48 s6-rc-compile: tracing: universal-silabs-flasher depends on longrun s6rc-oneshot-runner (0)
Jan 18 10:25:48 s6-rc-compile: tracing: fix-attrs depends on longrun s6rc-oneshot-runner (0)
Jan 18 10:25:48 s6-rc-compile: tracing: legacy-cont-init depends on oneshot fix-attrs (9)
Jan 18 10:25:48 s6-rc-compile: tracing: legacy-cont-init depends on longrun s6rc-oneshot-runner (0)
Jan 18 10:25:48 s6-rc-compile: tracing: legacy-services depends on bundle user
Jan 18 10:25:48 s6-rc-compile: tracing: legacy-services depends on bundle base
Jan 18 10:25:48 s6-rc-compile: tracing: legacy-services depends on longrun s6rc-oneshot-runner (0)
Jan 18 10:25:48 s6-rc-compile: info: converting service dependency array
Jan 18 10:25:48 s6-rc-compile: info: checking database correctness
Jan 18 10:25:48 s6-rc-compile: info: writing compiled information to /run/s6/db
Jan 18 10:25:48 s6-rc-compile: info: writing /run/s6/db/n
Jan 18 10:25:48 s6-rc-compile: info: writing /run/s6/db/resolve.cdb
Jan 18 10:25:48 s6-rc-compile: info: writing /run/s6/db/db
Jan 18 10:25:48 s6-rc-compile: info: writing /run/s6/db/servicedirs
Jan 18 10:25:48 s6-rc: info: bringing selected services up
Jan 18 10:25:48 s6-rc: info: service mdns: starting
Jan 18 10:25:48 s6-rc: info: service s6rc-oneshot-runner: starting
Jan 18 10:25:48 s6-rc: info: service mdns successfully started
Jan 18 10:25:48 s6-rc: info: service s6rc-oneshot-runner successfully started
Jan 18 10:25:48 s6-rc: info: service fix-attrs: starting
Jan 18 10:25:48 s6-ipcclient: info: s6-ipcclient: connected to /run/s6-rc/servicedirs/s6rc-oneshot-runner/s
Jan 18 10:25:48 s6-rc: info: service universal-silabs-flasher: starting
Jan 18 10:25:48 s6-ipcclient: info: s6-ipcclient: connected to /run/s6-rc/servicedirs/s6rc-oneshot-runner/s
Jan 18 10:25:48 s6-rc: info: service fix-attrs successfully started
Jan 18 10:25:48 s6-rc: info: service legacy-cont-init: starting
Jan 18 10:25:48 s6-ipcclient: info: s6-ipcclient: connected to /run/s6-rc/servicedirs/s6rc-oneshot-runner/s
Jan 18 10:25:48 cont-init: info: running /etc/cont-init.d/check-cpcd-shm.sh
Jan 18 10:25:48 cont-init: info: /etc/cont-init.d/check-cpcd-shm.sh exited 0
Jan 18 10:25:48 cont-init: info: running /etc/cont-init.d/config.sh
Jan 18 10:25:48 2024-01-18 10:25:48 [INFO] Starting mDNS Responder...
Jan 18 10:25:48 Default: mDNSResponder (Engineering Build) (Jan 11 2024 17:02:25) starting
Jan 18 10:25:48 2024-01-18 10:25:48 [INFO] Flashing firmware is disabled
Jan 18 10:25:48 s6-rc: info: service universal-silabs-flasher successfully started
Jan 18 10:25:48 s6-rc: info: service cpcd: starting
Jan 18 10:25:48 2024-01-18 10:25:48 [INFO] 
Jan 18 10:25:48 ######### ENV ######
Jan 18 10:25:48 DEBUG_MODE=true
Jan 18 10:25:48 S6_BEHAVIOUR_IF_STAGE2_FAILS=2
Jan 18 10:25:48 HOSTNAME=shinkandia
Jan 18 10:25:48 S6_CMD_WAIT_FOR_SERVICES_MAXTIME=0
Jan 18 10:25:48 S6_SERVICES_READYTIME=50
Jan 18 10:25:48 BAUDRATE=460800
Jan 18 10:25:48 BACKBONE_IF=enp86s0
Jan 18 10:25:48 PWD=/run/s6-rc:s6-rc-init:JMbGce/servicedirs/s6rc-oneshot-runner
Jan 18 10:25:48 BACKBONE_ROUTER=1
Jan 18 10:25:48 FLOW_CONTROL=true
Jan 18 10:25:48 HOME=/root
Jan 18 10:25:48 LANG=C.UTF-8
Jan 18 10:25:48 WEB_GUI=1
Jan 18 10:25:48 OTBR_LOG_LEVEL=notice
Jan 18 10:25:48 S6_VERBOSITY=5
Jan 18 10:25:48 S6_STAGE2_HOOK=/etc/s6-overlay/scripts/enable-check.sh
Jan 18 10:25:48 AUTOFLASH_FIRMWARE=0
Jan 18 10:25:48 OTBR_WEB_PORT=8086
Jan 18 10:25:48 TERM=xterm
Jan 18 10:25:48 OTB_FIREWALL=1
Jan 18 10:25:48 CURL_CA_BUNDLE=/etc/ssl/certs/ca-certificates.crt
Jan 18 10:25:48 CPCD_TRACE=false
Jan 18 10:25:48 OTBR_BUILD_DEPS=build-essential ninja-build cmake wget ca-certificates   libreadline-dev libncurses-dev libcpputest-dev libdbus-1-dev libavahi-common-dev   libavahi-client-dev libboost-dev libboost-filesystem-dev libboost-system-dev   libnetfilter-queue-dev
Jan 18 10:25:48 SHLVL=1
Jan 18 10:25:48 DOCKER=1
Jan 18 10:25:48 CPCP_DISABLE_ENCRYPTION=true
Jan 18 10:25:48 OTBR_REST_LISTEN_PORT=8081
Jan 18 10:25:48 DEVICE=/dev/ttyUSB0
Jan 18 10:25:48 BORDER_ROUTING=1
Jan 18 10:25:48 PATH=/command:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
Jan 18 10:25:48 S6_CMD_WAIT_FOR_SERVICES=1
Jan 18 10:25:48 NETWORK_DEVICES=0
Jan 18 10:25:48 EZSP_LISTEN_PORT=20108
Jan 18 10:25:48 DEBIAN_FRONTEND=noninteractive
Jan 18 10:25:48 OTBR_ENABLE=1
Jan 18 10:25:48 _=/usr/bin/env
Jan 18 10:25:48 2024-01-18 10:25:48 [INFO] Starting cpcd...
Jan 18 10:25:48 WARNING in function 'main' in file /usr/src/cpc-daemon/main.c at line #187 : Running CPCd as 'root' is not recommended. Proceed at your own risk.
Jan 18 10:25:48 FATAL in function 'config_validate_configuration' in file /usr/src/cpc-daemon/misc/config.c at line #967 : Use of encryption was requested, but the daemon was not compiled with -DENABLE_ENCRYPTION
Jan 18 10:25:48 2024-01-18 10:25:48 [INFO] Generating cpcd configuration.
Jan 18 10:25:48 cont-init: info: /etc/cont-init.d/config.sh exited 0
Jan 18 10:25:48 s6-rc: info: service legacy-cont-init successfully started
Jan 18 10:25:49 [2024-01-18T10:25:48.088960Z] Info : [CPCd v4.4.0.0] [Library API v3] [RCP Protocol v5]
Jan 18 10:25:49 [2024-01-18T10:25:48.088977Z] Info : Git commit: 1fcaa81347466165f81e4533ee4471e9c3b6db0a / branch: 
Jan 18 10:25:49 [2024-01-18T10:25:48.088978Z] Info : Sources hash: 1e938c77bacd9c9d6d8fe7b457208a3a8a2435bd6374a1918605ffb864bf1ebe
Jan 18 10:25:49 [2024-01-18T10:25:48.088979Z] WARNING : In function 'main' in file /usr/src/cpc-daemon/main.c at line #187 : Running CPCd as 'root' is not recommended. Proceed at your own risk.
Jan 18 10:25:49 [2024-01-18T10:25:48.088986Z] Info : Reading cli arguments
Jan 18 10:25:49 [2024-01-18T10:25:48.088989Z] Info : /usr/local/bin/cpcd 
Jan 18 10:25:49 [2024-01-18T10:25:48.089037Z] *** ASSERT *** : FATAL in function 'config_validate_configuration' in file /usr/src/cpc-daemon/misc/config.c at line #967 : Use of encryption was requested, but the daemon was not compiled with -DENABLE_ENCRYPTION
Jan 18 10:25:49 [2024-01-18T10:25:49.089121Z] Info : Daemon exiting with status EXIT_FAILURE
Jan 18 10:25:49 Logger buffer size = 28672, highwater mark = 844 : 2.94%. Lost logs : 0
Jan 18 10:25:49 2024-01-18 10:25:49 [INFO] CPC ended with exit code 1 (signal 0)...
Jan 18 10:25:49 rm: cannot remove '/dev/shm/cpcd': No such file or directory
Jan 18 10:25:50 2024-01-18 10:25:50 [INFO] Starting cpcd...
Jan 18 10:25:50 WARNING in function 'main' in file /usr/src/cpc-daemon/main.c at line #187 : Running CPCd as 'root' is not recommended. Proceed at your own risk.
Jan 18 10:25:51 s6-rc: info: service cpcd successfully started
Jan 18 10:25:51 s6-rc: info: service zigbeed: starting
Jan 18 10:25:51 s6-rc: info: service otbr-agent: starting
Jan 18 10:25:51 s6-rc: info: service zigbeed successfully started
Jan 18 10:25:51 2024-01-18 10:25:51 [INFO] Starting zigbeed...
Jan 18 10:25:51 By using this software, you are agreeing to the Silicon Labs MSLA found at https://www.silabs.com/about-us/legal/master-software-license-agreement.
Jan 18 10:25:51 2024-01-18 10:25:51 [INFO] Setup OTBR firewall...
Jan 18 10:25:51 2024-01-18 10:25:51 [INFO] Starting otbr-agent...
Jan 18 10:25:51 otbr-agent[259]: [NOTE]-AGENT---: Running 0.3.0
Jan 18 10:25:51 otbr-agent[259]: [NOTE]-AGENT---: Thread version: 1.3.0
Jan 18 10:25:51 otbr-agent[259]: [NOTE]-AGENT---: Thread interface: wpan0
Jan 18 10:25:51 otbr-agent[259]: [NOTE]-AGENT---: Radio URL: spinel+cpc://cpcd_0?iid=2&iid-list=0
Jan 18 10:25:51 otbr-agent[259]: [NOTE]-ILS-----: Infra link selected: enp86s0
Jan 18 10:25:51 otbr-agent[259]: 49d.18:08:52.541 [C] Platform------: mCpcBusSpeed = 115200
Jan 18 10:25:51 [2024-01-18T10:25:50.139998Z] Info : [CPCd v4.4.0.0] [Library API v3] [RCP Protocol v5]
Jan 18 10:25:51 [2024-01-18T10:25:50.140025Z] Info : Git commit: 1fcaa81347466165f81e4533ee4471e9c3b6db0a / branch: 
Jan 18 10:25:51 [2024-01-18T10:25:50.140028Z] Info : Sources hash: 1e938c77bacd9c9d6d8fe7b457208a3a8a2435bd6374a1918605ffb864bf1ebe
Jan 18 10:25:51 [2024-01-18T10:25:50.140032Z] WARNING : In function 'main' in file /usr/src/cpc-daemon/main.c at line #187 : Running CPCd as 'root' is not recommended. Proceed at your own risk.
Jan 18 10:25:51 [2024-01-18T10:25:50.140043Z] Info : Reading cli arguments
Jan 18 10:25:51 [2024-01-18T10:25:50.140049Z] Info : /usr/local/bin/cpcd 
Jan 18 10:25:51 [2024-01-18T10:25:50.141212Z] Info : Reading configuration
Jan 18 10:25:51 [2024-01-18T10:25:50.141213Z] Info :   file_path = /usr/local/etc/cpcd.conf
Jan 18 10:25:51 [2024-01-18T10:25:50.141214Z] Info :   instance_name = cpcd_0
Jan 18 10:25:51 [2024-01-18T10:25:50.141215Z] Info :   socket_folder = /dev/shm
Jan 18 10:25:51 [2024-01-18T10:25:50.141216Z] Info :   operation_mode = MODE_NORMAL
Jan 18 10:25:51 [2024-01-18T10:25:50.141217Z] Info :   use_encryption = false
Jan 18 10:25:51 [2024-01-18T10:25:50.141218Z] Info :   binding_key_file = /root/.cpcd/binding.key
Jan 18 10:25:51 [2024-01-18T10:25:50.141219Z] Info :   stdout_tracing = false
Jan 18 10:25:51 [2024-01-18T10:25:50.141219Z] Info :   file_tracing = false
Jan 18 10:25:51 [2024-01-18T10:25:50.141220Z] Info :   lttng_tracing = false
Jan 18 10:25:51 [2024-01-18T10:25:50.141221Z] Info :   enable_frame_trace = false
Jan 18 10:25:51 [2024-01-18T10:25:50.141222Z] Info :   traces_folder = /dev/shm/cpcd-traces
Jan 18 10:25:51 [2024-01-18T10:25:50.141222Z] Info :   bus = UART
Jan 18 10:25:51 [2024-01-18T10:25:50.141223Z] Info :   uart_baudrate = 460800
Jan 18 10:25:51 [2024-01-18T10:25:50.141224Z] Info :   uart_hardflow = true
Jan 18 10:25:51 [2024-01-18T10:25:50.141225Z] Info :   uart_file = /dev/ttyUSB0
Jan 18 10:25:51 [2024-01-18T10:25:50.141226Z] Info :   fu_recovery_pins_enabled = false
Jan 18 10:25:51 [2024-01-18T10:25:50.141226Z] Info :   fu_connect_to_bootloader = false
Jan 18 10:25:51 [2024-01-18T10:25:50.141227Z] Info :   fu_enter_bootloader = false
Jan 18 10:25:51 [2024-01-18T10:25:50.141228Z] Info :   restart_cpcd = false
Jan 18 10:25:51 [2024-01-18T10:25:50.141229Z] Info :   application_version_validation = false
Jan 18 10:25:51 [2024-01-18T10:25:50.141229Z] Info :   print_secondary_versions_and_exit = false
Jan 18 10:25:51 [2024-01-18T10:25:50.141230Z] Info :   use_noop_keep_alive = false
Jan 18 10:25:51 [2024-01-18T10:25:50.141231Z] Info :   reset_sequence = true
Jan 18 10:25:51 [2024-01-18T10:25:50.141232Z] Info :   stats_interval = 0
Jan 18 10:25:51 [2024-01-18T10:25:50.141233Z] Info :   rlimit_nofile = 2000
Jan 18 10:25:51 [2024-01-18T10:25:50.141233Z] Info : ENCRYPTION IS DISABLED 
Jan 18 10:25:51 [2024-01-18T10:25:50.152406Z] Info : Starting daemon in normal mode
Jan 18 10:25:51 [2024-01-18T10:25:50.163755Z] Info : Connecting to Secondary...
Jan 18 10:25:51 [2024-01-18T10:25:50.239540Z] Info : RX capability is 256 bytes
Jan 18 10:25:51 [2024-01-18T10:25:50.239558Z] Info : Connected to Secondary
Jan 18 10:25:51 [2024-01-18T10:25:50.242852Z] Info : Secondary Protocol v4
Jan 18 10:25:51 [2024-01-18T10:25:50.249714Z] Info : Secondary CPC v4.3.2
Jan 18 10:25:51 [2024-01-18T10:25:50.753373Z] Info : Secondary bus bitrate is 460800
Jan 18 10:25:51 [2024-01-18T10:25:50.760088Z] Info : Secondary APP vUNDEFINED
Jan 18 10:25:51 [2024-01-18T10:25:50.760190Z] Info : Daemon startup was successful. Waiting for client connections
Jan 18 10:25:51 [2024-01-18T10:25:51.111854Z] Info : New client connection using library v4.4.0.0
Jan 18 10:25:51 [2024-01-18T10:25:51.115399Z] Info : Opened connection socket for ep#12
Jan 18 10:25:51 [2024-01-18T10:25:51.119001Z] Info : Endpoint socket #12: Client connected. 1 connection(s)
Jan 18 10:25:52 [2024-01-18T10:25:52.080417Z] Info : New client connection using library v4.4.0.0
Jan 18 10:25:52 [2024-01-18T10:25:52.084100Z] Info : Endpoint socket #12: Client connected. 2 connection(s)
Jan 18 10:25:53 otbr-agent[259]: 00:00:00.068 [N] RoutingManager: BR ULA prefix: fd75:999a:abae::/48 (loaded)
Jan 18 10:25:53 otbr-agent[259]: 00:00:00.068 [N] RoutingManager: Local on-link prefix: fdde:ad00:beef:cafe::/64
Jan 18 10:25:53 s6-rc: info: service otbr-agent successfully started
Jan 18 10:25:53 s6-rc: info: service otbr-web: starting
Jan 18 10:25:53 s6-rc: info: service otbr-web successfully started
Jan 18 10:25:53 s6-ipcclient: info: s6-ipcclient: connected to /run/s6-rc/servicedirs/s6rc-oneshot-runner/s
Jan 18 10:25:53 2024-01-18 10:25:53 [INFO] Starting otbr-web...
Jan 18 10:25:53 s6-rc: info: service legacy-services: starting
Jan 18 10:25:53 otbr-web[346]: [INFO]-WEB-----: Running 0.3.0
Jan 18 10:25:53 listenAddr not specified, using default ::
Jan 18 10:25:53 otbr-web[346]: [INFO]-WEB-----: Border router web started on wpan0
Jan 18 10:25:53 s6-rc: info: service legacy-services successfully started
Jan 18 10:25:53 s6-rc: info: bringing selected services down
Jan 18 10:25:53 s6-rc: info: service legacy-services: stopping
Jan 18 10:25:53 s6-ipcclient: info: s6-ipcclient: connected to /run/s6-rc/servicedirs/s6rc-oneshot-runner/s
Jan 18 10:25:53 s6-rc: info: service legacy-services successfully stopped
Jan 18 10:25:53 s6-rc: info: service legacy-cont-init: stopping
Jan 18 10:25:53 s6-ipcclient: info: s6-ipcclient: connected to /run/s6-rc/servicedirs/s6rc-oneshot-runner/s
Jan 18 10:25:53 s6-rc: info: service zigbeed: stopping
Jan 18 10:25:53 s6-rc: info: service otbr-web: stopping
Jan 18 10:25:53 s6-rc: info: service mdns: stopping
Jan 18 10:25:53 otbr-web[346]: [CRIT]-WEB-----: Stopping web server
Jan 18 10:25:53 Default: mDNSResponder (Engineering Build) (Jan 11 2024 17:02:25) stopping
Jan 18 10:25:53 otbr-agent[259]: [WARN]-MDNS----: DNSServiceProcessResult failed: Service Not Running (serviceRef = 0x5606e1a4c0c0)
Jan 18 10:25:53 otbr-agent[259]: [WARN]-MDNS----: Need to reconnect to mdnsd
Jan 18 10:25:53 otbr-agent[259]: dnssd_clientstub ConnectToServer: connect() failed path:/var/run/mdnsd Socket:20 Err:-1 Errno:111 Connection refused
Jan 18 10:25:53 otbr-agent[259]: [ERR ]-MDNS----: Failed to register service Home Assistant Silicon Labs Multiprotocol #4AC7._meshcop._udp: Service Not Running
Jan 18 10:25:53 otbr-agent[259]: [WARN]-BA------: Result of publish meshcop service Home Assistant Silicon Labs Multiprotocol #4AC7._meshcop._udp.local: Invalid state
Jan 18 10:25:53 s6-rc: info: service legacy-cont-init successfully stopped
Jan 18 10:25:53 s6-rc: info: service fix-attrs: stopping
Jan 18 10:25:53 s6-ipcclient: info: s6-ipcclient: connected to /run/s6-rc/servicedirs/s6rc-oneshot-runner/s
Jan 18 10:25:53 s6-rc: info: service fix-attrs successfully stopped
Jan 18 10:25:53 2024-01-18 10:25:53 [INFO] zigbeed ended with exit code 256 (signal 15)...
Jan 18 10:25:53 2024-01-18 10:25:53 [INFO] otbr-web ended with exit code 0 (signal 0)...
Jan 18 10:25:53 s6-rc: info: service zigbeed successfully stopped
Jan 18 10:25:53 2024-01-18 10:25:53 [INFO] mDNS ended with exit code 4 (signal 0)...
Jan 18 10:25:53 s6-rc: info: service otbr-web successfully stopped
Jan 18 10:25:53 s6-rc: info: service otbr-agent: stopping
Jan 18 10:25:53 s6-rc: info: service mdns successfully stopped
Jan 18 10:25:53 2024-01-18 10:25:53 [INFO] otbr-agent ended with exit code 0 (signal 0)...
Jan 18 10:25:53 OTBR_FORWARD_INGRESS  all opt    in * out wpan0  ::/0  -> ::/0  
Jan 18 10:25:53 Chain OTBR_FORWARD_INGRESS (0 references)
Jan 18 10:25:53 target     prot opt source               destination         
Jan 18 10:25:53 DROP       all      anywhere             anywhere             PKTTYPE = unicast
Jan 18 10:25:53 DROP       all      anywhere             anywhere             match-set otbr-ingress-deny-src src
Jan 18 10:25:53 ACCEPT     all      anywhere             anywhere             match-set otbr-ingress-allow-dst dst
Jan 18 10:25:53 DROP       all      anywhere             anywhere             PKTTYPE = unicast
Jan 18 10:25:53 ACCEPT     all      anywhere             anywhere            
Jan 18 10:25:53 otbr-ingress-deny-src
Jan 18 10:25:53 otbr-ingress-deny-src-swap
Jan 18 10:25:53 otbr-ingress-allow-dst
Jan 18 10:25:53 otbr-ingress-allow-dst-swap
Jan 18 10:25:53 OTBR_FORWARD_EGRESS  all opt    in wpan0 out *  ::/0  -> ::/0  
Jan 18 10:25:53 Chain OTBR_FORWARD_EGRESS (0 references)
Jan 18 10:25:53 target     prot opt source               destination         
Jan 18 10:25:53 ACCEPT     all      anywhere             anywhere            
Jan 18 10:25:53 2024-01-18 10:25:53 [INFO] OTBR firewall teardown completed.
Jan 18 10:25:53 s6-rc: info: service otbr-agent successfully stopped
Jan 18 10:25:53 s6-rc: info: service cpcd: stopping
Jan 18 10:25:53 [2024-01-18T10:25:53.586989Z] Info : Endpoint socket #12: Client disconnected. 1 connections
Jan 18 10:25:53 [2024-01-18T10:25:53.587008Z] Info : Client disconnected
Jan 18 10:25:53 [2024-01-18T10:25:53.600524Z] Info : Endpoint socket #12: Client disconnected. 0 connections
Jan 18 10:25:53 [2024-01-18T10:25:53.642579Z] Info : Client disconnected
Jan 18 10:25:53 [2024-01-18T10:25:53.971508Z] Info : Server core cleanup
Jan 18 10:25:53 [2024-01-18T10:25:53.971558Z] Info : Daemon exiting with status EXIT_SUCCESS
Jan 18 10:25:53 Logger buffer size = 28672, highwater mark = 3231 : 11.27%. Lost logs : 0
Jan 18 10:25:53 2024-01-18 10:25:53 [INFO] CPC ended with exit code 0 (signal 0)...
Jan 18 10:25:53 s6-rc: info: service cpcd successfully stopped
Jan 18 10:25:53 s6-rc: info: service universal-silabs-flasher: stopping
Jan 18 10:25:53 s6-ipcclient: info: s6-ipcclient: connected to /run/s6-rc/servicedirs/s6rc-oneshot-runner/s
Jan 18 10:25:53 s6-rc: info: service universal-silabs-flasher successfully stopped
Jan 18 10:25:53 s6-rc: info: service s6rc-oneshot-runner: stopping
Jan 18 10:25:53 s6-rc: info: service s6rc-oneshot-runner successfully stopped

After the legacy-services started, s6 brings the services down, not sure why

Jan 18 10:25:53 s6-rc: info: service legacy-services successfully started
Jan 18 10:25:53 s6-rc: info: bringing selected services down
b2un0 commented 7 months ago

does it work before?

thats looks like the relevant errors..

Jan 18 10:25:53 otbr-agent[259]: [WARN]-MDNS----: DNSServiceProcessResult failed: Service Not Running (serviceRef = 0x5606e1a4c0c0)
Jan 18 10:25:53 otbr-agent[259]: [WARN]-MDNS----: Need to reconnect to mdnsd
Jan 18 10:25:53 otbr-agent[259]: dnssd_clientstub ConnectToServer: connect() failed path:/var/run/mdnsd Socket:20 Err:-1 Errno:111 Connection refused
Jan 18 10:25:53 otbr-agent[259]: [ERR ]-MDNS----: Failed to register service Home Assistant Silicon Labs Multiprotocol #4AC7._meshcop._udp: Service Not Running
Jan 18 10:25:53 otbr-agent[259]: [WARN]-BA------: Result of publish meshcop service Home Assistant Silicon Labs Multiprotocol #4AC7._meshcop._udp.local: Invalid state
Jan 18 10:25:53 s6-rc: info: service legacy-cont-init successfully stopped
Jan 18 10:25:53 s6-rc: info: service fix-attrs: stopping
Jan 18 10:25:53 s6-ipcclient: info: s6-ipcclient: connected to /run/s6-rc/servicedirs/s6rc-oneshot-runner/s
Jan 18 10:25:53 s6-rc: info: service fix-attrs successfully stopped
Jan 18 10:25:53 �[32m2024-01-18 10:25:53 [INFO] zigbeed ended with exit code 256 (signal 15)...�[0m
Jan 18 10:25:53 �[32m2024-01-18 10:25:53 [INFO] otbr-web ended with exit code 0 (signal 0)...�[0m
Jan 18 10:25:53 s6-rc: info: service zigbeed successfully stopped
Jan 18 10:25:53 �[32m2024-01-18 10:25:53 [INFO] mDNS ended with exit code 4 (signal 0)...�[0m

so some questions:

  1. do you have a working IPv6 in your LAN?
  2. whats usb stick you are using?
  3. whats the firmware version on this stick?
crystalin commented 7 months ago
  1. This is the first time I use it.
  2. SkyConnect (in multipan)
  3. When I misconfigure the env variable which make the otbr-agent fails (like providing a wrong backbone), the docker image works fine (ZigBee works but obviously Thread is not because the agent keeps rebooting).

The error you pointed are probably not related, as they appear after s6 stops the services. So I suspect it is normal the agent complains the mdns is not reachable after having been stopped.

What I don't understand is why the s6 is stopping the services once they all start. The docker image also stops without obvious error if I use OTBR_ENABLE=0

crystalin commented 7 months ago

I found the issue.

When starting cpcd the configuration is not yet initialize so it fails

Jan 18 10:25:49 [2024-01-18T10:25:48.088979Z] WARNING : In function 'main' in file /usr/src/cpc-daemon/main.c at line #187 : Running CPCd as 'root' is not recommended. Proceed at your own risk.
Jan 18 10:25:49 [2024-01-18T10:25:48.088986Z] Info : Reading cli arguments
Jan 18 10:25:49 [2024-01-18T10:25:48.088989Z] Info : /usr/local/bin/cpcd 
Jan 18 10:25:49 [2024-01-18T10:25:48.089037Z] *** ASSERT *** : FATAL in function 'config_validate_configuration' in file /usr/src/cpc-daemon/misc/config.c at line #967 : Use of encryption was requested, but the daemon was not compiled with -DENABLE_ENCRYPTION
Jan 18 10:25:49 [2024-01-18T10:25:49.089121Z] Info : Daemon exiting with status EXIT_FAILURE
Jan 18 10:25:49 Logger buffer size = 28672, highwater mark = 844 : 2.94%. Lost logs : 0
Jan 18 10:25:49 �[32m2024-01-18 10:25:49 [INFO] CPC ended with exit code 1 (signal 0)...�[0m

which is fine because it then restart after the configuration has been done

but the script https://github.com/b2un0/silabs-multipan-docker/blob/main/rootfs/etc/s6-overlay/s6-rc.d/cpcd/finish#L12 forces s6 to halt

b2un0 commented 7 months ago

have you seen the VERSIONS.md?

crystalin commented 7 months ago

I'm using NabuCasa_SkyConnect_RCP_v4.4.0_rcp-uart-hw-802154_460800.gbl and 2.4.3 yes

crystalin commented 7 months ago

I think this bug only happens if you have a powerful setup that allows cpcd to run before the configuration gets generated. I'll try to make a PR to fix it later today

b2un0 commented 7 months ago

in the HA community was the same problem by another user https://community.home-assistant.io/t/skyconnect-silabs-multiprotocol-and-docker/526779/116

it's strange that this happens to you with the same setup as it does to me. Except that everything works for me. I also integrade the zigbeed als ZHA Integration for testing purposes.

crystalin commented 7 months ago

The issue in that case is not that the encryption is disable, but it is the fact that the conf file, that contains the flag about encryption is generated (see https://github.com/b2un0/silabs-multipan-docker/blob/main/rootfs/etc/cont-init.d/config.sh#L39-L43) after cpcd is executed. So the first execution of cpcd doesn't have the correct conf file and fails.

I'm sure you can trigger the same bug if you put a sleep 3 before the cp command in that file.

I'm not home, but I'll work on a quick fix later (I tested to remove the halt and it worked locally but I want a better fix)

b2un0 commented 7 months ago

thank your for your fix!

the 2.4.3(latest) and 2.4.2 image are rebuilded and pushed to the registries

crystalin commented 7 months ago

I confirm it fixed it