Zigbee2mqtt: Lost Sensors after HA Restart with Auto-discovery Enabled

[jarrah31]

I would like to find out if this is normal behaviour and whether there's a solution please?

I have auto-discovery enabled on HA and Z2M (zigbee2mqtt - quicker to type!) ;)
Z2M:
homeassistant: true
HA:

mqtt:
  discovery: true

If I restart Z2M the sensors automatically appear in HA which works well. However, if I restart HA (after doing some yaml config), the sensors disappear! I then have to also restart Z2M to add them back into HA.

If this is expected behaviour (do others see this too?), perhaps a solution is to publish the sensors back to HA when Z2M detects a restart. For example, I notice in Z2M logs the following occurs during a HA reboot:

Jun 09 09:26:35 zigbeepi npm[2813]: 2018-6-9 09:26:35 ERROR Not connected to MQTT server!
Jun 09 09:26:45 zigbeepi npm[2813]: 2018-6-9 09:26:45 ERROR Not connected to MQTT server!
Jun 09 09:26:55 zigbeepi npm[2813]: 2018-6-9 09:26:55 ERROR Not connected to MQTT server!
Jun 09 09:27:05 zigbeepi npm[2813]: 2018-6-9 09:27:05 ERROR Not connected to MQTT server!
Jun 09 09:27:07 zigbeepi npm[2813]: 2018-6-9 09:27:07 INFO Connected to MQTT server
Jun 09 09:27:07 zigbeepi npm[2813]: 2018-6-9 09:27:07 INFO MQTT publish, topic: 'zigbee2mqtt/bridge/state', payload: 'online'
Jun 09 09:27:07 zigbeepi npm[2813]: 2018-6-9 09:27:07 WARN `permit_join` set to  `true` in configuration.yaml.
Jun 09 09:27:07 zigbeepi npm[2813]: 2018-6-9 09:27:07 WARN Allowing new devices to join.
Jun 09 09:27:07 zigbeepi npm[2813]: 2018-6-9 09:27:07 WARN Set `permit_join` to `false` once you joined all devices.
Jun 09 09:27:07 zigbeepi npm[2813]: 2018-6-9 09:27:07 INFO Zigbee: allowing new devices to join.

At the point where it says INFO Connected to MQTT server, could the sensors be published back to HA (it may need a delay if HA isn't ready just then)? e.g. like this:

Jun 09 09:25:49 zigbeepi npm[2813]: 2018-6-9 09:25:49 INFO MQTT publish, topic: 'homeassistant/binary_sensor/0x00158d0001b149eb/contact/config', payload: '{"payload_on":false,"payload_off":true,"value_template":"{{ value_json.contact }}","device_class":"door","json_attributes":["battery","voltage"],"state_topic":"zigbee2mqtt/window_ensuite_velux","availability_topic":"zigbee2mqtt/bridge/state","name":"window_ensuite_velux","unique_id":"0x00158d0001b149eb_contact_zigbee2mqtt"}'

[Koenkk]

This happens when you are using the built-in homeassistant MQTT broker, when you restart home assistant the retained zigbee2mqtt configuration messages are lost.

Possible solution: enable Home Assistant MQTT birth and last will message, listen for them in zigbee2mqtt and send configuration again on hass/status online.

Do you indeed use the builtin home assistant broker?

EDIT: Another solution would be to just send all configuration messages when zigbee2mqtt reconnects to the MQTT server (even easier).

[jarrah31]

Yep, using the builtin mqtt broker.

Great, sending all config messages after a reconnect is just what I was hoping for (I suggested this in the OP) - thanks!

[jarrah31]

Sorry, a few title typo's there... :)

[ciotlosm]

If we get auto discovery to send data back, would there be a chance to include sensor updates if data is in cache on the same birth/last messages?

[Koenkk]

@jarrah31 @ciotlosm both implemented now, can you verify?

[ciotlosm]

I've checked with temperature sensor and cube and seams to work 👍

Notes:

• I haven't tested using integrated mqtt broker - using mosquitto addon
• I haven't tested discovery part (which probably related to mqtt broker) - but I didn't see discovery messages being re-posted.

Update 1: Actually read the code and figured out that discovery was only for mqtt reconnect which makes sense.

Update 2: @Koenkk Unsure how this was implemented, but will this also send actions back? (click, rotate, etc.) It shouldn't send those as you might trigger many automations if you do. Unsure on best approach to only get this for useful things like binary sensors or temperature sensors.
s.

Update 3: Maybe it was just a coincidence but my sensor sent data on HA restart. Code seems to only do it on mqtt reconnect - Even on reconnect we should not send clicks & other actions.

[jarrah31]

@Koenkk updated and tested - works brilliantly, thank you!!

I have the integrated mqtt broker and can confirm my Xiaomi Aqara door/window sensors are automatically re-posted.

Jun 11 20:21:17 zigbeepi npm[6108]: 2018-6-11 20:21:17 ERROR Not connected to MQTT server!
Jun 11 20:21:27 zigbeepi npm[6108]: 2018-6-11 20:21:27 ERROR Not connected to MQTT server!
Jun 11 20:21:28 zigbeepi npm[6108]: 2018-6-11 20:21:28 INFO Connected to MQTT server
Jun 11 20:21:28 zigbeepi npm[6108]: 2018-6-11 20:21:28 INFO MQTT publish, topic: 'zigbee2mqtt/bridge/state', payload: 'online'
Jun 11 20:21:28 zigbeepi npm[6108]: 2018-6-11 20:21:28 INFO MQTT publish, topic: 'homeassistant/binary_sensor/0x00158d0001b149eb/contact/config', payload: '{"payload_on":false,"payload_off":true,"value_template":"{{ value_json.contact }}","device_class":"door","json_attributes":["battery","voltage"],"state_topic":"zigbee2mqtt/window_ensuite_velux","availability_topic":"zigbee2mqtt/bridge/state","name":"window_ensuite_velux","unique_id":"0x00158d0001b149eb_contact_zigbee2mqtt"}'
Jun 11 20:21:28 zigbeepi npm[6108]: 2018-6-11 20:21:28 INFO MQTT publish, topic: 'homeassistant/binary_sensor/0x00158d000245b389/contact/config', payload: '{"payload_on":false,"payload_off":true,"value_template":"{{ value_json.contact }}","device_class":"door","json_attributes":["battery","voltage"],"state_topic":"zigbee2mqtt/window_bed2_mainleft","availability_topic":"zigbee2mqtt/bridge/state","name":"window_bed2_mainleft","unique_id":"0x00158d000245b389_contact_zigbee2mqtt"}'
Jun 11 20:22:51 zigbeepi npm[6108]: 2018-6-11 20:22:51 INFO MQTT publish, topic: 'zigbee2mqtt/window_bed2_mainleft', payload: '{"contact":false}'
Jun 11 20:22:52 zigbeepi npm[6108]: 2018-6-11 20:22:52 INFO MQTT publish, topic: 'zigbee2mqtt/window_bed2_mainleft', payload: '{"contact":true}'

[Koenkk]

@ciotlosm these are not resent as these are not cached: https://github.com/Koenkk/zigbee2mqtt/blob/master/lib/controller.js#L291. Messages which contain one of the following keys are not cached: ['click', 'action', 'button', 'button_left', 'button_right'];

[jarrah31]

I've just tested the cached status and confirm that works as well:

Jun 11 20:32:44 zigbeepi npm[6108]: 2018-6-11 20:32:44 ERROR Not connected to MQTT server!
Jun 11 20:32:44 zigbeepi npm[6108]: 2018-6-11 20:32:44 ERROR Cannot send message: topic: 'zigbee2mqtt/window_ensuite_velux', payload: '{"contact":false}
Jun 11 20:32:47 zigbeepi npm[6108]: 2018-6-11 20:32:47 ERROR Not connected to MQTT server!
Jun 11 20:32:48 zigbeepi npm[6108]: 2018-6-11 20:32:48 ERROR Not connected to MQTT server!
Jun 11 20:32:48 zigbeepi npm[6108]: 2018-6-11 20:32:48 ERROR Cannot send message: topic: 'zigbee2mqtt/window_bed2_mainleft', payload: '{"contact":false}
Jun 11 20:32:57 zigbeepi npm[6108]: 2018-6-11 20:32:57 ERROR Not connected to MQTT server!
Jun 11 20:32:57 zigbeepi npm[6108]: 2018-6-11 20:32:57 ERROR Not connected to MQTT server!
Jun 11 20:32:57 zigbeepi npm[6108]: 2018-6-11 20:32:57 ERROR Cannot send message: topic: 'zigbee2mqtt/window_ensuite_velux', payload: '{"contact":true}
Jun 11 20:33:07 zigbeepi npm[6108]: 2018-6-11 20:33:07 ERROR Not connected to MQTT server!
Jun 11 20:33:12 zigbeepi npm[6108]: 2018-6-11 20:33:12 INFO Connected to MQTT server
Jun 11 20:33:12 zigbeepi npm[6108]: 2018-6-11 20:33:12 INFO MQTT publish, topic: 'zigbee2mqtt/bridge/state', payload: 'online'
Jun 11 20:33:12 zigbeepi npm[6108]: 2018-6-11 20:33:12 INFO MQTT publish, topic: 'homeassistant/binary_sensor/0x00158d0001b149eb/contact/config', payload: '{"payload_on":false,"payload_off":true,"value_template":"{{ value_json.contact }}","device_class":"door","json_attributes":["battery","voltage"],"state_topic":"zigbee2mqtt/window_ensuite_velux","availability_topic":"zigbee2mqtt/bridge/state","name":"window_ensuite_velux","unique_id":"0x00158d0001b149eb_contact_zigbee2mqtt"}'
Jun 11 20:33:12 zigbeepi npm[6108]: 2018-6-11 20:33:12 INFO MQTT publish, topic: 'homeassistant/binary_sensor/0x00158d000245b389/contact/config', payload: '{"payload_on":false,"payload_off":true,"value_template":"{{ value_json.contact }}","device_class":"door","json_attributes":["battery","voltage"],"state_topic":"zigbee2mqtt/window_bed2_mainleft","availability_topic":"zigbee2mqtt/bridge/state","name":"window_bed2_mainleft","unique_id":"0x00158d000245b389_contact_zigbee2mqtt"}'
Jun 11 20:33:12 zigbeepi npm[6108]: 2018-6-11 20:33:12 INFO MQTT publish, topic: 'zigbee2mqtt/window_ensuite_velux', payload: '{"contact":true}'
Jun 11 20:33:12 zigbeepi npm[6108]: 2018-6-11 20:33:12 INFO MQTT publish, topic: 'zigbee2mqtt/window_bed2_mainleft', payload: '{"contact":false}'

[Koenkk]

@ciotlosm @jarrah31 thanks!

[jarrah31]

sorry, just spotted a problem with the cached state (that open sensor still reports as off in HA), let me do some digging

[jarrah31]

Steps followed:

• both sensors in off/closed state
• restart HA
• wait for "Not connected to MQTT server" message
• open one sensor
• cached sensors sent as MQTT message when HA detected online
• wait for HA to finish loading
• States page shows sensor as off when it should be on:
  

zigbee2mqtt log:

Jun 11 20:40:17 zigbeepi npm[6108]: 2018-6-11 20:40:17 ERROR Not connected to MQTT server!
Jun 11 20:40:19 zigbeepi npm[6108]: 2018-6-11 20:40:19 ERROR Not connected to MQTT server!
Jun 11 20:40:19 zigbeepi npm[6108]: 2018-6-11 20:40:19 ERROR Cannot send message: topic: 'zigbee2mqtt/window_ensuite_velux', payload: '{"contact":false}
Jun 11 20:40:27 zigbeepi npm[6108]: 2018-6-11 20:40:27 ERROR Not connected to MQTT server!
Jun 11 20:40:37 zigbeepi npm[6108]: 2018-6-11 20:40:37 ERROR Not connected to MQTT server!
Jun 11 20:40:42 zigbeepi npm[6108]: 2018-6-11 20:40:42 INFO Connected to MQTT server
Jun 11 20:40:42 zigbeepi npm[6108]: 2018-6-11 20:40:42 INFO MQTT publish, topic: 'zigbee2mqtt/bridge/state', payload: 'online'
Jun 11 20:40:42 zigbeepi npm[6108]: 2018-6-11 20:40:42 INFO MQTT publish, topic: 'homeassistant/binary_sensor/0x00158d0001b149eb/contact/config', payload: '{"payload_on":false,"payload_off":true,"value_template":"{{ value_json.contact }}","device_class":"door","json_attributes":["battery","voltage"],"state_topic":"zigbee2mqtt/window_ensuite_velux","availability_topic":"zigbee2mqtt/bridge/state","name":"window_ensuite_velux","unique_id":"0x00158d0001b149eb_contact_zigbee2mqtt"}'
Jun 11 20:40:42 zigbeepi npm[6108]: 2018-6-11 20:40:42 INFO MQTT publish, topic: 'homeassistant/binary_sensor/0x00158d000245b389/contact/config', payload: '{"payload_on":false,"payload_off":true,"value_template":"{{ value_json.contact }}","device_class":"door","json_attributes":["battery","voltage"],"state_topic":"zigbee2mqtt/window_bed2_mainleft","availability_topic":"zigbee2mqtt/bridge/state","name":"window_bed2_mainleft","unique_id":"0x00158d000245b389_contact_zigbee2mqtt"}'
Jun 11 20:40:42 zigbeepi npm[6108]: 2018-6-11 20:40:42 INFO MQTT publish, topic: 'zigbee2mqtt/window_ensuite_velux', payload: '{"contact":false}'
Jun 11 20:40:42 zigbeepi npm[6108]: 2018-6-11 20:40:42 INFO MQTT publish, topic: 'zigbee2mqtt/window_bed2_mainleft', payload: '{"contact":true}'

HA log:

2018-06-11 20:40:27 INFO (MainThread) [homeassistant.setup] Setting up mqtt
2018-06-11 20:40:27 INFO (MainThread) [homeassistant.loader] Loaded mqtt.server from homeassistant.components.mqtt.server
2018-06-11 20:40:34 INFO (MainThread) [hbmqtt.broker] Listener 'default' bind to 0.0.0.0:1883 (max_connections=-1)
2018-06-11 20:40:34 INFO (MainThread) [hbmqtt.broker] Listener 'ws-1' bind to 0.0.0.0:8080 (max_connections=-1)
2018-06-11 20:40:35 INFO (MainThread) [homeassistant.loader] Loaded mqtt.discovery from homeassistant.components.mqtt.discovery
2018-06-11 20:40:35 INFO (MainThread) [hbmqtt.broker] Listener 'default': 1 connections acquired
2018-06-11 20:40:35 INFO (MainThread) [hbmqtt.broker] Connection from 127.0.0.1:33737 on listener 'default'
2018-06-11 20:40:35 INFO (MainThread) [homeassistant.setup] Setup of domain mqtt took 7.4 seconds.
2018-06-11 20:40:38 INFO (MainThread) [hbmqtt.broker] Listener 'default': 2 connections acquired
2018-06-11 20:40:38 INFO (MainThread) [hbmqtt.broker] Connection from 192.168.1.58:53946 on listener 'default'
2018-06-11 20:40:43 INFO (MainThread) [homeassistant.components.mqtt.discovery] Found new component: binary_sensor 0x00158d0001b149eb_contact
2018-06-11 20:40:43 INFO (MainThread) [homeassistant.loader] Loaded binary_sensor.mqtt from homeassistant.components.binary_sensor.mqtt
2018-06-11 20:40:43 INFO (MainThread) [homeassistant.components.mqtt.discovery] Found new component: binary_sensor 0x00158d000245b389_contact
2018-06-11 20:40:43 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.mqtt
2018-06-11 20:40:43 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.mqtt
2018-06-11 20:40:56 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.mqtt
2018-06-11 20:40:56 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.mqtt

I'll enable debug for MQTT on HA and see if that reports anything more.

[Koenkk]

The last value your sensor reported is contact: false.

--> Jun 11 20:40:19 zigbeepi npm[6108]: 2018-6-11 20:40:19 ERROR Cannot send message: topic: 'zigbee2mqtt/window_ensuite_velux', payload: '{"contact":false} <--
Jun 11 20:40:27 zigbeepi npm[6108]: 2018-6-11 20:40:27 ERROR Not connected to MQTT server!
Jun 11 20:40:37 zigbeepi npm[6108]: 2018-6-11 20:40:37 ERROR Not connected to MQTT server!
Jun 11 20:40:42 zigbeepi npm[6108]: 2018-6-11 20:40:42 INFO Connected to MQTT server
Jun 11 20:40:42 zigbeepi npm[6108]: 2018-6-11 20:40:42 INFO MQTT publish, topic: 'zigbee2mqtt/bridge/state', payload: 'online'
Jun 11 20:40:42 zigbeepi npm[6108]: 2018-6-11 20:40:42 INFO MQTT publish, topic: 'homeassistant/binary_sensor/0x00158d0001b149eb/contact/config', payload: '{"payload_on":false,"payload_off":true,"value_template":"{{ value_json.contact }}","device_class":"door","json_attributes":["battery","voltage"],"state_topic":"zigbee2mqtt/window_ensuite_velux","availability_topic":"zigbee2mqtt/bridge/state","name":"window_ensuite_velux","unique_id":"0x00158d0001b149eb_contact_zigbee2mqtt"}'
Jun 11 20:40:42 zigbeepi npm[6108]: 2018-6-11 20:40:42 INFO MQTT publish, topic: 'homeassistant/binary_sensor/0x00158d000245b389/contact/config', payload: '{"payload_on":false,"payload_off":true,"value_template":"{{ value_json.contact }}","device_class":"door","json_attributes":["battery","voltage"],"state_topic":"zigbee2mqtt/window_bed2_mainleft","availability_topic":"zigbee2mqtt/bridge/state","name":"window_bed2_mainleft","unique_id":"0x00158d000245b389_contact_zigbee2mqtt"}'
Jun 11 20:40:42 zigbeepi npm[6108]: 2018-6-11 20:40:42 INFO MQTT publish, topic: 'zigbee2mqtt/window_ensuite_velux', payload: '{"contact":false}'

contact: false means that the door is open.

[jarrah31]

Yeah, all looks great from zigbee2mqtt's perspective, so I wonder if the cached entries are posted too soon/quickly for HA to process them. Perhaps a 5 second delay is needed before the cached payload is sent to HA?

I'm just trying to decipher the debug logs to see if it sees the message. Should be in here somewhere. :)

[Koenkk]

Yes, probably, can you set retain: true for that device in the configuration.yaml?

[ciotlosm]

Either mqtt broker started before HA could process, or HA processed correctly but restored value from recorder once sensor was setup. Best to try retain flag, but most likely not a zigbee2mqtt issue.

[jarrah31]

I by no means know much about MQTT, so here is my best guess at what's happening (see comments in the log)

#Received new sensor information here
2018-06-11 20:54:00 DEBUG (MainThread) [hbmqtt.broker.plugins.packet_logger_plugin] home-assistant -out-> PublishPacket(ts=2018-06-11 20:54:00.570359, fixed=MQTTFixedHeader(length=388, flags=0x0), variable=PublishVariableHeader(topic=homeassistant/binary_sensor/0x00158d0001b149eb/contact/config, packet_id=None), payload=PublishPayload(data='bytearray(b\'{"payload_on":false,"payload_off":true,"value_template":"{{ value_json.contact }}","device_class":"door","json_attributes":["battery","voltage"],"state_topic":"zigbee2mqtt/window_ensuite_velux","availability_topic":"zigbee2mqtt/bridge/state","name":"window_ensuite_velux","unique_id":"0x00158d0001b149eb_contact_zigbee2mqtt"}\')'))

#Receiving the cached state here
2018-06-11 20:54:00 DEBUG (MainThread) [hbmqtt.broker.plugins.packet_logger_plugin] mqttjs_051f631c <-in-- PublishPacket(ts=2018-06-11 20:54:00.571785, fixed=MQTTFixedHeader(length=51, flags=0x0), variable=PublishVariableHeader(topic=zigbee2mqtt/window_ensuite_velux, packet_id=None), payload=PublishPayload(data='bytearray(b\'{"contact":false}\')'))
2018-06-11 20:54:00 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on homeassistant/binary_sensor/0x00158d0001b149eb/contact/config: b'{"payload_on":false,"payload_off":true,"value_template":"{{ value_json.contact }}","device_class":"door","json_attributes":["battery","voltage"],"state_topic":"zigbee2mqtt/window_ensuite_velux","availability_topic":"zigbee2mqtt/bridge/state","name":"window_ensuite_velux","unique_id":"0x00158d0001b149eb_contact_zigbee2mqtt"}'
2018-06-11 20:54:00 DEBUG (MainThread) [hbmqtt.broker] broadcasting {'topic': 'zigbee2mqtt/window_ensuite_velux', 'session': Session(clientId=mqttjs_051f631c, state=connected), 'data': bytearray(b'{"contact":false}')}

#To me it then looks like MQTT is being set up to receive messages from this point, so the cached post above is being ignored?
2018-06-11 20:54:05 DEBUG (MainThread) [homeassistant.components.mqtt] Subscribing to zigbee2mqtt/window_ensuite_velux
2018-06-11 20:54:05 DEBUG (MainThread) [hbmqtt.broker.plugins.packet_logger_plugin] home-assistant <-in-- SubscribePacket(ts=2018-06-11 20:54:05.412231, fixed=MQTTFixedHeader(length=37, flags=0x2), variable=PacketIdVariableHeader(packet_id=5), payload=SubscribePayload(topics=[('zigbee2mqtt/window_ensuite_velux', 0)]))
2018-06-11 20:54:05 DEBUG (MainThread) [hbmqtt.broker] Begin broadcasting messages retained due to subscription on 'zigbee2mqtt/window_ensuite_velux' from (client id=home-assistant)
2018-06-11 20:54:05 DEBUG (MainThread) [hbmqtt.broker] matching : homeassistant/binary_sensor/0x00158d0001b149eb/contact/config zigbee2mqtt/window_ensuite_velux
2018-06-11 20:54:05 DEBUG (MainThread) [hbmqtt.broker] matching : $SYS/broker/version zigbee2mqtt/window_ensuite_velux
2018-06-11 20:54:05 DEBUG (MainThread) [hbmqtt.broker] matching : homeassistant/binary_sensor/0x00158d000245b389/contact/config zigbee2mqtt/window_ensuite_velux
2018-06-11 20:54:05 DEBUG (MainThread) [hbmqtt.broker] matching : zigbee2mqtt/bridge/state zigbee2mqtt/window_ensuite_velux
2018-06-11 20:54:05 DEBUG (MainThread) [hbmqtt.broker] End broadcasting messages retained due to subscription on 'zigbee2mqtt/window_ensuite_velux' from (client id=home-assistant)

[Koenkk]

@jarrah31 have you set retain: true for this sensor?

[jarrah31]

Yes, probably, can you set retain: true for that device in the configuration.yaml?

I'm not sure I fully understand what this option does. On the wiki it says retain: Retain MQTT messages of this device. - I assumed it retained messages on zigbee2mqtt somewhere, but does it instead set something on HA?

I have this set to false at the moment.

EDIT - testing it with true now...

[Koenkk]

Retained messages will be resend when a client subscribes to that topic (while non retained are not). This is controlled by the MQTT broker.

So when setting retain: true.

• MQTT broker starts
• Zigbee2mqtt sends home assistant config and cached values retained, at this point home assistant is not connected yet, no values are received by home assistant
• Home assistant connects to broker and subscribes to topic
• Because the message is retained MQTT broker resends the cached values to home assistant

[jarrah31]

Thanks @Koenkk, setting retain: true has worked!

Really sorry for my misunderstanding of this option and for taking up your time this evening. If you don't mind could you copy your excellent explanation above into the wiki for this option please so that others don't make the same mistake?

Thanks again for fixing the original problem in this issue!

[Koenkk]

I'm still wondering what a good solution would be, I don't like using retain: true just to work around this issue.

[ciotlosm]

@Koenkk a PR for home assistant to publish to MQTT it is now online and listening (if not already exists)

[ciotlosm]

@Koenkk @jarrah31 I'm going to close this issue as it's fixed. If needed we can always open a separate enhancement issue with a solution to avoid using retain: true when this use case is used (embedded mqtt broker).

[Koenkk]

I will reopen this, already working on an implementation which listens to: https://www.home-assistant.io/docs/mqtt/birth_will/

[Koenkk]

This should work properly now, see updated documentation: https://github.com/Koenkk/zigbee2mqtt/wiki/Integrating-with-Home-Assistant

[ciotlosm]

@jarrah31 can you retest your setup without retain?

[ciotlosm]

@Koenkk Maybe your docs got rewritten by some other process? I can't see the updates on the wiki.

[Koenkk]

Yes, i've just updated docgen.

[jarrah31]

Unfortunately it doesn't seem to have worked.

After updating, I commented out the retain: true lines, and added the birth and will messages in HA as follows:

mqtt:
  discovery: true
  birth_message:
    topic: 'hass/status'
    payload: 'online'
  will_message:
    topic: 'hass/status'
    payload: 'offline'

I didn't include broker: because I'm using the built-in one (should a comment be added in the wiki to say this line is optional?)

I restarted Z2M, and then restarted HA. When the Not connected to MQTT server! messages appeared, I opened the sensors. After letting HA settle, I could see on the states page that the sensors remained off instead of on. After a quick sensor on/off test, I restarted HA again just in case, but the sensors still report as off.

Next I un-commented the retain line, leaving one sensor as false and the other as true, then as above restarted HA and opened the sensor when offline. The retain true line updated the sensor state correctly after a reboot.

[ciotlosm]

@jarrah31 can you please post logs? (Remember to use hastebin)

[jarrah31]

nice! Not used hastebin before. :)

https://hastebin.com/ukuhebemas.scala

[ciotlosm]

@jarrah31 can you also post your home assistant log for the same period as the one above?

[jarrah31]

ah sorry - here we go: https://hastebin.com/ewagixoqah.js

Not much to show really - shall I restart with debug enabled?

[ciotlosm]

I was hoping to see the hass/status messages somewhere to see some correlation.

[jarrah31]

no problems - HA debug logs with hass/status: https://hastebin.com/uhogasacey.pl
Z2M logs at the same time - https://hastebin.com/awecavexop.scala

Hope they help - signing off for the night but can do more testing tomorrow. Thanks!!

[Koenkk]

These messages should be send two times while they are only send once:

Jun 13 21:40:36 zigbeepi npm[8836]: 2018-6-13 21:40:36 INFO MQTT publish, topic: 'zigbee2mqtt/window_ensuite_velux', payload: '{"contact":false}'
Jun 13 21:40:36 zigbeepi npm[8836]: 2018-6-13 21:40:36 INFO MQTT publish, topic: 'zigbee2mqtt/window_bed2_mainleft', payload: '{"contact":false}'

That means that this code is not triggering: https://github.com/Koenkk/zigbee2mqtt/blob/master/lib/controller.js#L326

We should add more debug logging to debug this problem.

For now, can you add console.log(topic) here https://github.com/Koenkk/zigbee2mqtt/blob/master/lib/controller.js#L337 ?

[jarrah31]

I noticed that it did send the message twice on an earlier run so not sure why it didn't work in that instance: https://hastebin.com/ocihocoqoy.scala

Will will try again later today as at work atm. Do you need debug logs on zigbee2mqtt as well as HA?

[Koenkk]

Yes I need both logs.

[jarrah31]

Added console.log(topic) and tested again with the output below. Just to confirm my current commit version and to check I've put the console.log in the right place:

pi@zigbeepi:/opt/zigbee2mqtt $ git rev-parse HEAD
b0cdcf2e2161bb6076f93a51ecb71a6144bde988
pi@zigbeepi:/opt/zigbee2mqtt $
pi@zigbeepi:/opt/zigbee2mqtt $ cat lib/controller.js | grep -C 3 "console.log(topic)"

    handleMQTTMessageConfig(topic, message) {
        const option = topic.split('/')[3];
    console.log(topic)
        if (option === 'permit_join') {
            this.zigbee.permitJoin(message.toString().toLowerCase() === 'true');
        } else if (option === 'devices') {

HA logs: https://hastebin.com/kefeguveye.pl
Z2M logs: https://hastebin.com/zukufinoba.scala

[Koenkk]

Are you sure home assistant is sending the hass/status online message, as I don't see it in the log.

[ciotlosm]

@Koenkk wrong place for console.log, should have been higher up

    handleMQTTMessage(topic, message) {
<HERE>
        if (topic.match(mqttConfigRegex)) {

Instead of:

    handleMQTTMessageConfig(topic, message) {
        const option = topic.split('/')[3];
<NOT HERE>
        if (option === 'permit_join') {

See position in the PR https://github.com/Koenkk/zigbee2mqtt/pull/110/files#diff-f68567477d803b49930337bf7fe1556bR312

[jarrah31]

Also just realised my version of HA may be a factor (0.66.1), so i’ll upgrade it this evening before further testing.

[ciotlosm]

@jarrah31 are you using hassio or hassbian? Just curious on how easy it is to try the new version of zigbee2mqtt.

[jarrah31]

hassbian, so easy to update to the latest commit.

[ciotlosm]

Can you retry your test with latest commits? Extra logging was added. Make sure you start with DEBUG=* npm start

[jarrah31]

HA offline atm due to upgrading, but just before I did that I updated to the latest Z2M and captured the logs. Unfortunately I didn't enable Z2M debug logs this time but I do have debug enabled in the config yaml if that helps.

advanced:
  log_level: debug

https://hastebin.com/vocexebeno.pl

[ciotlosm]

Thanks. Looks like hass tries to publish, but nothing is received on Z2M side:

2018-06-14 21:01:09 DEBUG (MainThread) [hbmqtt.broker] Begin broadcasting messages retained due to subscription on 'hass/status' from (client id=mqttjs_0359e342)
2018-06-14 21:01:09 DEBUG (MainThread) [hbmqtt.broker] matching : $SYS/broker/version hass/status
2018-06-14 21:01:09 DEBUG (MainThread) [hbmqtt.broker] End broadcasting messages retained due to subscription on 'hass/status' from (client id=mqttjs_0359e342)

We'll wait for your update, maybe something changes.

[jarrah31]

Ok, so now running 0.71.0 but I'm afraid cached sensor state isn't being updated in HA.

Latest logs are: https://hastebin.com/vigalukele.scala

More detail in this log in case it helps (grep'd for mqtt): https://hastebin.com/amexeresaz.scala

[Koenkk]

I could reproduce this and got it fixed by setting retain: true for both birth and will messags.

mqtt:
  discovery: true
  broker: [YOUR MQTT BROKER]  # Remove if you want to use builtin-in MQTT broker
  birth_message:
    topic: 'hass/status'
    payload: 'online'
    retain: true
  will_message:
    topic: 'hass/status'
    payload: 'offline'
    retain: true

Can you confirm?

EDIT: this however seems inconsistent with the documentation: https://www.home-assistant.io/docs/mqtt/birth_will/ (as it should be true by default).

[jarrah31]

I'm afraid it hasn't worked on my setup for some reason. I have added the retain lines on my HA configuration.yaml mqtt entry as shown above, restarted HA (tried 3 times now, with the 3rd enabling debug), opened the sensors when the connection was lost, and waited for HA to finish booting. In each case, both sensors remained as 'off' within the states page.

Logs: https://hastebin.com/edazepuniz.pl

The old method of having retain: true in Z2M configuration.yaml no longer works either (set to true in both sets of yaml files).

[Koenkk]

It seems that something strange is going on with your HA installation, zigbee2mqtt receives the hass/status now and send the cached states:

Jun 18 20:29:17 zigbeepi npm[15346]: 2018-6-18 20:29:17 DEBUG Recieved mqtt message on topic 'hass/status' with data 'online'
Jun 18 20:29:21 zigbeepi npm[15346]: 2018-6-18 20:29:21 INFO MQTT publish, topic: 'zigbee2mqtt/window_ensuite_velux', payload: '{"contact":false}'
Jun 18 20:29:21 zigbeepi npm[15346]: 2018-6-18 20:29:21 INFO MQTT publish, topic: 'zigbee2mqtt/window_bed2_mainleft', payload: '{"contact":false}'

[jarrah31]

Yeah, I know what you mean. I'm curious to know if anyone else has the same issue so would you mind if I asked others to test this out on the forum please?

On a side note, I've got it working again by commenting out the retain: true lines in HA and just having them enabled in Z2M.

[Koenkk]

Feel free to ask around!

[ciotlosm]

@Koenkk considering https://github.com/Koenkk/zigbee2mqtt/issues/126 is fixed (just needs firmware in right place) and this has a fix already, should 0.1 be considered soon?

[Koenkk]

@ciotlosm yes, if this is fixed, 0.1 is ready.

@jarrah31 can you try increasing the timeout after which the states are send: https://github.com/Koenkk/zigbee2mqtt/blob/master/lib/controller.js#L333. Change 3000 to e.g. 10000 (10 seconds).

Rationale: I tried on my mac which is ofcourse much faster than a pi, perhaps the pi needs more time to get the MQTT broker/home assistant up-and-running.

[jarrah31]

That appears to have done the trick! In my case I had to increase the timeout value to 20000 until it worked, so perhaps this could be a configurable option in configuration.yaml? (I just went to 20 straight from 10 so a lower value may work, but it doesn't seem to be an issue with with this length of delay as it took another minute before the GUI was ready)

[jarrah31]

oops, sorry wrong button. :)

[ciotlosm]

This sucks. I think this should be a bug/issue logged in Home Assistant. Ideally when you get hass/online you should have both MQTT and HA state machine up and running, regardless of UI. You shouldn't need a timeout to publish a state to be recorded by the state machine.

[Koenkk]

@ciotlosm I completely agree but for now this is the only solution. Would you mind filling a bug at home assistant?

[jeremywillans]

Hey @Koenkk, sorry to dig up an old thread, but is it possible to move this timeout value to a configuratation variable? This issue has been driving me nuts running Z2M and HA in docker on a RPi4 and every reboot all the sensors report Unknown value.

@ciotlosm - Did you happen to raise a HA bug for this?

My workaround is re-publishing the birth message to MQTT on HA Start with a delay.

automation:
  # Force Publish HA Birth Message
  - id: zigbee_publish_birth_message
    alias: Zigbee Publish MQTT Birth Message
    trigger:
      platform: homeassistant
      event: start
    action:
      - delay: '10' # Adjust as required, Z2M adds 20 sec before cache send
      - service: mqtt.publish
        data:
          topic: 'hass/status'
          payload: 'online'

[Koenkk]

@jeremywillans would 30 seconds be a good value? (in that case we can make it the default)

[jeremywillans]

Happy to try it at 30 seconds !

[Koenkk]

Done, please try with the latest dev branch.

[jeremywillans]

Tested and works perfectly! Thanks! 👍