Just want to send a follow-up that the issue seems to have disappeared once I have upgraded to the latest snapshot of all httpcomponents per Oleg's suggestions. Thanks!
Raymond On Tue, Feb 14, 2012 at 10:45 AM, Raymond Mak <[email protected]> wrote: > 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 >
