[MQTT] OH 3.0.0.M1 suddenly stopped working

waldorf · October 25, 2020, 6:06am

I was just about to change my operational OH2.5 to OH3 M1 because it was quite stable. Unfortunately MQTT stopped spontaneously yesterday. I could’t find any error / exception in the logs. So not much useful info yet to create an issue.

Symptom: When moving a dimmer slider to a new position, it jumped back to the previous position. Dimmer itself not changed either. (I also use ZWave, which did not show this behaviour)

Restarted bundles: mqtt-transport and mqtt-broker-binding
No effect.

Restart OH: System back to normal.

Note: MQTT log level was set to TRACE, I do not know if this might introduce any side effects.

Anyone experienced a similar problem with OH3 M1 ?

Marcell_Gerzsenyi · April 13, 2021, 7:51pm

Similar error on openHAB 3.0.1 Release Build

System: OH 3.0.1 → MySensensors MQTT Bridge → Mosquitto → MySensors MQTT Gateway

Fresh OpenHab install on debian, system start without any error, running about 1 day, then cannot communicate via MQTT. Messages does not arrive from Mosquitto to OH, also no outgoing messages to the broker. Checked mosquitto with MQTT Explorer, thats seems working, there are messages from the MySensorsGW.
There aren’t any clue in logs ( working untill ~2021-04-13 10:27:12:757) :

2021-04-13 10:27:00.947 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - MQTT message received. Topic: mygateway1-out/11/5/1/1/2, Message: 0
2021-04-13 10:27:00.947 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Message topic part: 11/5/1/1/2
2021-04-13 10:27:00.947 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Converted MQTT message to MySensors Serial format. Sending on to bridge: 11;5;1;1;2;0
2021-04-13 10:27:00.949 [DEBUG] [rsAbstractConnection$MySensorsReader] - Message from gateway received: 11;5;1;1;2;0
2021-04-13 10:27:00.949 [DEBUG] [rs.internal.gateway.MySensorsGateway] - Node 11 found in gateway
2021-04-13 10:27:00.949 [DEBUG] [rs.internal.gateway.MySensorsGateway] - Child 5 found in node 11
2021-04-13 10:27:00.949 [DEBUG] [ensors.handler.MySensorsThingHandler] - Updating channel: status(V_STATUS) value to: OFF
2021-04-13 10:27:00.950 [DEBUG] [ensors.handler.MySensorsThingHandler] - Setting last update for node/child 11/5 to 2021-04-13T10:27:00.000+0200
2021-04-13 10:27:01.001 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 11;6;1;1;2;0
2021-04-13 10:27:01.002 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Sending MQTT Message: Topic: mygateway1-in, Message: 11;6;1;1;2;0
2021-04-13 10:27:01.026 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - MQTT message received. Topic: mygateway1-out/11/6/1/1/2, Message: 0
2021-04-13 10:27:01.026 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Message topic part: 11/6/1/1/2
2021-04-13 10:27:01.027 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Converted MQTT message to MySensors Serial format. Sending on to bridge: 11;6;1;1;2;0
2021-04-13 10:27:01.031 [DEBUG] [rsAbstractConnection$MySensorsReader] - Message from gateway received: 11;6;1;1;2;0
2021-04-13 10:27:01.031 [DEBUG] [rs.internal.gateway.MySensorsGateway] - Node 11 found in gateway
2021-04-13 10:27:01.031 [DEBUG] [rs.internal.gateway.MySensorsGateway] - Child 6 found in node 11
2021-04-13 10:27:01.032 [DEBUG] [ensors.handler.MySensorsThingHandler] - Updating channel: status(V_STATUS) value to: OFF
2021-04-13 10:27:01.032 [DEBUG] [ensors.handler.MySensorsThingHandler] - Setting last update for node/child 11/6 to 2021-04-13T10:27:01.000+0200
2021-04-13 10:27:01.102 [INFO ] [rsAbstractConnection$MySensorsWriter] - ACK received for message: 11;5;1;1;2;0

2021-04-13 10:27:01.103 [INFO ] [rsAbstractConnection$MySensorsWriter] - ACK received for message: 9;6;1;1;3;0

2021-04-13 10:27:01.103 [INFO ] [rsAbstractConnection$MySensorsWriter] - ACK received for message: 11;6;1;1;2;0

2021-04-13 10:27:02.727 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - MQTT message received. Topic: mygateway1-out/11/13/1/0/24, Message: 0
2021-04-13 10:27:02.728 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Message topic part: 11/13/1/0/24
2021-04-13 10:27:02.728 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Converted MQTT message to MySensors Serial format. Sending on to bridge: 11;13;1;0;24;0
2021-04-13 10:27:02.732 [DEBUG] [rsAbstractConnection$MySensorsReader] - Message from gateway received: 11;13;1;0;24;0
2021-04-13 10:27:02.733 [DEBUG] [rs.internal.gateway.MySensorsGateway] - Node 11 found in gateway
2021-04-13 10:27:02.733 [DEBUG] [rs.internal.gateway.MySensorsGateway] - Child 13 found in node 11
2021-04-13 10:27:02.734 [DEBUG] [ensors.handler.MySensorsThingHandler] - Updating channel: var1(V_VAR1) value to: 0
2021-04-13 10:27:02.734 [DEBUG] [ensors.handler.MySensorsThingHandler] - Setting last update for node/child 11/13 to 2021-04-13T10:27:02.000+0200
2021-04-13 10:27:02.826 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - MQTT message received. Topic: mygateway1-out/11/14/1/0/2, Message: 0
2021-04-13 10:27:02.826 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Message topic part: 11/14/1/0/2
2021-04-13 10:27:02.827 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Converted MQTT message to MySensors Serial format. Sending on to bridge: 11;14;1;0;2;0
2021-04-13 10:27:02.836 [DEBUG] [rsAbstractConnection$MySensorsReader] - Message from gateway received: 11;14;1;0;2;0
2021-04-13 10:27:02.836 [DEBUG] [rs.internal.gateway.MySensorsGateway] - Node 11 found in gateway
2021-04-13 10:27:02.837 [DEBUG] [rs.internal.gateway.MySensorsGateway] - Child 14 found in node 11
2021-04-13 10:27:02.837 [DEBUG] [ensors.handler.MySensorsThingHandler] - Updating channel: status(V_STATUS) value to: OFF
2021-04-13 10:27:02.838 [DEBUG] [ensors.handler.MySensorsThingHandler] - Setting last update for node/child 11/14 to 2021-04-13T10:27:02.000+0200
2021-04-13 10:27:04.050 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - MQTT message received. Topic: mygateway1-out/7/255/3/0/22, Message: 1260498882
2021-04-13 10:27:04.051 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Message topic part: 7/255/3/0/22
2021-04-13 10:27:04.052 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Converted MQTT message to MySensors Serial format. Sending on to bridge: 7;255;3;0;22;1260498882
2021-04-13 10:27:04.052 [DEBUG] [rsAbstractConnection$MySensorsReader] - Message from gateway received: 7;255;3;0;22;1260498882
2021-04-13 10:27:04.725 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - MQTT message received. Topic: mygateway1-out/9/255/3/0/22, Message: 568774403
2021-04-13 10:27:04.726 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Message topic part: 9/255/3/0/22
2021-04-13 10:27:04.726 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Converted MQTT message to MySensors Serial format. Sending on to bridge: 9;255;3;0;22;568774403
2021-04-13 10:27:12.747 [INFO ] [org.openhab.core.model.script.Info  ] - Hot Water Heating: Off
2021-04-13 10:27:12.755 [DEBUG] [ensors.handler.MySensorsThingHandler] - Adapter: class org.openhab.binding.mysensors.converter.MySensorsOnOffTypeConverter loaded
2021-04-13 10:27:12.757 [DEBUG] [rs.internal.gateway.MySensorsGateway] - Node 11 found in gateway
2021-04-13 10:27:12.757 [DEBUG] [rs.internal.gateway.MySensorsGateway] - Child 6 found in node 11
2021-04-13 10:27:12.757 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 11;6;1;1;2;0
2021-04-13 10:27:12.757 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Sending MQTT Message: Topic: mygateway1-in, Message: 11;6;1;1;2;0
2021-04-13 10:27:12.858 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 11;6;1;1;2;0
2021-04-13 10:27:12.858 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Sending MQTT Message: Topic: mygateway1-in, Message: 11;6;1;1;2;0
2021-04-13 10:27:12.959 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 11;6;1;1;2;0
2021-04-13 10:27:12.960 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Sending MQTT Message: Topic: mygateway1-in, Message: 11;6;1;1;2;0
2021-04-13 10:27:13.461 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 11;6;1;1;2;0
2021-04-13 10:27:13.462 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Sending MQTT Message: Topic: mygateway1-in, Message: 11;6;1;1;2;0
2021-04-13 10:27:14.464 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 11;6;1;1;2;0
2021-04-13 10:27:14.464 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Sending MQTT Message: Topic: mygateway1-in, Message: 11;6;1;1;2;0
2021-04-13 10:27:15.695 [INFO ] [org.openhab.core.model.script.Info  ] - Nappali Heating Demand : 0
2021-04-13 10:27:15.697 [INFO ] [org.openhab.core.model.script.Info  ] - Gyerekszoba Heating Demand set to: 0
2021-04-13 10:27:15.699 [INFO ] [org.openhab.core.model.script.Info  ] - Haloszoba Heating Demand set to: 0
2021-04-13 10:27:15.703 [DEBUG] [ensors.handler.MySensorsThingHandler] - Adapter: class org.openhab.binding.mysensors.converter.MySensorsOnOffTypeConverter loaded
2021-04-13 10:27:15.703 [DEBUG] [ensors.handler.MySensorsThingHandler] - Adapter: class org.openhab.binding.mysensors.converter.MySensorsPercentTypeConverter loaded
2021-04-13 10:27:15.704 [DEBUG] [rs.internal.gateway.MySensorsGateway] - Node 9 found in gateway
2021-04-13 10:27:15.704 [DEBUG] [rs.internal.gateway.MySensorsGateway] - Node 11 found in gateway
2021-04-13 10:27:15.704 [DEBUG] [rs.internal.gateway.MySensorsGateway] - Child 6 found in node 9
2021-04-13 10:27:15.705 [DEBUG] [rs.internal.gateway.MySensorsGateway] - Child 5 found in node 11
2021-04-13 10:27:15.866 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 9;6;1;1;3;0
2021-04-13 10:27:15.867 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Sending MQTT Message: Topic: mygateway1-in, Message: 9;6;1;1;3;0
2021-04-13 10:27:15.968 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 11;5;1;1;2;0
2021-04-13 10:27:15.969 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Sending MQTT Message: Topic: mygateway1-in, Message: 11;5;1;1;2;0
2021-04-13 10:27:16.170 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 9;6;1;1;3;0
2021-04-13 10:27:16.171 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Sending MQTT Message: Topic: mygateway1-in, Message: 9;6;1;1;3;0
2021-04-13 10:27:16.274 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 11;5;1;1;2;0
2021-04-13 10:27:16.274 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Sending MQTT Message: Topic: mygateway1-in, Message: 11;5;1;1;2;0
2021-04-13 10:27:16.475 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 9;6;1;1;3;0
2021-04-13 10:27:16.476 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Sending MQTT Message: Topic: mygateway1-in, Message: 9;6;1;1;3;0
2021-04-13 10:27:16.576 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 11;5;1;1;2;0
2021-04-13 10:27:16.577 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Sending MQTT Message: Topic: mygateway1-in, Message: 11;5;1;1;2;0
2021-04-13 10:27:16.678 [WARN ] [rsAbstractConnection$MySensorsWriter] - NO ACK for message: 11;6;1;1;2;0

2021-04-13 10:27:16.679 [DEBUG] [rs.internal.gateway.MySensorsGateway] - Node 11 found in gateway
2021-04-13 10:27:16.680 [DEBUG] [rs.internal.gateway.MySensorsGateway] - Child 6 found in node 11
2021-04-13 10:27:16.680 [DEBUG] [rs.internal.gateway.MySensorsGateway] - Variable MySensorsVariableVStatus found, it will be reverted to last know state
2021-04-13 10:27:16.681 [DEBUG] [ensors.handler.MySensorsThingHandler] - Updating channel: status(V_STATUS) value to: OFF
2021-04-13 10:27:16.683 [WARN ] [ensors.handler.MySensorsThingHandler] - Setting last update for node/child 11/6 BACK (due to revert) to 2021-04-13T10:27:02.000+0200
2021-04-13 10:27:17.085 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 9;6;1;1;3;0
2021-04-13 10:27:17.086 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Sending MQTT Message: Topic: mygateway1-in, Message: 9;6;1;1;3;0
2021-04-13 10:27:17.187 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 11;5;1;1;2;0
2021-04-13 10:27:17.188 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Sending MQTT Message: Topic: mygateway1-in, Message: 11;5;1;1;2;0
2021-04-13 10:27:18.090 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 9;6;1;1;3;0
2021-04-13 10:27:18.091 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Sending MQTT Message: Topic: mygateway1-in, Message: 9;6;1;1;3;0
2021-04-13 10:27:18.191 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 11;5;1;1;2;0
2021-04-13 10:27:18.192 [DEBUG] [rotocol.mqtt.MySensorsMqttConnection] - Sending MQTT Message: Topic: mygateway1-in, Message: 11;5;1;1;2;0
2021-04-13 10:27:20.095 [WARN ] [rsAbstractConnection$MySensorsWriter] - NO ACK for message: 9;6;1;1;3;0