Core: MQTT: Updates to templates do not take effect before restart

[LordMike]

The problem

When pushing MQTT discovery documents, using value templates, the new templates do not take effect until HASS is restarted.

Environment

• Home Assistant Core release with the issue: 0.109.6
• Last working Home Assistant Core release (if known): N/A
• Operating environment (Home Assistant/Supervised/Docker/venv): Docker
• Integration causing this issue: MQTT
• Link to integration documentation on our website: Link

Problem-relevant configuration.yaml

# Configure a default setup of Home Assistant (frontend, api, etc)
mqtt:
  broker: queue.home
  username: home-assistant
  password: home-assistant
  discovery: true
  discovery_prefix: homeassistant
  birth_message:
    topic: 'hass/status'
    payload: 'online'
  will_message:
    topic: 'hass/status'
    payload: 'offline'

Traceback/Error logs

In my specific case, I was missing a template to extract the value from my sensor. So I received errors like this:

2020-05-15 21:32:01 ERROR (MainThread) [homeassistant.util.logging] Exception in brightness_received when handling msg on 'zwave2mqtt/powerplug_3/38/1/0': '{"time":1589571121863,"value":0}'
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 35, in wrapper
    msg_callback(msg)
  File "/usr/src/homeassistant/homeassistant/components/mqtt/light/schema_basic.py", line 328, in brightness_received
    device_value = float(payload)
ValueError: could not convert string to float: '{"time":1589571121863,"value":0}'

I pushed a new discovery config document with a "brightness_value_template": "{{ value_json.value }}" (for my light), but the issue persisted. Only after restarting HASS, did the new template take effect.

I have the same experience with other template values in the MQTT integration.

Additional information

It should be entirely possible to reproduce this, by setting a value template that produces an error. If the error does not occur, the template hasn't taken effect.

[stale[bot]]

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.
Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍
This issue now has been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

[LordMike]

I can see, for the MQTT Sensor, that the template is set from config when topics are subscribed .. but also that topics should be subscribed on discovery_update.. so it _should_ work..

I'm running 0.113.3 now.

I can confirm that this is still an issue. I've tested like this:

Initial discovery

homeassistant/sensor/test_mqtt/my_sensor/config

{
    "device": {
        "identifiers": ["my_test_identifier"],
        "name": "My test device"
    },
    "name": "My Test Sensor",
    "state_topic": "test/test_mqtt/state",
    "unique_id": "test_mqtt__my_sensor",
    "value_template": "{{ value_json.value }}"
}

I send the first value:

test/test_mqtt/state

{"value": "a"}

HASS receives a just fine, and any other value I put in there.

Change the template

homeassistant/sensor/test_mqtt/my_sensor/config

{
    "device": {
        "identifiers": ["my_test_identifier"],
        "name": "My test device"
    },
    "name": "My Test Sensor",
    "state_topic": "test/test_mqtt/state",
    "unique_id": "test_mqtt__my_sensor",
    "value_template": "{{ value_json.othervalue }}"
}

Send a new value

{"othervalue": "b"}

HASS will not react to the b value, it will instead clear its state (presumably because value was null). If I resend an earlier state message, with value set, it works as it did before. HASS has not used the new template.

Notes

I've set device configs, to allow me to see the new "MQTT Info", to see if it notices the new template. And it does.

[LordMike]

Having looked through MqttDiscoveryUpdate.discovery_callback (which I can see in the logs is called on updates to the discovery payload).. and then Sensor._subscribe_topics (which should be called by the previous code)...

I can't spot where the template is lost. There is some scoping of the template variable, as it's used in message_received, which in turn is given to subscription.async_subscribe_topics later. I think a new method, message_received is created on each invocation, and provided to async_subscribe_topics - so it should be good. ..

At async_subscribe_topics, the topic may be subscribed, if not previously known, but in all cases the sub_state is updated with objects that contain the reference to the message_received method from before.

It all looks fine .. I haven't actually found the place where the sub_state's message_callback is called.. so I can't verify if it is in any way caching the method reference.

Edit

Uhm.. maybe it's here.. I found the core MQTT loop where stuff happens, and in it a method named MQTT.async_subscribe. This fills up the subscriptions list, which contains the callback that is eventually called. In the line I link, subscriptions are appended, and not replaced. .. nvm. The unsubscribe callback is called in subscription.resubscribe_if_necessary.

So if I keep changing my discovery payload - will subscriptions continue to pile up without ever being cleaned?

At least _each_ subscription that matches a topic is called, and not just the first one.

[LordMike]

Aha!

In subscription.resubscribe_if_necessary, mqtt.async_subscribe is only called, if _should_resubscribe returns true. And _that_ function only evaluates the topic, qos and encoding.

So in theory, my new template (ie. callback) should be used, if I change one of those three.

[LordMike]

It works!

By changing my qos from 0 to 1 on the second discovery payload, my new template was used.

[LordMike]

@emontnemery I saw your work on https://github.com/home-assistant/core/pull/39820 - which touches the same areas of HASS as this issue will - would you be able to take a look at this issue? :)

Sorry in advance, for intruding..

[probot-home-assistant[bot]]

mqtt documentation
mqtt source
_{^{(message by IssueLinks)}}

[emontnemery]

@LordMike No worries, I just didn't notice this issue since it was not tagged.
By coincidence, the patch in #39325 (will be included in 0.115.0) should solve this issue, can you give it a try?

[probot-home-assistant[bot]]

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

[LordMike]

It will?

The change only affects the MQTT Light integration, but my experimentation has been with Sensors.

I even traced the issue down to some logic, here that determines when to replace the template function. If one of the three values, topic, qos and encoding aren't changed, then the new template isn't used.

It should affect lights too. If you set a template to one function, e.g. 1+1, and then send a value - it should print 2. But if you then change the template to something else, e.g. 2+2 - then it should still render 2 ..

[emontnemery]

The problem mentioned in the title (templates for lights not updating) should be solved by #39325, I didn't notice that you see the same problem also with sensors, sorry about that.

Edit: Fix link to wrong PR

[LordMike]

I didn't update the title, but my investigation indicated that this affected _all_ integrations. It's all abstracted down to a topic -> method/function - and this link isn't updated unless one of the three values there are changed. :)

[emontnemery]

I just realized that I linked to the wrong PR, the correction for the handling of MQTT light's value templates is in #39325.
The problem is that the template is picked from a local variable visible to the message callback closure, maybe that's what you mean by this link isn't updated unless one of the three values there are change?

As you correctly point out this problem is not limited to MQTT.light, several other MQTT integrations have exactly the same problem, I'll try get them all sorted.

[LordMike]

Ah - that makes sense. I see that you've made the callback use a variable for the template, rather than embedding the template within itself. I suppose the resubscribe has other sideeffects, like actually unsubscribing and subscribing to topics - unecessary chatter.

Seems cool. I'll check it out in 0.115 when it's included. :)

... aand its in 0.115.0b5.

Will check it out soon.

[LordMike]

Works. @emontnemery - thanks :)