Openhab-addons: [mqtt] Updating values through a subscription does not work

[pavel-gololobov]

Expected Behavior

1. Send message to topic "presence/pavel/phone" with payload "online"
2. The Switch Item Pavel_At_Home2 turns on

Current Behavior

1. Send message to topic "presence/pavel/phone" with payload "online"
2. Nothing (in log too)

Context

The problem appeared after updating 2.5.0M6 (that also has a problem with subscribe on reconnection, but works until reconnect to broker) to snapshot Build #1774

Thing refresh log:

....
....
2019-12-10 15:08:16.358 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'mqtt.things'
2019-12-10 15:08:16.373 [TRACE] [.transport.mqtt.MqttBrokerConnection] - Closing the MQTT broker connection 'mqtt.parabox.org'
2019-12-10 15:08:16.376 [TRACE] [.transport.mqtt.MqttBrokerConnection] - Unsubscribing message consumer for topic 'presence/pavel/phone' from broker 'mqtt.parabox.org'
2019-12-10 15:08:16.385 [TRACE] [.transport.mqtt.MqttBrokerConnection] - Unsubscribing message consumer for topic 'homeassistant/#' from broker 'mqtt.parabox.org'
2019-12-10 15:08:16.385 [TRACE] [.transport.mqtt.MqttBrokerConnection] - Unsubscribing message consumer for topic 'presence/victoria/phone' from broker 'mqtt.parabox.org'
2019-12-10 15:08:16.385 [TRACE] [.transport.mqtt.MqttBrokerConnection] - Unsubscribing message consumer for topic '+/+/$homie' from broker 'mqtt.parabox.org'
2019-12-10 15:08:16.391 [TRACE] [ternal.client.MqttAsyncClientWrapper] - Successfully unsubscribed org.eclipse.smarthome.io.transport.mqtt.internal.client.Mqtt3AsyncClientWrapper@25771597 from topic presence/pavel/phone
2019-12-10 15:08:16.392 [TRACE] [ternal.client.MqttAsyncClientWrapper] - Successfully unsubscribed org.eclipse.smarthome.io.transport.mqtt.internal.client.Mqtt3AsyncClientWrapper@25771597 from topic homeassistant/#
2019-12-10 15:08:16.394 [TRACE] [ternal.client.MqttAsyncClientWrapper] - Successfully unsubscribed org.eclipse.smarthome.io.transport.mqtt.internal.client.Mqtt3AsyncClientWrapper@25771597 from topic presence/victoria/phone
2019-12-10 15:08:16.394 [TRACE] [ternal.client.MqttAsyncClientWrapper] - Successfully unsubscribed org.eclipse.smarthome.io.transport.mqtt.internal.client.Mqtt3AsyncClientWrapper@25771597 from topic +/+/$homie
2019-12-10 15:08:16.441 [TRACE] [.transport.mqtt.MqttBrokerConnection] - Tried to unsubscribe org.openhab.binding.mqtt.discovery.TopicSubscribe@69484ab from topic homeassistant/#, but subscriber list is empty
2019-12-10 15:08:16.442 [TRACE] [.transport.mqtt.MqttBrokerConnection] - Tried to unsubscribe org.openhab.binding.mqtt.discovery.TopicSubscribe@1390caa0 from topic +/+/$homie, but subscriber list is empty
2019-12-10 15:08:16.467 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'mqtt.parabox.org' with clientid c274032d-f16a-48ba-9884-9bf6d3837630
2019-12-10 15:08:16.471 [TRACE] [g.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery@21a27de8 to discovery topic homeassistant/# on broker mqtt:broker:mqtt_broker
2019-12-10 15:08:16.472 [TRACE] [g.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery@54a8134f to discovery topic +/+/$homie on broker mqtt:broker:mqtt_broker
2019-12-10 15:08:16.654 [TRACE] [.transport.mqtt.MqttBrokerConnection] - subscribeRaw message consumer for topic 'homeassistant/#' from broker 'mqtt.parabox.org'
2019-12-10 15:08:16.655 [TRACE] [ternal.client.MqttAsyncClientWrapper] - Trying to subscribe org.eclipse.smarthome.io.transport.mqtt.internal.client.Mqtt3AsyncClientWrapper@f2d4188 to topic homeassistant/#
2019-12-10 15:08:16.662 [TRACE] [.transport.mqtt.MqttBrokerConnection] - subscribeRaw message consumer for topic '+/+/$homie' from broker 'mqtt.parabox.org'
2019-12-10 15:08:16.662 [TRACE] [ternal.client.MqttAsyncClientWrapper] - org.eclipse.smarthome.io.transport.mqtt.internal.client.Mqtt3AsyncClientWrapper@f2d4188 already subscribed to topic +/+/$homie
2019-12-10 15:08:16.669 [TRACE] [ternal.client.MqttAsyncClientWrapper] - Successfully subscribed org.eclipse.smarthome.io.transport.mqtt.internal.client.Mqtt3AsyncClientWrapper@f2d4188 to topic homeassistant/#
2019-12-10 15:08:16.672 [TRACE] [ternal.client.MqttAsyncClientWrapper] - org.eclipse.smarthome.io.transport.mqtt.internal.client.Mqtt3AsyncClientWrapper@f2d4188 already subscribed to topic presence/victoria/phone
2019-12-10 15:08:16.673 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:mqtt_broker:presence:presence_victoria to topic: presence/victoria/phone
2019-12-10 15:08:16.674 [TRACE] [ternal.client.MqttAsyncClientWrapper] - org.eclipse.smarthome.io.transport.mqtt.internal.client.Mqtt3AsyncClientWrapper@f2d4188 already subscribed to topic presence/pavel/phone
2019-12-10 15:08:16.674 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:mqtt_broker:presence:presence_pavel to topic: presence/pavel/phone
2019-12-10 15:09:41.178 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel mqtt:topic:mqtt_broker:presence:presence_pavel
2019-12-10 15:09:41.179 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel mqtt:topic:mqtt_broker:presence:presence_pavel
2019-12-10 15:09:41.179 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel mqtt:topic:mqtt_broker:presence:presence_pavel
....
....

Things configuration:

Bridge mqtt:broker:mqtt_broker "MQTT Broker Connection" [ publickeypin=false, lastwill_qos=0, retain=false, secure=true, certificatepin=false, keep_alive_time=60000, password="*****", qos=0, port=8883, host="*****", reconnect_time=60000, username="*****" ] {
  Thing topic presence "MQTT Presence" {
    Channels:
      Type switch : presence_pavel "Pavel presence" [ stateTopic="presence/pavel/phone", on="online", off="offline"]
  }
}

Item configuration:

Switch Pavel_At_Home2 "At home" <man_3> (Group_At_Home) {channel="mqtt:topic:mqtt_broker:presence:presence_pavel"}

Your Environment

2.5.0-snapshot Build #1774 (Docker installation)
x86_64, Linux Debian

[radokristof]

I think this is the same problem on the RC1 as well, reported by many users...

2019-12-10 14:18:02.062 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '10.0.0.135' with clientid 25ac0f0e-ea64-4ed3-8ea8-9afb3e7a40b2
2019-12-10 14:18:02.164 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:e066ff21:1
2019-12-10 14:18:02.175 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:e066ff21:2
2019-12-10 14:18:02.262 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:e066ff21:2 to topic: thermostat/state
2019-12-10 14:18:02.263 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:e066ff21:1 to topic: thermostat/state
2019-12-10 14:18:02.295 [TRACE] [g.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery@46233609 to discovery topic +/+/$homie on broker mqtt:broker:a0a637ca
2019-12-10 14:18:02.425 [TRACE] [g.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery@4a2bebb to discovery topic homeassistant/# on broker mqtt:broker:a0a637ca

2019-12-10 14:18:07.039 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel mqtt:topic:e066ff21:2
2019-12-10 14:18:07.041 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel mqtt:topic:e066ff21:2
2019-12-10 14:18:07.045 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel mqtt:topic:e066ff21:2
2019-12-10 14:18:07.048 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel mqtt:topic:e066ff21:1
2019-12-10 14:18:07.049 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel mqtt:topic:e066ff21:1
2019-12-10 14:18:07.051 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel mqtt:topic:e066ff21:2

[J-N-K]

This is a core-issue, can someone move it over there?

I have an idea what‘s happening and I‘ll try to fix that this evening.

[radokristof]

@J-N-K Thank you!

[J-N-K]

Please update the "openHAB Core :: Bundles :: MQTT Transport" bundle with https://janessa.me/esh/org.openhab.core.io.transport.mqtt-2.5.0-fs.jar this one and report back. Instructions https://janessa.me/esh. option 2.

[tavalin]

Thanks @J-N-K

Initial testing with snapshot build 1774 and the new bundle seems positive. My items seem to be updating their state based on the incoming MQTT data.

[Mr-Eskildsen]

Hmmm, I have just updated the bundle as described. That doesn't seem to do any change, besides from that I now have two MQTT sytem brokers :-) (Would really like to get rid of them)

[radokristof]

Same for me on RC1. After updating and restarting nothing changed. I only have one MQTT broker in my Things, I can see on the console that the version number changed so the update was successful, but still no state updates.

[J-N-K]

Please show the TRACE log of the core bundle.

[tavalin]

As mentioned, it worked for me on build 1774 so I'll switch to RC1 and test.

Edit: not working for me on RC1 either.

Edit#2: Restarted openHAB a couple of times and it's working again.

[radokristof]

@J-N-K this helps?
I have set log:set TRACE org.openhab.core

2019-12-10 20:48:54.847 [DEBUG] [core.karaf.internal.FeatureInstaller] - Failed uninstalling 'openhab-ui-dashboard': Feature named 'openhab-ui-dashboard/0' is not installed
2019-12-10 20:48:56.421 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'tv.items'
2019-12-10 20:48:56.454 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'thermostat.items'
2019-12-10 20:48:56.902 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'home.sitemap'
2019-12-10 20:48:58.337 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2019-12-10 20:48:59.238 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://172.18.79.152:8080
2019-12-10 20:48:59.239 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://172.18.79.152:8443
2019-12-10 20:48:59.590 [INFO ] [ebuilder.internal.HomeBuilderServlet] - Started Home Builder at /homebuilder
2019-12-10 20:48:59.637 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2019-12-10 20:48:59.681 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2019-12-10 20:49:00.395 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '10.0.0.135' with clientid ee235fea-fabb-469a-ba30-d464e0276491
2019-12-10 20:49:00.475 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:e066ff21:1
2019-12-10 20:49:00.481 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:e066ff21:2
2019-12-10 20:49:00.502 [TRACE] [g.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery@4adc89e9 to discovery topic homeassistant/# on broker mqtt:broker:a0a637ca
2019-12-10 20:49:00.515 [TRACE] [g.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery@14d20214 to discovery topic +/+/$homie on broker mqtt:broker:a0a637ca
2019-12-10 20:49:00.614 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:e066ff21:1 to topic: thermostat/state
2019-12-10 20:49:00.618 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:e066ff21:2 to topic: thermostat/state

2019-12-10 20:49:06.946 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel mqtt:topic:e066ff21:2
2019-12-10 20:49:06.948 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel mqtt:topic:e066ff21:2
2019-12-10 20:49:06.949 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel mqtt:topic:e066ff21:2
2019-12-10 20:49:06.952 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel mqtt:topic:e066ff21:1
2019-12-10 20:49:06.954 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel mqtt:topic:e066ff21:1
2019-12-10 20:49:06.956 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel mqtt:topic:e066ff21:2
2019-12-10 20:49:54.800 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2019-12-10 20:49:54.817 [DEBUG] [core.karaf.internal.FeatureInstaller] - Failed uninstalling 'openhab-ui-dashboard': Feature named 'openhab-ui-dashboard/0' is not installed

[nanosonde]

I have tested RC1 with the updated mqtt transport bundle.
It is working again for me now. Items subscribed to MQTT topics get updated with the fixed transport bundle. However, I had to restart OpenHAB.

[radokristof]

Edit: After cleaning the cache and restarting, now it is working for me as well! (on RC1)

[Mr-Eskildsen]

Clear Cache and restart also helped here. I also had some MQTT 1.x that cluttered my log. So that is also gone. :-)

[J-N-K]

Since it works for all if you: I‘ll prepare a PR. Thanks for your assistance.

[Aquariusquintini]

Fix works for RC1 after a restart of OH. Thanks!

[pavel-gololobov]

@J-N-K, thank you. Now with your fix subscription works well.

[falkena]

Thanks @J-N-K : 24 hour test run was successfull: States are updated properly.