hc-httpclient-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Raymond Mak <raymond...@gmail.com>
Subject Leaking pool entries when using DefaultHttpAsyncClient with PoolingAsyncClientConnectionManager
Date Tue, 14 Feb 2012 18:45:50 GMT
While I was testing DefaultHttpAsyncClient with
PoolingAsyncClientConnectionManager in the production environment
(httpasyncclient-4.0-alpha3 + httpcore-4.2-alpha2 +
httpcore-nio-4.2-alpha2) , I noticed that my application was slowly
accumulating closed connections in the underlying connection pool as leased
connections. After digging through the debug log, the following appears to
be what might be happening to one of the orphaned connections:



1.  The (GET) request was successfully sent and the first response packet
was received with a somewhat larger number of bytes read than what was
included in the header and the body per the following log entry:



2012-02-14 03:05:27,204 [I/O dispatcher 9] DEBUG
org.apache.http.impl.nio.reactor.IOSessionImpl - http-outgoing-2
10.16.1.223:44382<->10.16.99.63:80[ACTIVE][r:r]: 2187 bytes read



2.  The headers were successfully parsed per the following log entries:



2012-02-14 03:05:27,227 [I/O dispatcher 9] DEBUG org.apache.http.headers -
http-outgoing-2 << HTTP/1.1 200 OK

2012-02-14 03:05:27,246 [I/O dispatcher 9] DEBUG org.apache.http.headers -
http-outgoing-2 << Date: Tue, 14 Feb 2012 03:05:51 GMT

2012-02-14 03:05:27,246 [I/O dispatcher 9] DEBUG org.apache.http.headers -
http-outgoing-2 << Server: Microsoft-IIS/6.0

2012-02-14 03:05:27,246 [I/O dispatcher 9] DEBUG org.apache.http.headers -
http-outgoing-2 << X-Powered-By: ASP.NET

2012-02-14 03:05:27,246 [I/O dispatcher 9] DEBUG org.apache.http.headers -
http-outgoing-2 << X-AspNet-Version: 2.0.50727

2012-02-14 03:05:27,246 [I/O dispatcher 9] DEBUG org.apache.http.headers -
http-outgoing-2 << Cache-Control: private

2012-02-14 03:05:27,246 [I/O dispatcher 9] DEBUG org.apache.http.headers -
http-outgoing-2 << Content-Type: text/plain; charset=utf-8

2012-02-14 03:05:27,246 [I/O dispatcher 9] DEBUG org.apache.http.headers -
http-outgoing-2 << Content-Length: 1965



and I have verified that the response body was indeed 1965 bytes


3. However, it would appear that the protocol handler/decoder didn't
consider the response stream to be completed according to the following log
entry:


2012-02-14 03:05:27,292 [I/O dispatcher 9] DEBUG
org.apache.http.nio.protocol.HttpAsyncClientProtocolHandler -
http-outgoing-2 [ACTIVE] Input ready [content length: 1965; pos: 0;
completed: false]


and so it skipped calling my response handler (and scheduled another
timeout waiting for more response packets per the following log entry?:


2012-02-14 03:05:27,443 [http-apr-8080-exec-62] DEBUG
org.apache.http.impl.nio.reactor.IOSessionImpl - http-outgoing-2
10.16.1.223:44382<->10.16.99.63:80[ACTIVE][rw:r]: Event set [w])


4. Eventually a timeout occurred, but it appeared that my response handler
was skipped, again and the connection was closed without it being released
back to the pool as far as I can tell from the following log entries:


2012-02-14 03:05:28,136 [I/O dispatcher 9] DEBUG
org.apache.http.nio.protocol.HttpAsyncClientProtocolHandler -
http-outgoing-2 [ACTIVE] Timeout
2012-02-14 03:05:28,137 [I/O dispatcher 9] DEBUG
org.apache.http.impl.nio.reactor.IOSessionImpl - http-outgoing-2
10.16.1.223:44382<->10.16.99.63:80[ACTIVE][rw:r]: Close
2012-02-14 03:05:28,137 [I/O dispatcher 9] DEBUG
org.apache.http.nio.protocol.HttpAsyncClientProtocolHandler -
http-outgoing-2 [CLOSED]: Disconnected


Given that I do have access to the source code, I am fully prepared to dig
through this further. But before going to the deep end, I thought I would
send this out in case someone knew something about this already and/or
suggestions on how to track this down quicker.


Thanks much,


-Raymond

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