search

eclipse / paho.mqtt.java

Eclipse Paho Java MQTT client library. Paho is an Eclipse IoT project.
https://eclipse.org/paho
Other
2.1k stars 880 forks source link

Websocket connection lost with mosquitto 1.6.15 and 2.0.11+ #960

Open kdevkr opened 1 year ago

kdevkr commented 1 year ago

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

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 ```shell 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 ```shell 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: < ```
oreillymj commented 1 year ago

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

devopsample commented 1 year ago

@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:

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

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 commented 1 year ago

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.

oreillymj commented 1 year ago

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 roger@atchoo.org 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.

nuessgens commented 2 weeks ago

Maybe related to https://github.com/eclipse/paho.mqtt.java/issues/1000#issuecomment-2266321088 had the same issue with mosquitto.org as paho mqtt client is unable to handle the Websocket PING Framges