You are viewing a plain text version of this content. The canonical link for it is here.
Posted to httpclient-users@hc.apache.org by Mark Johnson <mj...@gmail.com> on 2016/01/23 00:06:34 UTC
Close Hang
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
Re: Close Hang
Posted by Mark Johnson <mj...@gmail.com>.
Hi,
I can reproduce this with our (large) application by trying to send an
HTTPS request to a host that doesn't support the connection (really,
just pointing to a bad host - one that exists but is not correct). I'll
see if I can put together a small test program.
Thanks,
Mark
On 1/25/2016 9:26 AM, Oleg Kalnichevski wrote:
> On Fri, 2016-01-22 at 17:06 -0600, Mark Johnson wrote:
>> 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:
>>
> Hi Mark
>
> Can this issue be reproduced with a test case?
>
> Oleg
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> For additional commands, e-mail: httpclient-users-help@hc.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
Re: Close Hang
Posted by Oleg Kalnichevski <ol...@apache.org>.
On Wed, 2016-01-27 at 08:44 -0600, Mark Johnson wrote:
> Hi Oleg,
>
> Yes, we're shutting down the client from a callback in the actual
> application. The design of the program is a state machine that issues
> requests and processes the responses. If there's a failure during the
> process (received via the failure() callback) we terminate the state
> machine and part of that process is closing the client.
>
But what for? HttpAsyncClient instances are expensive and, more
importantly, stateless. Unless you also intent to shut down the VM it
seems unreasonable to throw away the client simply because there was an
I/O error on one of connections.
Oleg
> We've added code, as a workaround, to spawn a temporary worker thread to
> close the connection. That has worked. So if there's no solution to
> the original problem, we have a way to get around this.
>
> Thanks again,
> Mark
>
>
> On 1/27/2016 3:38 AM, Oleg Kalnichevski wrote:
> > On Tue, 2016-01-26 at 13:30 -0600, Mark Johnson wrote:
> >> Hi Oleg,
> >>
> >> Below is a program that reproduces the hang. It might take a couple of
> >> runs to make this happen - it depends on what thread the callback is
> >> generated on. If it's on the IO Dispatcher thread, we can close the
> >> connection on that thread also and there's no problem. If the callback
> >> comes on the pool-thread the program hangs. The stack trace of the
> >> pool-thread when this happens looks like this:
> >>
> >> Thread [pool-1-thread] (Suspended) <-- I paused it in the debugger
> >> but this is where it stays
> >> owns: SessionRequestImpl (id=44)
> >> waiting for: Thread (id=21)
> >> Object.wait(long)
> >> Thread.join(long)
> >> Thread.join()
> >> InternalHttpAsyncClient(ClosableHttpAsyncClientBase).close()
> >> Testprog$Callback.failed(Exception)
> >> etc.
> > ...
> >
> >> @Override
> >>
> >> public void cancelled() {
> >>
> >> Thread t = Thread.currentThread();
> >>
> >> System.out.println(t.getName() + ": " + "Request cancelled");
> >>
> >> try {
> >>
> >> System.out.println(t.getName() + ": " + "Closing client connection");
> >>
> >> _httpclient.close();
> >>
> >> } catch (Exception ex) {
> >>
> >> System.out.println(t.getName() + ": " + ex.getMessage());
> >>
> >> }
> >>
> >> _latch.countDown();
> >>
> >> }
> >>
> > Good Lord! You are shutting down the client from a callback. Is there a
> > good reason for that?
> >
> > Regardless I'll see if there is a way to avoid a deadlock here.
> >
> > Thanks for the reproducer.
> >
> > Oleg
> >
> >
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> > For additional commands, e-mail: httpclient-users-help@hc.apache.org
> >
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> For additional commands, e-mail: httpclient-users-help@hc.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
Re: Close Hang
Posted by Mark Johnson <mj...@gmail.com>.
Hi Oleg,
Yes, we're shutting down the client from a callback in the actual
application. The design of the program is a state machine that issues
requests and processes the responses. If there's a failure during the
process (received via the failure() callback) we terminate the state
machine and part of that process is closing the client.
We've added code, as a workaround, to spawn a temporary worker thread to
close the connection. That has worked. So if there's no solution to
the original problem, we have a way to get around this.
Thanks again,
Mark
On 1/27/2016 3:38 AM, Oleg Kalnichevski wrote:
> On Tue, 2016-01-26 at 13:30 -0600, Mark Johnson wrote:
>> Hi Oleg,
>>
>> Below is a program that reproduces the hang. It might take a couple of
>> runs to make this happen - it depends on what thread the callback is
>> generated on. If it's on the IO Dispatcher thread, we can close the
>> connection on that thread also and there's no problem. If the callback
>> comes on the pool-thread the program hangs. The stack trace of the
>> pool-thread when this happens looks like this:
>>
>> Thread [pool-1-thread] (Suspended) <-- I paused it in the debugger
>> but this is where it stays
>> owns: SessionRequestImpl (id=44)
>> waiting for: Thread (id=21)
>> Object.wait(long)
>> Thread.join(long)
>> Thread.join()
>> InternalHttpAsyncClient(ClosableHttpAsyncClientBase).close()
>> Testprog$Callback.failed(Exception)
>> etc.
> ...
>
>> @Override
>>
>> public void cancelled() {
>>
>> Thread t = Thread.currentThread();
>>
>> System.out.println(t.getName() + ": " + "Request cancelled");
>>
>> try {
>>
>> System.out.println(t.getName() + ": " + "Closing client connection");
>>
>> _httpclient.close();
>>
>> } catch (Exception ex) {
>>
>> System.out.println(t.getName() + ": " + ex.getMessage());
>>
>> }
>>
>> _latch.countDown();
>>
>> }
>>
> Good Lord! You are shutting down the client from a callback. Is there a
> good reason for that?
>
> Regardless I'll see if there is a way to avoid a deadlock here.
>
> Thanks for the reproducer.
>
> Oleg
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> For additional commands, e-mail: httpclient-users-help@hc.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
Re: Close Hang
Posted by Oleg Kalnichevski <ol...@apache.org>.
On Tue, 2016-01-26 at 13:30 -0600, Mark Johnson wrote:
> Hi Oleg,
>
> Below is a program that reproduces the hang. It might take a couple of
> runs to make this happen - it depends on what thread the callback is
> generated on. If it's on the IO Dispatcher thread, we can close the
> connection on that thread also and there's no problem. If the callback
> comes on the pool-thread the program hangs. The stack trace of the
> pool-thread when this happens looks like this:
>
> Thread [pool-1-thread] (Suspended) <-- I paused it in the debugger
> but this is where it stays
> owns: SessionRequestImpl (id=44)
> waiting for: Thread (id=21)
> Object.wait(long)
> Thread.join(long)
> Thread.join()
> InternalHttpAsyncClient(ClosableHttpAsyncClientBase).close()
> Testprog$Callback.failed(Exception)
> etc.
...
> @Override
>
> public void cancelled() {
>
> Thread t = Thread.currentThread();
>
> System.out.println(t.getName() + ": " + "Request cancelled");
>
> try {
>
> System.out.println(t.getName() + ": " + "Closing client connection");
>
> _httpclient.close();
>
> } catch (Exception ex) {
>
> System.out.println(t.getName() + ": " + ex.getMessage());
>
> }
>
> _latch.countDown();
>
> }
>
Good Lord! You are shutting down the client from a callback. Is there a
good reason for that?
Regardless I'll see if there is a way to avoid a deadlock here.
Thanks for the reproducer.
Oleg
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
Re: Close Hang
Posted by Mark Johnson <mj...@gmail.com>.
Hi Oleg,
Below is a program that reproduces the hang. It might take a couple of
runs to make this happen - it depends on what thread the callback is
generated on. If it's on the IO Dispatcher thread, we can close the
connection on that thread also and there's no problem. If the callback
comes on the pool-thread the program hangs. The stack trace of the
pool-thread when this happens looks like this:
Thread [pool-1-thread] (Suspended) <-- I paused it in the debugger
but this is where it stays
owns: SessionRequestImpl (id=44)
waiting for: Thread (id=21)
Object.wait(long)
Thread.join(long)
Thread.join()
InternalHttpAsyncClient(ClosableHttpAsyncClientBase).close()
Testprog$Callback.failed(Exception)
etc.
Here's the example program:
package httptest;
import java.util.concurrent.CountDownLatch;
import org.apache.http.HttpResponse;
import org.apache.http.client.methods.HttpGet;
import org.apache.http.concurrent.FutureCallback;
import org.apache.http.impl.nio.client.CloseableHttpAsyncClient;
import org.apache.http.impl.nio.client.HttpAsyncClients;
public class Testprog {
public void run() throws Exception
{
Thread t = Thread.currentThread();
System.out.println(t.getName() + ": " + "Start of test program");
CloseableHttpAsyncClient httpclient = HttpAsyncClients.createDefault();
try {
httpclient.start();
try {
CountDownLatch latch = new CountDownLatch(1);
finalHttpGet request= newHttpGet("https://www.redpt.com/api/versions/");
Callback cb = new Callback(httpclient, request, latch);
httpclient.execute(request, cb);
System.out.println(t.getName() + ": " + "Waiting for requests to complete");
latch.await();
System.out.println(t.getName() + ": " + "Requests are complete");
} catch (Exception ex) {
System.out.println(t.getName() + ": " + ex.getMessage());
}
} finally{
//httpclient.close(); <-- This works if it's done here
}
System.out.println(t.getName() + ": " + "End of test program");
}
public static void main(final String[] args) throws Exception {
Testprog prog = new Testprog();
prog.run();
}
private class Callback implements FutureCallback<HttpResponse>
{
CloseableHttpAsyncClient _httpclient;
HttpGet _request;
CountDownLatch _latch;
public Callback(CloseableHttpAsyncClient httpclient, HttpGet request,
CountDownLatch latch)
{
_httpclient= httpclient;
_request= request;
_latch = latch;
}
@Override
public void cancelled() {
Thread t = Thread.currentThread();
System.out.println(t.getName() + ": " + "Request cancelled");
try {
System.out.println(t.getName() + ": " + "Closing client connection");
_httpclient.close();
} catch (Exception ex) {
System.out.println(t.getName() + ": " + ex.getMessage());
}
_latch.countDown();
}
@Override
public void completed(HttpResponse response) {
Thread t = Thread.currentThread();
System.out.println(t.getName() + ": " + "Request completed");
System.out.println(t.getName() + ": " + _request.getRequestLine()+ " ->
" + response.getStatusLine());
try {
System.out.println(t.getName() + ": " + "Closing client connection");
_httpclient.close();
} catch (Exception ex) {
System.out.println(t.getName() + ": " + ex.getMessage());
}
_latch.countDown();
}
@Override
public void failed(Exception ex) {
Thread t = Thread.currentThread();
System.out.println(t.getName() + ": " + "Request failed");
System.out.println(t.getName() + ": " + _request.getRequestLine() + " ->
" + ex.getMessage());
try {
System.out.println(t.getName() + ": " + "Closing client connection");
_httpclient.close();
} catch (Exception ex1) {
System.out.println(t.getName() + ": " + ex1.getMessage());
}
_latch.countDown();
}
}
}
Looks like my formatting got messed up.
Thanks again,
Mark
On 1/26/2016 12:31 PM, Oleg Kalnichevski wrote:
> On January 26, 2016 6:01:59 PM GMT+01:00, Mark Johnson <mj...@gmail.com> wrote:
>> Hi,
>>
>> We're still trying to put together a concise example but have
>> determined
>> some information and a work-around. Here's the scenario that happens:
>>
>> Thread:
>> Start-up : Creates the Http connection; This starts an IO
>> Dispatcher
>> 3 thread and a pool-41-thread-1 (for example). The Http request is now
>>
>> issued
>>
>> pool-41-thread-1: Gets the error (timeout or connection closed by
>> peer). This Http request is retried
>> pool-41-thread-1: Gets the error again; The operation is retried
>> again.
>> pool-41-thread-1: Gets the error again; The connection is closed
>> (hangs here)
>>
> Hi Mark
> What does 'hangs here' mean exactly? Blocked on a mutex? Running in a tight loop? Something else?
>
> Is your application using plain HTTP or HTTPS?
>
> Oleg
>
Re: Close Hang
Posted by Oleg Kalnichevski <ol...@ok2consulting.com>.
On January 26, 2016 6:01:59 PM GMT+01:00, Mark Johnson <mj...@gmail.com> wrote:
>Hi,
>
>We're still trying to put together a concise example but have
>determined
>some information and a work-around. Here's the scenario that happens:
>
>Thread:
>Start-up : Creates the Http connection; This starts an IO
>Dispatcher
>3 thread and a pool-41-thread-1 (for example). The Http request is now
>
>issued
>
>pool-41-thread-1: Gets the error (timeout or connection closed by
>peer). This Http request is retried
>pool-41-thread-1: Gets the error again; The operation is retried
>again.
>pool-41-thread-1: Gets the error again; The connection is closed
>(hangs here)
>
Hi Mark
What does 'hangs here' mean exactly? Blocked on a mutex? Running in a tight loop? Something else?
Is your application using plain HTTP or HTTPS?
Oleg
--
Sent from my Android device with K-9 Mail. Please excuse my brevity.
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
Re: Close Hang
Posted by Mark Johnson <mj...@gmail.com>.
Hi,
We're still trying to put together a concise example but have determined
some information and a work-around. Here's the scenario that happens:
Thread:
Start-up : Creates the Http connection; This starts an IO Dispatcher
3 thread and a pool-41-thread-1 (for example). The Http request is now
issued
pool-41-thread-1: Gets the error (timeout or connection closed by
peer). This Http request is retried
pool-41-thread-1: Gets the error again; The operation is retried again.
pool-41-thread-1: Gets the error again; The connection is closed
(hangs here)
I've added code to perform the connection close on a new worker thread
when the error occurs instead of closing the connection in the
"pool-41-thread-1" thread. The hang does not occur in this case.
In our test program, it executes
AbstractMultiworkerIOReactor.doShutdown() as part of the client close.
In the testing with our larger application, this does not appear to be
called during the client close (when done on the "pool-41-thread-1" thread).
Are we doing something here that isn't correct?
Thanks in advance for any ideas.
Mark
On 1/25/2016 9:26 AM, Oleg Kalnichevski wrote:
> On Fri, 2016-01-22 at 17:06 -0600, Mark Johnson wrote:
>> 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:
>>
> Hi Mark
>
> Can this issue be reproduced with a test case?
>
> Oleg
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> For additional commands, e-mail: httpclient-users-help@hc.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
Re: Close Hang
Posted by Oleg Kalnichevski <ol...@apache.org>.
On Fri, 2016-01-22 at 17:06 -0600, Mark Johnson wrote:
> 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:
>
Hi Mark
Can this issue be reproduced with a test case?
Oleg
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org