Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Addon crashes and does not restart via watchdog on Home Assistant Yellow with ezsp #431

Closed
CrazyCoder opened this issue Dec 6, 2022 · 14 comments
Labels

Comments

@CrazyCoder
Copy link

Description of the issue

UI is not available: 502: Bad Gateway.

The log freezes with the below.

[12:37:38] INFO: Preparing to start...
[12:37:39] INFO: Socat enabled
[12:37:39] INFO: Starting socat
Socat startup parameters:
Options:     -d -d
Master:      pty,raw,echo=0,link=/tmp/ttyZ2M,mode=777
Slave:       tcp-listen:8485,keepalive,nodelay,reuseaddr,keepidle=1,keepintvl=1,keepcnt=5
[12:37:39] INFO: Starting socat process ...
2022/12/06 12:37:39 socat[53] N PTY is /dev/pts/0
2022/12/06 12:37:39 socat[53] N listening on AF=2 0.0.0.0:8485
[12:37:40] INFO: Zigbee Herdsman debug logging enabled
[12:37:41] INFO: Starting Zigbee2MQTT...
Zigbee2MQTT:info  2022-12-06 12:37:47: Logging to console and directory: '/config/zigbee2mqtt/log/2022-12-06.12-37-46' filename: log.txt
Zigbee2MQTT:info  2022-12-06 12:37:47: Starting Zigbee2MQTT version 1.28.4-dev (commit #b0e352b)
Zigbee2MQTT:info  2022-12-06 12:37:47: Starting zigbee-herdsman (0.14.76)
2022-12-06T20:37:47.536Z zigbee-herdsman:adapter Failed to validate path: 'Error: spawn udevadm ENOENT'
2022-12-06T20:37:47.541Z zigbee-herdsman:controller:log Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":[1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13],"panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[11]},"serialPort":{"rtscts":true,"path":"/dev/ttyAMA1","adapter":"ezsp"},"databasePath":"/config/zigbee2mqtt/database.db","databaseBackupPath":"/config/zigbee2mqtt/database.db.backup","backupPath":"/config/zigbee2mqtt/coordinator_backup.json","adapter":{"disableLED":false,"concurrent":null,"delay":null}}'
2022-12-06T20:37:47.546Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with /dev/ttyAMA1 and {"baudRate":115200,"rtscts":true,"autoOpen":false}
2022-12-06T20:37:47.560Z zigbee-herdsman:adapter:ezsp:uart Serialport opened
2022-12-06T20:37:47.560Z zigbee-herdsman:adapter:ezsp:uart Uart reseting
2022-12-06T20:37:47.561Z zigbee-herdsman:adapter:ezsp:uart --> Write reset
2022-12-06T20:37:47.564Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e]
2022-12-06T20:37:47.606Z zigbee-herdsman:adapter:ezsp:uart <-- [c20203d20a7e]
2022-12-06T20:37:47.609Z zigbee-herdsman:adapter:ezsp:uart <-- Error: c20203d20a7e
2022-12-06T20:37:47.609Z zigbee-herdsman:adapter:ezsp:uart Uart reseting
2022-12-06T20:37:47.610Z zigbee-herdsman:adapter:ezsp:uart --> Write reset
2022-12-06T20:37:47.611Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e]
2022-12-06T20:37:48.692Z zigbee-herdsman:adapter:ezsp:uart <-- [c1020b0a527ea0547d3a7e]
2022-12-06T20:37:48.693Z zigbee-herdsman:adapter:ezsp:uart <-- RSTACK: c1020b0a527e
2022-12-06T20:37:48.696Z zigbee-herdsman:adapter:ezsp:uart RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e
2022-12-06T20:37:48.698Z zigbee-herdsman:adapter:ezsp:uart <-- NAK  (0): a0541a7e
2022-12-06T20:37:48.699Z zigbee-herdsman:adapter:ezsp:uart NAK Unexpected packet sequence 0

Addon version

1.28.4-dev (commit #b0e352b)

Platform

Home Assistant 2022.11.5
Supervisor 2022.11.2
Operating System 9.3
Frontend 20221108.0 - latest

Logs of the issue (if applicable)

No response

@LookInIs
Copy link

LookInIs commented Dec 26, 2022

Home Assistant 2022.12.8
Supervisor 2022.12.1
Operating System 9.4
Frontend 20221213.1 - latest

Zigbee2MQTT Current version: 1.28.4-1

[09:16:21] INFO: Preparing to start...
[09:16:21] INFO: Socat not enabled
[09:16:21] INFO: Zigbee Herdsman debug logging enabled
[09:16:22] INFO: Starting Zigbee2MQTT...
2022-12-26T06:16:26.600Z zigbee-herdsman:adapter Failed to validate path: 'Error: spawn udevadm ENOENT'
2022-12-26T06:16:26.613Z zigbee-herdsman:controller:log Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":[1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13],"panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[11]},"serialPort":{"path":"/dev/serial/by-id/usb-ITEAD_SONOFF_Zigbee_3.0_USB_Dongle_Plus_V2_20220815162838-if00","adapter":"ezsp"},"databasePath":"/config/zigbee2mqtt/database.db","databaseBackupPath":"/config/zigbee2mqtt/database.db.backup","backupPath":"/config/zigbee2mqtt/coordinator_backup.json","adapter":{"disableLED":false,"concurrent":null,"delay":null}}'
2022-12-26T06:16:26.615Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with /dev/serial/by-id/usb-ITEAD_SONOFF_Zigbee_3.0_USB_Dongle_Plus_V2_20220815162838-if00 and {"baudRate":115200,"rtscts":false,"autoOpen":false}
2022-12-26T06:16:26.638Z zigbee-herdsman:adapter:ezsp:uart Serialport opened
2022-12-26T06:16:26.639Z zigbee-herdsman:adapter:ezsp:uart Uart reseting
2022-12-26T06:16:26.640Z zigbee-herdsman:adapter:ezsp:uart --> Write reset
2022-12-26T06:16:26.643Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e]
2022-12-26T06:16:26.648Z zigbee-herdsman:adapter:ezsp:uart <-- [2a15b65894a524ab5593499cb37b7d384b629874f0cf5f8bfc782aa5ebc9de6f8ffece1c7e7f77b1a96b2a164fa674eb04aaa76d499db3d83deace6740f37e0f74a1a92a2a8c597e1f74b1a97d312a15b65894a524ab5593499cb57b7d384b629874f0cf598bfc7d5e2ca5ebc9de6f8e9069ac7e2f74b1a97d312a15b65894a5a5ebc9de6f8ffe9a237ec20251a8bd7e]
2022-12-26T06:16:26.650Z zigbee-herdsman:adapter:ezsp:uart <-- CRC error: 2a15b65894a524ab5593499cb37b184b629874f0cf5f8bfc782aa5ebc9de6f8ffece1c7e|ce1c|9271
2022-12-26T06:16:26.651Z zigbee-herdsman:adapter:ezsp:uart --> [a0547d3a7e]
2022-12-26T06:16:26.654Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (7,7,1): 7f77b1a96b2a164fa674eb04aaa76d499db3d83deace6740f37e
2022-12-26T06:16:26.655Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (0)
2022-12-26T06:16:26.657Z zigbee-herdsman:adapter:ezsp:uart --> [8070787e]
2022-12-26T06:16:26.658Z zigbee-herdsman:adapter:ezsp:uart Unexpected packet sequence 7 | 0
2022-12-26T06:16:26.659Z zigbee-herdsman:adapter:ezsp:uart Skipping the packet as repeated (0)
2022-12-26T06:16:26.659Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (0,7,1): 0f74a1a92a2a8c597e
2022-12-26T06:16:26.659Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (1)
2022-12-26T06:16:26.660Z zigbee-herdsman:adapter:ezsp:uart --> [8160597e]
2022-12-26T06:16:26.660Z zigbee-herdsman:adapter:ezsp:uart Unexpected packet sequence 7 | 0
2022-12-26T06:16:26.661Z zigbee-herdsman:adapter:ezsp:uart Skipping the packet as repeated (1)
2022-12-26T06:16:26.661Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (1,7,1): 1f74b1a9112a15b65894a524ab5593499cb57b184b629874f0cf598bfc7e2ca5ebc9de6f8e9069ac7e
2022-12-26T06:16:26.662Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (2)
2022-12-26T06:16:26.662Z zigbee-herdsman:adapter:ezsp:uart --> [82503a7e]
2022-12-26T06:16:26.662Z zigbee-herdsman:adapter:ezsp:uart Unexpected packet sequence 7 | 0
2022-12-26T06:16:26.663Z zigbee-herdsman:adapter:ezsp:uart Skipping the packet as repeated (2)
2022-12-26T06:16:26.663Z zigbee-herdsman:adapter:ezsp:uart <-- CRC error: 2f74b1a9112a15b65894a5a5ebc9de6f8ffe9a237e|9a23|478e
2022-12-26T06:16:26.663Z zigbee-herdsman:adapter:ezsp:uart --> [a274587e]
2022-12-26T06:16:26.668Z zigbee-herdsman:adapter:ezsp:uart <-- Error: c20251a8bd7e
2022-12-26T06:16:26.668Z zigbee-herdsman:adapter:ezsp:uart Uart reseting
2022-12-26T06:16:26.669Z zigbee-herdsman:adapter:ezsp:uart --> Write reset
2022-12-26T06:16:26.669Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e]
2022-12-26T06:16:26.772Z zigbee-herdsman:adapter:ezsp:uart <-- [11]
2022-12-26T06:16:27.771Z zigbee-herdsman:adapter:ezsp:uart <-- [c1020b0a527e]
2022-12-26T06:16:27.774Z zigbee-herdsman:adapter:ezsp:uart <-- RSTACK: c1020b0a527e
2022-12-26T06:16:27.775Z zigbee-herdsman:adapter:ezsp:uart RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e

after reboot the Z2M everything works.
After a few hours, the error repeats

@bjornberg
Copy link

I have the same issue, seems to be after I installed beta of 2023.1. After restoring backup it worked again only occasionally the report comes back, or zigbee2mqtt crashes and the only solution is a reboot of the yellow.

When the addon crashed I also lost some devices in z2m and I have to repair them before they become visible again. This happens almost every day and I can't figure out where this problem comes from.

@lensherm
Copy link

lensherm commented Jan 6, 2023

I have my Zigbee coordinator and a Z-wave stick connected to a RPi, whose only purpose in life is to serve those two out over ser2net. If I need to install updates on the RPi, which require a reboot, or if the network link is unavailable for a period of time, between the RPi and the machine running z2m, then even with Watchdog turned on, I get the bellow error, with no subsequent retries and have to manually restart the container. On the other hand, Z-Wave JS UI MQTT behaves as-expected, and resumes normal operation once the network communications are restored.

[11:46:51] INFO: Preparing to start... [11:46:51] INFO: Socat not enabled [11:46:52] INFO: Starting Zigbee2MQTT... Zigbee2MQTT:error 2023-01-06 11:46:56: Error while starting zigbee-herdsman Zigbee2MQTT:error 2023-01-06 11:46:56: Failed to start zigbee Zigbee2MQTT:error 2023-01-06 11:46:56: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions Zigbee2MQTT:error 2023-01-06 11:46:56: Exiting... Zigbee2MQTT:error 2023-01-06 11:46:56: Error: Error while opening socket at Socket.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/z-stack/znp/znp.ts:198:24) at Socket.emit (node:events:525:35) at emitErrorNT (node:internal/streams/destroy:157:8) at emitErrorCloseNT (node:internal/streams/destroy:122:3) at processTicksAndRejections (node:internal/process/task_queues:83:21)

@CrazyCoder
Copy link
Author

CrazyCoder commented Jan 23, 2023

Still the same problem. The first start/restart of the addon always fails with the following log:

[23:43:48] INFO: Preparing to start...
[23:43:49] INFO: Socat not enabled
[23:43:49] INFO: Zigbee Herdsman debug logging enabled
[23:43:51] INFO: Starting Zigbee2MQTT...
Zigbee2MQTT:info  2023-01-22 23:43:56: Logging to console and directory: '/config/zigbee2mqtt/log/2023-01-22.23-43-56' filename: log.txt
Zigbee2MQTT:info  2023-01-22 23:43:56: Starting Zigbee2MQTT version 1.29.2-dev (commit #f4f2c49)
Zigbee2MQTT:info  2023-01-22 23:43:56: Starting zigbee-herdsman (0.14.88)
2023-01-23T07:43:57.376Z zigbee-herdsman:adapter Failed to validate path: 'Error: spawn udevadm ENOENT'
2023-01-23T07:43:57.380Z zigbee-herdsman:controller:log Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":[1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13],"panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[11]},"serialPort":{"rtscts":true,"path":"/dev/ttyAMA1","adapter":"ezsp"},"databasePath":"/config/zigbee2mqtt/database.db","databaseBackupPath":"/config/zigbee2mqtt/database.db.backup","backupPath":"/config/zigbee2mqtt/coordinator_backup.json","adapter":{"disableLED":false,"concurrent":null,"delay":null}}'
2023-01-23T07:43:57.385Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/ttyAMA1","baudRate":115200,"rtscts":true,"autoOpen":false}
2023-01-23T07:43:57.401Z zigbee-herdsman:adapter:ezsp:uart Serialport opened
2023-01-23T07:43:57.402Z zigbee-herdsman:adapter:ezsp:uart Uart reseting
2023-01-23T07:43:57.403Z zigbee-herdsman:adapter:ezsp:uart --> Write reset
2023-01-23T07:43:57.406Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e]
2023-01-23T07:43:57.451Z zigbee-herdsman:adapter:ezsp:uart <-- [c20203d20a7e]
2023-01-23T07:43:57.454Z zigbee-herdsman:adapter:ezsp:uart <-- Error: c20203d20a7e
2023-01-23T07:43:57.455Z zigbee-herdsman:adapter:ezsp:uart Uart reseting
2023-01-23T07:43:57.455Z zigbee-herdsman:adapter:ezsp:uart --> Write reset
2023-01-23T07:43:57.457Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e]
2023-01-23T07:43:58.516Z zigbee-herdsman:adapter:ezsp:uart <-- [c1020b0a527ea0547d3a7e]
2023-01-23T07:43:58.518Z zigbee-herdsman:adapter:ezsp:uart <-- RSTACK: c1020b0a527e
2023-01-23T07:43:58.520Z zigbee-herdsman:adapter:ezsp:uart RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e
2023-01-23T07:43:58.523Z zigbee-herdsman:adapter:ezsp:uart <-- NAK  (0): a0541a7e
2023-01-23T07:43:58.525Z zigbee-herdsman:adapter:ezsp:uart NAK Unexpected packet sequence 0

The next start/restart works fine.

My serial settings are as follows:

serial:
  port: /dev/ttyAMA1
  adapter: ezsp
  rtscts: false
  baudrate: 115200

Yet the first start/restart ALWAYS fails :( The next one ALWAYS works.

[00:17:47] INFO: Preparing to start...
[00:17:48] INFO: Socat not enabled
[00:17:48] INFO: Zigbee Herdsman debug logging enabled
[00:17:51] INFO: Starting Zigbee2MQTT...
Zigbee2MQTT:info  2023-01-23 00:17:57: Logging to console and directory: '/config/zigbee2mqtt/log/2023-01-23.00-17-56' filename: log.txt
Zigbee2MQTT:info  2023-01-23 00:17:57: Starting Zigbee2MQTT version 1.29.2-dev (commit #f4f2c49)
Zigbee2MQTT:info  2023-01-23 00:17:57: Starting zigbee-herdsman (0.14.88)
2023-01-23T08:17:57.481Z zigbee-herdsman:adapter Failed to validate path: 'Error: spawn udevadm ENOENT'
2023-01-23T08:17:57.486Z zigbee-herdsman:controller:log Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":[1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13],"panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[11]},"serialPort":{"baudRate":115200,"rtscts":false,"path":"/dev/ttyAMA1","adapter":"ezsp"},"databasePath":"/config/zigbee2mqtt/database.db","databaseBackupPath":"/config/zigbee2mqtt/database.db.backup","backupPath":"/config/zigbee2mqtt/coordinator_backup.json","adapter":{"disableLED":false,"concurrent":null,"delay":null}}'
2023-01-23T08:17:57.491Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/ttyAMA1","baudRate":115200,"rtscts":false,"autoOpen":false}
2023-01-23T08:17:57.504Z zigbee-herdsman:adapter:ezsp:uart Serialport opened
2023-01-23T08:17:57.505Z zigbee-herdsman:adapter:ezsp:uart Uart reseting
2023-01-23T08:17:57.506Z zigbee-herdsman:adapter:ezsp:uart --> Write reset
2023-01-23T08:17:57.509Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e]
2023-01-23T08:17:57.561Z zigbee-herdsman:adapter:ezsp:uart <-- [c20203d20a7e]
2023-01-23T08:17:57.565Z zigbee-herdsman:adapter:ezsp:uart <-- Error: c20203d20a7e
2023-01-23T08:17:57.566Z zigbee-herdsman:adapter:ezsp:uart Uart reseting
2023-01-23T08:17:57.567Z zigbee-herdsman:adapter:ezsp:uart --> Write reset
2023-01-23T08:17:57.569Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e]
2023-01-23T08:17:58.620Z zigbee-herdsman:adapter:ezsp:uart <-- [c1020b0a527e]
2023-01-23T08:17:58.621Z zigbee-herdsman:adapter:ezsp:uart <-- RSTACK: c1020b0a527e
2023-01-23T08:17:58.624Z zigbee-herdsman:adapter:ezsp:uart RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e

@LookInIs
Copy link

I am also waiting for a solution to this problem

@CrazyCoder
Copy link
Author

Still not fixed:

[12:18:24] INFO: Preparing to start...
[12:18:25] INFO: Socat not enabled
[12:18:25] INFO: Zigbee Herdsman debug logging enabled
[12:18:28] INFO: Starting Zigbee2MQTT...
Zigbee2MQTT:info  2023-02-02 12:18:34: Logging to console and directory: '/config/zigbee2mqtt/log/2023-02-02.12-18-34' filename: log.txt
Zigbee2MQTT:info  2023-02-02 12:18:34: Starting Zigbee2MQTT version 1.30.0-dev (commit #1e7a761)
Zigbee2MQTT:info  2023-02-02 12:18:34: Starting zigbee-herdsman (0.14.89)
2023-02-02T20:18:34.809Z zigbee-herdsman:adapter Failed to validate path: 'Error: spawn udevadm ENOENT'
2023-02-02T20:18:34.813Z zigbee-herdsman:controller:log Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":[1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13],"panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[11]},"serialPort":{"baudRate":115200,"rtscts":false,"path":"/dev/ttyAMA1","adapter":"ezsp"},"databasePath":"/config/zigbee2mqtt/database.db","databaseBackupPath":"/config/zigbee2mqtt/database.db.backup","backupPath":"/config/zigbee2mqtt/coordinator_backup.json","adapter":{"disableLED":false,"concurrent":null,"delay":null}}'
2023-02-02T20:18:34.817Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/ttyAMA1","baudRate":115200,"rtscts":false,"autoOpen":false}
2023-02-02T20:18:34.831Z zigbee-herdsman:adapter:ezsp:uart Serialport opened
2023-02-02T20:18:34.832Z zigbee-herdsman:adapter:ezsp:uart Uart reseting
2023-02-02T20:18:34.832Z zigbee-herdsman:adapter:ezsp:uart --> Write reset
2023-02-02T20:18:34.834Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e]
2023-02-02T20:18:34.883Z zigbee-herdsman:adapter:ezsp:uart <-- [c20203d20a7e]
2023-02-02T20:18:34.886Z zigbee-herdsman:adapter:ezsp:uart <-- Error: c20203d20a7e
2023-02-02T20:18:34.887Z zigbee-herdsman:adapter:ezsp:uart Uart reseting
2023-02-02T20:18:34.888Z zigbee-herdsman:adapter:ezsp:uart --> Write reset
2023-02-02T20:18:34.890Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e]
2023-02-02T20:18:35.946Z zigbee-herdsman:adapter:ezsp:uart <-- [c1020b0a527e]
2023-02-02T20:18:35.948Z zigbee-herdsman:adapter:ezsp:uart <-- RSTACK: c1020b0a527e
2023-02-02T20:18:35.951Z zigbee-herdsman:adapter:ezsp:uart RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e

@tienducle
Copy link

Still persists with 1.30.0-1 (running Home Assistant Yellow)

One start-up fails:

Zigbee2MQTT:debug 2023-02-03 13:29:56: Loaded state from file /config/zigbee2mqtt/state.json
Zigbee2MQTT:info  2023-02-03 13:29:56: Logging to console and directory: '/config/zigbee2mqtt/log/2023-02-03.13-29-56' filename: log.txt
Zigbee2MQTT:debug 2023-02-03 13:29:56: Removing old log directory '/config/zigbee2mqtt/log/2023-02-02.21-18-50'
Zigbee2MQTT:info  2023-02-03 13:29:56: Starting Zigbee2MQTT version 1.30.0 (commit #unknown)
Zigbee2MQTT:info  2023-02-03 13:29:56: Starting zigbee-herdsman (0.14.89)
Zigbee2MQTT:debug 2023-02-03 13:29:56: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":null,"disableLED":false},"backupPath":"/config/zigbee2mqtt/coordinator_backup.json","databaseBackupPath":"/config/zigbee2mqtt/database.db.backup","databasePath":"/config/zigbee2mqtt/database.db","network":{"channelList":[25],"extendedPanID":...,"networkKey":"...","panID":...},"serialPort":{"adapter":"ezsp","baudRate":115200,"path":"/dev/ttyAMA1","rtscts":false}}'
2023-02-03T12:29:56.614Z zigbee-herdsman:adapter Failed to validate path: 'Error: spawn udevadm ENOENT'
2023-02-03T12:29:56.619Z zigbee-herdsman:controller:log Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":...,"panID":...,"extendedPanID":...,"channelList":[25]},"serialPort":{"baudRate":115200,"rtscts":false,"path":"/dev/ttyAMA1","adapter":"ezsp"},"databasePath":"/config/zigbee2mqtt/database.db","databaseBackupPath":"/config/zigbee2mqtt/database.db.backup","backupPath":"/config/zigbee2mqtt/coordinator_backup.json","adapter":{"disableLED":false,"concurrent":null,"delay":null}}'
2023-02-03T12:29:56.624Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/ttyAMA1","baudRate":115200,"rtscts":false,"autoOpen":false}
2023-02-03T12:29:56.638Z zigbee-herdsman:adapter:ezsp:uart Serialport opened
2023-02-03T12:29:56.639Z zigbee-herdsman:adapter:ezsp:uart Uart reseting
2023-02-03T12:29:56.640Z zigbee-herdsman:adapter:ezsp:uart --> Write reset
2023-02-03T12:29:56.642Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e]
2023-02-03T12:29:56.683Z zigbee-herdsman:adapter:ezsp:uart <-- [c20203d20a7e]
2023-02-03T12:29:56.686Z zigbee-herdsman:adapter:ezsp:uart <-- Error: c20203d20a7e
2023-02-03T12:29:56.687Z zigbee-herdsman:adapter:ezsp:uart Uart reseting
2023-02-03T12:29:56.688Z zigbee-herdsman:adapter:ezsp:uart --> Write reset
2023-02-03T12:29:56.690Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e]
2023-02-03T12:29:57.758Z zigbee-herdsman:adapter:ezsp:uart <-- [c1020b0a527e]
2023-02-03T12:29:57.760Z zigbee-herdsman:adapter:ezsp:uart <-- RSTACK: c1020b0a527e
2023-02-03T12:29:57.762Z zigbee-herdsman:adapter:ezsp:uart RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e

Next one is working again (not much different in the logs, except the error in the first "Uart reseting"

Zigbee2MQTT:debug 2023-02-03 13:26:16: Loaded state from file /config/zigbee2mqtt/state.json
Zigbee2MQTT:info  2023-02-03 13:26:16: Logging to console and directory: '/config/zigbee2mqtt/log/2023-02-03.13-26-16' filename: log.txt
Zigbee2MQTT:debug 2023-02-03 13:26:16: Removing old log directory '/config/zigbee2mqtt/log/2023-02-02.18-30-20'
Zigbee2MQTT:info  2023-02-03 13:26:16: Starting Zigbee2MQTT version 1.30.0 (commit #unknown)
Zigbee2MQTT:info  2023-02-03 13:26:16: Starting zigbee-herdsman (0.14.89)
Zigbee2MQTT:debug 2023-02-03 13:26:16: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":null,"disableLED":false},"backupPath":"/config/zigbee2mqtt/coordinator_backup.json","databaseBackupPath":"/config/zigbee2mqtt/database.db.backup","databasePath":"/config/zigbee2mqtt/database.db","network":{"channelList":[25],"extendedPanID":...,"networkKey":"...","panID":...},"serialPort":{"adapter":"ezsp","baudRate":115200,"path":"/dev/ttyAMA1","rtscts":false}}'
2023-02-03T12:26:17.092Z zigbee-herdsman:adapter Failed to validate path: 'Error: spawn udevadm ENOENT'
2023-02-03T12:26:17.096Z zigbee-herdsman:controller:log Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":...,"panID":...,"extendedPanID":...,"channelList":[25]},"serialPort":{"baudRate":115200,"rtscts":false,"path":"/dev/ttyAMA1","adapter":"ezsp"},"databasePath":"/config/zigbee2mqtt/database.db","databaseBackupPath":"/config/zigbee2mqtt/database.db.backup","backupPath":"/config/zigbee2mqtt/coordinator_backup.json","adapter":{"disableLED":false,"concurrent":null,"delay":null}}'
2023-02-03T12:26:17.101Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/ttyAMA1","baudRate":115200,"rtscts":false,"autoOpen":false}
2023-02-03T12:26:17.115Z zigbee-herdsman:adapter:ezsp:uart Serialport opened
2023-02-03T12:26:17.116Z zigbee-herdsman:adapter:ezsp:uart Uart reseting
2023-02-03T12:26:17.117Z zigbee-herdsman:adapter:ezsp:uart --> Write reset
2023-02-03T12:26:17.120Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e]
2023-02-03T12:26:18.241Z zigbee-herdsman:adapter:ezsp:uart <-- [c1020b0a527e]
2023-02-03T12:26:18.245Z zigbee-herdsman:adapter:ezsp:uart <-- RSTACK: c1020b0a527e
2023-02-03T12:26:18.247Z zigbee-herdsman:adapter:ezsp:uart RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e
2023-02-03T12:26:18.253Z zigbee-herdsman:adapter:ezsp:ezsp ==> version: {"desiredProtocolVersion":4}
2023-02-03T12:26:18.256Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"version","_id_":0,"_isRequest_":true,"desiredProtocolVersion":4}
2023-02-03T12:26:18.260Z zigbee-herdsman:adapter:ezsp:uart --> DATA (0,0,0): 00000004
2023-02-03T12:26:18.263Z zigbee-herdsman:adapter:ezsp:uart --> [004221a850ed2c7e]
2023-02-03T12:26:18.263Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (1)
2023-02-03T12:26:18.268Z zigbee-herdsman:adapter:ezsp:uart <-- [0142a1a85c2825d8e12b7e]
2023-02-03T12:26:18.269Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (0,1,0): 0142a1a85c2825d8e12b7e
2023-02-03T12:26:18.270Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (1)
2023-02-03T12:26:18.270Z zigbee-herdsman:adapter:ezsp:uart --> [8160597e]
2023-02-03T12:26:18.273Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: 0080000802306a
2023-02-03T12:26:18.275Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x0: {"_id_":0,"_cls_":"version","_isRequest_":false,"protocolVersion":8,"stackType":2,"stackVersion":27184}
2023-02-03T12:26:18.276Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (1) success
2023-02-03T12:26:18.276Z zigbee-herdsman:adapter:ezsp:ezsp Switching to eszp version 8
...

I am currently using a workaround where I let Home Assistant check the logs using a command_line sensor which executes:

#!/bin/bash
CHECK=$(tail -n 1 /config/zigbee2mqtt/log/current/log.txt | grep "Starting zigbee-herdsman")

if [[ -z $CHECK ]]; then
        echo "0"
else
        echo "1"
fi

and restarts the Addon/Container using an automation. This is actually only needed because the Z2M Addon would sometimes crash (e.g. during an OTA update of some bulbs), then gets restarted by HA and then gets stuck..

@CrazyCoder
Copy link
Author

@tienducle Nice workaround! Could you please describe the logic of the automation?

"Starting zigbee-herdsman" would be in the log for a long time, so your automation will always trigger until the log is rotated.

How do you make it restart only once if it's stuck?

@tienducle
Copy link

This is the automation:

alias: Restart Z2M
description: ""
trigger:
  - platform: state
    entity_id:
      - sensor.z2m_failure
    from: "False"
    to: "True"
    for:
      hours: 0
      minutes: 1
      seconds: 0
    id: Failure
  - platform: state
    entity_id:
      - sensor.z2m_failure
    from: "True"
    to: "False"
    id: Recovered
condition: []
action:
  - choose:
      - conditions:
          - condition: trigger
            id: Recovered
        sequence:
          - service: notify.matrix_home_admin
            data:
              message: Zigbee2MQTT is back online.
      - conditions:
          - condition: trigger
            id: Failure
        sequence:
          - service: notify.matrix_home_admin
            data:
              message: Attempting to restart Zigbee2MQTT..
          - service: hassio.addon_restart
            data:
              addon: 45df7312_zigbee2mqtt
mode: single

The sensor config is

- platform: command_line
  name: Z2M Failure
  command: /config/checkz2m.sh
  value_template: "{{ value == '1' }}"
  scan_interval: 30

So when the container gets stuck on the "Starting zigbee-herdsman" log message, the sensor would turn from False to True and that triggers the automation which then waits another minute until calling the restart service. When the container restarts, the log file is rotated automatically (not sure if that's a default setting in Z2M but I don't remember changing anything for that) so that after ~30 seconds, the sensor changes to False again.

@github-actions
Copy link

github-actions bot commented Mar 6, 2023

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

@github-actions github-actions bot added the Stale label Mar 6, 2023
@luke-g86
Copy link

luke-g86 commented Mar 6, 2023

Any updates on this?

@CrazyCoder
Copy link
Author

This may be fixed in 1.30.2-1.

At least now restart works for me. Probably related to the most recent fixes in ezsp adapter.

@github-actions github-actions bot removed the Stale label Mar 7, 2023
@github-actions
Copy link

github-actions bot commented Apr 7, 2023

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

@SpartanTech
Copy link

still having this issue. what non-workaround is there for this? is there a way we can see why or how watchdog works to fix it?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

7 participants