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

Restarting home assistant and mosquitto at the same time leaves zigbee entities unavailable until zigbee2mqtt restarts #9629

Closed
matejdro opened this issue Nov 13, 2021 · 59 comments · Fixed by #17891
Labels
problem Something isn't working

Comments

@matejdro
Copy link

How to reproduce it (minimal and precise)

  1. Have Zigbee2MQTT connected to the Home Assistant via Mosquitto MQTT broker
  2. Restart both Home Assistant and Mosquitto at the same time (for example, on my machine: docker container restart hass mosquitto)
  3. Check out Home Assistant

BUG: All Zigbee2MQTT entities will be unavailable

To fix the problem, I also have to restart Zigbee2MQTT afterwards (restarting from web UI is sufficient).

It is possible that the problem lies on the Home Assistant side, but up until recently I was also using zwavejs2mqtt with mqtt discovery entities and I did not experience that issue with it (only zigbee entities got unavailable).

Debug info

Only thing from the logs is this, which is not particularly useful:

Zigbee2MQTT:debug 2021-11-13 08:13:46: Received MQTT message on 'hass/status' with data 'offline'
Zigbee2MQTT:info  2021-11-13 08:13:47: Connected to MQTT server
Zigbee2MQTT:info  2021-11-13 08:13:47: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload 'online'
Zigbee2MQTT:debug 2021-11-13 08:14:07: Received MQTT message on 'hass/status' with data 'online'

Mosquitto version: 2.0.13
Home Assistant version: 2021.11.3
Zigbee2MQTT version: 1.22.0 commit: 0a1fccf
Adapter hardware: Smartlight CC2652P
Adapter firmware version: 20210708

@matejdro matejdro added the problem Something isn't working label Nov 13, 2021
@alax
Copy link

alax commented Nov 13, 2021

I am seeing this exact same issue, usually with a restart of the VM running Mosquitto/HA.

Edit: If HA restarts and Mosquitto is still running, everything works perfectly. I think this is probably a Home Assistant problem.

@github-actions
Copy link
Contributor

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 Stale issues label Dec 15, 2021
@matejdro
Copy link
Author

Still happens with

Home Assistant 2021.11.5
Zigbee2MQTT 1.22.1 commit: c2b5229

@github-actions github-actions bot removed the stale Stale issues label Dec 16, 2021
@github-actions
Copy link
Contributor

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 Stale issues label Jan 15, 2022
@matejdro
Copy link
Author

Still happens with Zigbee2MqTT 1.22.2 commit: 414c51f

@Koenkk
Copy link
Owner

Koenkk commented Jan 15, 2022

@matejdro are you using the availability feature? https://www.zigbee2mqtt.io/guide/configuration/device-availability.html

@matejdro
Copy link
Author

matejdro commented Jan 15, 2022

From what I can see, no (I never turned it on explicitly and I can't see it in any of the configs).

@Koenkk
Copy link
Owner

Koenkk commented Jan 15, 2022

@matejdro could you provide the z2m debug log of this?

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

@matejdro
Copy link
Author

matejdro commented Jan 16, 2022

Logs from the first post are already captured with debug enabled. Here it is again:

debug 2022-01-16 08:09:02: Received MQTT message on 'hass/status' with data 'offline'
error 2022-01-16 08:09:02: Not connected to MQTT server!
info  2022-01-16 08:09:03: Connected to MQTT server
info  2022-01-16 08:09:03: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload 'online'
debug 2022-01-16 08:09:20: Received MQTT message on 'hass/status' with data 'online'

(also, can you remove the stale label please just in case? It looks like bot did not do it).

@Koenkk
Copy link
Owner

Koenkk commented Jan 16, 2022

@matejdro what is logged after: debug 2022-01-16 08:09:20: Received MQTT message on 'hass/status' with data 'online'

@matejdro
Copy link
Author

Nothing. After couple of seconds, usual "Received Zigbee message from ... " will continue, but there are no logs related to the MQTT.

@Koenkk
Copy link
Owner

Koenkk commented Jan 16, 2022

Can you configure the HA birth/last will topic to homeassistant/status instead of hass/status? https://www.home-assistant.io/docs/mqtt/birth_will/

Does this change the logging after receiving Received MQTT message on 'homeassistant/status' with data 'online'

@matejdro
Copy link
Author

Changed and I got bunch of messages after that:

debug 2022-01-16 11:48:33: Received MQTT message on 'homeassistant/status' with data 'offline'
info  2022-01-16 11:48:35: Connected to MQTT server
info  2022-01-16 11:48:35: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload 'online'
debug 2022-01-16 11:48:44: Received Zigbee message from 'lighthouse_zvocnik', type 'attributeReport', cluster 'haElectricalMeasurement', data '{"rmsVoltage":243}' from endpoint 1 with groupID 0
info  2022-01-16 11:48:44: MQTT publish: topic 'zigbee2mqtt/lighthouse_zvocnik', payload '{"current":0,"energy":2.88,"linkquality":78,"power":0,"state":"OFF","voltage":243}'
debug 2022-01-16 11:48:45: Received Zigbee message from 'window_jedilnica', type 'attributeReport', cluster 'genBasic', data '{"65281":{"1":3005,"10":0,"100":0,"3":28,"4":5032,"5":17,"6":[0,1]}}' from endpoint 1 with groupID 0
info  2022-01-16 11:48:45: MQTT publish: topic 'zigbee2mqtt/window_jedilnica', payload '{"battery":100,"contact":true,"linkquality":138,"temperature":28,"voltage":3005}'
debug 2022-01-16 11:48:51: Received MQTT message on 'homeassistant/status' with data 'online'
debug 2022-01-16 11:48:58: Received Zigbee message from 'lighthouse_zvocnik', type 'attributeReport', cluster 'haElectricalMeasurement', data '{"rmsVoltage":245}' from endpoint 1 with groupID 0
info  2022-01-16 11:48:58: MQTT publish: topic 'zigbee2mqtt/lighthouse_zvocnik', payload '{"current":0,"energy":2.88,"linkquality":69,"power":0,"state":"OFF","voltage":245}'
debug 2022-01-16 11:49:07: Received Zigbee message from 'door_dnevna', type 'attributeReport', cluster 'genBasic', data '{"65281":{"1":2995,"10":0,"100":1,"3":30,"4":5032,"5":12,"6":[0,1]}}' from endpoint 1 with groupID 0
info  2022-01-16 11:49:07: MQTT publish: topic 'zigbee2mqtt/door_dnevna', payload '{"battery":97,"contact":false,"linkquality":75,"temperature":30,"voltage":2995}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/environment_sensor_dnevna', payload '{"battery":97,"humidity":39.9,"linkquality":null,"pressure":990.8,"temperature":21.69,"voltage":2995}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/tradfri_button_kuhna', payload '{"action":null,"battery":87,"linkquality":null,"update":{"state":"available"},"update_available":true}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/motion_kopalnica', payload '{"battery":100,"illuminance":6,"illuminance_lux":6,"linkquality":null,"occupancy":false,"temperature":27,"voltage":3065}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/motion_spalnica', payload '{"battery":100,"illuminance":1000,"illuminance_lux":1000,"linkquality":null,"occupancy":false,"temperature":25,"voltage":3075}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/window_dnevna_small', payload '{"battery":100,"contact":true,"linkquality":null,"temperature":26,"voltage":3005}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/window_dnevna_large', payload '{"battery":100,"contact":true,"linkquality":null,"temperature":25,"voltage":3005}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/window_jedilnica', payload '{"battery":100,"contact":true,"linkquality":138,"temperature":28,"voltage":3005}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/window_mala_soba', payload '{"battery":100,"contact":true,"linkquality":null,"temperature":25,"voltage":3025}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/door_balkon', payload '{"battery":100,"contact":true,"linkquality":null,"temperature":24,"voltage":3015}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/door_mala_soba', payload '{"battery":100,"contact":false,"linkquality":null,"temperature":28,"voltage":3025}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/door_dnevna', payload '{"battery":97,"contact":false,"linkquality":75,"temperature":30,"voltage":2995}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/door_kuhna', payload '{"battery":100,"contact":false,"linkquality":null,"temperature":28,"voltage":3025}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/door_entrance', payload '{"battery":100,"contact":true,"linkquality":null,"temperature":26,"voltage":3015}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/door_freezer', payload '{"battery":100,"contact":true,"linkquality":null,"temperature":28,"voltage":3015}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/door_fridge', payload '{"battery":100,"contact":true,"linkquality":null,"temperature":27,"voltage":3025}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/door_spalnica', payload '{"battery":100,"contact":false,"linkquality":null,"temperature":26,"voltage":3025}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/door_kopalnica', payload '{"battery":100,"contact":false,"linkquality":null,"temperature":24,"voltage":3065}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/motion_mala_soba', payload '{"battery":100,"illuminance":873,"illuminance_lux":873,"linkquality":null,"occupancy":false,"temperature":32,"voltage":3045}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/motion_dnevna', payload '{"battery":100,"illuminance":296,"illuminance_lux":296,"linkquality":null,"occupancy":false,"temperature":26,"voltage":3055}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/motion_jedilnica', payload '{"battery":100,"illuminance":825,"illuminance_lux":825,"linkquality":null,"occupancy":false,"temperature":24,"voltage":3085}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/motion_kuhna', payload '{"battery":100,"illuminance":150,"illuminance_lux":150,"linkquality":null,"occupancy":false,"temperature":31,"voltage":3025}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/motion_hodnik', payload '{"battery":100,"illuminance":242,"illuminance_lux":242,"linkquality":null,"occupancy":false,"temperature":27,"voltage":3045}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/vr_headset', payload '{"current":0,"energy":0.71,"linkquality":108,"power":0,"state":"OFF","voltage":239}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/lighthouse_zvocnik', payload '{"current":0,"energy":2.88,"linkquality":69,"power":0,"state":"OFF","voltage":245}'
info  2022-01-16 11:49:21: MQTT publish: topic 'zigbee2mqtt/lighthouse_omara', payload '{"linkquality":72,"power":0,"state":"OFF"}'
debug 2022-01-16 11:49:25: Received Zigbee message from 'vr_headset', type 'attributeReport', cluster 'haElectricalMeasurement', data '{"rmsVoltage":241}' from endpoint 1 with groupID 0
info  2022-01-16 11:49:25: MQTT publish: topic 'zigbee2mqtt/vr_headset', payload '{"current":0,"energy":0.71,"linkquality":111,"power":0,"state":"OFF","voltage":241}'
debug 2022-01-16 11:49:26: Received Zigbee message from 'lighthouse_zvocnik', type 'attributeReport', cluster 'haElectricalMeasurement', data '{"rmsVoltage":243}' from endpoint 1 with groupID 0
info  2022-01-16 11:49:26: MQTT publish: topic 'zigbee2mqtt/lighthouse_zvocnik', payload '{"current":0,"energy":2.88,"linkquality":75,"power":0,"state":"OFF","voltage":243}'

However, issue still persists.

Also, possibly related: home-assistant/core#59647

@Koenkk
Copy link
Owner

Koenkk commented Jan 16, 2022

Could you check if the latest-dev fixes this issue? After z2m receives 'homeassistant/status' with data 'online' it will now publish 'zigbee2mqtt/bridge/state', payload 'online' after 30 seconds

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)

@matejdro
Copy link
Author

@Koenkk can you reopen this? It looks like stale tag was not removed for some reason. I did not have the time to check out latest dev build yet.

@Koenkk Koenkk reopened this Jan 24, 2022
@matejdro
Copy link
Author

Tried out the 1.22.2-dev commit: 93921c6, issue persists. Logs on restart:

debug 2022-01-30 07:00:55: Received MQTT message on 'homeassistant/status' with data 'offline'
info  2022-01-30 07:00:56: Connected to MQTT server
info  2022-01-30 07:00:56: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload 'online'
debug 2022-01-30 07:01:12: Received Zigbee message from 'lighthouse_zvocnik', type 'attributeReport', cluster 'haElectricalMeasurement', data '{"rmsVoltage":241}' from endpoint 1 with groupID 0
info  2022-01-30 07:01:12: MQTT publish: topic 'zigbee2mqtt/lighthouse_zvocnik', payload '{"current":0,"energy":2.91,"linkquality":87,"power":0,"state":"OFF","voltage":241}'
debug 2022-01-30 07:01:16: Received MQTT message on 'homeassistant/status' with data 'online'
debug 2022-01-30 07:01:35: Received Zigbee message from 'door_freezer', type 'attributeReport', cluster 'genBasic', data '{"65281":{"1":3015,"10":0,"100":0,"3":26,"4":5032,"5":6,"6":[0,1]}}' from endpoint 1 with groupID 0
info  2022-01-30 07:01:35: Configuring 'door_freezer'
info  2022-01-30 07:01:35: Successfully configured 'door_freezer'
info  2022-01-30 07:01:35: MQTT publish: topic 'zigbee2mqtt/door_freezer', payload '{"battery":100,"contact":true,"linkquality":102,"temperature":26,"voltage":3015}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload 'online'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/environment_sensor_dnevna', payload '{"battery":97,"humidity":39.9,"linkquality":null,"pressure":990.8,"temperature":21.69,"voltage":2995}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/tradfri_button_kuhna', payload '{"action":null,"battery":87,"linkquality":null,"update":{"state":"available"},"update_available":true}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/motion_kopalnica', payload '{"battery":100,"illuminance":3,"illuminance_lux":3,"linkquality":null,"occupancy":false,"temperature":27,"voltage":3055}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/motion_spalnica', payload '{"battery":100,"illuminance":8,"illuminance_lux":8,"linkquality":null,"occupancy":false,"temperature":22,"voltage":3065}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/window_dnevna_small', payload '{"battery":100,"contact":true,"linkquality":null,"temperature":23,"voltage":3005}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/window_dnevna_large', payload '{"battery":100,"contact":true,"linkquality":null,"temperature":23,"voltage":3005}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/window_jedilnica', payload '{"battery":100,"contact":true,"linkquality":null,"temperature":25,"voltage":3005}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/window_mala_soba', payload '{"battery":100,"contact":true,"linkquality":null,"temperature":23,"voltage":3025}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/door_balkon', payload '{"battery":100,"contact":true,"linkquality":null,"temperature":21,"voltage":3005}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/door_mala_soba', payload '{"battery":100,"contact":true,"linkquality":null,"temperature":26,"voltage":3025}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/door_dnevna', payload '{"battery":97,"contact":false,"linkquality":null,"temperature":30,"voltage":2995}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/door_kuhna', payload '{"battery":100,"contact":false,"linkquality":null,"temperature":27,"voltage":3025}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/door_entrance', payload '{"battery":100,"contact":true,"linkquality":null,"temperature":26,"voltage":3015}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/door_freezer', payload '{"battery":100,"contact":true,"linkquality":102,"temperature":26,"voltage":3015}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/door_fridge', payload '{"battery":100,"contact":true,"linkquality":null,"temperature":25,"voltage":3025}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/door_spalnica', payload '{"battery":100,"contact":false,"linkquality":null,"temperature":25,"voltage":3025}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/door_kopalnica', payload '{"battery":100,"contact":false,"linkquality":null,"temperature":23,"voltage":3055}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/motion_mala_soba', payload '{"battery":100,"illuminance":7,"illuminance_lux":7,"linkquality":null,"occupancy":false,"temperature":30,"voltage":3035}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/motion_dnevna', payload '{"battery":100,"illuminance":20,"illuminance_lux":20,"linkquality":null,"occupancy":false,"temperature":25,"voltage":3055}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/motion_jedilnica', payload '{"battery":100,"illuminance":19,"illuminance_lux":19,"linkquality":null,"occupancy":false,"temperature":23,"voltage":3075}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/motion_kuhna', payload '{"battery":100,"illuminance":8,"illuminance_lux":8,"linkquality":null,"occupancy":false,"temperature":30,"voltage":3025}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/motion_hodnik', payload '{"battery":100,"illuminance":14,"illuminance_lux":14,"linkquality":null,"occupancy":false,"temperature":26,"voltage":3045}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/vr_headset', payload '{"current":0,"energy":0.79,"linkquality":null,"power":0,"state":"OFF","voltage":238}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/lighthouse_zvocnik', payload '{"current":0,"energy":2.91,"linkquality":87,"power":0,"state":"OFF","voltage":241}'
info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/lighthouse_omara', payload '{"linkquality":66,"power":0,"state":"OFF"}'
debug 2022-01-30 07:01:54: Received Zigbee message from 'lighthouse_zvocnik', type 'attributeReport', cluster 'haElectricalMeasurement', data '{"rmsVoltage":243}' from endpoint 1 with groupID 0
info  2022-01-30 07:01:54: MQTT publish: topic 'zigbee2mqtt/lighthouse_zvocnik', payload '{"current":0,"energy":2.91,"linkquality":84,"power":0,"state":"OFF","voltage":243}'
debug 2022-01-30 07:02:06: Received Zigbee message from 'motion_kuhna', type 'attributeReport', cluster 'genBasic', data '{"65281":{"1":3025,"10":0,"100":0,"11":18,"3":30,"4":5032,"5":35,"6":[0,2]}}' from endpoint 1 with groupID 0
info  2022-01-30 07:02:06: MQTT publish: topic 'zigbee2mqtt/motion_kuhna', payload '{"battery":100,"illuminance":18,"illuminance_lux":18,"linkquality":45,"occupancy":false,"temperature":30,"voltage":3025}'
debug 2022-01-30 07:02:08: Received Zigbee message from 'lighthouse_zvocnik', type 'attributeReport', cluster 'haElectricalMeasurement', data '{"rmsVoltage":241}' from endpoint 1 with groupID 0
info  2022-01-30 07:02:08: MQTT publish: topic 'zigbee2mqtt/lighthouse_zvocnik', payload '{"current":0,"energy":2.91,"linkquality":84,"power":0,"state":"OFF","voltage":241}'
debug 2022-01-30 07:02:36: Received Zigbee message from 'lighthouse_zvocnik', type 'attributeReport', cluster 'haElectricalMeasurement', data '{"rmsVoltage":243}' from endpoint 1 with groupID 0
info  2022-01-30 07:02:36: MQTT publish: topic 'zigbee2mqtt/lighthouse_zvocnik', payload '{"current":0,"energy":2.91,"linkquality":84,"power":0,"state":"OFF","voltage":243}'

@Koenkk
Copy link
Owner

Koenkk commented Jan 30, 2022

@matejdro I believe this is a HA issue, as you can see in the logs z2m publishes a online message:

info  2022-01-30 07:01:46: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload 'online'

This should make all devices be available in HA, I suggest creating an issue at the HA issue tracker.

@matejdro
Copy link
Author

I guess it is up to the HA then. There is already an issue there, albeit it did not appear to gain any traction: home-assistant/core#59647

Thanks.

@matejdro
Copy link
Author

@Koenkk continuing discussion from the other thread (home-assistant/core#59647 (comment)):

After restarting mosquitto, zigbee2mqtt/bridge/state is online, but /availability is not published until I also restart Z2M.

Could that signal that Z2M is the issue, not the hass?

@Koenkk
Copy link
Owner

Koenkk commented Jul 17, 2022

@matejdro the availability messages from z2m have a retain flag, so Home Assistant should receive the state on a HA restart. If that is not the case it is a HA bug.

@matejdro
Copy link
Author

matejdro commented May 14, 2023

@Koenkk This issue appears to be back with Z2M 1.30.4 commit: b2dd21e, HA 2023.5.2, Mosquitto 2.0.15

Z2M logs after restart:
logs.txt

@matejdro matejdro reopened this May 14, 2023
@Koenkk
Copy link
Owner

Koenkk commented May 14, 2023

@matejdro what is the latest known working version? And can you re-confirm that version works? (could also be due to a HA update)

@github-actions github-actions bot removed the stale Stale issues label May 15, 2023
@matejdro
Copy link
Author

Went through versions, 1.27.0 is the last working version, 1.27.1 is already broken.

This is with everything else (config, ha version, mosquitto version) staying the same.

@Koenkk
Copy link
Owner

Koenkk commented May 20, 2023

Could you provide the debug log of 1.27.0 vs latest z2m of this problem?

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

@xconverge
Copy link
Contributor

I have been following this issue and experience it as well. @Koenkk Here are the latest logs with z2m experiencing this problem (restarted HA and mosquito at this time). Entities in HA remain unavailable until I restarted z2m (after these logs)

log.txt

I haven't rolled back to try and bisect the issue, so can't confirm or deny if this has always been this way, etc

@matejdro
Copy link
Author

Here are logs from 1.27.0:

restart_log_1.27.0.txt

latest z2m logs are on above post (#9629 (comment))

@Koenkk
Copy link
Owner

Koenkk commented May 31, 2023

Can you check if your MQTT broker is configured to persist retained messages?

  1. Use any MQTT client and subscribe to e.g. homeassistant/sensor/0x00158d000678e798/battery/config, verify that a message is received upon connection
  2. Restart the MQTT server
  3. Repeat step 1, verify that an MQTT message is received. If this is not the case, your MQTT server does not persist retained messages (which it should do)

@xconverge
Copy link
Contributor

I do not have persistence enabled (it is off by default) in Eclipse Mosquitto. I would prefer to not be constantly writing to disk for something that I don't feel needs to be written to disk, but will give it a try and then decide if I want to keep it as a long term solution. I will look into enabling it and perform the test.

https://mosquitto.org/man/mosquitto-conf-5.html

Is there a reason why z2m can't/shouldnt just resend the config messages on mqtt reconnect, if it does at startup?

@matejdro
Copy link
Author

matejdro commented Jun 1, 2023

I'm with xconverge here, disk persistence was off until now and I don't really want to turn it on (unnecessary disk writing plus I like the idea of MQTT server being restarted gives me a clean slate with all old MQTT data thrown away).

Z2M worked without persistence until 1.27.0, so why are the new versions suddenly a problem?

@Koenkk
Copy link
Owner

Koenkk commented Jun 1, 2023

How are you running z2m? I want you to make a local change so you can check a possible fix.

@xconverge
Copy link
Contributor

I run it via docker. The image looks pretty stripped of development dependencies though so unless you have a better idea I will clone and build from source and just run locally (or build an image)

I also think that the change looks logical, so if you want to put it in a test or dev build because you are pretty confident and just want it sanity checked, I could do that too

@Koenkk
Copy link
Owner

Koenkk commented Jun 2, 2023

No need to install dev dependencies, vi is enough. Enter the docker container with docker exec -it Z2M_CONTAINER /bin/bash, in de /app/dist folder you will find all the source code.

@xconverge
Copy link
Contributor

xconverge commented Jun 2, 2023

That code change did not seem to fix the problem for me unfortunately. The logs and behavior all look similar.

I do notice that the topic for each device:

availability

with:

{
  "state": "online"
}

Are not being resent after the mqtt reconnection

@Koenkk
Copy link
Owner

Koenkk commented Jun 2, 2023

Can you add a this.publish('MY_DEVICE/availability, {state: 'online'}` (for a single device) and see if that resolves the issue for that device?

@xconverge
Copy link
Contributor

xconverge commented Jun 2, 2023

I realized the timeout wasnt firing

Object.values(this.retainedMessages).forEach((e) =>

so I commented out these 2 lines and things seem to work properly now

clearTimeout(this.republishRetainedTimer);

Looks like maybe a race condition a bit where we send the reinitialize, start a 2 second timer, and in the meantime we receive the reininitalize and clear the timer so it never fires?

@xconverge
Copy link
Contributor

xconverge commented Jun 2, 2023

Yes that is exactly it I think, this is a regression/somewhat of a race condition caused from 6314b86 which was released in 1.27.1 ... I think?

@xconverge
Copy link
Contributor

I propose removing this block entirely from onMessage?

        if (this.republishRetainedTimer && topic == `${settings.get().mqtt.base_topic}/bridge/state`) {
            clearTimeout(this.republishRetainedTimer);
            this.republishRetainedTimer = null;
        }

@Koenkk
Copy link
Owner

Koenkk commented Jun 3, 2023

I responded in #17891

@Koenkk Koenkk closed this as completed Jun 7, 2023
@Koenkk
Copy link
Owner

Koenkk commented Jun 7, 2023

Fixed in #17891

@matejdro
Copy link
Author

Is the fix supposed to be in 1.31.2? It is still happening with that version for me.

@xconverge
Copy link
Contributor

Is the fix supposed to be in 1.31.2? It is still happening with that version for me.

It is not in 1.31.2 and is currently just in the dev build.

@matejdro
Copy link
Author

matejdro commented Jul 5, 2023

Can confirm that this is not the issue anymore in 1.32.0. Thanks a lot!

@antibill51
Copy link

I have a similar problem but only concerns groups. The only solution I have found is to add an entity to each group that is already part of it so that the group entity reappears on the HA side.

  optimistic: true/false
  retain: true/false

in groups.yaml don't change anything.

Home Assistant 2023.7.2
Supervisor 2023.07.1
Operating System 10.3

Z2M 1.32.1-dev commit: ee1a5f0

Thanks

@KimCarlsen
Copy link

Just had the same issue in Z2M 1.32.1.
my setup is:
HA in hyper-V VM.
Z2M on windows server (same as HA host)
Mosquitto in Proxmox container
When restarting Proxmox, and thereby Mosquitto, the devices became unavailable in HA. After restart of Z2M (from UI ) all devices where updated in HA.

@matejdro
Copy link
Author

matejdro commented Dec 6, 2023

This issue appears to be back in 1.34.0.

EDIT: It happened once, but I cannot reproduce it anymore. Will try a bit more.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
problem Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

7 participants