Hello,
We are using HttpAsyncClient underneath our custom client object to send
requests to a production server. The client object might get closed while there
are pending requests on the server. If that happens, we would like to abort all
the pending requests and shutdown the httpasyncclient.
However, we are seeing a sporadic failure.
Below is the debug log:
apache execute AbstractHttpAsyncClient
2015/10/17 21:13:00:981 EDT [DEBUG] DefaultHttpAsyncClient - [exchange: 2]
start execution
2015/10/17 21:13:00:981 EDT [DEBUG] DefaultHttpAsyncClient - [exchange: 2]
Request connection for {}->http://pchawla-deb7-64:9910
DefaultHttpClientConnection - NhttpConnectionBase.status : 0
2015/10/17 21:13:00:981 EDT [DEBUG] PoolingClientAsyncConnectionManager -
Connection request: [route: {}->http://pchawla-deb7-64:9910][total kept alive:
1; route allocated: 1 of 20; total allocated: 1 of 20]
2015/10/17 21:13:00:982 EDT [DEBUG] PoolingClientAsyncConnectionManager -
Connection leased: [id: 1][route: {}->http://pchawla-deb7-64:9910][total kept
alive: 0; route allocated: 1 of 20; total allocated: 1 of 20]
2015/10/17 21:13:00:982 EDT [DEBUG] DefaultHttpAsyncClient - [exchange: 2]
Connection allocated: [id:1][route:{}->http://pchawla-deb7-64:9910][state:null]
2015/10/17 21:13:00:982 EDT [DEBUG] IOSessionImpl - http-outgoing-1
172.28.11.41:55678<->172.28.11.144:9910[ACTIVE][r:r]: Set attribute
http.nio.exchange-handler
2015/10/17 21:13:00:982 EDT [DEBUG] IOSessionImpl - http-outgoing-1
172.28.11.41:55678<->172.28.11.144:9910[ACTIVE][rw:r]: Event set [w]
2015/10/17 21:13:00:982 EDT [DEBUG] IOSessionImpl - http-outgoing-1
172.28.11.41:55678<->172.28.11.144:9910[ACTIVE][r:w]: Event cleared [w]
2015/10/17 21:13:00:982 EDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[ACTIVE] Request ready
2015/10/17 21:13:00:983 EDT [DEBUG] DefaultHttpAsyncClient - [exchange: 2]
Attempt 1 to execute request
2015/10/17 21:13:00:983 EDT [DEBUG] IOSessionImpl - http-outgoing-1
172.28.11.41:55678<->172.28.11.144:9910[ACTIVE][r:w]: Set timeout 10000
2015/10/17 21:13:00:983 EDT [DEBUG] DefaultHttpAsyncClient - [exchange: 2]
Cancelled
2015/10/17 21:13:00:983 EDT [DEBUG] RequestAddCookies - CookieSpec selected:
best-match
2015/10/17 21:13:00:983 EDT [DEBUG] RequestAuthCache - Auth cache not set in
the context
2015/10/17 21:13:00:983 EDT [DEBUG] RequestTargetAuthentication - Target auth
state: UNCHALLENGED
2015/10/17 21:13:00:983 EDT [DEBUG] RequestProxyAuthentication - Proxy auth
state: UNCHALLENGED
2015/10/17 21:13:00:983 EDT [DEBUG] headers - http-outgoing-1 >> POST
/waitFor/spendTime?mode=async&client=172dcde5-0800-4608-9529-649458c40a98
HTTP/1.1
2015/10/17 21:13:00:983 EDT [DEBUG] headers - http-outgoing-1 >> Content-Type:
application/x-google-protobuf
2015/10/17 21:13:00:983 EDT [DEBUG] headers - http-outgoing-1 >>
Content-Length: 19
2015/10/17 21:13:00:983 EDT [DEBUG] headers - http-outgoing-1 >> Host:
pchawla-deb7-64:9910
2015/10/17 21:13:00:983 EDT [DEBUG] headers - http-outgoing-1 >> Connection:
Keep-Alive
2015/10/17 21:13:00:983 EDT [DEBUG] headers - http-outgoing-1 >> User-Agent:
com.mathworks.mps.client.internal.ApacheHttpClient
2015/10/17 21:13:00:984 EDT [DEBUG] DefaultHttpAsyncClient - [exchange: 2]
aborting connection [id:1][route:{}->http://pchawla-deb7-64:9910][state:null]
2015/10/17 21:13:00:984 EDT [DEBUG] IOSessionImpl - http-outgoing-1
172.28.11.41:55678<->172.28.11.144:9910[ACTIVE][rw:w]: Event set [w]
DefaultHttpClientConnection - NhttpConnectionBase.status: 2
DefaultHttpClientConnection caught exception on apache produceOutput : geck
about http protocol exception
2015/10/17 21:13:00:984 EDT [DEBUG] IOSessionImpl - http-outgoing-1
172.28.11.41:55678<->172.28.11.144:9910[ACTIVE][rw:w]: Shutdown
2015/10/17 21:13:00:984 EDT [DEBUG] IOSessionImpl - http-outgoing-1
0.0.0.0:55678<->172.28.11.144:9910[CLOSED][]: 272 bytes written
2015/10/17 21:13:00:984 EDT [DEBUG] IOSessionImpl - http-outgoing-1
0.0.0.0:55678<->172.28.11.144:9910[CLOSED][]: Shutdown
2015/10/17 21:13:00:984 EDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[CLOSED] Output ready
2015/10/17 21:13:00:984 EDT [DEBUG] PoolingClientAsyncConnectionManager -
Connection released: [id: 1][route: {}->http://pchawla-deb7-64:9910][total kept
alive: 0; route allocated: 0 of 20; total allocated: 0 of 20]
2015/10/17 21:13:00:984 EDT [DEBUG] DefaultHttpAsyncClient - [exchange: 2]
produce content
2015/10/17 21:13:00:984 EDT [ERROR] HttpAsyncRequestExecutor - http-outgoing-1
[CLOSED] HTTP protocol exception: null
<java.nio.channels.ClosedChannelException>java.nio.channels.ClosedChannelException
at sun.nio.ch.SocketChannelImpl.ensureWriteOpen(Unknown Source)
at sun.nio.ch.SocketChannelImpl.write(Unknown Source)
at
org.apache.http.impl.nio.conn.LoggingIOSession$LoggingByteChannel.write(LoggingIOSession.java:202)
at
org.apache.http.impl.nio.codecs.LengthDelimitedEncoder.write(LengthDelimitedEncoder.java:89)
at
org.apache.http.nio.entity.EntityAsyncContentProducer.produceContent(EntityAsyncContentProducer.java:70)
at
org.apache.http.nio.protocol.BasicAsyncRequestProducer.produceContent(BasicAsyncRequestProducer.java:133)
at
org.apache.http.impl.nio.client.DefaultAsyncRequestDirector.produceContent(DefaultAsyncRequestDirector.java:324)
at
org.apache.http.nio.protocol.HttpAsyncRequestExecutor.outputReady(HttpAsyncRequestExecutor.java:184)
at
org.apache.http.impl.nio.client.LoggingAsyncRequestExecutor.outputReady(LoggingAsyncRequestExecutor.java:108)
at
org.apache.http.impl.nio.DefaultNHttpClientConnection.produceOutput(DefaultNHttpClientConnection.java:232)
at
org.apache.http.impl.nio.DefaultHttpClientIODispatch.onOutputReady(DefaultHttpClientIODispatch.java:130)
at
org.apache.http.impl.nio.DefaultHttpClientIODispatch.onOutputReady(DefaultHttpClientIODispatch.java:1)
at
org.apache.http.impl.nio.reactor.AbstractIODispatch.outputReady(AbstractIODispatch.java:141)
at
org.apache.http.impl.nio.reactor.BaseIOReactor.writable(BaseIOReactor.java:181)
at
org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(AbstractIOReactor.java:346)
at
org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(AbstractIOReactor.java:320)
at
org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:280)
at
org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:106)
at
org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:604)
at java.lang.Thread.run(Unknown Source)
2015/10/17 21:13:00:985 EDT [DEBUG] IOSessionImpl - http-outgoing-1
0.0.0.0:55678<->172.28.11.144:9910[CLOSED][]: Shutdown
2015/10/17 21:13:00:985 EDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[CLOSED]: Disconnected
2015/10/17 21:13:00:986 EDT [DEBUG] PoolingClientAsyncConnectionManager -
Connection manager is shutting down
2015/10/17 21:13:00:990 EDT [DEBUG] PoolingClientAsyncConnectionManager -
Connection manager shut down
********* Here is the log when it works successfully *********
apache execute AbstractHttpAsyncClient
2015/10/17 21:16:11:268 EDT [DEBUG] DefaultHttpAsyncClient - [exchange: 2]
start execution
2015/10/17 21:16:11:268 EDT [DEBUG] DefaultHttpAsyncClient - [exchange: 2]
Request connection for {}->http://pchawla-deb7-64:9910
2015/10/17 21:16:11:269 EDT [DEBUG] PoolingClientAsyncConnectionManager -
Connection request: [route: {}->http://pchawla-deb7-64:9910][total kept alive:
1; route allocated: 1 of 20; total allocated: 1 of 20]
2015/10/17 21:16:11:269 EDT [DEBUG] PoolingClientAsyncConnectionManager -
Connection leased: [id: 1][route: {}->http://pchawla-deb7-64:9910][total kept
alive: 0; route allocated: 1 of 20; total allocated: 1 of 20]
2015/10/17 21:16:11:269 EDT [DEBUG] DefaultHttpAsyncClient - [exchange: 2]
Connection allocated: [id:1][route:{}->http://pchawla-deb7-64:9910][state:null]
2015/10/17 21:16:11:269 EDT [DEBUG] IOSessionImpl - http-outgoing-1
172.28.11.41:55705<->172.28.11.144:9910[ACTIVE][r:r]: Set attribute
http.nio.exchange-handler
2015/10/17 21:16:11:269 EDT [DEBUG] IOSessionImpl - http-outgoing-1
172.28.11.41:55705<->172.28.11.144:9910[ACTIVE][rw:r]: Event set [w]
DefaultHttpClientConnection - NhttpConnectionBase.status: 0
2015/10/17 21:16:11:269 EDT [DEBUG] IOSessionImpl - http-outgoing-1
172.28.11.41:55705<->172.28.11.144:9910[ACTIVE][r:w]: Event cleared [w]
2015/10/17 21:16:11:269 EDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[ACTIVE] Request ready
2015/10/17 21:16:11:270 EDT [DEBUG] DefaultHttpAsyncClient - [exchange: 2]
Attempt 1 to execute request
2015/10/17 21:16:11:270 EDT [DEBUG] DefaultHttpAsyncClient - [exchange: 2]
Cancelled
2015/10/17 21:16:11:270 EDT [DEBUG] IOSessionImpl - http-outgoing-1
172.28.11.41:55705<->172.28.11.144:9910[ACTIVE][r:w]: Set timeout 10000
2015/10/17 21:16:11:270 EDT [DEBUG] RequestAddCookies - CookieSpec selected:
best-match
2015/10/17 21:16:11:270 EDT [DEBUG] RequestAuthCache - Auth cache not set in
the context
2015/10/17 21:16:11:270 EDT [DEBUG] RequestTargetAuthentication - Target auth
state: UNCHALLENGED
2015/10/17 21:16:11:270 EDT [DEBUG] RequestProxyAuthentication - Proxy auth
state: UNCHALLENGED
2015/10/17 21:16:11:270 EDT [DEBUG] headers - http-outgoing-1 >> POST
/waitFor/spendTime?mode=async&client=3060869a-d981-4efc-b716-d4ba98a6b74a
HTTP/1.1
2015/10/17 21:16:11:270 EDT [DEBUG] headers - http-outgoing-1 >> Content-Type:
application/x-google-protobuf
2015/10/17 21:16:11:270 EDT [DEBUG] headers - http-outgoing-1 >>
Content-Length: 19
2015/10/17 21:16:11:271 EDT [DEBUG] headers - http-outgoing-1 >> Host:
pchawla-deb7-64:9910
2015/10/17 21:16:11:271 EDT [DEBUG] DefaultHttpAsyncClient - [exchange: 2]
aborting connection [id:1][route:{}->http://pchawla-deb7-64:9910][state:null]
2015/10/17 21:16:11:271 EDT [DEBUG] headers - http-outgoing-1 >> Connection:
Keep-Alive
2015/10/17 21:16:11:271 EDT [DEBUG] PoolingClientAsyncConnectionManager -
Connection manager is shutting down
2015/10/17 21:16:11:271 EDT [DEBUG] IOSessionImpl - http-outgoing-1
172.28.11.41:55705<->172.28.11.144:9910[ACTIVE][r:w]: Shutdown
2015/10/17 21:16:11:271 EDT [DEBUG] headers - http-outgoing-1 >> User-Agent:
com.mathworks.mps.client.internal.ApacheHttpClient
2015/10/17 21:16:11:271 EDT [DEBUG] IOSessionImpl - http-outgoing-1
172.28.11.41:55705<->172.28.11.144:9910[ACTIVE][r:w]: Shutdown
2015/10/17 21:16:11:271 EDT [DEBUG] IOSessionImpl - http-outgoing-1
0.0.0.0:55705<->172.28.11.144:9910[CLOSED][]: Event set [w]
2015/10/17 21:16:11:271 EDT [DEBUG] IOSessionImpl - http-outgoing-1
0.0.0.0:55705<->172.28.11.144:9910[CLOSED][]: Shutdown
2015/10/17 21:16:11:271 EDT [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[CLOSED]: Disconnected
2015/10/17 21:16:11:272 EDT [DEBUG] PoolingClientAsyncConnectionManager -
Connection manager shut down
I have added a few debug statements to the function that I think might be
responsible for this race condition. I would really appreciate any help.
For reference, I am using the following versions of HTTPComponents:
HttpAsyncClient - 4.0-beta3.jar
HttpClient - 4.2.2.jar
HttpCore - 4.2.2.jar
HttpCore-nio - 4.2.2.jar
Thanks,
Poonam
