MQTT binding errors

Add-ons Bindings
,
1

Every 3-4 day i got this errors from MQTT binding.
OH and MQTT ‘agdisk’ is on the NAS, and ‘wb’ broker is on homeautomatic controller.
Please help to find solution.

OH 1.8.3
My CFG file:

mqtt:wb.url=tcp://192.168.1.1:1883
mqtt:wb.clientId=openhab
mqtt:wb.retain=false
mqtt:wb.lwt=/openhab/online:0:1:0
mqtt:wb.qos=2

mqtt:agdisk.url=tcp://192.168.1.2:1883
#mqtt-eventbus:broker=agdisk
mqtt:agdisk.clientId=openhab_local
mqtt:agdisk.retain=false
mqtt:agdisk.lwt=/openhab/online:0:1:0
mqtt:agdisk.qos=2

mqtt:agdisk_r.url=tcp://192.168.1.2:1883
mqtt:agdisk_r.clientId=openhab_local_r
mqtt:agdisk_r.retain=true
mqtt:agdisk_r.lwt=/openhab/online:0:1:0
mqtt:agdisk_r.qos=2

Log:

2016-10-03 13:09:53.053 [ERROR] [o.i.t.m.i.MqttBrokerConnection] - MQTT connection to broker was lost
org.eclipse.paho.client.mqttv3.MqttException: Unexpected error
    at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:115) ~[na:na]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_77]
2016-10-03 13:09:53.077 [ERROR] [o.i.t.m.i.MqttBrokerConnection] - MQTT connection to 'wb' was lost: Unexpected error : ReasonCode 6 : Cause : Unknown
2016-10-03 13:09:53.077 [INFO ] [o.i.t.m.i.MqttBrokerConnection] - Starting connection helper to periodically try restore connection to broker 'wb'
2016-10-03 13:09:55.607 [WARN ] [o.i.t.m.i.MqttBrokerConnection] - Broker connection not started. Cannot publish message to topic '/devices/openhab/controls/Time'
2016-10-03 13:10:00.471 [INFO ] [g.openhab.model.script.Heating] - Целевая температура снижена на 0.5 °C, т.к. окно в комнате открыто.
2016-10-03 13:10:00.496 [INFO ] [g.openhab.model.script.Heating] - Целевая температура снижена на 0.5 °C, т.к. окно в спальне открыто.
2016-10-03 13:10:00.616 [INFO ] [g.openhab.model.script.Heating] - Цель в батарее=18   Currtemp=25.1   Темп в кв=24.8   Нужно достичь=23.0
2016-10-03 13:10:00.999 [WARN ] [o.i.t.m.i.MqttBrokerConnection] - Broker connection not started. Cannot publish message to topic '/devices/openhab/controls/Time'
2016-10-03 13:10:03.110 [INFO ] [o.i.t.m.i.MqttBrokerConnection] - Starting MQTT broker connection 'wb'
2016-10-03 13:10:11.546 [WARN ] [o.i.t.m.i.MqttBrokerConnection] - Broker connection not started. Cannot publish message to topic '/devices/noolite_tx_0x102/controls/level/on'
2016-10-03 13:10:16.870 [WARN ] [o.i.t.m.i.MqttBrokerConnection] - Broker connection not started. Cannot publish message to topic '/devices/openhab/controls/Time'
2016-10-03 13:10:19.955 [WARN ] [o.i.t.m.i.MqttBrokerConnection] - Broker connection not started. Cannot publish message to topic '/devices/noolite_tx_0x102/controls/level/on'
2016-10-03 13:10:19.996 [WARN ] [o.i.t.m.i.MqttBrokerConnection] - Broker connection not started. Cannot publish message to topic '/devices/noolite_tx_0x102/controls/level/on'
2016-10-03 13:10:20.112 [WARN ] [o.i.t.m.i.MqttBrokerConnection] - Broker connection not started. Cannot publish message to topic '/devices/openhab/controls/Time'
2016-10-03 13:10:20.134 [WARN ] [o.i.t.m.i.MqttBrokerConnection] - Broker connection not started. Cannot publish message to topic '/devices/wb-gpio/controls/Relay_1/on'
2016-10-03 13:11:43.532 [WARN ] [esoftware.smack.XMPPConnection] - Connection closed with error
java.io.EOFException: no more data available - expected end tag </stream:stream> to close start tag <stream:stream> from line 1, parser stopped on END_TAG seen ...45ea-a5cd-3cfe612a575d:id=1qc6g-31404:susTrigger=xmpp]]></oa></iq>... @9:9628
    at org.xmlpull.mxp1.MXParser.fillBuf(MXParser.java:3035) ~[xpp3-1.1.4c.jar:na]
    at org.xmlpull.mxp1.MXParser.more(MXParser.java:3046) ~[xpp3-1.1.4c.jar:na]
    at org.xmlpull.mxp1.MXParser.nextImpl(MXParser.java:1144) ~[xpp3-1.1.4c.jar:na]
    at org.xmlpull.mxp1.MXParser.next(MXParser.java:1093) ~[xpp3-1.1.4c.jar:na]
    at org.jivesoftware.smack.tcp.PacketReader.parsePackets(PacketReader.java:279) [smack-tcp-4.0.2.jar:4.0.2]
    at org.jivesoftware.smack.tcp.PacketReader.access$000(PacketReader.java:47) [smack-tcp-4.0.2.jar:4.0.2]
    at org.jivesoftware.smack.tcp.PacketReader$1.run(PacketReader.java:81) [smack-tcp-4.0.2.jar:4.0.2]
2016-10-03 13:11:43.810 [WARN ] [n.w.harmony.HarmonyClient     ] - Send heartbeat failed
java.lang.RuntimeException: Failed communicating with Harmony Hub
    at net.whistlingfish.harmony.HarmonyClient.sendOAPacket(HarmonyClient.java:266) ~[na:na]
    at net.whistlingfish.harmony.HarmonyClient.sendOAPacket(HarmonyClient.java:255) ~[na:na]
    at net.whistlingfish.harmony.HarmonyClient.sendPing(HarmonyClient.java:328) ~[na:na]
    at net.whistlingfish.harmony.HarmonyClient$2.run(HarmonyClient.java:170) ~[na:na]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_77]
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [na:1.8.0_77]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_77]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [na:1.8.0_77]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_77]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_77]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_77]
Caused by: org.jivesoftware.smack.SmackException$NotConnectedException: null
    at org.jivesoftware.smack.tcp.PacketWriter.sendPacket(PacketWriter.java:92) ~[na:na]
    at org.jivesoftware.smack.tcp.XMPPTCPConnection.sendPacketInternal(XMPPTCPConnection.java:393) ~[na:na]
    at org.jivesoftware.smack.XMPPConnection.sendPacket(XMPPConnection.java:603) ~[na:na]
    at net.whistlingfish.harmony.HarmonyClient.sendOAPacket(HarmonyClient.java:263) ~[na:na]
    ... 10 common frames omitted
2016-10-03 13:11:49.912 [ERROR] [o.i.t.m.i.MqttBrokerConnection] - MQTT connection to broker was lost
org.eclipse.paho.client.mqttv3.MqttException: Connection lost
    at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:138) [mqtt-client-0.4.0.jar:na]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_77]
Caused by: java.io.EOFException: null
    at java.io.DataInputStream.readByte(DataInputStream.java:267) ~[na:1.8.0_77]
    at org.eclipse.paho.client.mqttv3.internal.wire.MqttInputStream.readMqttWireMessage(MqttInputStream.java:56) ~[na:na]
    at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:100) [mqtt-client-0.4.0.jar:na]
    ... 1 common frames omitted
2016-10-03 13:11:49.945 [ERROR] [o.i.t.m.i.MqttBrokerConnection] - MQTT connection to 'agdisk_r' was lost: Connection lost : ReasonCode 32109 : Cause : null
2016-10-03 13:11:49.945 [INFO ] [o.i.t.m.i.MqttBrokerConnection] - Starting connection helper to periodically try restore connection to broker 'agdisk_r'
2016-10-03 13:12:08.481 [INFO ] [o.i.t.m.i.MqttBrokerConnection] - Starting MQTT broker connection 'agdisk_r'
2016-10-03 13:12:44.195 [ERROR] [.c.mqttv3.internal.ClientState] - openhab: Timed out as no activity, keepAlive=60,000 lastOutboundActivity=1,475,489,503,653 lastInboundActivity=1,475,489,503,757
2016-10-03 13:13:14.020 [ERROR] [.c.mqttv3.internal.ClientState] - openhab_local: Timed out as no activity, keepAlive=60,000 lastOutboundActivity=1,475,489,533,171 lastInboundActivity=1,475,489,509,045
2016-10-03 13:13:20.982 [ERROR] [o.o.a.m.i.MqttMessagePublisher] - Error publishing message: Client is not connected
2016-10-03 13:13:23.111 [ERROR] [o.o.a.m.i.MqttMessagePublisher] - Error publishing message: Client is not connected
2016-10-03 13:13:23.200 [ERROR] [o.o.a.m.i.MqttMessagePublisher] - Error publishing message: Client is not connected
2016-10-03 13:13:23.319 [ERROR] [o.o.a.m.i.MqttMessagePublisher] - Error publishing message: Client is not connected
2016-10-03 13:13:23.364 [ERROR] [o.i.t.m.i.MqttBrokerConnection] - MQTT connection to broker was lost
org.eclipse.paho.client.mqttv3.MqttException: Timed out waiting for a response from the server
    at org.eclipse.paho.client.mqttv3.internal.ExceptionHelper.createMqttException(ExceptionHelper.java:27) ~[na:na]
    at org.eclipse.paho.client.mqttv3.internal.ClientState.checkForActivity(ClientState.java:541) ~[na:na]
    at org.eclipse.paho.client.mqttv3.internal.ClientState.get(ClientState.java:592) ~[na:na]
    at org.eclipse.paho.client.mqttv3.internal.CommsSender.run(CommsSender.java:96) ~[na:na]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_77]
2016-10-03 13:13:23.402 [ERROR] [o.o.a.m.i.MqttMessagePublisher] - Error publishing message: Client is not connected
2016-10-03 13:13:23.406 [ERROR] [o.i.t.m.i.MqttBrokerConnection] - MQTT connection to 'agdisk' was lost: Timed out waiting for a response from the server : ReasonCode 32000 : Cause : Unknown
2016-10-03 13:13:23.602 [ERROR] [o.i.t.m.i.MqttBrokerConnection] - MQTT connection to broker was lost
org.eclipse.paho.client.mqttv3.MqttException: Timed out waiting for a response from the server
    at org.eclipse.paho.client.mqttv3.internal.ExceptionHelper.createMqttException(ExceptionHelper.java:27) ~[na:na]
    at org.eclipse.paho.client.mqttv3.internal.ClientState.checkForActivity(ClientState.java:541) ~[na:na]
    at org.eclipse.paho.client.mqttv3.internal.ClientState.get(ClientState.java:592) ~[na:na]
    at org.eclipse.paho.client.mqttv3.internal.CommsSender.run(CommsSender.java:96) ~[na:na]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_77]
2016-10-03 13:13:24.077 [INFO ] [o.i.t.m.i.MqttBrokerConnection] - Starting connection helper to periodically try restore connection to broker 'agdisk'
2016-10-03 13:13:24.078 [ERROR] [o.i.t.m.i.MqttBrokerConnection] - MQTT connection to 'wb' was lost: Timed out waiting for a response from the server : ReasonCode 32000 : Cause : Unknown
2016-10-03 13:13:24.079 [INFO ] [o.i.t.m.i.MqttBrokerConnection] - Starting connection helper to periodically try restore connection to broker 'wb'
2016-10-03 13:13:24.171 [WARN ] [o.i.t.m.i.MqttBrokerConnection] - Broker connection not started. Cannot publish message to topic '/esp/esp-gas/lcd/line4'
2

That error implies that OH received an message that either didn’t contain any data, or contained incomplete data. Or the socket was killed while reading the message.

I’d try to figure out what the messages are and where they are coming from when this error occurs to debug the problem further.

3

Thank for answer.
After this error it works f couple hours and stops working with this errors:

2016-10-03 18:14:26.034 [ERROR] [o.o.a.m.i.MqttMessagePublisher] - Error publishing message: Too many publishes in progress
2016-10-03 18:14:26.148 [ERROR] [o.o.a.m.i.MqttMessagePublisher] - Error publishing message: Too many publishes in progress
2016-10-03 18:14:26.199 [ERROR] [o.o.a.m.i.MqttMessagePublisher] - Error publishing message: Too many publishes in progress
2016-10-03 18:14:26.339 [ERROR] [o.o.a.m.i.MqttMessagePublisher] - Error publishing message: Too many publishes in progress
2016-10-03 18:14:26.455 [ERROR] [o.o.a.m.i.MqttMessagePublisher] - Error publishing message: Too many publishes in progress
2016-10-03 18:14:26.652 [ERROR] [o.o.a.m.i.MqttMessagePublisher] - Error publishing message: Too many publishes in progress
2016-10-03 18:14:26.746 [INFO ] [.model.script.Sensors Temp Hum] - Всё хорошо.   2016-10-03T18:14:26.743+03:00
2016-10-03 18:14:26.754 [ERROR] [o.o.a.m.i.MqttMessagePublisher] - Error publishing message: Too many publishes in progress
2016-10-03 18:14:28.128 [ERROR] [o.i.t.m.i.MqttBrokerConnection] - MQTT connection to broker was lost
org.eclipse.paho.client.mqttv3.MqttException: Unexpected error
    at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:115) ~[na:na]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_77]
2016-10-03 18:14:28.153 [ERROR] [o.i.t.m.i.MqttBrokerConnection] - MQTT connection to 'agdisk' was lost: Unexpected error : ReasonCode 6 : Cause : Unknown
2016-10-03 18:14:28.154 [INFO ] [o.i.t.m.i.MqttBrokerConnection] - Starting connection helper to periodically try restore connection to broker 'agdisk'
2016-10-03 18:14:28.534 [WARN ] [o.i.t.m.i.MqttBrokerConnection] - Broker connection not started. Cannot publish message to topic '/esp/esp-gas/lcd/inverse'
4

I noticed that MQTT errors is appear when I start using mqtt action. In OH v1.8.0 it works by months.

5

I just migrated from using the mqtt event bus to publish/subscribe by item. After turning off the mqtt event bus I’m seeing similar errors and would appreciate any help troubleshooting (I tried restoring all my mqtt configs back but still seeing them). My mqtt broker logs look fine

2017-07-27 18:10:10.897 [ERROR] [g.mqtt.internal.MqttMessagePublisher] - Error publishing...
Too many publishes in progress (32202)
	at org.eclipse.paho.client.mqttv3.internal.ClientState.send(ClientState.java:496)[197:org.openhab.io.transport.mqtt:1.11.0.201707271615]
	at org.eclipse.paho.client.mqttv3.internal.ClientComms.internalSend(ClientComms.java:132)[197:org.openhab.io.transport.mqtt:1.11.0.201707271615]
	at org.eclipse.paho.client.mqttv3.internal.ClientComms.sendNoWait(ClientComms.java:156)[197:org.openhab.io.transport.mqtt:1.11.0.201707271615]
	at org.eclipse.paho.client.mqttv3.MqttTopic.publish(MqttTopic.java:107)[197:org.openhab.io.transport.mqtt:1.11.0.201707271615]
	at org.openhab.io.transport.mqtt.internal.MqttBrokerConnection$2.publish(MqttBrokerConnection.java:426)[197:org.openhab.io.transport.mqtt:1.11.0.201707271615]
	at org.openhab.binding.mqtt.internal.MqttMessagePublisher.publish(MqttMessagePublisher.java:175)[190:org.openhab.binding.mqtt:1.11.0.201707271615]
	at org.openhab.binding.mqtt.internal.MqttEventBusBinding.receiveUpdate(MqttEventBusBinding.java:128)[190:org.openhab.binding.mqtt:1.11.0.201707271615]
	at org.openhab.core.events.AbstractEventSubscriber.handleEvent(AbstractEventSubscriber.java:39)[194:org.openhab.core.compat1x:2.2.0.201707252016]
	at org.apache.felix.eventadmin.impl.handler.EventHandlerProxy.sendEvent(EventHandlerProxy.java:415)[6:org.apache.karaf.services.eventadmin:4.0.8]
	at org.apache.felix.eventadmin.impl.tasks.HandlerTask.run(HandlerTask.java:90)[6:org.apache.karaf.services.eventadmin:4.0.8]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_131]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_131]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_131]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_131]
	at java.lang.Thread.run(Thread.java:748)[:1.8.0_131]

Edit: I turned on debug logging and I’m not seeing a consistent publish item that seems to be triggering the error. One thing I am noticing is despite commenting out the eventbus cfg’s I’m still seeing items getting published to the event-bus topics on the broker side. Is there someplace else to disable the eventbus mqtt actions?

[Solved] It was the fact that just rem’ing out the mqtt event bus configuration didn’t stop using it. I had to go into userdata/config/org/openhab/ and delete the event bus config file then restart. No errors since restart.

1 Like