[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
Re: [paho-dev] Experiencing constant reconnects with paho client v1.1.1 and broker Active MQ 5.14.3

Hi everyone, James,

I tested with the Mosquitto broker and I am getting the same behavior.

Like explained before:
"sub" and "pub" being the ids for the paho clients in main app.
"paho1494930171596000000" and "paho1494930171987000000" being the randomly generated ids for the paho clients 3 and 4 in the test.

The mosquitto broker logs are:

1494930100: mosquitto version 1.4.10 (build date 2016-10-26 14:35:35+0000) starting
1494930100: Config loaded from /mosquitto/config/mosquitto.conf.
1494930100: Opening ipv4 listen socket on port 1883.
1494930100: Opening ipv6 listen socket on port 1883.
1494930171: New connection from xxx.xxx.xxx.xxx on port 1883.
1494930171: New client connected from xxx.xxx.xxx.xxx as paho1494930171596000000 (c0, k60).
1494930171: New connection from xxx.xxx.xxx.xxx on port 1883.
1494930171: New client connected from xxx.xxx.xxx.xxx as paho1494930171987000000 (c1, k60).
1494930173: New connection from xxx.xxx.xxx.xxx on port 1883.
1494930173: New client connected from xxx.xxx.xxx.xxx as sub (c0, k60).
1494930175: New connection from xxx.xxx.xxx.xxx on port 1883.
1494930175: New client connected from xxx.xxx.xxx.xxx as pub (c0, k60).
1494930182: Socket error on client sub, disconnecting.
1494930183: New connection from xxx.xxx.xxx.xxx on port 1883.
1494930183: Client sub disconnected.
1494930183: New client connected from xxx.xxx.xxx.xxx as sub (c0, k60).
1494930184: Socket error on client sub, disconnecting.
1494930185: New connection from xxx.xxx.xxx.xxx on port 1883.
1494930185: Client sub disconnected.
1494930185: New client connected from xxx.xxx.xxx.xxx as sub (c0, k60).
1494930185: Socket error on client sub, disconnecting.
1494930186: New connection from xxx.xxx.xxx.xxx on port 1883.
1494930186: Client sub disconnected.
1494930186: New client connected from xxx.xxx.xxx.xxx as sub (c0, k60).
1494930187: Socket error on client sub, disconnecting.
1494930188: New connection from xxx.xxx.xxx.xxx on port 1883.
1494930188: Client sub disconnected.
1494930188: New client connected from xxx.xxx.xxx.xxx as sub (c0, k60).
1494930189: Socket error on client sub, disconnecting.
1494930190: New connection from xxx.xxx.xxx.xxx on port 1883.
1494930190: Client sub disconnected.
1494930190: New client connected from xxx.xxx.xxx.xxx as sub (c0, k60).
1494930190: New connection from xxx.xxx.xxx.xxx on port 1883.
1494930190: Client sub already connected, closing old connection.
1494930190: Client sub disconnected.
1494930190: New client connected from xxx.xxx.xxx.xxx as sub (c0, k60).
1494930190: New connection from xxx.xxx.xxx.xxx on port 1883.
1494930190: Client pub already connected, closing old connection.
1494930190: Client pub disconnected.
1494930190: New client connected from xxx.xxx.xxx.xxx as pub (c0, k60).
1494930191: New connection from xxx.xxx.xxx.xxx on port 1883.
...

I also attached to the JVM running the test with VisualVM and it seems a lot of Paho threads are constantly spawned and then they finish immediately: Live: 77, Daemon: 46, Live peak: 84, Total started: 5,873. These leads to a lot of total started threads. They are always the same ones with names:
     MQTT Call: sub - 0ms running time, 1ms waiting time
     MQTT Snd: sub - 0ms running time, 1ms waiting time
     MQTT Rec: sub - 1ms running time, 0ms waiting time
     The same for pub.

Any ideas what could be happening? Could it be that my app somehow kills these threads? How could I further investigate that?

Also, just for my understanding of the Paho client internals, do these 3 threads per client map to the CommsCallback, CommsReceiver and CommsSender classes in the code?

Thanks,
M



On Mon, May 15, 2017 at 11:08 AM, Martin Eden <martineden131@xxxxxxxxx> wrote:
Hi everyone,

I am experiencing constant reconnects from my Paho MQTT subscriber and publisher clients running inside a JVM on my Mac talking to a Active MQ instance running in Virtual BOX also on my Mac.Â

It is an integration test where I am trying to test a simple app that runs two paho mqtt clients: a subscriber and a publisher. The subscriber subscribes to a topic, reads the messages via callback, processes them and then passes them to the publisher that will publish them to another topic. So this main app has 2 paho clients, separately instantiated like so (Scala code):

subscriber:
    val mqttClient = new MqttClient(brokerUrl, "sub", new MqttDefaultFilePersistence())
    val options = new MqttConnectOptions()
    options.setCleanSession(false)
    options.setAutomaticReconnect(true)
    client.setCallback(callback)
    client.connect(options)
    client.subscribe(topic, 1)


publisher:
    val mqttClient = new MqttClient(brokerUrl, "pub", new MemoryPersistence())
    val options = new MqttConnectOptions()
    options.setMaxInflight(maxInFlight)
    options.setAutomaticReconnect(true)
    mqttClient.connect(options)
    mqttClient.publish(key, new MqttMessage(value))


The point of the integration test is to verify that by enabling persistent session on the subscriber client (options.setCleanSession(false) and new MqttDefaultFilePersistence() above), we can consume the messages published to the topic during app downtime.

The test is simple:
- start main app.
- use a 3rd paho client (publisher) that publishes 1 message to the input topic.
- use a 4th paho client (subscriber) to check the expected message was published back to the output topic by the main app.
- kill app
- use the 3rd publisher paho client to publish 1 more message in the input topic.
- start app.
- use the 4th paho client (subscriber) to check the expected message was published back to the output topic by the main app.

The 3rd and 4th clients are instantiated by the test like so:
val mqttClient = new MqttClient(mqttBrokerUrl, MqttClient.generateClientId, new MemoryPersistence)

What happens is that all the messages get through as expected BUT the subscriber paho client, after the second start of the main app, continuously spits out:

2017-04-27 22:59:55 ERROR MQTTSource:64 - Connection lost for MqttClient with id [sub]; going to reconnect
Connection lost (32109) - java.io.EOFException
	at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:164)
	at java.lang.Thread.run(Thread.java:745)
Caused by: java.io.EOFException
	at java.io.DataInputStream.readByte(DataInputStream.java:267)
	at org.eclipse.paho.client.mqttv3.internal.wire.MqttInputStream.readMqttWireMessage(MqttInputStream.java:92)
	at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:116)
	... 1 more


The first time the app is started this does not happen! Only the second time!

Doing some digging around it seems people suggest this happens when you have two clients with the same id. This is not the case as all the ids are different. This is shown also in the Active MQ broker UI:
Name Remote Address Active Slow
paho1493328011500000000 tcp://192.168.99.1:58421 true false
sub tcp://192.168.99.1:59426 true false
pub tcp://192.168.99.1:59427 true false
paho1493328011993000000 tcp://192.168.99.1:58424 true false

"sub" and "pub" being the ids for the paho clients in main app.
"paho1493328011500000000" and "paho1493328011993000000" being the randomly generated ids for the paho clients 3 and 4 in the test.

Furthermore, the Active MQ server logs continuously print lines like these:
2017-04-27 21:44:48,487 | WARN  | Stealing link for clientId sub From Connection Transport Connection to: tcp://192.168.99.1:61766 | org.apache.activemq.broker.region.RegionBroker | ActiveMQ Transport: tcp:///192.168.99.1:61768@1883
2017-04-27 21:44:48,832 | WARN  | Stealing link for clientId pub From Connection Transport Connection to: tcp://192.168.99.1:61767 | org.apache.activemq.broker.region.RegionBroker | ActiveMQ Transport: tcp:///192.168.99.1:61769@1883
2017-04-27 21:44:49,497 | WARN  | Stealing link for clientId sub From Connection Transport Connection to: tcp://192.168.99.1:61768 | org.apache.activemq.broker.region.RegionBroker 
...


So it seems there is constant link stealing between the paho clients in the main app with ids "sub" and "pub".

Can anyone shed light on this behavior? Why is it happening? It does not seem normal. Why does it happen if the ids are different? How can I prevent it?

Sorry for the long message. Any help is much appreciated.