Every morning I have to restart the Zigbee2MQTT container

[dwillemsen]

Hello, I have a very strange problem. I am running Home Assistant on docker and Zigbee2MQTT. Since a couple of weeks now every morning around 6:20 HA report that all my ZIgbee devices are unavailable. After restarting the Zigbee2MQTT container everything works again.. until the next morning. I have looked in the log files and enabled debug mode on Zigbee2MQTT but I can see no trigger that causes the unavailability. The rest of the HA integrations keep on working normally. Can someone perhaps point me in a direction to look because at the moment I am at a loss. By the way, I use nodered for the automations, so also in HA there are no automations active.

[Koenkk]

Sounds similar to #13382, can you check with the latest dev branch? (https://www.zigbee2mqtt.io/advanced/more/switch-to-dev-branch.html)

[dwillemsen]

I updated it with the latest dev branch, will let you know tomorrow morning what the effect was. I did however, up until a few days ago always run the dev branch and the problems where also there. Reason I used the dev branch was that I have Neo Coolcam Power sockets and the stable branch did not support them yet. Now it does so I changed back to normal branch.

[dwillemsen]

Koen, unfortunately this morning at 6:19:09 everything became unavailable again. I am running the latest dev branch. Another strange thing is dat when everything become unavailable two light are switched to on. One in my office, which turns on via a philips hue switch and one in a closet which turn on via a motion sensor from ikea.

[Koenkk]

Can you provide the debug log when this happens?

See https://www.zigbee2mqtt.io/guide/usage/debug.html on how to enable debug logging.

[dwillemsen]

Koen, I have attached the logfile from this morning. I already had debug active :-) I have selected the period from a little before 6:19 until I reset the container (08:12). Hope it helps.
log.txt

[dwillemsen]

Koen, attached the log from this morning. This morning was a bit different since HA reported that on 6:17:57 the devices became unavailable but on 6:20:26 most of the devices came available again.
log.txt

[dwillemsen]

I have to enable logging for the MQTT broker because there are no logs at the moment. I am using the eclipse-mosquitto image for my broker

[Koenkk]

Can you make sure detailed mosquitto logging is enabled? Looking at https://iot.stackexchange.com/questions/1671/mosquitto-debug-level-log-how-to-keep-all-entries-but-pingreq-pingresp the following log types should be in your mosquitto config:

log_type error
log_type warning
log_type notice
log_type information
log_type debug
log_type subscribe
log_type unsubscribe
log_type websockets

[dwillemsen]

Ok turned it on and put types in config. Only problem I now see in log file is that there is no huma readable time stamps. Don't know how to change this in the config.

[Nardol]

In your Mosquitto config file, add for example:
log_timestamp_format %d/%m/%Y %H:%M:%S

[dwillemsen]

Thanks, I also just found it and had already added it. Tomorrow I will send the moquitto log file.

[dwillemsen]

This morning HA reported that at 6:19:07 devices became unavailable and at 6:21:39 they became available again. I have attached the mosquitto log
mosquitto.log
.

[Koenkk]

This is the problem: Client mqttjs_4109f67a has exceeded timeout

Could you try to increase the keepalive timeout in the z2m configuration.yaml? (docs).

Try setting it to a (crazy) high value of 600

mqtt:
  keepalive: 600

[dwillemsen]

Ok did it. I will let you know tomorrow morning how it went. There is however one thing that bugs me, that is why does it always occur in the morning around 6:20? I would expect a timeout to be more random?

[Koenkk]

I think it happens because many devices seems to publish at once at that time.

[dwillemsen]

Koen, I just checked and this morning everything went fine, so no unavailable devices. Seems like changing the keep alive value is the solution. Do you recommend leaving it at 600 or try to find (via trial and error) the best value. Don’t know if there are any downsides to having a high keep alive value?

[Koenkk]

I do not recommend it, I think z2m somehow gets locked up due to the spamming of all zigbee messages around this time. Can you set back the keepalive timeout and provide me the herdsman debug log when the MQTT disconnect happens?

See https://www.zigbee2mqtt.io/guide/usage/debug.html on how to enable the herdsman debug logging. Note that this is only logged to STDOUT and not to log files.

[dwillemsen]

I have enabled the herdsman logging and disabled the keepalive of 600. Tomorrow I will send you the log files

[dwillemsen]

Koen, please find attached the herdsman logs. The devices became unavailable at 6:19:58 and also at 6:20:1
log_herdsman.txt
2

[dwillemsen]

Last couple of days the issue persists this morning at 6:19:01

[Koenkk]

Pushed a fix to reduce the duplicated pushes for the plugs so e.g. this should not happen anymore:

{"log":"Zigbee2MQTT:info  2022-08-19 06:22:38: MQTT publish: topic 'zigbee2mqtt/Smart Plug waterbed', payload '{\"child_lock\":\"UNLOCK\",\"current\":0.18,\"energy\":160.72,\"indicator_mode\":\"off\",\"linkquality\":7,\"power\":18,\"power_outage_memory\":\"on\",\"state\":\"ON\",\"update\":{\"state\":\"idle\"},\"update_available\":null,\"voltage\":235}'\n","stream":"stdout","time":"2022-08-19T04:22:38.094018697Z"}
{"log":"Zigbee2MQTT:info  2022-08-19 06:22:38: MQTT publish: topic 'zigbee2mqtt/Smart Plug waterbed', payload '{\"child_lock\":\"UNLOCK\",\"current\":0.18,\"energy\":160.72,\"indicator_mode\":\"off\",\"linkquality\":7,\"power\":18,\"power_outage_memory\":\"on\",\"state\":\"ON\",\"update\":{\"state\":\"idle\"},\"update_available\":null,\"voltage\":235}'\n","stream":"stdout","time":"2022-08-19T04:22:38.094093371Z"}
{"log":"Zigbee2MQTT:info  2022-08-19 06:22:38: MQTT publish: topic 'zigbee2mqtt/Smart Plug waterbed', payload '{\"child_lock\":\"UNLOCK\",\"current\":0.18,\"energy\":160.72,\"indicator_mode\":\"off\",\"linkquality\":7,\"power\":18,\"power_outage_memory\":\"on\",\"state\":\"ON\",\"update\":{\"state\":\"idle\"},\"update_available\":null,\"voltage\":235}'\n","stream":"stdout","time":"2022-08-19T04:22:38.09416493Z"}
{"log":"Zigbee2MQTT:info  2022-08-19 06:22:38: MQTT publish: topic 'zigbee2mqtt/Smart Plug waterbed', payload '{\"child_lock\":\"UNLOCK\",\"current\":0.18,\"energy\":160.72,\"indicator_mode\":\"off\",\"linkquality\":7,\"power\":18,\"power_outage_memory\":\"on\",\"state\":\"ON\",\"update\":{\"state\":\"idle\"},\"update_available\":null,\"voltage\":235}'\n","stream":"stdout","time":"2022-08-19T04:22:38.094232119Z"}
{"log":"Zigbee2MQTT:info  2022-08-19 06:22:38: MQTT publish: topic 'zigbee2mqtt/Smart Plug waterbed', payload '{\"child_lock\":\"UNLOCK\",\"current\":0.18,\"energy\":160.72,\"indicator_mode\":\"off\",\"linkquality\":7,\"power\":18,\"power_outage_memory\":\"on\",\"state\":\"ON\",\"update\":{\"state\":\"idle\"},\"update_available\":null,\"voltage\":235}'\n","stream":"stdout","time":"2022-08-19T04:22:38.094305796Z"}
{"log":"Zigbee2MQTT:info  2022-08-19 06:22:38: MQTT publish: topic 'zigbee2mqtt/Smart Plug waterbed', payload '{\"child_lock\":\"UNLOCK\",\"current\":0.18,\"energy\":160.72,\"indicator_mode\":\"off\",\"linkquality\":7,\"power\":18,\"power_outage_memory\":\"on\",\"state\":\"ON\",\"update\":{\"state\":\"idle\"},\"update_available\":null,\"voltage\":235}'\n","stream":"stdout","time":"2022-08-19T04:22:38.094391073Z"}
{"log":"Zigbee2MQTT:info  2022-08-19 06:22:38: MQTT publish: topic 'zigbee2mqtt/Smart Plug waterbed', payload '{\"child_lock\":\"UNLOCK\",\"current\":0.18,\"energy\":160.72,\"indicator_mode\":\"off\",\"linkquality\":7,\"power\":18,\"power_outage_memory\":\"on\",\"state\":\"ON\",\"update\":{\"state\":\"idle\"},\"update_available\":null,\"voltage\":235}'\n","stream":"stdout","time":"2022-08-19T04:22:38.09446118Z"}
{"log":"Zigbee2MQTT:info  2022-08-19 06:22:38: MQTT publish: topic 'zigbee2mqtt/Smart Plug waterbed', payload '{\"child_lock\":\"UNLOCK\",\"current\":0.18,\"energy\":160.72,\"indicator_mode\":\"off\",\"linkquality\":7,\"power\":18,\"power_outage_memory\":\"on\",\"state\":\"ON\",\"update\":{\"state\":\"idle\"},\"update_available\":null,\"voltage\":235}'\n","stream":"stdout","time":"2022-08-19T04:22:38.094548269Z"}
{"log":"Zigbee2MQTT:info  2022-08-19 06:22:38: MQTT publish: topic 'zigbee2mqtt/Smart Plug waterbed', payload '{\"child_lock\":\"UNLOCK\",\"current\":0.18,\"energy\":160.72,\"indicator_mode\":\"off\",\"linkquality\":7,\"power\":18,\"power_outage_memory\":\"on\",\"state\":\"ON\",\"update\":{\"state\":\"idle\"},\"update_available\":null,\"voltage\":235}'\n","stream":"stdout","time":"2022-08-19T04:22:38.094641367Z"}
{"log":"Zigbee2MQTT:info  2022-08-19 06:22:38: MQTT publish: topic 'zigbee2mqtt/Smart Plug waterbed', payload '{\"child_lock\":\"UNLOCK\",\"current\":0.18,\"energy\":160.72,\"indicator_mode\":\"off\",\"linkquality\":7,\"power\":18,\"power_outage_memory\":\"on\",\"state\":\"ON\",\"update\":{\"state\":\"idle\"},\"update_available\":null,\"voltage\":235}'\n","stream":"stdout","time":"2022-08-19T04:22:38.094701588Z"}
{"log":"Zigbee2MQTT:info  2022-08-19 06:22:38: MQTT publish: topic 'zigbee2mqtt/Smart Plug waterbed', payload '{\"child_lock\":\"UNLOCK\",\"current\":0.18,\"energy\":160.72,\"indicator_mode\":\"off\",\"linkquality\":7,\"power\":18,\"power_outage_memory\":\"on\",\"state\":\"ON\",\"update\":{\"state\":\"idle\"},\"update_available\":null,\"voltage\":235}'\n","stream":"stdout","time":"2022-08-19T04:22:38.094786298Z"}
{"log":"Zigbee2MQTT:info  2022-08-19 06:22:38: MQTT publish: topic 'zigbee2mqtt/Smart Plug waterbed', payload '{\"child_lock\":\"UNLOCK\",\"current\":0.18,\"energy\":160.72,\"indicator_mode\":\"off\",\"linkquality\":7,\"power\":18,\"power_outage_memory\":\"on\",\"state\":\"ON\",\"update\":{\"state\":\"idle\"},\"update_available\":null,\"voltage\":235}'\n","stream":"stdout","time":"2022-08-19T04:22:38.094852268Z"}
{"log":"Zigbee2MQTT:info  2022-08-19 06:22:38: MQTT publish: topic 'zigbee2mqtt/Smart Plug waterbed', payload '{\"child_lock\":\"UNLOCK\",\"current\":0.18,\"energy\":160.72,\"indicator_mode\":\"off\",\"linkquality\":7,\"power\":18,\"power_outage_memory\":\"on\",\"state\":\"ON\",\"update\":{\"state\":\"idle\"},\"update_available\":null,\"voltage\":235}'\n","stream":"stdout","time":"2022-08-19T04:22:38.094935735Z"}
{"log":"Zigbee2MQTT:info  2022-08-19 06:22:38: MQTT publish: topic 'zigbee2mqtt/Smart Plug waterbed', payload '{\"child_lock\":\"UNLOCK\",\"current\":0.18,\"energy\":160.72,\"indicator_mode\":\"off\",\"linkquality\":7,\"power\":18,\"power_outage_memory\":\"on\",\"state\":\"ON\",\"update\":{\"state\":\"idle\"},\"update_available\":null,\"voltage\":235}'\n","stream":"stdout","time":"2022-08-19T04:22:38.094982853Z"}
{"log":"Zigbee2MQTT:info  2022-08-19 06:22:38: MQTT publish: topic 'zigbee2mqtt/Smart Plug waterbed', payload '{\"child_lock\":\"UNLOCK\",\"current\":0.18,\"energy\":160.72,\"indicator_mode\":\"off\",\"linkquality\":7,\"power\":18,\"power_outage_memory\":\"on\",\"state\":\"ON\",\"update\":{\"state\":\"idle\"},\"update_available\":null,\"voltage\":235}'\n","stream":"stdout","time":"2022-08-19T04:22:38.095069673Z"}
{"log":"Zigbee2MQTT:info  2022-08-19 06:22:38: MQTT publish: topic 'zigbee2mqtt/Smart Plug waterbed', payload '{\"child_lock\":\"UNLOCK\",\"current\":0.23,\"energy\":160.72,\"indicator_mode\":\"off\",\"linkquality\":7,\"power\":18,\"power_outage_memory\":\"on\",\"state\":\"ON\",\"update\":{\"state\":\"idle\"},\"update_available\":null,\"voltage\":235}'\n","stream":"stdout","time":"2022-08-19T04:22:38.095116908Z"}

Maybe it also fixes this issue, could you check that?

Changes will be available in the dev branch in a few hours from now. (https://www.zigbee2mqtt.io/advanced/more/switch-to-dev-branch.html)

[dwillemsen]

the issues are still there. This morning all devices became unavailable at 6:21 and then again at 6:39 so the problems have increased.

[Koenkk]

Can you provide the herdsman debug log of this again?

[dwillemsen]

Will do tomorrow, because I saw Z2M got updated today so logfile of this morning is gone

[dwillemsen]

This morning at 6:21:01 (all devices) and 6:24:53 (some) devices became unavailable. Herdsman log is attache
log_herdsman.txt
d

[dwillemsen]

Ok debug=* generates so much logs that the logs from this morning have already been overwritten. I will try tomorrow morning to catch them

[dwillemsen]

Koen, the last two days there was no problem that’s why I have not send log files yet. I will now add more wallplugs to see if the problem is solved. Let you know!!

[dwillemsen]

Koen, this morning at 06:21:06 all devices where unavailable again. I have not added any extra plugs. Logfile is included. Day before yesterday it didn't occur in the morning but I discovered it occured 12 hours later, so in the evening.
log_Z2M.txt

[Koenkk]

I don't see a freeze in this log. In logs we also saw Connected to MQTT server, however this doesn't occur in this log. Do you still have the mosquito logs of this time?

[dwillemsen]

No I don't have the mosquitto log. Wierd. I will check again tomorrow morning. To be honest the unavailability of the devices doesn't cause a problem anymore, because after a minute or so everything is back online, whereas in the beginning it didn't come back online again. Maybe we should leave it at this ? I will keep monitoring it and when it causes more problems I will reach out again.

[dwillemsen]

Koen, now the system has completely stopped working. When I reset it, it works for a minute or so and then it gives errors. I have included the normal log. I am at a loss why this is happening.
_zigbee2mqtt_logs (1).txt

[dwillemsen]

Koen, please find attached the herdsman log. I haven't made any changes to my setup. I did spin up another container (joomla) on the server but I now deleted it and the problem persists. I have also tried removed some motion sensors to see if they were causing the problem, but no effect. Hope you can find it.
herdsman log.txt

[Koenkk]

It seems that the coordinator crashes but it is unclear why. It happens after Device 'Bewegingssensor Bed Betty' announced itself\n",, can you try to remove the battery of this sensor and see if the problem still occurs? If yes provide me the log of that.

[dwillemsen]

Koen, I haven't removed the battery because after the dev branch update from yesterday, everything worked again. I don't know what you changed but for now it looks like it is working again the way it should. I will try to add the smart plugs again to see if it also works with those in the network. I will keep you posted.

[dwillemsen]

Koen, this morning I was checking the logs and the system is unavailable again multiple times. It does continu afterwards but only this morning form 6 to 7 it happened three time. Do you have any suggestions what to do to prevent this from happening. Should I tweak the keep alive value to see if it will solve the problem. What would be the maximum it can be set to for the system to be operating normally?

[Koenkk]

Should I tweak the keep alive value to see if it will solve the problem. What would be the maximum it can be set to for the system to be operating normally?

You should set it as little as possible, since the default is 60 I suggest starting with 120, then 180 etc.

[xsirpreisx]

It seems for the past view days, every morning at a few minutes past 6 am, my Z2M stops working as well... The web UI doesn't respond, CPU usage goes way up.

I don't have logs yet, but will try to get them. After restarting my LCX container, everything is back to normal.

This started happening a few days ago, after the system working for a couple of weeks without issues.

[xsirpreisx]

So, I still have this problem. Almost (but not every) morning at 06:05 am my Zigbee2mqtt is unresponsive, with high CPU usage. I have to restart the container, then everything is fine.

I looked into the log file. I can see that starting at 06:05 am I get a LOT of directories with on log.log file each, which each shows that the USB device (Sonoff Dongle E) is not there anymore (by its ID).

zh:ember:uart:ash: Failed to init port with error Error: Error: No such file or directory, cannot open /dev/serial/by-id/usb-Itead_Sonoff_Zigbee_3.0_USB_Dongle_Plus_V2_b64c56adeb12ef11b14c78b8bf9df066-if00-port0

After restarting the container in Proxmox, everything goes back to normal.

Any ideas? What happens everyday at 06:05 that the USB device via ID is no longer available?