Hi,
I'm getting a hang in an application using the Async Client. Here's
what's going on:
The application issues an HTTPS request to a host and gets an error
(timeout or other). The operation is retried a couple of times just to
make sure. After a couple of failures, we try to close the connection.
This is where it hangs.
I've done a thread dump of the application and it appears as this:
"pool-1497-thread-1" prio=10 tid=0x00002ba035214000 nid=0x1099 in
Object.wait() [0x00002ba05079a000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Thread.join(Unknown Source)
- locked <0x0000000528d668e8> (a java.lang.Thread)
at java.lang.Thread.join(Unknown Source)
at
org.apache.http.impl.nio.client.CloseableHttpAsyncClientBase.close(CloseableHttpAsyncClientBase.java:104)
at
com.servicemesh.io.http.impl.DefaultHttpClient.close(DefaultHttpClient.java:181)
I've also reproduced this in Eclipse and found the thread at the same
condition. The code appears to be:
@Override
public void close() {
if (this.status.compareAndSet(Status.ACTIVE, Status.STOPPED)) {
if (this.reactorThread != null) {
try {
this.connmgr.shutdown();
} catch (IOException ex) {
this.log.error("I/O error shutting down connection manager", ex);
}
try {
this.reactorThread.join(); <---------------------------
} catch (final InterruptedException ex) {
Thread.currentThread().interrupt();
}
}
}
}
At the "this.reactorThread.join()" call.
I turned on the HTTP logging and have this:
2016-01-22 14:24:24,837 | DEBUG | vcloudDirector |
MainClientExec | 58 - com.servicemesh.io - 1.0.0.0 |
[exchange: 1] start execution
2016-01-22 14:24:24,843 | DEBUG | vcloudDirector |
RequestAddCookies | 58 - com.servicemesh.io - 1.0.0.0 |
CookieSpec selected: default
2016-01-22 14:24:24,850 | DEBUG | vcloudDirector |
RequestAuthCache | 58 - com.servicemesh.io - 1.0.0.0 |
Auth cache not set in the context
2016-01-22 14:24:24,850 | DEBUG | vcloudDirector |
InternalHttpAsyncClient | 58 - com.servicemesh.io - 1.0.0.0 |
[exchange: 1] Request connection for {s}->https://www.redpt.com:443
2016-01-22 14:24:24,851 | DEBUG | vcloudDirector |
lingNHttpClientConnectionManager | 58 - com.servicemesh.io - 1.0.0.0 |
Connection request: [route: {s}->https://www.redpt.com:443][total kept
alive: 0; route allocated: 0 of 2; total allocated: 0 of 20]
2016-01-22 14:24:25,101 | DEBUG | I/O dispatcher 1 |
lingNHttpClientConnectionManager | 58 - com.servicemesh.io - 1.0.0.0 |
Connection leased: [id: http-outgoing-0][route:
{s}->https://www.redpt.com:443][total kept alive: 0; route allocated: 1
of 2; total allocated: 1 of 20]
2016-01-22 14:24:25,101 | DEBUG | I/O dispatcher 1 |
InternalHttpAsyncClient | 58 - com.servicemesh.io - 1.0.0.0 |
[exchange: 1] Connection allocated: CPoolProxy{http-outgoing-0 [ACTIVE]}
2016-01-22 14:24:25,102 | DEBUG | I/O dispatcher 1 |
ManagedNHttpClientConnectionImpl | 58 - com.servicemesh.io - 1.0.0.0 |
http-outgoing-0 192.168.1.4:64681<->50.63.202.56:443[ACTIVE][r:]: Set
attribute http.nio.exchange-handler
2016-01-22 14:24:25,102 | DEBUG | I/O dispatcher 1 |
ManagedNHttpClientConnectionImpl | 58 - com.servicemesh.io - 1.0.0.0 |
http-outgoing-0 192.168.1.4:64681<->50.63.202.56:443[ACTIVE][rw:]: Event
set [w]
2016-01-22 14:24:25,102 | DEBUG | I/O dispatcher 1 |
ManagedNHttpClientConnectionImpl | 58 - com.servicemesh.io - 1.0.0.0 |
http-outgoing-0 192.168.1.4:64681<->50.63.202.56:443[ACTIVE][rw:]: Set
timeout 0
2016-01-22 14:24:25,102 | DEBUG | I/O dispatcher 1 |
InternalIODispatch | 58 - com.servicemesh.io - 1.0.0.0 |
http-outgoing-0 [ACTIVE]: Connected
2016-01-22 14:24:25,103 | DEBUG | I/O dispatcher 1 |
ManagedNHttpClientConnectionImpl | 58 - com.servicemesh.io - 1.0.0.0 |
http-outgoing-0 192.168.1.4:64681<->50.63.202.56:443[ACTIVE][rw:]: Set
attribute http.nio.http-exchange-state
2016-01-22 14:24:25,103 | DEBUG | I/O dispatcher 1 |
InternalHttpAsyncClient | 58 - com.servicemesh.io - 1.0.0.0 |
Start connection routing
2016-01-22 14:24:25,111 | DEBUG | I/O dispatcher 1 |
ManagedNHttpClientConnectionImpl | 58 - com.servicemesh.io - 1.0.0.0 |
http-outgoing-0 Upgrade session
192.168.1.4:64681<->50.63.202.56:443[ACTIVE][rw:][ACTIVE][rw][NEED_UNWRAP][0][0][242][0]
2016-01-22 14:24:25,112 | DEBUG | I/O dispatcher 1 |
MainClientExec | 58 - com.servicemesh.io - 1.0.0.0 |
Connection route established
2016-01-22 14:24:25,112 | DEBUG | I/O dispatcher 1 |
MainClientExec | 58 - com.servicemesh.io - 1.0.0.0 |
[exchange: 1] Attempt 1 to execute request
2016-01-22 14:24:25,112 | DEBUG | I/O dispatcher 1 |
MainClientExec | 58 - com.servicemesh.io - 1.0.0.0 |
Target auth state: UNCHALLENGED
2016-01-22 14:24:25,112 | DEBUG | I/O dispatcher 1 |
MainClientExec | 58 - com.servicemesh.io - 1.0.0.0 |
Proxy auth state: UNCHALLENGED
2016-01-22 14:24:25,112 | DEBUG | I/O dispatcher 1 |
ManagedNHttpClientConnectionImpl | 58 - com.servicemesh.io - 1.0.0.0 |
http-outgoing-0
192.168.1.4:64681<->50.63.202.56:443[ACTIVE][rw:][ACTIVE][rw][NEED_UNWRAP][0][0][242][0]:
Set timeout 50000
2016-01-22 14:24:25,112 | DEBUG | I/O dispatcher 1 |
headers | 58 - com.servicemesh.io - 1.0.0.0 |
http-outgoing-0 >> GET /api/versions HTTP/1.1
2016-01-22 14:24:25,113 | DEBUG | I/O dispatcher 1 |
headers | 58 - com.servicemesh.io - 1.0.0.0 |
http-outgoing-0 >> Accept: application/*+xml;version=5.5
2016-01-22 14:24:25,113 | DEBUG | I/O dispatcher 1 |
headers | 58 - com.servicemesh.io - 1.0.0.0 |
http-outgoing-0 >> Host: www.redpt.com
2016-01-22 14:24:25,113 | DEBUG | I/O dispatcher 1 |
headers | 58 - com.servicemesh.io - 1.0.0.0 |
http-outgoing-0 >> Connection: Keep-Alive
2016-01-22 14:24:25,113 | DEBUG | I/O dispatcher 1 |
headers | 58 - com.servicemesh.io - 1.0.0.0 |
http-outgoing-0 >> User-Agent: Apache-HttpAsyncClient/4.1 (Java/1.8.0_60)
2016-01-22 14:24:25,113 | DEBUG | I/O dispatcher 1 |
ManagedNHttpClientConnectionImpl | 58 - com.servicemesh.io - 1.0.0.0 |
http-outgoing-0
192.168.1.4:64681<->50.63.202.56:443[ACTIVE][rw:][ACTIVE][rw][NEED_UNWRAP][0][0][242][0]:
Event set [w]
2016-01-22 14:24:25,113 | DEBUG | I/O dispatcher 1 |
MainClientExec | 58 - com.servicemesh.io - 1.0.0.0 |
[exchange: 1] Request completed
2016-01-22 14:24:25,150 | DEBUG | I/O dispatcher 1 |
InternalIODispatch | 58 - com.servicemesh.io - 1.0.0.0 |
http-outgoing-0 [ACTIVE] Exception
at
org.apache.http.nio.reactor.ssl.SSLIOSession.receiveEncryptedData(SSLIOSession.java:478)[58:com.servicemesh.io:1.0.0.0]
at
org.apache.http.nio.reactor.ssl.SSLIOSession.isAppInputReady(SSLIOSession.java:576)[58:com.servicemesh.io:1.0.0.0]
at
org.apache.http.impl.nio.reactor.AbstractIODispatch.inputReady(AbstractIODispatch.java:122)[58:com.servicemesh.io:1.0.0.0]
at
org.apache.http.impl.nio.reactor.BaseIOReactor.readable(BaseIOReactor.java:164)[58:com.servicemesh.io:1.0.0.0]
at
org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(AbstractIOReactor.java:339)[58:com.servicemesh.io:1.0.0.0]
at
org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(AbstractIOReactor.java:317)[58:com.servicemesh.io:1.0.0.0]
at
org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:278)[58:com.servicemesh.io:1.0.0.0]
at
org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:106)[58:com.servicemesh.io:1.0.0.0]
at
org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:590)[58:com.servicemesh.io:1.0.0.0]
2016-01-22 14:24:25,152 | DEBUG | I/O dispatcher 1 |
ManagedNHttpClientConnectionImpl | 58 - com.servicemesh.io - 1.0.0.0 |
http-outgoing-0
192.168.1.4:64681<->50.63.202.56:443[ACTIVE][r:r][ACTIVE][rw][NEED_UNWRAP][0][0][0][0]:
Shutdown
2016-01-22 14:24:25,153 | DEBUG | I/O dispatcher 1 |
ManagedNHttpClientConnectionImpl | 58 - com.servicemesh.io - 1.0.0.0 |
http-outgoing-0
0.0.0.0:64681<->50.63.202.56:443[CLOSED][][CLOSED][rw][NEED_UNWRAP][0][0][0][0]:
Shutdown
2016-01-22 14:24:25,153 | DEBUG | I/O dispatcher 1 |
InternalHttpAsyncClient | 58 - com.servicemesh.io - 1.0.0.0 |
[exchange: 1] connection aborted
2016-01-22 14:24:25,153 | DEBUG | I/O dispatcher 1 |
lingNHttpClientConnectionManager | 58 - com.servicemesh.io - 1.0.0.0 |
Releasing connection: [id: http-outgoing-0][route:
{s}->https://www.redpt.com:443][total kept alive: 0; route allocated: 1
of 2; total allocated: 1 of 20]
2016-01-22 14:24:25,153 | DEBUG | I/O dispatcher 1 |
lingNHttpClientConnectionManager | 58 - com.servicemesh.io - 1.0.0.0 |
Connection released: [id: http-outgoing-0][route:
{s}->https://www.redpt.com:443][total kept alive: 0; route allocated: 0
of 2; total allocated: 0 of 20]
2016-01-22 14:24:25,155 | DEBUG | I/O dispatcher 1 |
MainClientExec | 58 - com.servicemesh.io - 1.0.0.0 |
[exchange: 2] start execution
2016-01-22 14:24:25,155 | DEBUG | I/O dispatcher 1 |
RequestAddCookies | 58 - com.servicemesh.io - 1.0.0.0 |
CookieSpec selected: default
2016-01-22 14:24:25,156 | DEBUG | I/O dispatcher 1 |
RequestAuthCache | 58 - com.servicemesh.io - 1.0.0.0 |
Auth cache not set in the context
2016-01-22 14:24:25,156 | DEBUG | I/O dispatcher 1 |
InternalHttpAsyncClient | 58 - com.servicemesh.io - 1.0.0.0 |
[exchange: 2] Request connection for {s}->https://www.redpt.com:443
2016-01-22 14:24:25,156 | DEBUG | I/O dispatcher 1 |
lingNHttpClientConnectionManager | 58 - com.servicemesh.io - 1.0.0.0 |
Connection request: [route: {s}->https://www.redpt.com:443][total kept
alive: 0; route allocated: 0 of 2; total allocated: 0 of 20]
2016-01-22 14:24:25,157 | DEBUG | I/O dispatcher 1 |
InternalIODispatch | 58 - com.servicemesh.io - 1.0.0.0 |
http-outgoing-0 [CLOSED]: Disconnected
2016-01-22 14:25:40,672 | DEBUG | pool-39-thread-1 |
lingNHttpClientConnectionManager | 58 - com.servicemesh.io - 1.0.0.0 |
Connection request failed
at
org.apache.http.impl.nio.reactor.DefaultConnectingIOReactor.processEvent(DefaultConnectingIOReactor.java:173)[58:com.servicemesh.io:1.0.0.0]
at
org.apache.http.impl.nio.reactor.DefaultConnectingIOReactor.processEvents(DefaultConnectingIOReactor.java:147)[58:com.servicemesh.io:1.0.0.0]
at
org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor.execute(AbstractMultiworkerIOReactor.java:350)[58:com.servicemesh.io:1.0.0.0]
at
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager.execute(PoolingNHttpClientConnectionManager.java:191)[58:com.servicemesh.io:1.0.0.0]
at
org.apache.http.impl.nio.client.CloseableHttpAsyncClientBase$1.run(CloseableHttpAsyncClientBase.java:64)[58:com.servicemesh.io:1.0.0.0]
2016-01-22 14:25:40,673 | DEBUG | pool-39-thread-1 |
InternalHttpAsyncClient | 58 - com.servicemesh.io - 1.0.0.0 |
[exchange: 2] connection request failed
2016-01-22 14:25:40,674 | DEBUG | pool-39-thread-1 |
MainClientExec | 58 - com.servicemesh.io - 1.0.0.0 |
[exchange: 3] start execution
2016-01-22 14:25:40,674 | DEBUG | pool-39-thread-1 |
RequestAddCookies | 58 - com.servicemesh.io - 1.0.0.0 |
CookieSpec selected: default
2016-01-22 14:25:40,674 | DEBUG | pool-39-thread-1 |
RequestAuthCache | 58 - com.servicemesh.io - 1.0.0.0 |
Auth cache not set in the context
2016-01-22 14:25:40,674 | DEBUG | pool-39-thread-1 |
InternalHttpAsyncClient | 58 - com.servicemesh.io - 1.0.0.0 |
[exchange: 3] Request connection for {s}->https://www.redpt.com:443
2016-01-22 14:25:40,674 | DEBUG | pool-39-thread-1 |
lingNHttpClientConnectionManager | 58 - com.servicemesh.io - 1.0.0.0 |
Connection request: [route: {s}->https://www.redpt.com:443][total kept
alive: 0; route allocated: 0 of 2; total allocated: 0 of 20]
2016-01-22 14:26:55,902 | DEBUG | pool-39-thread-1 |
lingNHttpClientConnectionManager | 58 - com.servicemesh.io - 1.0.0.0 |
Connection request failed
at
org.apache.http.impl.nio.reactor.DefaultConnectingIOReactor.processEvent(DefaultConnectingIOReactor.java:173)[58:com.servicemesh.io:1.0.0.0]
at
org.apache.http.impl.nio.reactor.DefaultConnectingIOReactor.processEvents(DefaultConnectingIOReactor.java:147)[58:com.servicemesh.io:1.0.0.0]
at
org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor.execute(AbstractMultiworkerIOReactor.java:350)[58:com.servicemesh.io:1.0.0.0]
at
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager.execute(PoolingNHttpClientConnectionManager.java:191)[58:com.servicemesh.io:1.0.0.0]
at
org.apache.http.impl.nio.client.CloseableHttpAsyncClientBase$1.run(CloseableHttpAsyncClientBase.java:64)[58:com.servicemesh.io:1.0.0.0]
2016-01-22 14:26:55,902 | DEBUG | pool-39-thread-1 |
InternalHttpAsyncClient | 58 - com.servicemesh.io - 1.0.0.0 |
[exchange: 3] connection request failed
2016-01-22 14:31:24,402 | DEBUG | pool-39-thread-1 |
lingNHttpClientConnectionManager | 58 - com.servicemesh.io - 1.0.0.0 |
Connection manager is shutting down
2016-01-22 14:31:26,427 | DEBUG | pool-39-thread-1 |
lingNHttpClientConnectionManager | 58 - com.servicemesh.io - 1.0.0.0 |
Connection manager shut down
So I guess my question is - why is the reactor thread not shutting
down? Is there something I should be testing here before I close the
connection? What additional troubleshooting should I do?
We're using:
httpcore-nio-4.4.1.jar
httpasyncclient-4.1.jar
httpclient-4.4.1.jar
httpcore-4.4.1.jar
Thanks in advance,
Mark
