Small problem with mqtt after model refresh

Hi @ll,

I’m currently playing around with zigbee2mqtt and my TRADFRI bulb. So far everything works quite well (I use mosquitto as broker).

But I have a very strange effect which is especially annoying during testing: as soon as I have changed a .things file via the samba share, OH reconnects to the broker and afterwards I can’t control the bulb anymore. A log can be found at Pastebin.

  • At 22:02:31 I switched the bulb on and off
  • At 22:04:03 I save the .things file
  • The mqtt connection paho25940145631026 unsubscribes from all topics and disconnects (but with an error, “failed, not disconnected”, line 2334)
  • The new mqtt connection paho26117018666791 is being set up but don’t subscubes to any topic?

This problem causes me to have to restart openhab everytime I changed a file. When trying out small changes very annoying and certainly not right either.

Any idea?

Greetings,
Funny

This fix may improve things

So the problem should already be solved in OH2.5M2.

If you don’t want to move to OH2.5M2 yet, I have a little workaround for you :wink: It’s sufficient to restart the mqtt bundle. This is done through the Karaf console.

Installed 2.5M2 and it works like a charm :slight_smile:

So far, I only play around with OM, so it’s no problem for me to use M2. But thanks for the hint to restart the mqtt bundle :wink:

Looks like I am seeing a similar disconnect behaviour with 2.5.0.M4…
Out of the blue the OH paho client disconnects:

2019-10-26 07:05:16.368 [hingStatusInfoChangedEvent] - 'mqtt:broker:mosquitto' changed from UNINITIALIZED to INITIALIZING
2019-10-26 07:05:16.546 [hingStatusInfoChangedEvent] - 'mqtt:broker:mosquitto' changed from INITIALIZING to OFFLINE
2019-10-26 07:05:17.650 [hingStatusInfoChangedEvent] - 'mqtt:broker:mosquitto' changed from OFFLINE to ONLINE
2019-10-26 07:05:17.673 [me.event.ThingUpdatedEvent] - Thing 'mqtt:broker:mosquitto' has been updated.
2019-10-26 07:05:23.320 [hingStatusInfoChangedEvent] - 'mqtt:topic:mosquitto:dsmr' changed from UNINITIALIZED to INITIALIZING
2019-10-26 07:05:23.554 [hingStatusInfoChangedEvent] - 'mqtt:topic:mosquitto:dsmr' changed from INITIALIZING to ONLINE
  ...
2019-10-26 09:13:36.885 [hingStatusInfoChangedEvent] - 'mqtt:broker:mosquitto' changed from ONLINE to OFFLINE
2019-10-26 09:13:36.891 [hingStatusInfoChangedEvent] - 'mqtt:topic:mosquitto:dsmr' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-10-26 09:13:36.892 [hingStatusInfoChangedEvent] - 'mqtt:broker:mosquitto' changed from ONLINE to OFFLINE
2019-10-26 09:13:36.903 [me.event.ThingUpdatedEvent] - Thing 'mqtt:broker:mosquitto' has been updated.
2019-10-26 09:13:37.217 [hingStatusInfoChangedEvent] - 'mqtt:broker:mosquitto' changed from OFFLINE to ONLINE
2019-10-26 09:13:37.219 [hingStatusInfoChangedEvent] - 'mqtt:topic:mosquitto:dsmr' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-10-26 09:13:37.226 [me.event.ThingUpdatedEvent] - Thing 'mqtt:broker:mosquitto' has been updated.
  ...

And openhab.log:

2019-10-26 07:04:44.530 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mqtt.things'
2019-10-26 07:05:16.679 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '192.168.2.2' with clientid paho38132086163237 and file store '/openhab/userdata/mqtt/192.168.2.2'
  ...
2019-10-26 09:13:36.808 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'mqtt.things'
2019-10-26 09:13:36.895 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '192.168.2.2' with clientid paho45832498899654 and file store '/openhab/userdata/mqtt/192.168.2.2'

The mosquitto.log:

2019-10-26T07:04:16: mosquitto version 1.6.7 starting
2019-10-26T07:04:16: Config loaded from /mosquitto/config/mosquitto.conf.
2019-10-26T07:04:16: Opening ipv4 listen socket on port 1883.
2019-10-26T07:04:16: Opening ipv6 listen socket on port 1883.
2019-10-26T07:04:16: New connection from 192.168.2.87 on port 1883.
2019-10-26T07:04:16: New client connected from 192.168.2.87 as dsmrv4 (p2, c1, k15, u'**redacted**').
2019-10-26T07:04:16: No will message specified.
2019-10-26T07:04:16: Sending CONNACK to dsmrv4 (0, 0)
2019-10-26T07:05:08: Received PUBLISH from dsmrv4 (d0, q0, r1, m0, 'sensor/dsmr', ... (315 bytes))
2019-10-26T07:05:16: Received PINGREQ from dsmrv4
2019-10-26T07:05:16: Sending PINGRESP to dsmrv4
2019-10-26T07:05:16: New connection from 172.18.0.1 on port 1883.
2019-10-26T07:05:17: New client connected from 172.18.0.1 as paho38132086163237 (p2, c1, k60000, u'moerman').
2019-10-26T07:05:17: No will message specified.
2019-10-26T07:05:17: Sending CONNACK to paho38132086163237 (0, 0)
2019-10-26T07:05:23: Received SUBSCRIBE from paho38132086163237
2019-10-26T07:05:23:    homeassistant/# (QoS 0)                                                                                                                                                                                2019-10-26T07:05:23: Sending SUBACK to paho38132086163237
2019-10-26T07:05:23: Received SUBSCRIBE from paho38132086163237
2019-10-26T07:05:23:    sensor/dsmr (QoS 0)
2019-10-26T07:05:23: Sending SUBACK to paho38132086163237
2019-10-26T07:05:23: Sending PUBLISH to paho38132086163237 (d0, q0, r1, m0, 'sensor/dsmr', ... (315 bytes))
  ...
2019-10-26T09:13:28: Received PINGREQ from dsmrv4
2019-10-26T09:13:28: Sending PINGRESP to dsmrv4
2019-10-26T09:13:34: Received PUBLISH from dsmrv4 (d0, q0, r1, m0, 'sensor/dsmr', ... (315 bytes))
2019-10-26T09:13:34: Sending PUBLISH to paho38132086163237 (d0, q0, r0, m0, 'sensor/dsmr', ... (315 bytes))
2019-10-26T09:13:36: Received UNSUBSCRIBE from paho38132086163237
2019-10-26T09:13:36:    homeassistant/#
2019-10-26T09:13:36: Sending UNSUBACK to paho38132086163237
2019-10-26T09:13:36: Received UNSUBSCRIBE from paho38132086163237
2019-10-26T09:13:36:    sensor/dsmr
2019-10-26T09:13:36: Sending UNSUBACK to paho38132086163237
2019-10-26T09:13:36: Received UNSUBSCRIBE from paho38132086163237
2019-10-26T09:13:36:    +/+/$homie
2019-10-26T09:13:36: Sending UNSUBACK to paho38132086163237
2019-10-26T09:13:36: Received DISCONNECT from paho38132086163237
2019-10-26T09:13:36: Client paho38132086163237 disconnected.
2019-10-26T09:13:36: New connection from 172.18.0.1 on port 1883.
2019-10-26T09:13:37: New client connected from 172.18.0.1 as paho45832498899654 (p2, c1, k60000, u'**redacted***').
2019-10-26T09:13:37: No will message specified.
2019-10-26T09:13:37: Sending CONNACK to paho45832498899654 (0, 0)
2019-10-26T09:13:43: Received PINGREQ from dsmrv4
2019-10-26T09:13:43: Sending PINGRESP to dsmrv4
2019-10-26T09:13:58: Received PINGREQ from dsmrv4
2019-10-26T09:13:58: Sending PINGRESP to dsmrv4
2019-10-26T09:14:13: Received PINGREQ from dsmrv4
2019-10-26T09:14:13: Sending PINGRESP to dsmrv4
2019-10-26T09:14:24: Received PUBLISH from dsmrv4 (d0, q0, r1, m0, 'sensor/dsmr', ... (315 bytes))

So, after a short disconnect from OH (don’t know why…), it reconnects but does not respond to the CONNACK from Mosquitto anymore…