MQTT connection lost

Hello, I’m trying to configure SONOFF using MQTT in Openhab but looking at the log file I find the following errors one after the other:

[203:org.openhab.io.transport.mqtt:1.10.0]
at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:107)[203:org.openhab.io.transport.mqtt:1.10.0]
… 1 more
2017-07-20 21:36:27.550 [ERROR] [t.mqtt.internal.MqttBrokerConnection] - MQTT connection to ‘raspberrypi’ was lost: Connection lost : ReasonCode 32109 : Cause : null
2017-07-20 21:36:27.553 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting connection helper to periodically try restore connection to broker 'raspberrypi’
2017-07-20 21:36:37.559 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'raspberrypi’
2017-07-20 21:36:38.825 [ERROR] [t.mqtt.internal.MqttBrokerConnection] - MQTT connection to broker was lost
Connection lost (32109) - java.io.EOFException
at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:146)[203:org.openhab.io.transport.mqtt:1.10.0]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_65]
Caused by: java.io.EOFException
at java.io.DataInputStream.readByte(DataInputStream.java:267)[:1.8.0_65]
at org.eclipse.paho.client.mqttv3.internal.wire.MqttInputStream.readMqttWireMessage(MqttInputStream.java:65)

please anyone can help me??

thank you

Please show your defnitions in mqtt.cfg and one example for a item with mqtt.
Does the broker work and what is the name/ip of the server where the broker runs.

Hello!
Can i take over this thread or should i open a new one?

i have almost (?) the same problem (already posted in ITEAD sonoff switches thread, no answer though): openHAB won’t connect to mosquitto:

2017-07-20 22:57:33.677 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'mqttson'
2017-07-20 22:57:35.679 [ERROR] [t.mqtt.internal.MqttBrokerConnection] - MQTT connection to broker was lost
Connection lost (32109) - java.io.EOFException
	at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:146)[197:org.openhab.io.transport.mqtt:1.10.0]
	at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
Caused by: java.io.EOFException
	at java.io.DataInputStream.readByte(DataInputStream.java:267)[:1.8.0_121]
	at org.eclipse.paho.client.mqttv3.internal.wire.MqttInputStream.readMqttWireMessage(MqttInputStream.java:65)[197:org.openhab.io.transport.mqtt:1.10.0]
	at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:107)[197:org.openhab.io.transport.mqtt:1.10.0]
	... 1 more
2017-07-20 22:57:35.682 [ERROR] [t.mqtt.internal.MqttBrokerConnection] - MQTT connection to 'mqttson' was lost: Connection lost : ReasonCode 32109 : Cause : null
2017-07-20 22:57:35.683 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting connection helper to periodically try restore connection to broker 'mqttson'

mqtt.cfg:

mqttson.url=tcp://localhost:1883
mqttson.clientId=OH2MQTT

installed mosquitto via openhabian-conf
and “systemctl status mosquitto” says it’s running.
no items configured so far - but the broker should still connect, right?

are there more settings?

i already tried to delete the mqtt binding config via karafe console but the error remains :frowning:
what am i missing (again)…?

is your broker alive and kicking? use a tool like mqtt.fx to connect to it and try some publish/subscribe stuff to test it out.
if it’s working ok: check if you have installed the MQTT Action addon (remove it)

otherwise: post your mosquitto.conf (and log) and make sure that the clientID in mqtt.cfg is unique for the connection to the broker.

SOLVED!

[quote=“Dim, post:4, topic:31993”]
is your broker alive and kicking? use a tool like mqtt.fx to connect to it and try some publish/subscribe stuff to test it out.
if it’s working ok: check if you have installed the MQTT Action addon (remove it)
[/quote]connected mqtt.fx with Broker Address = openHAB2 ip (where mosquitto runs, too)
then on “broker status” i can subscribe to “Mosquitto” or “Hive MQ”, when i subscribe to Mosquitto i can see some messages regarding my sonoff device like:

2017-07-21 20:44:28,519  INFO --- MqttFX ClientModel             : messageArrived() with topic: tele/sonoff/LWT
2017-07-21 20:44:28,520  INFO --- MqttFX ClientModel             : messageArrived() added: message #5 to topic 'tele/sonoff/LWT'
2017-07-21 20:44:28,569  INFO --- MqttFX ClientModel             : messageArrived() with topic: cmnd/sonoff/POWER
2017-07-21 20:44:28,570  INFO --- MqttFX ClientModel             : messageArrived() added: message #6 to topic 'cmnd/sonoff/POWER'

no idea if that means my broker is alive and kicking…

mosquitto.conf seems empty?

[20:46:39] openhabian@openHABianPi:~$ cat /etc/mosquitto/mosquitto.conf
# Place your local configuration in /etc/mosquitto/conf.d/
#
# A full description of the configuration file is at
# /usr/share/doc/mosquitto/examples/mosquitto.conf.example

pid_file /var/run/mosquitto.pid

persistence true
persistence_location /var/lib/mosquitto/

log_dest file /var/log/mosquitto/mosquitto.log

include_dir /etc/mosquitto/conf.d

in /etc/mosquitto/conf.d/ are no files

clientID is unique for sure, i have only one MQTT device here (and got a random Client id wth MQTT.fx).

SOLVED!

i’m feeling like forrest gump here… "i am not a very smart man"
i configured openHAB with the same clientID as my sonoff device… it’s my first time with mqtt and i thought what openhab conf was supposed to look like :blush:

Sorry for the trouble!

1 Like
1 Like

well. next problem:
mosquitto log:

1500670980: mosquitto version 1.4.14 (build date Mon, 10 Jul 2017 23:48:43 +0100) starting
1500670980: Config loaded from /etc/mosquitto/mosquitto.conf.
1500670980: Opening ipv4 listen socket on port 1883.
1500670980: Opening ipv6 listen socket on port 1883.
1500671006: New connection from 192.168.178.160 on port 1883.
1500671006: New client connected from 192.168.178.160 as OH2MQTT (c1, k15, u'DVES_USER').
1500671044: New connection from 127.0.0.1 on port 1883.
1500671044: New client connected from 127.0.0.1 as openHAB2 (c1, k60).
1500671234: New connection from ::1 on port 1883.
1500671234: New client connected from ::1 as mosqsub|1535-openHABian (c1, k60).
1500671242: Socket error on client mosqsub|1535-openHABian, disconnecting.

i get no error message in openHAB2, switch doesnt work:

Switch Sonoff_TH16A "Sonoff Test" <light>
    { mqtt=">[broker:cmnd/OH2MQTT/POWER:command:*:default],
            <[broker:stat/OH2MQTT/POWER:state:default]" }

where’s the client mosqsub|1535-openHABian coming from?

Hello, I’m following the steps and I am still behind Peter:

mqtt.cfg

raspberrypi.url=tcp://10.0.0.101:1883
raspberrypi.clientId=DVES_A7F83D
raspberrypi.user=openhabian
raspberrypi.pwd=password

at the mqtt.fx I got the following messages (but I didn’t see any topic):

2017-07-21 22:32:17,511 INFO — MqttFX ClientModel : messageArrived for:
SYS/broker/load/bytes/sent/15min
2017-07-21 22:32:17,511 INFO — MqttFX ClientModel : messageArrived for: $SYS/broker/load/sockets/15min
2017-07-21 22:32:17,512 INFO — MqttFX ClientModel : messageArrived for: > $SYS/broker/load/connections/15min
2017-07-21 22:32:17,512 INFO — MqttFX ClientModel : messageArrived for: $SYS/broker/messages/received
2017-07-21 22:32:17,512 INFO — MqttFX ClientModel : messageArrived for: $SYS/broker/messages/sent
2017-07-21 22:32:17,514 INFO — MqttFX ClientModel : messageArrived for: $SYS/broker/publish/messages/received
2017-07-21 22:32:17,522 INFO — MqttFX ClientModel : messageArrived for: $SYS/broker/bytes/received
2017-07-21 22:32:17,545 INFO — MqttFX ClientModel : messageArrived for: $SYS/broker/bytes/sent

my mosquitto.cfg:

pid_file /var/run/mosquitto.pid

persistence true
persistence_location /var/lib/mosquitto/

log_dest file /var/log/mosquitto/mosquitto.log

include_dir /etc/mosquitto/conf.d

password_file /etc/mosquitto/passwd
allow_anonymous false

at the mosquitto.log I can see that the connections are opening and closing:

1500629087: New client connected from 10.0.0.104 as DVES_A7F83D (c1, k15, u’openhabian’).
1500629097: New connection from 10.0.0.101 on port 1883.
1500629097: Client DVES_A7F83D already connected, closing old connection.
1500629097: Client DVES_A7F83D disconnected.
1500629097: New client connected from 10.0.0.101 as DVES_A7F83D (c1, k60, u’openhabian’).
1500629099: New connection from 10.0.0.104 on port 1883.
1500629099: Client DVES_A7F83D already connected, closing old connection.
1500629099: Client DVES_A7F83D disconnected.
1500629099: New client connected from 10.0.0.104 as DVES_A7F83D (c1, k15, u’openhabian’).
1500629106: Reloading config.

If you have any advices I’d really appreciate it!!

Paulo

hmmm… it looks like the MQTT binding (?) on the local host is initiating 2 connections towards the broker… (not sure why)
One using IPv4 (127.0.0.1) and another one using IPv6 (::1)

Try the following:

  1. Modify /etc/openhab2/services/mqtt.cfg and use:
mqttson.url=tcp://127.0.0.1:1883
mqttson.clientId=openHAB2

(/etc/hosts resolves localhost to both ipv4 & ipv6 addresses… force the binding to use ipv4 only)

  1. Disable the IPv6 listener on the Broker config /etc/mosquitto/mosquitto.conf:
listener 1883 0.0.0.0

(check with netstat -atn |grep 1883 if it is listening only on tcp(4) or also on tcp6)
(don’t use listener 1833 127.0.0.1 since this will not allow remote connections to the broker (e.g. from the Sonoff))

  1. Check /var/lib/openhab2/config/org/openhab/mqtt.config for old, stale config entries

it looks like you are using the same clientID (DVES_A7F83D) in 2 client hosts (.101 & .104)

@ThomDietrich: does this: mosqsub|1535-openHABian ring any bells? could openHABian be the local hostname?
This looks like the an auto-generated clientID (for the IPv6 connection?) using: mosqsub| + some random? number (1535) + hostname. I will check the source code of the MQTT binding to see if I find anything…

edit: found something:

public static java.lang.String generateClientId()
Returns a randomly generated client identifier based on the current user's login name and the system time.

still researching why 2 connections are created :slight_smile:

@narf27: please post the contents of your /var/lib/openhab2/config/org/openhab/mqtt.config
(don’t delete it … I would like to see the info first to see if there is any entry in there that could be the reason for the 2nd IPv6 based connection)

Also: Double check please the log for the 2nd clientId… In theory it should be mosqsub/1535-openHABian (not mosqsub|1535-openHABian)… not with vertical bar ( | ) but with Slash (/)

I opened an issue on https://github.com/openhab/openhab1-addons/issues/5261 to check this…
I couldn’t find the answer myself

1 Like

goood morning!

made the changes as indicated:

[quote]1) Modify /etc/openhab2/services/mqtt.cfg and use:

mqttson.url=tcp://127.0.0.1:1883
mqttson.clientId=openHAB2

(/etc/hosts resolves localhost to both ipv4 & ipv6 addresses… force the binding to use ipv4 only)

  1. Disable the IPv6 listener on the Broker config /etc/mosquitto/mosquitto.conf:

listener 1883 0.0.0.0

(check with netstat -atn |grep 1883 if it is listening only on tcp(4) or also on tcp6)
(don’t use listener 1833 127.0.0.1 since this will not allow remote connections to the broker (e.g. from the Sonoff))[/quote]

netstat before:

[08:58:34] openhabian@openHABianPi:~$ netstat -atn |grep 1883
tcp        0      0 0.0.0.0:1883            0.0.0.0:*               LISTEN
tcp        0      0 127.0.0.1:1883          127.0.0.1:59416         ESTABLISHED
tcp        0      0 192.168.178.173:1883    192.168.178.160:12389   ESTABLISHED
tcp6       0      0 :::1883                 :::*                    LISTEN
tcp6       0      0 127.0.0.1:59416         127.0.0.1:1883          ESTABLISHED

netstat afterwards:

[09:03:58] openhabian@openHABianPi:~$ netstat -atn |grep 1883
tcp        0      0 0.0.0.0:1883            0.0.0.0:*               LISTEN
tcp        0      0 192.168.178.173:1883    192.168.178.160:22232   ESTABLISHED
tcp        0      0 127.0.0.1:1883          127.0.0.1:38182         ESTABLISHED
tcp6       0      0 127.0.0.1:38182         127.0.0.1:1883          ESTABLISHED

this is mqtt.config

[08:59:55] openhabian@openHABianPi:~$ cat /var/lib/openhab2/config/org/openhab/mqtt.config
mqttson.clientId="openHAB2"
mqttson.url="tcp://127.0.0.1:1883"
service.pid="org.openhab.mqtt"

it’s the verticatl bar…
the number changes, here’s the log after said changes and reboot:

1500706908: mosquitto version 1.4.14 (build date Mon, 10 Jul 2017 23:48:43 +0100) starting
1500706908: Config loaded from /etc/mosquitto/mosquitto.conf.
1500706908: Opening ipv4 listen socket on port 1883.
1500706935: New connection from 192.168.178.160 on port 1883.
1500706935: New client connected from 192.168.178.160 as OH2MQTT (c1, k15, u'DVES_USER').
1500706972: New connection from 127.0.0.1 on port 1883.
1500706972: New client connected from 127.0.0.1 as openHAB2 (c1, k60).
1500707208: New connection from 127.0.0.1 on port 1883.
1500707208: New client connected from 127.0.0.1 as mosqsub|1542-openHABian (c1, k60).
1500707211: Socket error on client mosqsub|1542-openHABian, disconnecting.

are the first numbers here a timestamp?

good morning!

ok… please post the contents of /var/lib/openhab2/config/org/openhab/mqtt.config

it’s in the middle of my previous post!

1 Like

oops :slight_smile: saw it

is there any other process running locally on the machine that would initiate a new connection to the broker? (except openHAB… example: owntracks recorder or something similar)

Yes, use: https://www.epochconverter.com/

not that i would know of.
there’s a /etc/openhab2/services/mqtt-eventbus.cfg, but i don’t think that would make a connection?
how can i check for anoter process?

noticed a new connection (and disconnect) - see last 3 linkes

1500706890: mosquitto version 1.4.14 terminating
1500706908: mosquitto version 1.4.14 (build date Mon, 10 Jul 2017 23:48:43 +0100) starting
1500706908: Config loaded from /etc/mosquitto/mosquitto.conf.
1500706908: Opening ipv4 listen socket on port 1883.
1500706935: New connection from 192.168.178.160 on port 1883.
1500706935: New client connected from 192.168.178.160 as OH2MQTT (c1, k15, u'DVES_USER').
1500706972: New connection from 127.0.0.1 on port 1883.
1500706972: New client connected from 127.0.0.1 as openHAB2 (c1, k60).
1500707208: New connection from 127.0.0.1 on port 1883.
1500707208: New client connected from 127.0.0.1 as mosqsub|1542-openHABian (c1, k60).
1500707211: Socket error on client mosqsub|1542-openHABian, disconnecting.
1500707619: New connection from 127.0.0.1 on port 1883.
1500707619: New client connected from 127.0.0.1 as mosqsub|1730-openHABian (c1, k60).
1500707800: Socket error on client mosqsub|1730-openHABian, disconnecting.

1500706972 = GMT: Saturday, July 22, 2017 7:02:52 AM (openHAB2 client connects)
1500707208 = GMT: Saturday, July 22, 2017 7:06:48 AM (mosqsub|1730-openHABian client connects)

almost 4 mins delta… strange

then… after 3 seconds… disconnection happens due to Socket error for client mosqsub|1730-openHABian
1500707211 = GMT: Saturday, July 22, 2017 7:06:51 AM

and then…
1500707619 = GMT: Saturday, July 22, 2017 7:13:39 AM client mosqsub|1730-openHABian tries to reconnect (and gets busted again :slight_smile:)

…but… this time after almost 3 minutes…
1500707800 = GMT: Saturday, July 22, 2017 7:16:40 AM (2nd socket error)

I believe that the event-bus uses the main mqtt connection (it doesn’t establish a new one). Do you have anything configured in there?

lsof -i :1883

…but if it is disconnected… it won’t show up