search

zigbee2mqtt / hassio-zigbee2mqtt

Official Zigbee2MQTT Home Assistant add-on
https://www.zigbee2mqtt.io
Apache License 2.0
1.02k stars 369 forks source link

Z2M unrecoverable error. Add-on is NOT starting, #546

Closed Krzysztonek closed 4 months ago

Krzysztonek commented 7 months ago

Description of the issue

Since version 1.32.0 I'm not able to start Z2M add-on correctly. However, it randomly starts with no issue very rarely. When errors occur I'm getting the log given below. I'm quite confused.

Addon version

1.34.0

Platform

Core 2023.12.1 Supervisor 2023.11.6 Operating System 11.2

Logs of the issue (if applicable)

[11:10:13] INFO: Preparing to start...
[11:10:13] INFO: Socat not enabled
[11:10:13] INFO: Zigbee Herdsman debug logging enabled
[11:10:14] INFO: Starting Zigbee2MQTT...
Zigbee2MQTT:debug 10: Loaded state from file /config/z2m_sky/state.json
Zigbee2MQTT:info  10: Logging to console and directory: '/config/z2m_sky/log/2023-12-10.11-10-16' filename: log.txt
Zigbee2MQTT:debug 10: Removing old log directory '/config/z2m_sky/log/2023-12-10.11-05-02'
Zigbee2MQTT:info  10: Starting Zigbee2MQTT version 1.34.0 (commit #unknown)
Zigbee2MQTT:info  10: Starting zigbee-herdsman (0.25.0)
Zigbee2MQTT:debug 10: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":null,"disableLED":false},"backupPath":"/config/z2m_sky/coordinator_backup.json","databaseBackupPath":"/config/z2m_sky/database.db.backup","databasePath":"/config/z2m_sky/database.db","network":{"channelList":[11],"extendedPanID":[125,47,193,240,180,159,183,194],"networkKey":"HIDDEN","panID":29003},"serialPort":{"adapter":"ezsp","path":"/dev/ttyUSB0","rtscts":true}}'
2023-12-10T10:10:16.832Z zigbee-herdsman:adapter Failed to validate path: 'Error: spawn udevadm ENOENT'
2023-12-10T10:10:16.834Z zigbee-herdsman:adapter:ezsp:debg Adapter concurrent: 8
2023-12-10T10:10:16.835Z zigbee-herdsman:controller:log Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":[109,224,182,4,162,166,201,149,59,208,4,180,249,155,13,208],"panID":29003,"extendedPanID":[125,47,193,240,180,159,183,194],"channelList":[11]},"serialPort":{"rtscts":true,"path":"/dev/ttyUSB0","adapter":"ezsp"},"databasePath":"/config/z2m_sky/database.db","databaseBackupPath":"/config/z2m_sky/database.db.backup","backupPath":"/config/z2m_sky/coordinator_backup.json","adapter":{"disableLED":false,"concurrent":null,"delay":null}}'
2023-12-10T10:10:16.837Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/ttyUSB0","baudRate":115200,"rtscts":true,"autoOpen":false}
2023-12-10T10:10:16.852Z zigbee-herdsman:adapter:ezsp:uart Serialport opened
2023-12-10T10:10:16.852Z zigbee-herdsman:adapter:ezsp:uart Uart reseting
2023-12-10T10:10:16.853Z zigbee-herdsman:adapter:ezsp:uart --> Write reset
2023-12-10T10:10:16.855Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e]
2023-12-10T10:10:16.856Z zigbee-herdsman:adapter:ezsp:uart -?- waiting reset
2023-12-10T10:10:17.715Z zigbee-herdsman:adapter:ezsp:uart <-- [c20203d20a7e]
2023-12-10T10:10:17.717Z zigbee-herdsman:adapter:ezsp:uart <-- Error: c20203d20a7e
2023-12-10T10:10:17.717Z zigbee-herdsman:adapter:ezsp:uart Uart reseting
2023-12-10T10:10:17.717Z zigbee-herdsman:adapter:ezsp:uart --> Write reset
2023-12-10T10:10:17.718Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e]
2023-12-10T10:10:17.718Z zigbee-herdsman:adapter:ezsp:uart -?- waiting reset
2023-12-10T10:10:18.789Z zigbee-herdsman:adapter:ezsp:uart <-- [c1020b0a527e]
2023-12-10T10:10:18.790Z zigbee-herdsman:adapter:ezsp:uart <-- RSTACK: c1020b0a527e
2023-12-10T10:10:18.790Z zigbee-herdsman:adapter:ezsp:uart RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e
2023-12-10T10:10:18.791Z zigbee-herdsman:adapter:ezsp:uart -+- waiting reset success
2023-12-10T10:10:18.791Z zigbee-herdsman:adapter:ezsp:uart -+- waiting reset success
2023-12-10T10:10:18.792Z zigbee-herdsman:adapter:ezsp:ezsp ==> version: {"desiredProtocolVersion":4}
2023-12-10T10:10:18.793Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"version","_id_":0,"_isRequest_":true,"desiredProtocolVersion":4}
2023-12-10T10:10:18.793Z zigbee-herdsman:adapter:ezsp:uart --> DATA (0,0,0): 00000004
2023-12-10T10:10:18.794Z zigbee-herdsman:adapter:ezsp:uart --> [004221a850ed2c7e]
2023-12-10T10:10:18.794Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (1)
2023-12-10T10:10:19.867Z zigbee-herdsman:adapter:ezsp:uart <-- [c1020b0a527e0142a1a8582805c1ae247e]
2023-12-10T10:10:19.867Z zigbee-herdsman:adapter:ezsp:uart <-- RSTACK: c1020b0a527e
2023-12-10T10:10:19.868Z zigbee-herdsman:adapter:ezsp:uart RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e
2023-12-10T10:10:19.868Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (0,1,0): 0142a1a8582805c1ae247e
2023-12-10T10:10:19.868Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (1)
2023-12-10T10:10:19.869Z zigbee-herdsman:adapter:ezsp:uart --> [8160597e]
2023-12-10T10:10:19.869Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: 0080000c021073
2023-12-10T10:10:19.870Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x0: {"_cls_":"version","_id_":0,"_isRequest_":false,"protocolVersion":12,"stackType":2,"stackVersion":29456}
2023-12-10T10:10:19.871Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (1) success
2023-12-10T10:10:19.871Z zigbee-herdsman:adapter:ezsp:ezsp Switching to eszp version 12
2023-12-10T10:10:19.871Z zigbee-herdsman:adapter:ezsp:ezsp ==> version: {"desiredProtocolVersion":12}
2023-12-10T10:10:19.871Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"version","_id_":0,"_isRequest_":true,"desiredProtocolVersion":12}
2023-12-10T10:10:19.872Z zigbee-herdsman:adapter:ezsp:uart --> DATA (0,1,0): 01000100000c
2023-12-10T10:10:19.872Z zigbee-herdsman:adapter:ezsp:uart --> [014321a9542a19be807e]
2023-12-10T10:10:19.873Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (1)
2023-12-10T10:10:19.878Z zigbee-herdsman:adapter:ezsp:uart <-- [a1443b7e]
2023-12-10T10:10:19.878Z zigbee-herdsman:adapter:ezsp:uart <-- NAK  (1): a1443b7e
2023-12-10T10:10:19.879Z zigbee-herdsman:adapter:ezsp:uart NAK Expected packet sequence 1
2023-12-10T10:10:19.879Z zigbee-herdsman:adapter:ezsp:uart --> Error: Error: Recv NAK frame
2023-12-10T10:10:19.879Z zigbee-herdsman:adapter:ezsp:uart -!- break waiting (1)
2023-12-10T10:10:19.880Z zigbee-herdsman:adapter:ezsp:uart Can't send DATA frame (0,1,0): 01000100000c
2023-12-10T10:10:20.381Z zigbee-herdsman:adapter:ezsp:uart ->> DATA (0,1,1): 01000100000c
2023-12-10T10:10:20.381Z zigbee-herdsman:adapter:ezsp:uart --> [094321a9542a192d2d7e]
2023-12-10T10:10:20.381Z zigbee-herdsman:adapter:ezsp:uart -?- rewaiting (1)
2023-12-10T10:10:20.385Z zigbee-herdsman:adapter:ezsp:uart <-- [8160597e]
2023-12-10T10:10:20.386Z zigbee-herdsman:adapter:ezsp:uart <-- ACK  (1): 8160597e
2023-12-10T10:10:20.386Z zigbee-herdsman:adapter:ezsp:uart -+- rewaiting (1) success
2023-12-10T10:10:20.386Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (1) success
2023-12-10T10:10:28.797Z zigbee-herdsman:adapter:ezsp:ezsp Time to watchdog ... 0
2023-12-10T10:10:28.798Z zigbee-herdsman:adapter:ezsp:ezsp ==> nop: null
2023-12-10T10:10:30.389Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"nop","_id_":5,"_isRequest_":true}
2023-12-10T10:10:30.389Z zigbee-herdsman:adapter:ezsp:uart --> DATA (1,1,0): 0200010500
2023-12-10T10:10:30.389Z zigbee-herdsman:adapter:ezsp:uart --> [7d314021a9512a9a0d7e]
2023-12-10T10:10:30.390Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (2)
Zigbee2MQTT:error 10: Error while starting zigbee-herdsman
Zigbee2MQTT:error 10: Failed to start zigbee
Zigbee2MQTT:error 10: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
Zigbee2MQTT:error 10: Exiting...
Zigbee2MQTT:error 10: Error: Failure send version:{"type":"Buffer","data":[1,0,1,0,0,12]}
    at /app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:562:23
    at Queue.executeNext (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:32:32)
Krzysztonek commented 6 months ago

Dear @Koenkk I've just updated Z2M add-on to the last available version 1.34.0-1, but the issue remains the same. The log is following:

[08:52:28] INFO: Preparing to start...
[08:52:28] INFO: Socat not enabled
[08:52:28] INFO: Starting Zigbee2MQTT...
Zigbee2MQTT:info  2023-12-24 08:52:32: Logging to console and directory: '/config/z2m/log/2023-12-24.08-52-32' filename: log.txt
Zigbee2MQTT:info  2023-12-24 08:52:32: Starting Zigbee2MQTT version 1.34.0 (commit #unknown)
Zigbee2MQTT:info  2023-12-24 08:52:32: Starting zigbee-herdsman (0.25.0)
Zigbee2MQTT:error 2023-12-24 08:52:46: Error while starting zigbee-herdsman
Zigbee2MQTT:error 2023-12-24 08:52:46: Failed to start zigbee
Zigbee2MQTT:error 2023-12-24 08:52:46: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
Zigbee2MQTT:error 2023-12-24 08:52:46: Exiting...
Zigbee2MQTT:error 2023-12-24 08:52:46: Error: Failure send version:{"type":"Buffer","data":[1,0,1,0,0,12]}
    at /app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:562:23
    at Queue.executeNext (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:32:32)

I have checked https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html but the above issue has not been treated there. I have over 120 zigbee devices and such an issue makes my HA instance totally useless..

I'm stuck. Can you help me, please?

Koenkk commented 6 months ago

This looks like some issue with the EZSP integration (which is experimental), could you report the issue here: https://github.com/Koenkk/zigbee-herdsman/issues/319 ?

Nerivec commented 6 months ago

Try with /dev/serial/by-id/ in the serial config instead of /dev/ttyUSB0. It seems to fix a lot of weird starting issues.

To get the proper ID for your adapter: ls -l /dev/serial/by-id

For example:

port: >-
  /dev/serial/by-id/usb-ITEAD_SONOFF_Zigbee_3.0_USB_Dongle_Plus_V2_XXXXXXXXXXXXXX-if00
adapter: ezsp
Krzysztonek commented 6 months ago 
port: >-
  /dev/serial/by-id/usb-Nabu_Casa_SkyConnect_v1.0_xxxxxxx-if00
adapter: ezsp
disable_led: true
rtscts: false

leads to the following:

[08:24:25] INFO: Preparing to start...
[08:24:25] INFO: Socat not enabled
[08:24:26] INFO: Starting Zigbee2MQTT...
Zigbee2MQTT:info  2023-12-26 08:24:28: Logging to console and directory: '/config/z2m/log/2023-12-26.08-24-28' filename: log.txt
Zigbee2MQTT:info  2023-12-26 08:24:28: Starting Zigbee2MQTT version 1.34.0 (commit #unknown)
Zigbee2MQTT:info  2023-12-26 08:24:28: Starting zigbee-herdsman (0.25.0)
Zigbee2MQTT:error 2023-12-26 08:24:49: Error while starting zigbee-herdsman
Zigbee2MQTT:error 2023-12-26 08:24:49: Failed to start zigbee
Zigbee2MQTT:error 2023-12-26 08:24:49: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
Zigbee2MQTT:error 2023-12-26 08:24:49: Exiting...
Zigbee2MQTT:error 2023-12-26 08:24:49: Error: Connection not initialized
    at Ezsp.execCommand (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:551:19)
    at Ezsp.version (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:349:35)
    at Driver.startup (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/driver.ts:140:25)
    at EZSPAdapter.start (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/adapter/ezspAdapter.ts:172:16)
    at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:132:29)
    at Zigbee.start (/app/lib/zigbee.ts:60:27)
    at Controller.start (/app/lib/controller.ts:101:27)
    at start (/app/index.js:107:5)
Nerivec commented 6 months ago

Seems it never manages to connect to your adapter (just fails at the wrong time because of above PR). Try enabling debug to get more info (tick Show unused optional configuration options in addon configuration page).

BenSki2023 commented 5 months ago

I have the same problem and I can't start the add-on.

Addon version 1.35.1-1

I'm using the Sonoff dongle v2 E.

data_path: /config/zigbee2mqtt socat: enabled: false master: pty,raw,echo=0,link=/tmp/ttyZ2M,mode=777 slave: tcp-listen:8485,keepalive,nodelay,reuseaddr,keepidle=1,keepintvl=1,keepcnt=5 options: "-d -d" log: false mqtt: server: mqtt://localhost:1883 base_topic: zigbee2mqtt user: mqttuser password: mqttpass serial: port: >- /dev/serial/by-id/usb-ITEAD_SONOFF_Zigbee_3.0_USB_Dongle_Plus_V2_20231216145407-if00 adapter: ezsp

[17:21:42] INFO: Preparing to start... [17:21:43] INFO: Socat not enabled [17:21:43] INFO: Starting Zigbee2MQTT... Zigbee2MQTT:info 2024-01-22 17:21:47: Logging to console and directory: '/config/zigbee2mqtt/log/2024-01-22.17-21-47' filename: log.txt Zigbee2MQTT:info 2024-01-22 17:21:47: Starting Zigbee2MQTT version 1.35.1 (commit #unknown) Zigbee2MQTT:info 2024-01-22 17:21:47: Starting zigbee-herdsman (0.30.0) Zigbee2MQTT:error 2024-01-22 17:22:07: Error while starting zigbee-herdsman Zigbee2MQTT:error 2024-01-22 17:22:07: Failed to start zigbee Zigbee2MQTT:error 2024-01-22 17:22:07: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions Zigbee2MQTT:error 2024-01-22 17:22:07: Exiting... Zigbee2MQTT:error 2024-01-22 17:22:07: Error: Failure to connect at Ezsp.connect (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:277:19) at Driver.startup (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/driver.ts:139:9) at EZSPAdapter.start (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/adapter/ezspAdapter.ts:172:16) at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:132:29) at Zigbee.start (/app/lib/zigbee.ts:60:27) at Controller.start (/app/lib/controller.ts:98:27) at start (/app/index.js:107:5)

@Krzysztonek is your problem solved?

github-actions[bot] commented 4 months ago

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 7 days