Koenkk
zigbee2mqtt does not start after being logged off for a while
What happened?
My SLZB-06 was offline for a few days, when it got rebooted the zigbee2mqtt docker container managed by HA (addon) did not restart and get it online.
What did you expect to happen?
I expected that if the device is online, HA will automatically restart the docker container.
I think the right way to fix this is to make zigbee2mqtt not crash but wait - or change HA so that it does not stop retrying after a significant number of retries.
How to reproduce it (minimal and precise)
Have a SLZB-06 connected over LAN to zigbee2mqtt (running as an addon in HA).
Disconnect the power from SLZB-06 and let zigbee2mqtt fail it will keep trying for a few times and then stop. Give it about 4 hours.
After this, connect the SLZB-06 and the system does not recover back.
Zigbee2MQTT version
1.38.0 commit: unknown
Adapter firmware version
20210708
Adapter
zstack
Setup
Add-on HA
Debug log
at Logger.info (/app/lib/util/logger.ts:177:14)
at Znp.onPortClose (/app/node_modules/zigbee-herdsman/src/adapter/z-stack/znp/znp.ts:113:16)
at Object.onceWrapper (node:events:632:26)
at Socket.emit (node:events:517:28)
at TCP.<anonymous> (node:net:350:12)
[17:12:51] INFO: Preparing to start...
[17:12:51] INFO: Socat not enabled
[17:12:53] INFO: Starting Zigbee2MQTT...
[2024-06-19 17:12:58] info: z2m: Logging to console, file (filename: log.log)
[2024-06-19 17:12:58] info: z2m: Starting Zigbee2MQTT version 1.38.0 (commit #unknown)
[2024-06-19 17:12:58] info: z2m: Starting zigbee-herdsman (0.49.2)
[2024-06-19 17:12:59] info: zh:zstack:znp: Opening TCP socket with 192.168.1.48:6638
[2024-06-19 17:13:02] info: zh:zstack:znp: Socket error
[2024-06-19 17:13:02] error: z2m: Error while starting zigbee-herdsman
[2024-06-19 17:13:02] error: z2m: Failed to start zigbee
[2024-06-19 17:13:02] error: z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
[2024-06-19 17:13:02] error: z2m: Exiting...
[2024-06-19 17:13:02] error: z2m: Error: Error while opening socket
at Socket.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/z-stack/znp/znp.ts:191:24)
at Socket.emit (node:events:529:35)
at emitErrorNT (node:internal/streams/destroy:151:8)
at emitErrorCloseNT (node:internal/streams/destroy:116:3)
at processTicksAndRejections (node:internal/process/task_queues:82:21)
/app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:264
var er = new ERR_STREAM_WRITE_AFTER_END();
^
Error: write after end
at writeAfterEnd (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:264:12)
at DerivedLogger.Writable.write (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:300:21)
at DerivedLogger.log (/app/node_modules/winston/lib/winston/logger.js:252:14)
at Logger.log (/app/lib/util/logger.ts:164:25)
at Logger.info (/app/lib/util/logger.ts:177:14)
at Znp.onPortClose (/app/node_modules/zigbee-herdsman/src/adapter/z-stack/znp/znp.ts:113:16)
at Object.onceWrapper (node:events:632:26)
at Socket.emit (node:events:517:28)
at TCP.<anonymous> (node:net:350:12)
[17:13:04] INFO: Preparing to start...
[17:13:05] INFO: Socat not enabled
[17:13:06] INFO: Starting Zigbee2MQTT...
[2024-06-19 17:13:11] info: z2m: Logging to console, file (filename: log.log)
[2024-06-19 17:13:12] info: z2m: Starting Zigbee2MQTT version 1.38.0 (commit #unknown)
[2024-06-19 17:13:12] info: z2m: Starting zigbee-herdsman (0.49.2)
[2024-06-19 17:13:12] info: zh:zstack:znp: Opening TCP socket with 192.168.1.48:6638
[2024-06-19 17:13:15] info: zh:zstack:znp: Socket error
[2024-06-19 17:13:15] error: z2m: Error while starting zigbee-herdsman
[2024-06-19 17:13:15] error: z2m: Failed to start zigbee
[2024-06-19 17:13:15] error: z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
[2024-06-19 17:13:15] error: z2m: Exiting...
[2024-06-19 17:13:15] error: z2m: Error: Error while opening socket
at Socket.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/z-stack/znp/znp.ts:191:24)
at Socket.emit (node:events:529:35)
at emitErrorNT (node:internal/streams/destroy:151:8)
at emitErrorCloseNT (node:internal/streams/destroy:116:3)
at processTicksAndRejections (node:internal/process/task_queues:82:21)
/app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:264
var er = new ERR_STREAM_WRITE_AFTER_END();
^
Error: write after end
at writeAfterEnd (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:264:12)
at DerivedLogger.Writable.write (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:300:21)
at DerivedLogger.log (/app/node_modules/winston/lib/winston/logger.js:252:14)
at Logger.log (/app/lib/util/logger.ts:164:25)
at Logger.info (/app/lib/util/logger.ts:177:14)
at Znp.onPortClose (/app/node_modules/zigbee-herdsman/src/adapter/z-stack/znp/znp.ts:113:16)
at Object.onceWrapper (node:events:632:26)
at Socket.emit (node:events:517:28)
at TCP.<anonymous> (node:net:350:12)
[17:13:18] INFO: Preparing to start...
[17:13:18] INFO: Socat not enabled
[17:13:20] INFO: Starting Zigbee2MQTT...
[2024-06-19 17:13:25] info: z2m: Logging to console, file (filename: log.log)
[2024-06-19 17:13:25] info: z2m: Starting Zigbee2MQTT version 1.38.0 (commit #unknown)
[2024-06-19 17:13:25] info: z2m: Starting zigbee-herdsman (0.49.2)
[2024-06-19 17:13:25] info: zh:zstack:znp: Opening TCP socket with 192.168.1.48:6638
[2024-06-19 17:13:28] info: zh:zstack:znp: Socket error
[2024-06-19 17:13:28] error: z2m: Error while starting zigbee-herdsman
[2024-06-19 17:13:28] error: z2m: Failed to start zigbee
[2024-06-19 17:13:28] error: z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
[2024-06-19 17:13:28] error: z2m: Exiting...
[2024-06-19 17:13:28] error: z2m: Error: Error while opening socket
at Socket.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/z-stack/znp/znp.ts:191:24)
at Socket.emit (node:events:529:35)
at emitErrorNT (node:internal/streams/destroy:151:8)
at emitErrorCloseNT (node:internal/streams/destroy:116:3)
at processTicksAndRejections (node:internal/process/task_queues:82:21)
/app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:264
var er = new ERR_STREAM_WRITE_AFTER_END();
^
Error: write after end
at writeAfterEnd (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:264:12)
at DerivedLogger.Writable.write (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:300:21)
at DerivedLogger.log (/app/node_modules/winston/lib/winston/logger.js:252:14)
at Logger.log (/app/lib/util/logger.ts:164:25)
at Logger.info (/app/lib/util/logger.ts:177:14)
at Znp.onPortClose (/app/node_modules/zigbee-herdsman/src/adapter/z-stack/znp/znp.ts:113:16)
at Object.onceWrapper (node:events:632:26)
at Socket.emit (node:events:517:28)
at TCP.<anonymous> (node:net:350:12)
It looks like the adapter is not accepting any connections: Error: Error while opening socket, don't think this is something that can be fixed from z2m.
Thanks for looking into the issue - I think the problem is created by the socket (as it was indeed offline for a few hours) - but it is exacerbated by the issue that zigbee2mqtt does not retry.
If you see, the last log on that entry was on 2024-06-19 17:13:28 ... however it was the latest logs I pulled up on 2024-06-23 - So atleast 4 days passed without zigbee2mqtt reloading.
I think either the HA add-on retry logic is busted or something needs to happen in zigbee2mqtt to make sure HA doesn't mark it as a permanent failure.
I looked a little bit into https://developers.home-assistant.io/docs/add-ons/configuration/ but I don't see a retry strategy listed there.
Would it be possible to not kill the docker job if the socket is not available - but instead catch that exception and retry after a fixed timeout ? That way the add-on keeps running and is self recoverable ?
@Nerivec recently introduced the watchdog feature in https://github.com/Koenkk/zigbee2mqtt/pull/23043, I've now added support for this for the HA addon. For this you will have to use the edge version of the addon. Docs:
- https://github.com/zigbee2mqtt/hassio-zigbee2mqtt/blob/master/zigbee2mqtt/DOCS.md#enabling-the-watchdog
- https://github.com/Koenkk/zigbee2mqtt.io/blob/develop/docs/guide/installation/15_watchdog.md
Thanks - Let me try it right away! Should I close this issue and re-open another one if it doesn't work as expected (to keep your issue-list clean) ?
I also have a somewhat similar issue?
After the machine reboots which uses docker to run zigbee2mqtt, it always fails to start it, with similar error (but instead of socket error, it is a "z2m: Error: Error: Not supported, cannot set" error).:
2024-11-10T14:42:37.948118931+01:00 [2024-11-10 14:42:37] info: z2m: Logging to console, file (filename: log.log)
2024-11-10T14:42:37.956165424+01:00 [2024-11-10 14:42:37] info: z2m: Starting Zigbee2MQTT version 1.41.0 (commit #cc31cea)
2024-11-10T14:42:37.957860613+01:00 [2024-11-10 14:42:37] info: z2m: Starting zigbee-herdsman (2.1.7)
2024-11-10T14:42:38.120625045+01:00 [2024-11-10 14:42:38] info: zh:zstack:znp: Opening SerialPort with {"path":"/dev/ttyACM0","baudRate":115200,"rtscts":false,"autoOpen":false}
2024-11-10T14:42:38.124607920+01:00 [2024-11-10 14:42:38] info: zh:zstack:znp: Serialport opened
2024-11-10T14:42:38.377973280+01:00 [2024-11-10 14:42:38] info: zh:zstack:znp: Writing CC2530/CC2531 skip bootloader payload
2024-11-10T14:42:39.631135082+01:00 [2024-11-10 14:42:39] info: zh:zstack:znp: Skip bootloader for CC2652/CC1352
2024-11-10T14:42:39.633380305+01:00 [2024-11-10 14:42:39] error: z2m: Error while starting zigbee-herdsman
2024-11-10T14:42:39.634580166+01:00 [2024-11-10 14:42:39] error: z2m: Failed to start zigbee
2024-11-10T14:42:39.635131101+01:00 [2024-11-10 14:42:39] error: z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
2024-11-10T14:42:39.635773975+01:00 [2024-11-10 14:42:39] error: z2m: Exiting...
2024-11-10T14:42:39.636519443+01:00 [2024-11-10 14:42:39] error: z2m: Error: Error: Not supported, cannot set
2024-11-10T14:42:39.673665729+01:00
2024-11-10T14:42:39.673672980+01:00 /app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:264
2024-11-10T14:42:39.673706451+01:00 var er = new ERR_STREAM_WRITE_AFTER_END();
2024-11-10T14:42:39.673713233+01:00 ^
2024-11-10T14:42:39.673720553+01:00 Error: write after end
2024-11-10T14:42:39.673726586+01:00 at writeAfterEnd (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:264:12)
2024-11-10T14:42:39.673732109+01:00 at DerivedLogger.Writable.write (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:300:21)
2024-11-10T14:42:39.673737561+01:00 at DerivedLogger.log (/app/node_modules/winston/lib/winston/logger.js:231:12)
2024-11-10T14:42:39.673742730+01:00 at Logger.log (/app/lib/util/logger.ts:198:25)
2024-11-10T14:42:39.673747797+01:00 at Logger.info (/app/lib/util/logger.ts:211:14)
2024-11-10T14:42:39.673756356+01:00 at Znp.onPortClose (/app/node_modules/zigbee-herdsman/src/adapter/z-stack/znp/znp.ts:96:16)
2024-11-10T14:42:39.673761354+01:00 at Object.onceWrapper (node:events:632:26)
2024-11-10T14:42:39.673766088+01:00 at SerialPort.emit (node:events:529:35)
2024-11-10T14:42:39.673771060+01:00 at port.close.then.closing (/app/node_modules/@serialport/stream/dist/index.js:242:18)
2024-11-10T14:43:18.532360149+01:00 Using '/app/data' as data directory
2024-11-10T14:43:18.628648042+01:00 Starting Zigbee2MQTT without watchdog.
But after this, If I just simply restart the container, it always starts.
2024-11-10T14:44:04.990631040+01:00 [2024-11-10 14:44:04] info: z2m: Logging to console, file (filename: log.log)
2024-11-10T14:44:04.999033252+01:00 [2024-11-10 14:44:04] info: z2m: Starting Zigbee2MQTT version 1.41.0 (commit #cc31cea)
2024-11-10T14:44:05.000664620+01:00 [2024-11-10 14:44:05] info: z2m: Starting zigbee-herdsman (2.1.7)
2024-11-10T14:44:05.162278816+01:00 [2024-11-10 14:44:05] info: zh:zstack:znp: Opening SerialPort with {"path":"/dev/ttyACM0","baudRate":115200,"rtscts":false,"autoOpen":false}
2024-11-10T14:44:05.166693398+01:00 [2024-11-10 14:44:05] info: zh:zstack:znp: Serialport opened
2024-11-10T14:44:06.835570310+01:00 [2024-11-10 14:44:06] info: z2m: zigbee-herdsman started (resumed)
2024-11-10T14:44:06.836554016+01:00 [2024-11-10 14:44:06] info: z2m: Coordinator firmware version: '{"meta":{"maintrel":2,"majorrel":2,"minorrel":7,"product":2,"revision":20190425,"transportrev":2},"type":"zStack30x"}'
2024-11-10T14:44:06.839383794+01:00 [2024-11-10 14:44:06] info: z2m: Zigbee: disabling joining new devices.
2024-11-10T14:44:07.071638540+01:00 [2024-11-10 14:44:07] info: z2m: Connecting to MQTT server at mqtt://mosquitto
2024-11-10T14:44:07.406864234+01:00 [2024-11-10 14:44:07] info: z2m: Connected to MQTT server
This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 7 days
![github-actions[bot] avatar](https://avatars.githubusercontent.com/in/15368?v=4 "Published by a pub.dev verified publisher"){kind=small}