-
Notifications
You must be signed in to change notification settings - Fork 52
Description
I just received my dual radio ezsp and I've been trying to connect to it but I haven't been able to the zigbee radio in any way.
I can see the web ui just fine. However, when I try connecting to it from zigbee2mqtt I get failures with this log.
[18:50:48] INFO: Preparing to start...
[18:50:48] INFO: Socat not enabled
[18:50:48] INFO: Starting Zigbee2MQTT...
Starting Zigbee2MQTT without watchdog.
[2025-06-05 18:50:49] debug: z2m: Removing old log directory '/config/zigbee2mqtt/log/2025-06-04.19-37-10'
[2025-06-05 18:50:49] info: z2m: Logging to console, file (filename: log.log)
[2025-06-05 18:50:49] debug: z2m: Loaded state from file /config/zigbee2mqtt/state.json
[2025-06-05 18:50:49] info: z2m: Starting Zigbee2MQTT version 2.4.0 (commit #unknown)
[2025-06-05 18:50:49] info: z2m: Starting zigbee-herdsman (4.1.0)
[2025-06-05 18:50:49] debug: z2m: Using zigbee-herdsman with settings: '"{\"network\":{\"panID\":6754,\"extendedPanID\":[221,221,221,221,221,221,221,221],\"channelList\":[24],\"networkKey\":\"HIDDEN\"},\"databasePath\":\"/config/zigbee2mqtt/database.db\",\"databaseBackupPath\":\"/config/zigbee2mqtt/database.db.backup\",\"backupPath\":\"/config/zigbee2mqtt/coordinator_backup.json\",\"serialPort\":{\"path\":\"tcp://192.168.1.250:6638\",\"adapter\":\"ember\"},\"adapter\":{\"disableLED\":false}}"'
[2025-06-05 18:50:49] info: zh:ember: Using default stack config.
[2025-06-05 18:50:49] debug: zh:controller: Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":"HIDDEN","panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[24]},"serialPort":{"path":"tcp://IP:6638","adapter":"ember"},"adapter":{"disableLED":false},"databasePath":"/config/zigbee2mqtt/database.db","databaseBackupPath":"/config/zigbee2mqtt/database.db.backup","backupPath":"/config/zigbee2mqtt/coordinator_backup.json"}'
[2025-06-05 18:50:49] info: zh:ember: ======== Ember Adapter Starting ========
[2025-06-05 18:50:49] info: zh:ember:ezsp: ======== EZSP starting ========
[2025-06-05 18:50:49] info: zh:ember:uart:ash: ======== ASH Adapter reset ========
[2025-06-05 18:50:49] debug: zh:ember:uart:ash: Opening TCP socket with IP:6638
[2025-06-05 18:50:49] debug: zh:ember:uart:ash: Socket connected
[2025-06-05 18:50:49] info: zh:ember:uart:ash: Socket ready
[2025-06-05 18:50:49] info: zh:ember:uart:ash: ======== ASH starting ========
[2025-06-05 18:50:49] debug: zh:ember:uart:ash: ---> [FRAME type=RST]
[2025-06-05 18:50:49] debug: zh:ember:uart:ash: Waiting for RSTACK... 0/2500
[2025-06-05 18:50:50] debug: zh:ember:uart:ash: Waiting for RSTACK... 100/2500
[2025-06-05 18:50:50] debug: zh:ember:uart:ash: Waiting for RSTACK... 200/2500
[2025-06-05 18:50:50] debug: zh:ember:uart:ash: Waiting for RSTACK... 300/2500
[2025-06-05 18:50:50] debug: zh:ember:uart:ash: Waiting for RSTACK... 400/2500
[2025-06-05 18:50:50] debug: zh:ember:uart:ash: Waiting for RSTACK... 500/2500
[2025-06-05 18:50:50] debug: zh:ember:uart:ash: Waiting for RSTACK... 600/2500
[2025-06-05 18:50:50] debug: zh:ember:uart:ash: Waiting for RSTACK... 700/2500
[2025-06-05 18:50:50] debug: zh:ember:uart:ash: Waiting for RSTACK... 800/2500
[2025-06-05 18:50:50] debug: zh:ember:uart:ash: Waiting for RSTACK... 900/2500
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: Waiting for RSTACK... 1000/2500
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: Waiting for RSTACK... 1100/2500
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=RSTACK]
[2025-06-05 18:50:51] info: zh:ember:uart:ash: ======== ASH connected ========
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0](ackRx=0)
[2025-06-05 18:50:51] info: zh:ember:uart:ash: ======== ASH started ========
[2025-06-05 18:50:51] info: zh:ember:ezsp: ======== EZSP started ========
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=0:"VERSION" Seq=0 Len=4]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0](ackRx=0)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1](ackRx=0 frmTx=1)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0](frmRx=0) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1](ackRx=1)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=0:"VERSION" Seq=0 Len=7]
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=0:"VERSION" Seq=1 Len=6]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1](ackRx=1)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=1 frmTx=2)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1](frmRx=1) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2](ackRx=2)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=0:"VERSION" Seq=1 Len=9]
[2025-06-05 18:50:51] info: zh:ember: Adapter EZSP protocol version (13) lower than Host. Switched.
[2025-06-05 18:50:51] debug: zh:ember: Adapter info: EZSPVersion=13 StackType=2 StackVersion=29760
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=170:"GET_VALUE" Seq=2 Len=6]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2](ackRx=2)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3](ackRx=2 frmTx=3)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2](frmRx=2) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3](ackRx=3)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=170:"GET_VALUE" Seq=2 Len=14]
[2025-06-05 18:50:51] info: zh:ember: Adapter version info: {"ezsp":13,"revision":"7.4.4 [GA]","build":0,"major":7,"minor":4,"patch":4,"special":0,"type":170}
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=3 Len=8]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3](ackRx=3)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4](ackRx=3 frmTx=4)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3](frmRx=3) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4](ackRx=4)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=3 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: [EzspConfigId] SET 'TRUST_CENTER_ADDRESS_CACHE_SIZE' TO '2' with status=OK.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=4 Len=8]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=4](ackRx=4)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5](ackRx=4 frmTx=5)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=4](frmRx=4) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5](ackRx=5)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=4 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: [EzspConfigId] SET 'INDIRECT_TRANSMISSION_TIMEOUT' TO '7680' with status=OK.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=5 Len=8]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=5](ackRx=5)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6](ackRx=5 frmTx=6)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5](frmRx=5) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6](ackRx=6)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=5 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: [EzspConfigId] SET 'MAX_HOPS' TO '30' with status=OK.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=6 Len=8]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6](ackRx=6)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7](ackRx=6 frmTx=7)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6](frmRx=6) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7](ackRx=7)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=6 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: [EzspConfigId] SET 'SUPPORTED_NETWORKS' TO '1' with status=OK.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=7 Len=7]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=7](ackRx=7)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0](ackRx=7 frmTx=0)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7](frmRx=7) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0](ackRx=0)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=7 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: [EzspPolicyId] SET 'BINDING_MODIFICATION_POLICY' TO '18' with status=OK.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=8 Len=7]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0](ackRx=0)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1](ackRx=0 frmTx=1)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0](frmRx=0) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1](ackRx=1)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=8 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: [EzspPolicyId] SET 'MESSAGE_CONTENTS_IN_CALLBACK_POLICY' TO '64' with status=OK.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=171:"SET_VALUE" Seq=9 Len=9]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1](ackRx=1)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=1 frmTx=2)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1](frmRx=1) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2](ackRx=2)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=171:"SET_VALUE" Seq=9 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: [EzspValueId] SET 'TRANSIENT_DEVICE_TIMEOUT' TO '16,39' with status=OK.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=21:"SET_MANUFACTURER_CODE" Seq=10 Len=7]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2](ackRx=2)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3](ackRx=2 frmTx=3)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2](frmRx=2) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3](ackRx=3)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=21:"SET_MANUFACTURER_CODE" Seq=10 Len=5]
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=11 Len=8]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3](ackRx=3)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4](ackRx=3 frmTx=4)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3](frmRx=3) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4](ackRx=4)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=11 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: [EzspConfigId] SET 'STACK_PROFILE' TO '2' with status=OK.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=12 Len=8]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=4](ackRx=4)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5](ackRx=4 frmTx=5)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=4](frmRx=4) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5](ackRx=5)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=12 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: [EzspConfigId] SET 'SECURITY_LEVEL' TO '5' with status=OK.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=13 Len=8]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=5](ackRx=5)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6](ackRx=5 frmTx=6)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5](frmRx=5) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6](ackRx=6)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=13 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: [EzspConfigId] SET 'MAX_END_DEVICE_CHILDREN' TO '32' with status=OK.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=14 Len=8]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6](ackRx=6)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7](ackRx=6 frmTx=7)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6](frmRx=6) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7](ackRx=7)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=14 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: [EzspConfigId] SET 'END_DEVICE_POLL_TIMEOUT' TO '8' with status=OK.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=15 Len=8]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=7](ackRx=7)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0](ackRx=7 frmTx=0)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7](frmRx=7) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0](ackRx=0)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=15 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: [EzspConfigId] SET 'TRANSIENT_KEY_TIMEOUT_S' TO '300' with status=OK.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=171:"SET_VALUE" Seq=16 Len=8]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0](ackRx=0)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1](ackRx=0 frmTx=1)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0](frmRx=0) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1](ackRx=1)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=171:"SET_VALUE" Seq=16 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: [EzspValueId] SET 'CCA_THRESHOLD' TO '0' with status=OK.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=17 Len=10]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1](ackRx=1)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=1 frmTx=2)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1](frmRx=1) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2](ackRx=2)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=17 Len=9]
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=2:"ADD_ENDPOINT" Seq=18 Len=63]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2](ackRx=2)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3](ackRx=2 frmTx=3)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2](frmRx=2) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3](ackRx=3)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=2:"ADD_ENDPOINT" Seq=18 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: Registered endpoint '1'.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=19 Len=10]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3](ackRx=3)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4](ackRx=3 frmTx=4)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3](frmRx=3) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4](ackRx=4)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=19 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: Registered multicast table entry (0): {"multicastId":0,"endpoint":1,"networkIndex":0}.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=20 Len=10]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=4](ackRx=4)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5](ackRx=4 frmTx=5)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=4](frmRx=4) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5](ackRx=5)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=20 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: Registered multicast table entry (1): {"multicastId":901,"endpoint":1,"networkIndex":0}.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=21 Len=10]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=5](ackRx=5)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6](ackRx=5 frmTx=6)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5](frmRx=5) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6](ackRx=6)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=21 Len=9]
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=2:"ADD_ENDPOINT" Seq=22 Len=17]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6](ackRx=6)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7](ackRx=6 frmTx=7)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6](frmRx=6) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7](ackRx=7)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=2:"ADD_ENDPOINT" Seq=22 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: Registered endpoint '242'.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=23 Len=10]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=7](ackRx=7)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0](ackRx=7 frmTx=0)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7](frmRx=7) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0](ackRx=0)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=23 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: Registered multicast table entry (2): {"multicastId":2948,"endpoint":242,"networkIndex":0}.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=24 Len=7]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0](ackRx=0)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1](ackRx=0 frmTx=1)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0](frmRx=0) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1](ackRx=1)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=24 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: [EzspPolicyId] SET 'TC_KEY_REQUEST_POLICY' TO '81' with status=OK.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=25 Len=7]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1](ackRx=1)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=1 frmTx=2)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1](frmRx=1) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2](ackRx=2)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=25 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: [EzspPolicyId] SET 'APP_KEY_REQUEST_POLICY' TO '96' with status=OK.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=26 Len=7]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2](ackRx=2)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3](ackRx=2 frmTx=3)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2](frmRx=2) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3](ackRx=3)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=26 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: [EzspPolicyId] SET 'TRUST_CENTER_POLICY' TO '3' with status=OK.
[2025-06-05 18:50:51] debug: zh:ember:ezsp: ===> [FRAME: ID=23:"NETWORK_INIT" Seq=27 Len=7]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3](ackRx=3)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4](ackRx=3 frmTx=4)
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3](frmRx=3) Added to rxQueue
[2025-06-05 18:50:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4](ackRx=4)
[2025-06-05 18:50:51] debug: zh:ember:ezsp: <=== [FRAME: ID=23:"NETWORK_INIT" Seq=27 Len=6]
[2025-06-05 18:50:51] debug: zh:ember: [INIT TC] Network init status=NOT_JOINED.
[2025-06-05 18:50:51] error: z2m: Error while starting zigbee-herdsman
[2025-06-05 18:50:51] error: z2m: Failed to start zigbee-herdsman
[2025-06-05 18:50:51] error: z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start_crashes-runtime.html for possible solutions
[2025-06-05 18:50:51] error: z2m: Exiting...
[2025-06-05 18:50:51] error: z2m: Error: [BACKUP] Current backup file is not for EmberZNet stack.
at EmberAdapter.getStoredBackup (/app/node_modules/.pnpm/[email protected]/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:1163:23)
at EmberAdapter.initTrustCenter (/app/node_modules/.pnpm/[email protected]/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:925:29)
at processTicksAndRejections (node:internal/process/task_queues:105:5)
at runNextTicks (node:internal/process/task_queues:69:3)
at processImmediate (node:internal/timers:453:9)
at EmberAdapter.initEzsp (/app/node_modules/.pnpm/[email protected]/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:708:18)
at EmberAdapter.start (/app/node_modules/.pnpm/[email protected]/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:1548:24)
at Controller.start (/app/node_modules/.pnpm/[email protected]/node_modules/zigbee-herdsman/src/controller/controller.ts:133:29)
at Zigbee.start (/app/lib/zigbee.ts:71:27)
at Controller.start (/app/lib/controller.ts:102:13)
At first because I am migrating from a previous install I realized I might need to change something. Looking at the docs it seems to be potentially possible to migrate controlelrs if you change their ieee address. I tried to change that with universal-silabs-flasher --device socket://IP:6638 write-ieee --ieee IEEE but I get the following log:
2025-06-05 18:55:30.186 beholder universal_silabs_flasher.flasher INFO Probing ApplicationType.GECKO_BOOTLOADER at 115200 baud
2025-06-05 18:55:32.190 beholder universal_silabs_flasher.flasher INFO Probing ApplicationType.EZSP at 115200 baud
Traceback (most recent call last):
File "/home/clint/.local/bin/universal-silabs-flasher", line 8, in <module>
sys.exit(main())
File "/home/clint/.local/lib/python3.9/site-packages/click/core.py", line 1161, in __call__
return self.main(*args, **kwargs)
File "/home/clint/.local/lib/python3.9/site-packages/click/core.py", line 1082, in main
rv = self.invoke(ctx)
File "/home/clint/.local/lib/python3.9/site-packages/click/core.py", line 1697, in invoke
return _process_result(sub_ctx.command.invoke(sub_ctx))
File "/home/clint/.local/lib/python3.9/site-packages/click/core.py", line 1443, in invoke
return ctx.invoke(self.callback, **ctx.params)
File "/home/clint/.local/lib/python3.9/site-packages/click/core.py", line 788, in invoke
return __callback(*args, **kwargs)
File "/home/clint/.local/lib/python3.9/site-packages/click/decorators.py", line 33, in new_func
return f(get_current_context(), *args, **kwargs)
File "/home/clint/.local/lib/python3.9/site-packages/universal_silabs_flasher/flash.py", line 37, in inner
return asyncio.run(f(*args, **kwargs))
File "/usr/lib/python3.9/asyncio/runners.py", line 44, in run
return loop.run_until_complete(main)
File "/usr/lib/python3.9/asyncio/base_events.py", line 642, in run_until_complete
return future.result()
File "/home/clint/.local/lib/python3.9/site-packages/universal_silabs_flasher/flash.py", line 269, in write_ieee
await ctx.obj["flasher"].write_emberznet_eui64(ieee, force=force)
File "/home/clint/.local/lib/python3.9/site-packages/universal_silabs_flasher/flasher.py", line 344, in write_emberznet_eui64
await self.probe_app_type(
File "/home/clint/.local/lib/python3.9/site-packages/universal_silabs_flasher/flasher.py", line 229, in probe_app_type
result = await probe_funcs[probe_method](baudrate=baudrate)
File "/home/clint/.local/lib/python3.9/site-packages/universal_silabs_flasher/flasher.py", line 149, in probe_ezsp
async with self._connect_ezsp(baudrate) as ezsp:
File "/usr/lib/python3.9/contextlib.py", line 175, in __aenter__
return await self.gen.__anext__()
File "/home/clint/.local/lib/python3.9/site-packages/universal_silabs_flasher/emberznet.py", line 27, in connect_ezsp
await ezsp.connect(use_thread=False)
File "/home/clint/.local/lib/python3.9/site-packages/bellows/ezsp/__init__.py", line 138, in connect
await self.startup_reset()
File "/home/clint/.local/lib/python3.9/site-packages/bellows/ezsp/__init__.py", line 119, in startup_reset
await self._gw.wait_for_startup_reset()
File "/home/clint/.local/lib/python3.9/site-packages/bellows/uart.py", line 63, in wait_for_startup_reset
await self._startup_reset_future
ConnectionResetError: Remote server closed connection
I reflashed it with the "TubesZB Dual Radio Kit MGM24" firmware but no change.
Possibly related: the device is discovered by home assistant but is not discovered by esphome. This was unexpected and seems like a bug too.