Intermittent hang in Paho client when application is connecting.(Using Paho client java, we are trying run test with IBM MQ MQTT service. Test tries to connect many client like 50 or 500 connections, 5000 connections and each connection tries to publish and subscribe)

[shivaprasaddn]

Using Paho client java, we are trying run test with IBM MQ MQTT service. Test tries to connect many client like 50 or 500 connections, 5000 connections and each connection tries to publish and subscribes few messages . Sometime we see hang in Paho client when application is connecting. Its intermittent problem .

Environment details :-

Paho Client Version :- Paho Client Mqttv3-1.2.5
OS :- Red Hat Enterprise Linux 9.2

Details :- Test tries to connect many client like 50 tries to publish and subscribes few messages .
From our test log, we see 49 application have connected(Searching [CONNECTED] in the java.stdout, can see 49 have connected (xr9client1 to xr9client50)), one application xr9client7 does not show as CONNECTED
[CONNECTED]

`From our MQTT log event. we see the following last entries for xr9client7 application. We do not see any entries that say "state=CONNECTED" for xr9client7. Other application has "state=CONNECTED".

11:14:41.431 62899:271 org.eclipse.paho.client.mqttv3.internal.CommsTokenStore saveToken xr9client7: key=Con message=CONNECT clientId xr9client7 keepAliveInterval 1800
11:14:41.431 62899:271 org.eclipse.paho.client.mqttv3.internal.CommsTokenStore saveToken xr9client7: key=Con message=CONNECT clientId xr9client7 keepAliveInterval 1800
11:14:41.432 62899:271 org.eclipse.paho.client.mqttv3.internal.CommsTokenStore saveToken xr9client7: key=Con token=org.eclipse.paho.client.mqttv3.MqttToken@6496d4a3
11:14:41.433 62899:271 org.eclipse.paho.client.mqttv3.internal.TCPNetworkModule start xr9client7: connect to host 127.0.0.1 port 18,006 timeout 30,000
11:14:41.433 62899:271 org.eclipse.paho.client.mqttv3.internal.CommsReceiver start xr9client7: starting
11:14:41.435 62899:280 org.eclipse.paho.client.mqttv3.internal.CommsReceiver run xr9client7: network read message
11:14:41.403 62899:227 org.eclipse.paho.client.mqttv3.internal.CommsCallback run xr9client7: notify spaceAvailable
11:14:41.537 62899:307 org.eclipse.paho.client.mqttv3.internal.ClientState get xr9client7: wait for new work or for space in the inflight window
11:14:42.440 62899:280 org.eclipse.paho.client.mqttv3.internal.CommsReceiver run xr9client7: network read message
11:14:43.442 62899:280 org.eclipse.paho.client.mqttv3.internal.CommsReceiver run xr9client7: network read message
11:14:44.443 62899:280 org.eclipse.paho.client.mqttv3.internal.CommsReceiver run xr9client7: network read message

One of call stack from javacore shows it is stuck in org.eclipse.paho.client.mqttv3.internal.Token waitForCompletion

3XMTHREADINFO "ThreadPool46" J9VMThread:0x00000000002C4800, omrthread_t:0x00007FD6A87437B0, java/lang/Thread:0x00000000E007D660, state:CW, prio=5
3XMJAVALTHREAD (java/lang/Thread getId:0x42, isDaemon:false)
3XMTHREADINFO1 (native thread ID:0xF5F5, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000181)
3XMTHREADINFO2 (native stack address range from:0x00007FD657EBC000, to:0x00007FD657EFC000, size:0x40000)
3XMCPUTIME CPU usage total: 0.004097063 secs, current category="Application"
3XMTHREADBLOCK Waiting on: java/lang/Object@0x00000000E00B09A8 Owned by:
3XMHEAPALLOC Heap bytes allocated since last GC cycle=0 (0x0)
3XMTHREADINFO3 Java callstack:
4XESTACKTRACE at java/lang/Object.wait(Native Method)
4XESTACKTRACE at java/lang/Object.wait(Object.java:189)
4XESTACKTRACE at org/eclipse/paho/client/mqttv3/internal/Token.waitForResponse(Token.java:143)
4XESTACKTRACE at org/eclipse/paho/client/mqttv3/internal/Token.waitForCompletion(Token.java:108)
4XESTACKTRACE at org/eclipse/paho/client/mqttv3/MqttToken.waitForCompletion(MqttToken.java:67)
4XESTACKTRACE at org/eclipse/paho/client/mqttv3/MqttClient.connect(MqttClient.java:331)
4XESTACKTRACE at com/ibm/mqst/mqxr/svt/recovery/Client.connect(Client.java:68)
4XESTACKTRACE at com/ibm/mqst/mqxr/svt/recovery/ClientManager.connectClient(ClientManager.java:357)
4XESTACKTRACE at com/ibm/mqst/mqxr/svt/recovery/ClientManager.threadPoolInvoke(ClientManager.java:310)
4XESTACKTRACE at com/ibm/mqst/mqxr/svt/recovery/ClientManager.threadPoolInvoke(ClientManager.java:42)
4XESTACKTRACE at com/ibm/mqst/mqxr/svt/recovery/ThreadPool.run(ThreadPool.java:149)
4XESTACKTRACE at java/lang/Thread.run(Thread.java:825)
3XMTHREADINFO3 Native callstack:
4XENATIVESTACK (0x00007FD6AD6DC2D2 [libj9prt29.so+0x5a2d2])
4XENATIVESTACK (0x00007FD6AD6A90F3 [libj9prt29.so+0x270f3])
4XENATIVESTACK (0x00007FD6AD6DC34E [libj9prt29.so+0x5a34e])
4XENATIVESTACK (0x00007FD6AD6DC444 [libj9prt29.so+0x5a444])
4XENATIVESTACK (0x00007FD6AD6A90F3 [libj9prt29.so+0x270f3])
4XENATIVESTACK (0x00007FD6AD6DC1AB [libj9prt29.so+0x5a1ab])
4XENATIVESTACK (0x00007FD6AD6D85BF [libj9prt29.so+0x565bf])
4XENATIVESTACK (0x00007FD6AFC39630 [libpthread.so.0+0xf630])
4XENATIVESTACK pthread_cond_wait+0xc3 (0x00007FD6AFC35A33 [libpthread.so.0+0xba33])
4XENATIVESTACK omrthread_monitor_wait_interruptable+0x48b (0x00007FD6ADB1F32B [libj9thr29.so+0xb32b])
4XENATIVESTACK (0x00007FD6ADE08345 [libj9vm29.so+0xd9345])
4XENATIVESTACK (0x00007FD6ADD452FB [libj9vm29.so+0x162fb])
4XENATIVESTACK (0x00007FD6ADD41F70 [libj9vm29.so+0x12f70])
4XENATIVESTACK (0x00007FD6ADE12342 [libj9vm29.so+0xe3342])
NULL`

[shivaprasaddn]

javacoreAndFrameWorkLog.zip