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

Lost Sensors after HA Restart with Auto-discovery Enabled #105

Closed
jarrah31 opened this issue Jun 9, 2018 · 65 comments
Closed

Lost Sensors after HA Restart with Auto-discovery Enabled #105

jarrah31 opened this issue Jun 9, 2018 · 65 comments
Labels
feature request Feature request
Milestone

Comments

@jarrah31
Copy link

jarrah31 commented Jun 9, 2018

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"}'
@jarrah31 jarrah31 changed the title Loose Sensors after HA Restart with Auto-discovered Enabled Loose Sensors after HA Restart with Auto-discoverey Enabled Jun 9, 2018
@jarrah31 jarrah31 changed the title Loose Sensors after HA Restart with Auto-discoverey Enabled Loose Sensors after HA Restart with Auto-discovery Enabled Jun 9, 2018
@Koenkk
Copy link
Owner

Koenkk commented Jun 9, 2018

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).

@Koenkk Koenkk added the feature request Feature request label Jun 9, 2018
@jarrah31
Copy link
Author

jarrah31 commented Jun 9, 2018

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 jarrah31 changed the title Loose Sensors after HA Restart with Auto-discovery Enabled Lost Sensors after HA Restart with Auto-discovery Enabled Jun 9, 2018
@jarrah31
Copy link
Author

jarrah31 commented Jun 9, 2018

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

@Koenkk Koenkk added this to the 0.1 milestone Jun 10, 2018
@ciotlosm
Copy link
Contributor

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
Copy link
Owner

Koenkk commented Jun 11, 2018

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

@ciotlosm
Copy link
Contributor

ciotlosm commented Jun 11, 2018

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
Copy link
Author

@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
Copy link
Owner

Koenkk commented Jun 11, 2018

@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
Copy link
Author

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
Copy link
Owner

Koenkk commented Jun 11, 2018

@ciotlosm @jarrah31 thanks!

@Koenkk Koenkk closed this as completed Jun 11, 2018
@jarrah31
Copy link
Author

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

@Koenkk Koenkk reopened this Jun 11, 2018
@jarrah31
Copy link
Author

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:

screen shot 2018-06-11 at 20 42 39

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
Copy link
Owner

Koenkk commented Jun 11, 2018

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
Copy link
Author

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
Copy link
Owner

Koenkk commented Jun 11, 2018

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

@ciotlosm
Copy link
Contributor

ciotlosm commented Jun 11, 2018

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
Copy link
Author

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
Copy link
Owner

Koenkk commented Jun 11, 2018

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

@jarrah31
Copy link
Author

jarrah31 commented Jun 11, 2018

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
Copy link
Owner

Koenkk commented Jun 11, 2018

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
Copy link
Author

jarrah31 commented Jun 11, 2018

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
Copy link
Owner

Koenkk commented Jun 15, 2018

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
Copy link
Author

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
Copy link
Owner

Koenkk commented Jun 18, 2018

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
Copy link
Author

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
Copy link
Owner

Koenkk commented Jun 18, 2018

Feel free to ask around!

@ciotlosm
Copy link
Contributor

@Koenkk considering #126 is fixed (just needs firmware in right place) and this has a fix already, should 0.1 be considered soon?

@Koenkk
Copy link
Owner

Koenkk commented Jun 19, 2018

@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
Copy link
Author

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 jarrah31 reopened this Jun 20, 2018
@jarrah31
Copy link
Author

oops, sorry wrong button. :)

@ciotlosm
Copy link
Contributor

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
Copy link
Owner

Koenkk commented Jun 20, 2018

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

@Koenkk Koenkk closed this as completed Jun 20, 2018
wilmardo pushed a commit to wilmardo/zigbee2mqtt that referenced this issue Sep 26, 2019
wilmardo pushed a commit to wilmardo/zigbee2mqtt that referenced this issue Sep 26, 2019
wilmardo pushed a commit to wilmardo/zigbee2mqtt that referenced this issue Sep 26, 2019
wilmardo pushed a commit to wilmardo/zigbee2mqtt that referenced this issue Sep 26, 2019
wilmardo pushed a commit to wilmardo/zigbee2mqtt that referenced this issue Sep 26, 2019
@jeremywillans
Copy link

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
Copy link
Owner

Koenkk commented Mar 10, 2020

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

@jeremywillans
Copy link

Happy to try it at 30 seconds !

@Koenkk
Copy link
Owner

Koenkk commented Mar 10, 2020

Done, please try with the latest dev branch.

@jeremywillans
Copy link

Tested and works perfectly! Thanks! 👍

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
feature request Feature request
Projects
None yet
Development

No branches or pull requests

4 participants