paho.mqtt.java icon indicating copy to clipboard operation
paho.mqtt.java copied to clipboard
verified publisher icon eclipse

Websocket connection lost with mosquitto 1.6.15 and 2.0.11+

Open kdevkr opened this issue 3 years ago • 6 comments

Please fill out the form below before submitting, thank you!

  • [x] Bug exists Release Version 1.2.5 ( Master Branch)
  • [ ] Bug exists in MQTTv3 Client on Snapshot Version 1.2.6-SNAPSHOT (Develop Branch)
  • [ ] Bug exists in MQTTv5 Client on Snapshot Version 1.2.6-SNAPSHOT (Develop Branch)

If this is a bug regarding the Android Service, please raise the bug here instead: https://github.com/eclipse/paho.mqtt.android/issues/new

ref: https://github.com/eclipse/mosquitto/issues/2631

paho.mqtt.golang does not terminate the connection, but paho.mqtt.java causes the websocket connection to terminate after 5 mins.

MqttConnectOptions connectOptions = new MqttConnectOptions();
connectOptions.setCleanSession(true);
connectOptions.setUserName("username");
connectOptions.setPassword("password');

MqttClient mqttClient = new MqttClient("ws://localhost:9001", MqttClient.generateClientId());
IMqttToken iMqttToken = mqttClient.connectWithResult(connectOptions);

I used the default connection option, and the Mosquitto settings were configured and tested as follows.

persistence true
persistence_location /mosquitto/data/
log_dest file /mosquitto/log/mosquitto.log

port 1883

listener 9001
protocol websockets
allow_anonymous false
password_file /mosquitto/config/passwd
set_tcp_nodelay true
socket_domain ipv4

log_type all
websockets_log_level 8

The test result with docker-compose, issue occurs from 1.6.15 and 2.0.11+. (Version 2.0.11 released)

JDK Paho Java Client Mosquitto EOF
Temurin 11.0.16 1.2.5 2.0.15 💥
Temurin 11.0.16 1.2.5 2.0.14 💥
Temurin 11.0.16 1.2.5 2.0.13 💥
Temurin 11.0.16 1.2.5 2.0.12 💥
Temurin 11.0.16 1.2.5 2.0.11 💥
Temurin 11.0.16 1.2.5 2.0.10 OK
Temurin 11.0.16 1.2.5 2.0.9 OK
Temurin 11.0.16 1.2.5 1.6.15 💥
Temurin 11.0.16 1.2.5 1.6.14 OK
Temurin 11.0.16 1.2.5 1.6.9 OK

Based on this result, I think there is a bug in the Paho Java Client library due to Mosquitto's changes.

More details

mosquitto.log

1662791998: mosquitto version 1.6.15 starting
1662791998: Config loaded from /mosquitto/config/mosquitto.conf.
1662791998: Opening websockets listen socket on port 9001.
1662791998: Opening ipv4 listen socket on port 1883.
1662791998: Opening ipv6 listen socket on port 1883.
1662791998: mosquitto version 1.6.15 running
1662792042: New client connected from 172.24.0.1 as paho1735120451144000 (p2, c1, k60, u'mambo').
1662792042: No will message specified.
1662792042: Sending CONNACK to paho1735120451144000 (0, 0)
1662792042: Received SUBSCRIBE from paho1735120451144000
1662792042: 	$SYS/broker/version (QoS 0)
1662792042: Sending PUBLISH to paho1735120451144000 (d0, q0, r1, m0, '$SYS/broker/version', ... (24 bytes))
1662792042: paho1735120451144000 0 $SYS/broker/version
1662792042: Sending SUBACK to paho1735120451144000
1662792042: Received SUBSCRIBE from paho1735120451144000
1662792042: 	test/# (QoS 0)
1662792042: paho1735120451144000 0 test/#
1662792042: Sending SUBACK to paho1735120451144000
1662792102: Received PINGREQ from paho1735120451144000
1662792102: Sending PINGRESP to paho1735120451144000
1662792162: Received PINGREQ from paho1735120451144000
1662792162: Sending PINGRESP to paho1735120451144000
1662792222: Received PINGREQ from paho1735120451144000
1662792222: Sending PINGRESP to paho1735120451144000
1662792282: Received PINGREQ from paho1735120451144000
1662792282: Sending PINGRESP to paho1735120451144000
1662792341: Socket error on client paho1735120451144000, disconnecting.
1662792842: mosquitto version 1.6.15 terminating
1662792842: Saving in-memory database to /mosquitto/data/mosquitto.db.

1662795072: mosquitto version 2.0.11 starting
1662795072: Config loaded from /mosquitto/config/mosquitto.conf.
1662795072: Opening websockets listen socket on port 9001.
1662795072: Opening ipv4 listen socket on port 1883.
1662795072: Opening ipv6 listen socket on port 1883.
1662795072: mosquitto version 2.0.11 running
1662795107: New client connected from 192.168.80.1:48834 as paho1738186178533400 (p2, c1, k60, u'mambo').
1662795107: No will message specified.
1662795107: Sending CONNACK to paho1738186178533400 (0, 0)
1662795107: Received SUBSCRIBE from paho1738186178533400
1662795107: 	$SYS/broker/version (QoS 0)
1662795107: paho1738186178533400 0 $SYS/broker/version
1662795107: Sending SUBACK to paho1738186178533400
1662795107: Sending PUBLISH to paho1738186178533400 (d0, q0, r1, m0, '$SYS/broker/version', ... (24 bytes))
1662795107: Received SUBSCRIBE from paho1738186178533400
1662795107: 	test/# (QoS 0)
1662795107: paho1738186178533400 0 test/#
1662795107: Sending SUBACK to paho1738186178533400
1662795167: Received PINGREQ from paho1738186178533400
1662795167: Sending PINGRESP to paho1738186178533400
1662795227: Received PINGREQ from paho1738186178533400
1662795227: Sending PINGRESP to paho1738186178533400
1662795287: Received PINGREQ from paho1738186178533400
1662795287: Sending PINGRESP to paho1738186178533400
1662795347: Received PINGREQ from paho1738186178533400
1662795347: Sending PINGRESP to paho1738186178533400
1662795407: Client paho1738186178533400 closed its connection.
1662795439: mosquitto version 2.0.11 terminating
1662795439: Saving in-memory database to /mosquitto/data//mosquitto.db.

Paho Java Client log

FINE: null: network read message
Sep 09, 2022 8:33:09 AM org.eclipse.paho.client.mqttv3.internal.websocket.WebSocketReceiver run
FINE: null: network read message
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.websocket.WebSocketReceiver run
FINE: null: network read message
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.websocket.WebSocketReceiver run
FINE: null: network read message
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.websocket.WebSocketReceiver stop
FINE: null: stopping
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.websocket.WebSocketReceiver stop
FINE: null: stopping
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.websocket.WebSocketReceiver stop
FINE: null: stopped
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.websocket.WebSocketReceiver stop
FINE: null: stopped
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsReceiver run
FINE: paho1622771147525800: Stopping due to IOException
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsReceiver run
FINE: paho1622771147525800: Stopping due to IOException
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.ClientComms shutdownConnection
FINE: paho1622771147525800: state=DISCONNECTING
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.ClientComms shutdownConnection
FINE: paho1622771147525800: state=DISCONNECTING
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsCallback stop
FINE: paho1622771147525800: stopping
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsCallback stop
FINE: paho1622771147525800: stopping
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsCallback stop
FINE: paho1622771147525800: notify workAvailable and wait for run
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsCallback stop
FINE: paho1622771147525800: notify workAvailable and wait for run
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsCallback stop
FINE: paho1622771147525800: stopped
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsCallback stop
FINE: paho1622771147525800: stopped
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsCallback run
FINE: paho1622771147525800: notify spaceAvailable
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsCallback run
FINE: paho1622771147525800: notify spaceAvailable
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsReceiver stop
FINE: paho1622771147525800: stopping
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsReceiver stop
FINE: paho1622771147525800: stopping
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsReceiver stop
FINE: paho1622771147525800: stopped
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsReceiver stop
FINE: paho1622771147525800: stopped
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.websocket.WebSocketReceiver stop
FINE: null: stopping
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.websocket.WebSocketReceiver stop
FINE: null: stopping
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.websocket.WebSocketReceiver stop
FINE: null: stopped
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.websocket.WebSocketReceiver stop
FINE: null: stopped
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsTokenStore quiesce
FINE: paho1622771147525800: resp=Client is currently disconnecting (32102)
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsTokenStore quiesce
FINE: paho1622771147525800: resp=Client is currently disconnecting (32102)
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.ClientComms handleOldTokens
FINE: paho1622771147525800: >
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.ClientComms handleOldTokens
FINE: paho1622771147525800: >
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.ClientState resolveOldTokens
FINE: paho1622771147525800: reason Connection lost (32109) - java.io.EOFException
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.ClientState resolveOldTokens
FINE: paho1622771147525800: reason Connection lost (32109) - java.io.EOFException
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsTokenStore getOutstandingTokens
FINE: paho1622771147525800: >
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsTokenStore getOutstandingTokens
FINE: paho1622771147525800: >
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.ClientState disconnected
FINE: paho1622771147525800: disconnected
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.ClientState disconnected
FINE: paho1622771147525800: disconnected
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.ClientState clearState
FINE: paho1622771147525800: >
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.ClientState clearState
FINE: paho1622771147525800: >
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsTokenStore clear
FINE: paho1622771147525800: > 0 tokens
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsTokenStore clear
FINE: paho1622771147525800: > 0 tokens
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsSender stop
FINE: paho1622771147525800: stopping sender
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsSender stop
FINE: paho1622771147525800: stopping sender
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.ClientState notifyQueueLock
FINE: paho1622771147525800: notifying queueLock holders
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.ClientState notifyQueueLock
FINE: paho1622771147525800: notifying queueLock holders
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsSender stop
FINE: paho1622771147525800: stopped
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsSender stop
FINE: paho1622771147525800: stopped
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.ClientState get
FINE: paho1622771147525800: new work or ping arrived 
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.TimerPingSender stop
FINE: paho1622771147525800: stop
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.ClientState get
FINE: paho1622771147525800: new work or ping arrived 
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.ClientState get
FINE: paho1622771147525800: no outstanding flows and not connected
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.ClientState get
FINE: paho1622771147525800: no outstanding flows and not connected
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.TimerPingSender stop
FINE: paho1622771147525800: stop
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsSender run
FINE: paho1622771147525800: get message returned null, stopping}
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsSender run
FINE: paho1622771147525800: get message returned null, stopping}
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsSender run
FINE: paho1622771147525800: <
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsSender run
FINE: paho1622771147525800: <
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.ClientComms shutdownConnection
FINE: paho1622771147525800: state=DISCONNECTED
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.ClientComms shutdownConnection
FINE: paho1622771147525800: state=DISCONNECTED
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsCallback connectionLost
FINE: paho1622771147525800: call connectionLost
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsCallback connectionLost
FINE: paho1622771147525800: call connectionLost
Connection lost (32109) - java.io.EOFException
	at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:197)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.io.EOFException
	at java.base/java.io.DataInputStream.readByte(DataInputStream.java:272)
	at org.eclipse.paho.client.mqttv3.internal.wire.MqttInputStream.readMqttWireMessage(MqttInputStream.java:92)
	at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:137)
	... 1 more
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsReceiver run
FINE: paho1622771147525800: <
Sep 09, 2022 8:33:10 AM org.eclipse.paho.client.mqttv3.internal.CommsReceiver run
FINE: paho1622771147525800: <

kdevkr avatar Sep 10 '22 03:09 kdevkr

The error 32109 in your logs is not new...... Connection lost (32109) - java.io.EOFException at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:197) at java.base/java.lang.Thread.run(Thread.java:829) Caused by: java.io.EOFException at java.base/java.io.DataInputStream.readByte(DataInputStream.java:272) at org.eclipse.paho.client.mqttv3.internal.wire.MqttInputStream.readMqttWireMessage(MqttInputStream.java:92) at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:137) ... 1 more

https://github.com/eclipse/paho.mqtt.java/issues/358 https://github.com/eclipse/paho.mqtt.java/issues/679 https://github.com/eclipse/paho.mqtt.java/issues/673 https://stackoverflow.com/questions/39594288/connection-lost-32109-java-io-eofexception-mqttandroidclient https://stackoverflow.com/questions/46788749/connection-lost-32109-java-io-eofexception

It's been around for multiple versions and never fixed. I see this error in an Android application connecting to Mosquitto 1.5.7

oreillymj avatar Sep 16 '22 16:09 oreillymj

@oreillymj Where did You get your error, in what environment?

In my case, I have met this issue with Azure IotHub SDK v1 about 1-2 months ago. I discovered this error in my automatic tests and there weren't any changes in libraries versions. Thus, devs from MS did something which isn't related to paho client. It's hard to say where their "sad" change could be. Saying more, switching to SDK v2 gives the same errors.

And now, the best story. In Azure IotHub there are couple ways of communication:

  • DeviceTwin
  • DirectMethod (DeviceMethod in sdk v1)

Despite this error with connection DeviceTwin works, but DirectMethod has stopped working. Taking the examples from official repo:

  • https://github.com/Azure/azure-iot-sdk-java/blob/main/device/iot-device-samples
  • https://github.com/Azure/azure-iot-sdk-java/blob/main/service/iot-service-samples

It just doesn't work.

I'm wondering how it's even possible. There are for sure plenty of applications which use this technology... I have created an issue with azure-iot-hub tag https://stackoverflow.com/questions/73840834/mqtt-connection-lost-java-io-eofexception-null

In summary: It doesn't work independently from sdk versions

devopsample avatar Sep 24 '22 20:09 devopsample

In my case the problem was in version of Azure SDK iot-service-client I was using 2.1.2, after switch to 2.1.4 it has started to work.

devopsample avatar Oct 16 '22 10:10 devopsample

I'm using Paho for an Android client connecting to a Mosquitto broker running Rasbian 10 Specifically $ mosquitto -v mosquitto version 1.5.7 starting

lsb_release -a No LSB modules are available. Distributor ID: Raspbian Description: Raspbian GNU/Linux 10 (buster) Release: 10 Codename: buster

Looking at later Raspbian releases, I don't see a "good" version from your list above... Bullseye moves to v 2.0.11-1 Package: mosquitto Version: 2.0.11-1 Architecture: armhf Maintainer: Roger A. Light [email protected] Installed-Size: 609

It would be interesting to see if the errors align timewise with these warning in the Mosquitto logs.

1625584799: Warning: Received PUBREC from ECO_Android_MQTT_svc_0dd4b5e067d60fce for an unknown packet identifier 18720. 1625588754: Warning: Received PUBREC from ECO_Android_MQTT_svc_0dd4b5e067d60fce for an unknown packet identifier 18720. 1625588801: Warning: Received PUBREC from ECO_Android_MQTT_svc_0dd4b5e067d60fce for an unknown packet identifier 18720. 1625588807: Warning: Received PUBREC from ECO_Android_MQTT_svc_0dd4b5e067d60fce for an unknown packet identifier 18720. 1625588813: Warning: Received PUBREC from ECO_Android_MQTT_svc_0dd4b5e067d60fce for an unknown packet identifier 18720. 1625588819: Warning: Received PUBREC from ECO_Android_MQTT_svc_0dd4b5e067d60fce for an unknown packet identifier 18720.

oreillymj avatar Oct 17 '22 10:10 oreillymj