hc-httpclient-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Poonam Chawla <Poonam.Cha...@mathworks.com>
Subject HttpAsyncRequestExecutor : HTTP protocol exception: null
Date Sun, 18 Oct 2015 01:24:08 GMT
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




Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message