Strange restart behavior with zigbee2mqtt

[chrismast]

Hi All,

## What happened

System config:

• zigbee2mqtt 1.18.2 running in a Proxmox LXC (did not upgrade yet as I am remote at the moment)
• Various zigbee devices from IKEA, Xiaomi, Tuya - all working fine
• Server is behind a CyberPower UPS for protection

I am running zigbee2mqtt for a longer time now, previously with a CC2531 stick, lately with a zzah stick which gives me better performance.
When I did the switch, I had some strange restart behaviors of z2m and at that time I connected it to power failures which might have impacted the USB stick, even though all of it is behind a UPS and my server worked fine. My zzah was then running since I got it (about 1 month ago) without issues and then it happened again yesterday.

I then looked further into logs today and saw that:

1. The potential power failure (as per Telegram logs sent via openHAB from my UPS) was around 8AM local time for 3 minutes
2. My syslog though shows that zigbee2mqtt started "restarting" and failing around 3:40AM and indeed, it shows even some restarts periodically in the log during normal operations

Below the log entries in syslog.

4AM restart loop - only resolved by restarting the LXC

May 23 03:38:53 mosquitto npm[18660]: #33[32mZigbee2MQTT:info #33[39m 2021-05-23 03:38:53: MQTT publish: topic 'zigbee2mqtt/IKEA_BUTTON_1/update_available', payload 'false'
May 23 03:38:53 mosquitto npm[18660]: #33[32mZigbee2MQTT:info #33[39m 2021-05-23 03:38:53: MQTT publish: topic 'zigbee2mqtt/IKEA_BUTTON_1/battery', payload '87'
May 23 03:38:53 mosquitto npm[18660]: #33[32mZigbee2MQTT:info #33[39m 2021-05-23 03:38:53: MQTT publish: topic 'zigbee2mqtt/IKEA_BUTTON_1/last_seen', payload '2021-05-23T03:38:53+07:00'
May 23 03:38:53 mosquitto npm[18660]: #33[32mZigbee2MQTT:info #33[39m 2021-05-23 03:38:53: MQTT publish: topic 'zigbee2mqtt/IKEA_BUTTON_1/linkquality', payload '60'
May 23 03:39:01 mosquitto CRON[18895]: (root) CMD ( [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
May 23 03:39:01 mosquitto systemd[1]: Starting Clean php session files...
May 23 03:39:01 mosquitto npm[18660]: Killed
May 23 03:39:01 mosquitto npm[18660]: npm ERR! code ELIFECYCLE
May 23 03:39:01 mosquitto npm[18660]: npm ERR! errno 137
May 23 03:39:01 mosquitto npm[18660]: npm ERR! zigbee2mqtt@1.18.2 start: node index.js
May 23 03:39:01 mosquitto npm[18660]: npm ERR! Exit status 137
May 23 03:39:01 mosquitto npm[18660]: npm ERR!
May 23 03:39:01 mosquitto npm[18660]: npm ERR! Failed at the zigbee2mqtt@1.18.2 start script.
May 23 03:39:01 mosquitto npm[18660]: npm ERR! This is probably not a problem with npm. There is likely additional logging output above.
May 23 03:39:01 mosquitto npm[18660]: npm ERR! A complete log of this run can be found in:
May 23 03:39:01 mosquitto npm[18660]: npm ERR! /root/.npm/_logs/2021-05-22T20_39_01_573Z-debug.log
May 23 03:39:01 mosquitto systemd[1]: zigbee2mqtt.service: Main process exited, code=exited, status=137/n/a
May 23 03:39:01 mosquitto systemd[1]: zigbee2mqtt.service: Failed with result 'exit-code'.
May 23 03:39:01 mosquitto systemd[1]: phpsessionclean.service: Succeeded.
May 23 03:39:01 mosquitto systemd[1]: Started Clean php session files.
May 23 03:39:01 mosquitto systemd[1]: zigbee2mqtt.service: Service RestartSec=100ms expired, scheduling restart.
May 23 03:39:01 mosquitto systemd[1]: zigbee2mqtt.service: Scheduled restart job, restart counter is at 27.
May 23 03:39:01 mosquitto systemd[1]: Stopped zigbee2mqtt.
May 23 03:39:01 mosquitto systemd[1]: Started zigbee2mqtt.
May 23 03:39:02 mosquitto npm[18938]: > zigbee2mqtt@1.18.2 start /opt/zigbee2mqtt
May 23 03:39:02 mosquitto npm[18938]: > node index.js
May 23 03:39:02 mosquitto npm[18938]: #33[34mZigbee2MQTT:debug#033[39m 2021-05-23 03:39:02: Loaded state from file /opt/zigbee2mqtt/data/state.json
May 23 03:39:02 mosquitto npm[18938]: #33[32mZigbee2MQTT:info #33[39m 2021-05-23 03:39:02: Logging to console and directory: '/opt/zigbee2mqtt/data/log/2021-05-23.03-39-02' filename: log.txt
May 23 03:39:02 mosquitto npm[18938]: #33[34mZigbee2MQTT:debug#033[39m 2021-05-23 03:39:02: Removing old log directory '/opt/zigbee2mqtt/data/log/2021-05-22.03-39-03'
May 23 03:39:02 mosquitto npm[18938]: #33[32mZigbee2MQTT:info #33[39m 2021-05-23 03:39:02: Starting Zigbee2MQTT version 1.18.2 (commit #abd8a092)
May 23 03:39:02 mosquitto npm[18938]: #33[32mZigbee2MQTT:info #33[39m 2021-05-23 03:39:02: Starting zigbee-herdsman (0.13.88)
May 23 03:39:02 mosquitto npm[18938]: #33[34mZigbee2MQTT:debug#033[39m 2021-05-23 03:39:02: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":null},"backupPath":"/opt/zigbee2mqt$
May 23 03:39:07 mosquitto npm[18938]: Killed
May 23 03:39:07 mosquitto npm[18938]: npm ERR! code ELIFECYCLE
May 23 03:39:07 mosquitto npm[18938]: npm ERR! errno 137
May 23 03:39:07 mosquitto npm[18938]: npm ERR! zigbee2mqtt@1.18.2 start: node index.js
May 23 03:39:07 mosquitto npm[18938]: npm ERR! Exit status 137
May 23 03:39:07 mosquitto npm[18938]: npm ERR!
May 23 03:39:07 mosquitto npm[18938]: npm ERR! Failed at the zigbee2mqtt@1.18.2 start script.
May 23 03:39:07 mosquitto npm[18938]: npm ERR! This is probably not a problem with npm. There is likely additional logging output above.
May 23 03:39:07 mosquitto npm[18938]: npm ERR! A complete log of this run can be found in:
May 23 03:39:07 mosquitto npm[18938]: npm ERR! /root/.npm/_logs/2021-05-22T20_39_07_944Z-debug.log

1AM restart - not sure why?

May 23 01:07:49 mosquitto npm[18268]: #33[34mZigbee2MQTT:debug#033[39m 2021-05-23 01:07:49: Received Zigbee message from 'TUYA_WALL_SWITCH_1', type 'attributeReport', cluster 'genBasic', data '{"appVersi$
May 23 01:07:53 mosquitto npm[18268]: #33[34mZigbee2MQTT:debug#033[39m 2021-05-23 01:07:53: Received Zigbee message from 'TUYA_WALL_SWITCH_4', type 'attributeReport', cluster 'genBasic', data '{"appVersi$
May 23 01:09:01 mosquitto CRON[18615]: (root) CMD ( [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
May 23 01:09:01 mosquitto CRON[18616]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
May 23 01:09:01 mosquitto systemd[1]: Starting Clean php session files...
May 23 01:09:01 mosquitto npm[18268]: Killed
May 23 01:09:01 mosquitto npm[18268]: npm ERR! code ELIFECYCLE
May 23 01:09:01 mosquitto npm[18268]: npm ERR! errno 137
May 23 01:09:01 mosquitto npm[18268]: npm ERR! zigbee2mqtt@1.18.2 start: node index.js
May 23 01:09:01 mosquitto npm[18268]: npm ERR! Exit status 137
May 23 01:09:01 mosquitto npm[18268]: npm ERR!
May 23 01:09:01 mosquitto npm[18268]: npm ERR! Failed at the zigbee2mqtt@1.18.2 start script.
May 23 01:09:01 mosquitto npm[18268]: npm ERR! This is probably not a problem with npm. There is likely additional logging output above.
May 23 01:09:01 mosquitto npm[18268]: npm ERR! A complete log of this run can be found in:
May 23 01:09:01 mosquitto npm[18268]: npm ERR! /root/.npm/_logs/2021-05-22T18_09_01_985Z-debug.log
May 23 01:09:02 mosquitto systemd[1]: zigbee2mqtt.service: Main process exited, code=exited, status=137/n/a
May 23 01:09:02 mosquitto systemd[1]: zigbee2mqtt.service: Failed with result 'exit-code'.
May 23 01:09:02 mosquitto systemd[1]: phpsessionclean.service: Succeeded.
May 23 01:09:02 mosquitto systemd[1]: Started Clean php session files.
May 23 01:09:02 mosquitto systemd[1]: zigbee2mqtt.service: Service RestartSec=100ms expired, scheduling restart.
May 23 01:09:02 mosquitto systemd[1]: zigbee2mqtt.service: Scheduled restart job, restart counter is at 26.
May 23 01:09:02 mosquitto systemd[1]: Stopped zigbee2mqtt.
May 23 01:09:02 mosquitto systemd[1]: Started zigbee2mqtt.
May 23 01:09:02 mosquitto npm[18660]: > zigbee2mqtt@1.18.2 start /opt/zigbee2mqtt
May 23 01:09:02 mosquitto npm[18660]: > node index.js
May 23 01:09:03 mosquitto npm[18660]: #33[34mZigbee2MQTT:debug#033[39m 2021-05-23 01:09:03: Loaded state from file /opt/zigbee2mqtt/data/state.json

Similar behavior on May 22 around 0:30AM:

May 22 00:30:36 mosquitto npm[13886]: #33[34mZigbee2MQTT:debug#033[39m 2021-05-22 00:30:36: Received Zigbee message from 'TUYA_WALL_SWITCH_1', type 'attributeReport', cluster 'genBasic', data '{"appVersi$
May 22 00:32:08 mosquitto npm[13886]: #33[34mZigbee2MQTT:debug#033[39m 2021-05-22 00:32:08: Received Zigbee message from 'TUYA_WALL_SWITCH_5', type 'attributeReport', cluster 'genBasic', data '{"appVersi$
May 22 00:32:23 mosquitto systemd[1]: Starting Daily apt download activities...
May 22 00:32:23 mosquitto npm[13886]: Killed
May 22 00:32:23 mosquitto npm[13886]: npm ERR! code ELIFECYCLE
May 22 00:32:23 mosquitto npm[13886]: npm ERR! errno 137
May 22 00:32:23 mosquitto npm[13886]: npm ERR! zigbee2mqtt@1.18.2 start: node index.js
May 22 00:32:23 mosquitto npm[13886]: npm ERR! Exit status 137
May 22 00:32:23 mosquitto npm[13886]: npm ERR!
May 22 00:32:23 mosquitto npm[13886]: npm ERR! Failed at the zigbee2mqtt@1.18.2 start script.
May 22 00:32:23 mosquitto npm[13886]: npm ERR! This is probably not a problem with npm. There is likely additional logging output above.
May 22 00:32:23 mosquitto npm[13886]: npm ERR! A complete log of this run can be found in:
May 22 00:32:23 mosquitto npm[13886]: npm ERR! /root/.npm/_logs/2021-05-21T17_32_23_835Z-debug.log
May 22 00:32:23 mosquitto systemd[1]: zigbee2mqtt.service: Main process exited, code=exited, status=137/n/a
May 22 00:32:23 mosquitto systemd[1]: zigbee2mqtt.service: Failed with result 'exit-code'.
May 22 00:32:24 mosquitto systemd[1]: zigbee2mqtt.service: Service RestartSec=100ms expired, scheduling restart.
May 22 00:32:24 mosquitto systemd[1]: zigbee2mqtt.service: Scheduled restart job, restart counter is at 13.
May 22 00:32:24 mosquitto systemd[1]: Stopped zigbee2mqtt.
May 22 00:32:24 mosquitto systemd[1]: Started zigbee2mqtt.
May 22 00:32:24 mosquitto npm[15219]: > zigbee2mqtt@1.18.2 start /opt/zigbee2mqtt
May 22 00:32:24 mosquitto npm[15219]: > node index.js
May 22 00:32:25 mosquitto npm[15219]: Killed
May 22 00:32:25 mosquitto npm[15219]: npm ERR! code ELIFECYCLE
May 22 00:32:25 mosquitto npm[15219]: npm ERR! errno 137
May 22 00:32:25 mosquitto npm[15219]: npm ERR! zigbee2mqtt@1.18.2 start: node index.js
May 22 00:32:25 mosquitto npm[15219]: npm ERR! Exit status 137
May 22 00:32:25 mosquitto npm[15219]: npm ERR!
May 22 00:32:25 mosquitto npm[15219]: npm ERR! Failed at the zigbee2mqtt@1.18.2 start script.
May 22 00:32:25 mosquitto npm[15219]: npm ERR! This is probably not a problem with npm. There is likely additional logging output above.
May 22 00:32:25 mosquitto npm[15219]: npm ERR! A complete log of this run can be found in:
May 22 00:32:25 mosquitto npm[15219]: npm ERR! /root/.npm/_logs/2021-05-21T17_32_25_859Z-debug.log
May 22 00:32:25 mosquitto systemd[1]: zigbee2mqtt.service: Main process exited, code=exited, status=137/n/a
May 22 00:32:25 mosquitto systemd[1]: zigbee2mqtt.service: Failed with result 'exit-code'.
May 22 00:32:26 mosquitto systemd[1]: zigbee2mqtt.service: Service RestartSec=100ms expired, scheduling restart.
May 22 00:32:26 mosquitto systemd[1]: zigbee2mqtt.service: Scheduled restart job, restart counter is at 14.
May 22 00:32:26 mosquitto systemd[1]: Stopped zigbee2mqtt.
May 22 00:32:26 mosquitto systemd[1]: Started zigbee2mqtt.
May 22 00:32:26 mosquitto npm[15507]: > zigbee2mqtt@1.18.2 start /opt/zigbee2mqtt
May 22 00:32:26 mosquitto npm[15507]: > node index.js
May 22 00:32:27 mosquitto npm[15507]: #33[34mZigbee2MQTT:debug#033[39m 2021-05-22 00:32:27: Loaded state from file /opt/zigbee2mqtt/data/state.json

The last 2 restarts always kind of resolved themselves, hence I never noticed that something was wrong, whereas the last one (4AM restart loop, above the first log past) made z2m freeze.

The npm logs do not really show anything though.

A bit stuck here on how to resolve it as I thought it was really connected to the (short) power failures but it seems there is something else "wrong" here?

Any advice on where to look next?

[ssiergl]

Exit code 137 usually indicates out of memory problems
You can see shortly before that the process got killed

Did you check?

[chrismast]

Exit code 137 usually indicates out of memory problems
You can see shortly before that the process got killed

Did you check?

Thanks for your reply.
I do run my LXC with 512MiB and 256MiB SWAP.
What I saw though when it did hang was that the SWAP was maxed out at 100%, whereas normal memory not.
Did not really have any issues with memory usage, but will try to up those values to 2GiB/1GiB.

[github-actions]

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