search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
73.48k stars 30.69k forks source link

[MQTT] Home Assistant Birth message is published too early #39007

Closed effelle closed 4 years ago

effelle commented 4 years ago

The problem

Following @emontnemery PR #37371 we added the subscription to homeassistant/status to keep Tasmota devices in sync with Home Assistant without using any kind of automation (our PR 9096 ). Tasmota will receive the messages correctly and then will automatically send out a /STATE topic for all our discovered devices present under Home Assistant but seems there is a race condition to be addressed. In all our tests even the fastest machine runing an HAss server took at least 12 seconds to be able to listen to a topic and that defeat a bit the pourpose of a Birth message. Using a simple automation, component loaded some seconds after the mqtt, shown Home Assistant is listening correctly after presenting the message "Home Assistant has started!" on Lovelace.

Environment

arch | armv7l
dev | false
docker | true
docker_version | 19.03.8
hassio | true
host_os | Ubuntu 18.04.4 LTS
installation_type | Home Assistant Supervised
os_name | Linux
os_version | 5.4.31-sunxi
python_version | 3.8.3
supervisor | 234
version | 0.114.1
virtualenv | false

Problem-relevant configuration.yaml

/config/automations.yaml
- id: '1597755207630'
  alias: mqtt sync
  description: Tasmota sync
  trigger:
  - event: start
    platform: homeassistant
  condition: []
  action:
  - data:
      payload: ready            #not a valid payload, just for test
      topic: homeassistant/status
    service: mqtt.publish
  - data:
      payload: ''
      topic: cmnd/tasmotas/state
    service: mqtt.publish
  mode: single

Traceback/Error logs

First part of the log, where the homeassistant/status will send its online status:

2020-08-18 11:00:22 INFO (Thread-5) [homeassistant.components.mqtt] Connected to MQTT server core-mosquitto:1883 (0)
2020-08-18 11:00:22 INFO (MainThread) [homeassistant.components.updater] Submitted analytics to Home Assistant servers. Information submitted includes {}
2020-08-18 11:00:23 INFO (MainThread) [homeassistant.setup] Setting up ssdp
2020-08-18 11:00:23 INFO (MainThread) [homeassistant.setup] Setup of domain ssdp took 0.0 seconds
2020-08-18 11:00:23 DEBUG (MainThread) [homeassistant.components.mqtt] Subscribing to homeassistant/#
2020-08-18 11:00:23 INFO (MainThread) [homeassistant.setup] Setting up cast
2020-08-18 11:00:23 INFO (MainThread) [homeassistant.setup] Setup of domain cast took 0.0 seconds
2020-08-18 11:00:24 INFO (MainThread) [homeassistant.setup] Setting up default_config
2020-08-18 11:00:24 DEBUG (MainThread) [homeassistant.components.mqtt] Transmitting message on homeassistant/status: online

Tasmota received it and publish its unheard /STATE topic:

11:00:24 MQT: Received Topic "homeassistant/status", Data Size 6, Data "online"
11:00:24 MQT: tele/tasmota_Hass/STATE = {"Time":"2020-08-18T11:00:24","Uptime":"0T00:44:24","UptimeSec":2664,"Heap":26,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":22,"MqttCount":1,"POWER":"ON","Wifi":{"AP":1,"SSId":"EffE-WiFi","BSSId":"XX:XX:XX:XX:XX:XX","Channel":13,"RSSI":82,"Signal":-59,"LinkCount":1,"Downtime":"0T00:00:03"}}

Then after several seconds the automation fires and Tasmota /STATE topic is finally registered:

2020-08-18 11:00:36 INFO (MainThread) [homeassistant.components.automation.mqtt_sync] Executing mqtt sync
2020-08-18 11:00:36 INFO (MainThread) [homeassistant.components.automation.mqtt_sync] mqtt sync: Running script
2020-08-18 11:00:36 INFO (MainThread) [homeassistant.components.automation.mqtt_sync] mqtt sync: Executing step call service
2020-08-18 11:00:36 INFO (MainThread) [homeassistant.components.automation.mqtt_sync] Initialized trigger mqtt sync
2020-08-18 11:00:36 DEBUG (MainThread) [homeassistant.components.mqtt] Transmitting message on homeassistant/status: ready
2020-08-18 11:00:36 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on homeassistant/status: b'ready'
2020-08-18 11:00:36 INFO (MainThread) [homeassistant.components.automation.mqtt_sync] mqtt sync: Executing step call service
2020-08-18 11:00:36 DEBUG (MainThread) [homeassistant.components.mqtt] Transmitting message on cmnd/tasmotas/state: 
2020-08-18 11:00:38 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on tele/tasmota_Hass/STATE: b'{"Time":"2020-08-18T11:00:36","Uptime":"0T00:44:36","UptimeSec":2676,"Heap":26,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"POWER":"ON","Wifi":{"AP":1,"SSId":"EffE-WiFi","BSSId":"64:70:02:38:FC:DB","Channel":13,"RSSI":80,"Signal":-60,"LinkCount":1,"Downtime":"0T00:00:03"}}'
2020-08-18 11:00:38 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on tele/tasmota_Hass/HASS_STATE: b'{"Version":"8.4.0.2(tasmota)","BuildDateTime":"2020-08-17T20:58:38","Module or Template":"Generic","RestartReason":"Software/System restart","Uptime":"0T00:44:36","Hostname":"tasmota_Hass-0956","IPAddress":"192.168.15.10","RSSI":"80","Signal (dBm)":"-60","WiFi LinkCount":1,"WiFi Downtime":"0T00:00:03","MqttCount":1,"LoadAvg":19}'

Additional information

Since the time needed to have Home Assistant listening to a topic depends on the machine where it is installed (Pi or Nuc have different loading time) I can't add a precise delay in our firmware and would be nice have homeassistant/status published after Home Assistant will be ready to manage a subscription.

Thanks,

Federico Leoni Tasmota Team

Support Information See Docs for more information. See Chat for more user experience. See Code of Conduct

probot-home-assistant[bot] commented 4 years ago

mqtt documentation mqtt source (message by IssueLinks)

probot-home-assistant[bot] commented 4 years ago

Hey there @home-assistant/core, @emontnemery, mind taking a look at this issue as its been labeled with an integration (mqtt) you are listed as a codeowner for? Thanks! (message by CodeOwnersMention)