eclipse-paho / eclipse-paho/paho.mqtt.java
Client stopped receiving messages from broker for no reasons
- Dominant language
- Java
- Stars
- 2.3k
- Forks
- 919
- PR merge metrics
- No merged PRs in 30d
Description
Please fill out the form below before submitting, thank you!
- [ ] Bug exists Release Version 1.2.0 ( Master Branch)
We have 2 java clients using this library. Both are using MqttAsyncClient with cleanSession = false, keepAlive = 10 seconds and automaticReconnect is enabled. We also have a python client and a node client connecting to the same broker (Mosca on top of Redis).
For some unknown reasons the Java clients stopped receiving any messages from the broker, whereas the others are fine. The python one checks for connection every 10 seconds and re-connect them (manually done in the code).
Here are the logs from the broker and one of the java clients. Essentially it's working fine, then it failed with "too many publish in progress", but then it seemed to be OK after that. And it had an auto-reconnect successfully and doing its things, and then after 17:13:53 it received nothing from the broker until I restarted the server. The TimePingSender seemed to keep doing its job OK though.
```
2018-10-02 07:13:51.364 INFO 1 --- [08b29c64da91ea3] a.c.b.marquee.mqtt.GenericMqttHandler : Successfully published to topic marquee/marquee_28122702576940aaa08b29c64da91ea3/flare/100/device/updated
2018-10-02 07:13:51.364 INFO 1 --- [08b29c64da91ea3] a.c.b.marquee.mqtt.GenericMqttHandler : Parsing message for topic flare/100/flare/100/device/discovered
2018-10-02 07:13:51.365 INFO 1 --- [08b29c64da91ea3] a.c.b.marquee.mqtt.GenericMqttHandler : Successfully parsed message for topic flare/100/flare/100/device/discovered
2018-10-02 07:13:51.365 INFO 1 --- [08b29c64da91ea3] a.c.b.m.mqtt.DeviceDiscoveredListener : Handling device discovered for flare: 100
2018-10-02 07:13:51.368 INFO 1 --- [08b29c64da91ea3] a.c.b.m.mqtt.DeviceDiscoveredListener : Successfully updated device 121400 for 100
2018-10-02 07:13:51.369 INFO 1 --- [08b29c64da91ea3] a.c.b.marquee.mqtt.GenericMqttHandler : Publishing to topic marquee/marquee_28122702576940aaa08b29c64da91ea3/flare/100/device/updated
2018-10-02 07:13:51.369 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.MqttAsyncClient : marquee_28122702576940aaa08b29c64da91ea3: < topic=marquee/marquee_28122702576940aaa08b29c64da91ea3/flare/100/device/updated message=nulluserContext=null callback=null
2018-10-02 07:13:51.369 ERROR 1 --- [08b29c64da91ea3] a.c.b.marquee.mqtt.GenericMqttHandler : Failed to process message for topic flare/100/flare/100/device/discovered with message {"meta": {"request": null, "createdAt": "2018-10-02T07:13:30"}, "payload": {"pduSource": "
**org.eclipse.paho.client.mqttv3.MqttException: Too many publishes in progress**
at org.eclipse.paho.client.mqttv3.internal.ClientState.send(ClientState.java:513) ~[org.eclipse.paho.client.mqttv3-1.2.0.jar!/:na]
....
2018-10-02 07:13:52.390 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.MqttAsyncClient : marquee_28122702576940aaa08b29c64da91ea3: **Triggering Automatic Reconnect attempt.**
2018-10-02 07:13:52.390 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.MqttAsyncClient : marquee_28122702576940aaa08b29c64da91ea3: Attempting to reconnect client: marquee_28122702576940aaa08b29c64da91ea3
2018-10-02 07:13:52.390 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.MqttAsyncClient : marquee_28122702576940aaa08b29c64da91ea3: Attempting to reconnect client: marquee_28122702576940aaa08b29c64da91ea3
2018-10-02 07:13:52.390 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.MqttAsyncClient : marquee_28122702576940aaa08b29c64da91ea3: cleanSession=false connectionTimeout=30 TimekeepAlive=10 userName=marquee password=[null] will=[null] userContext=null callback=org.eclipse.paho.client.mqttv3.MqttAsyncClient$MqttReconnectActionListener@5ef5629a
2018-10-02 07:13:52.390 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.MqttAsyncClient : marquee_28122702576940aaa08b29c64da91ea3: cleanSession=false connectionTimeout=30 TimekeepAlive=10 userName=marquee password=[null] will=[null] userContext=null callback=org.eclipse.paho.client.mqttv3.MqttAsyncClient$MqttReconnectActionListener@5ef5629a
2018-10-02 07:13:52.390 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.MqttAsyncClient : marquee_28122702576940aaa08b29c64da91ea3: URI=tcp://gaffer:1883
2018-10-02 07:13:52.390 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.MqttAsyncClient : marquee_28122702576940aaa08b29c64da91ea3: URI=tcp://gaffer:1883
2018-10-02 07:13:52.391 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.MqttAsyncClient : marquee_28122702576940aaa08b29c64da91ea3: <
2018-10-02 07:13:52.391 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.MqttAsyncClient : marquee_28122702576940aaa08b29c64da91ea3: <
2018-10-02 07:13:52.393 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: start timer for client:marquee_28122702576940aaa08b29c64da91ea3
2018-10-02 07:13:52.394 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.MqttAsyncClient : marquee_28122702576940aaa08b29c64da91ea3: Automatic Reconnect Successful: marquee_28122702576940aaa08b29c64da91ea3
2018-10-02 07:13:52.398 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.MqttAsyncClient : marquee_28122702576940aaa08b29c64da91ea3: Stop reconnect timer for client: marquee_28122702576940aaa08b29c64da91ea3
2018-10-02 07:13:52.403 INFO 1 --- [08b29c64da91ea3] a.c.b.marquee.mqtt.GenericMqttHandler : Parsing message for topic flare/100/flare/100/device/discovered
2018-10-02 07:13:52.403 INFO 1 --- [08b29c64da91ea3] a.c.b.marquee.mqtt.GenericMqttHandler : Successfully parsed message for topic flare/100/flare/100/device/discovered
2018-10-02 07:13:53.645 INFO 1 --- [08b29c64da91ea3] a.c.b.marquee.mqtt.GenericMqttHandler : Successfully published to topic marquee/marquee_28122702576940aaa08b29c64da91ea3/flare/100/device/updated
2018-10-02 07:13:53.646 INFO 1 --- [08b29c64da91ea3] a.c.b.marquee.mqtt.GenericMqttHandler : Parsing message for topic flare/100/flare/100/device/discovered
2018-10-02 07:13:53.648 INFO 1 --- [08b29c64da91ea3] a.c.b.marquee.mqtt.GenericMqttHandler : Successfully parsed message for topic flare/100/flare/100/device/discovered
2018-10-02 07:13:53.648 INFO 1 --- [08b29c64da91ea3] a.c.b.m.mqtt.DeviceDiscoveredListener : Handling device discovered for flare: 100
2018-10-02 07:13:53.655 INFO 1 --- [08b29c64da91ea3] a.c.b.m.mqtt.DeviceDiscoveredListener : Successfully updated device 1411100 for 100
2018-10-02 07:13:53.655 INFO 1 --- [08b29c64da91ea3] a.c.b.marquee.mqtt.GenericMqttHandler : Publishing to topic marquee/marquee_28122702576940aaa08b29c64da91ea3/flare/100/device/updated
2018-10-02 07:13:53.655 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.MqttAsyncClient : marquee_28122702576940aaa08b29c64da91ea3: < topic=marquee/marquee_28122702576940aaa08b29c64da91ea3/flare/100/device/updated message=nulluserContext=null callback=null
2018-10-02 07:13:53.658 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.MqttAsyncClient : marquee_28122702576940aaa08b29c64da91ea3: <
2018-10-02 07:13:53.658 INFO 1 --- [08b29c64da91ea3] a.c.b.marquee.mqtt.GenericMqttHandler : Successfully published to topic marquee/marquee_28122702576940aaa08b29c64da91ea3/flare/100/device/updated
2018-10-02 07:13:53.658 INFO 1 --- [08b29c64da91ea3] a.c.b.marquee.mqtt.GenericMqttHandler : Successfully published to topic marquee/marquee_28122702576940aaa08b29c64da91ea3/flare/100/device/updated
2018-10-02 07:14:03.488 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,464,443,488
2018-10-02 07:16:13.666 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,464,573,665
2018-10-02 07:16:23.666 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,464,583,666
2018-10-02 07:16:33.666 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,464,593,666
2018-10-02 07:16:43.667 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,464,603,667
2018-10-02 07:16:53.667 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,464,613,667
2018-10-02 07:17:03.667 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,464,623,667
2018-10-02 07:17:13.667 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,464,633,667
2018-10-02 07:17:23.667 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,464,643,667
2018-10-02 07:17:33.668 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,464,653,668
2018-10-02 07:17:43.668 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,464,663,668
2018-10-02 07:17:53.669 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,464,673,669
2018-10-02 07:18:03.669 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,464,683,669
2018-10-02 07:18:13.669 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,464,693,669
2018-10-02 07:18:23.670 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,464,703,670
2018-10-02 07:18:33.670 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,464,713,670
2018-10-02 07:18:43.671 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,464,723,671
2018-10-02 07:18:53.671 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,464,733,671
2018-10-02 07:47:23.738 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,466,443,738
....
....
2018-10-02 07:47:33.739 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,466,453,739
2018-10-02 07:47:43.739 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,466,463,739
2018-10-02 07:47:53.740 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,466,473,739
2018-10-02 07:47:53.740 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,466,473,739
2018-10-02 07:48:03.740 DEBUG 1 --- [08b29c64da91ea3] o.e.paho.client.mqttv3.TimerPingSender : null: Check schedule at 1,538,466,483,740
2018-10-02 07:48:05.976 INFO 1 --- [ Thread-6] ConfigServletWebServerApplicationContext : Closing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@483bf400: startup date [Tue Oct 02 05:48:21 UTC 2018]; root of context hierarchy```
This is the log from the broker. As you can see, client Marquee last published is at 17:13:53 too, and didn't see it again until I restarted Marquee server.
```2018-10-02T07:13:52+00:00 [INFO] Client marquee_28122702576940aaa08b29c64da91ea3 published to topic: "marquee/marquee_28122702576940aaa08b29c64da91ea3/flare/100/device/updated"
2018-10-02T07:13:52+00:00 [INFO] Client marquee_28122702576940aaa08b29c64da91ea3 published to topic: "marquee/marquee_28122702576940aaa08b29c64da91ea3/flare/100/device/updated"
2018-10-02T07:13:52+00:00 [INFO] Client disconnected with id marquee_28122702576940aaa08b29c64da91ea3
2018-10-02T07:13:52+00:00 [INFO] Client marquee_28122702576940aaa08b29c64da91ea3 published to topic: "marquee/marquee_28122702576940aaa08b29c64da91ea3/flare/100/device/updated"
2018-10-02T07:13:52+00:00 [INFO] Client marquee_28122702576940aaa08b29c64da91ea3 published to topic: "marquee/marquee_28122702576940aaa08b29c64da91ea3/flare/100/device/updated"
2018-10-02T07:13:53+00:00 [INFO] Client connected with id marquee_28122702576940aaa08b29c64da91ea3
2018-10-02T07:13:53+00:00 [INFO] Client marquee_28122702576940aaa08b29c64da91ea3 published to topic: "marquee/marquee_28122702576940aaa08b29c64da91ea3/flare/100/device/updated"
2018-10-02T07:13:53+00:00 [INFO] Client marquee_28122702576940aaa08b29c64da91ea3 published to topic: "marquee/marquee_28122702576940aaa08b29c64da91ea3/flare/100/device/updated"
2018-10-02T07:13:53+00:00 [INFO] Client marquee_28122702576940aaa08b29c64da91ea3 published to topic: "marquee/marquee_28122702576940aaa08b29c64da91ea3/flare/100/device/updated"
2018-10-02T07:13:53+00:00 [INFO] Client marquee_28122702576940aaa08b29c64da91ea3 published to topic: "marquee/marquee_28122702576940aaa08b29c64da91ea3/flare/100/device/updated"
2018-10-02T07:13:53+00:00 [INFO] Client marquee_28122702576940aaa08b29c64da91ea3 published to topic: "marquee/marquee_28122702576940aaa08b29c64da91ea3/flare/100/device/updated"
2018-10-02T07:13:53+00:00 [INFO] Client marquee_28122702576940aaa08b29c64da91ea3 published to topic: "marquee/marquee_28122702576940aaa08b29c64da91ea3/flare/100/device/updated"
2018-10-02T07:13:53+00:00 [INFO] Client marquee_28122702576940aaa08b29c64da91ea3 published to topic: "marquee/marquee_28122702576940aaa08b29c64da91ea3/flare/100/device/updated"
2018-10-02T07:13:53+00:00 [INFO] Client marquee_28122702576940aaa08b29c64da91ea3 published to topic: "marquee/marquee_28122702576940aaa08b29c64da91ea3/flare/100/device/updated"
2018-10-02T07:13:54+00:00 [INFO] Client 100 published to topic: "flare/100/flare/100/device/discover/error"
2018-10-02T07:13:54+00:00 [INFO] Client 100 published to topic: "flare/100/flare/100/device/discovered"
2018-10-02T07:13:55+00:00 [INFO] Client 100 published to topic: "flare/100/flare/100/status"
2018-10-02T07:13:55+00:00 [INFO] Client 100 published to topic: "flare/100/flare/100/device/discovered"
...
```
Anyone has any suggestions please? this is the production issues and it already occurred a few times that's why I enabled the logging at DEBUG level like above, but still not sure what the cause of it is.
Thanks & regards
Thinh
Contributor guide
Assessment
This issue has not been assessed yet.