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
