"Where there is great power, there is great responsibility"
~ Winston Churchill
If you have a Java-based application that makes HTTP requests, there's a good chance you are using Apache HttpClient to make these requests. If the application in question needs to make these requests at scale or with any sort of concurrency, there's a good chance that you are using HttpClient with the PoolingHttpClientConnectionManager.
If you aren't familiar with the PoolingHttpClientConnectionManager, in short, it makes requests via a pool of re-usable persistent connections. Re-using connections (to the same destination) is (I assume) more efficient and more performant than repeatedly tearing them down and re-establishing them. If you would like to read more about how to make use of this class, Eugen Paraschiv's article about HttpClient Connection Management is a good read.
Dangers Outside the Cocoon
While the PoolingHttpClientConnectionManager is very cool, working with it properly (in a way that won't leak connections) can be challenging. I suspect this is the reasoning behind the existence of- and recommendation of using the ResponseHandler class. The documentation's mention (in the HttpClient examples) that using the ResponseHandler "guarantees that the underlying HTTP connection will be released back to the connection manager automatically in all cases" indicates to me that this is (or was) a recurrent issue.
However, limiting yourself to the ResponseHandler (or, I speculate, Spring's RestTemplate) has drawbacks. In my code, I find myself wanting to shield client components from as much of the HttpClient innards as possible, while still providing those client components access to certain response headers and status codes (when needed). With ResponseHandler, I didn't see this being achievable. Worse, there are many circumstances where client components want access to the HTTP response content as a raw InputStream, possibly for piping back large responses to a client of the client with minimal buffering. Doing this within the protective bounds of the ResponseHandler is not feasible, as it completely defeats the protections that the ResponseHandler is attempting to provide.
So, you may find yourself outside of the protective bounds of the ResponseHandler. If so, your chances of experiencing connection leaks increases dramatically. It's when you find yourself attempting to plug such a leak that you realize that you need to understand all of the logging and log-containing terminology that HttpClient uses. For me, that was no simple task. Read on to see what I've come to understand.
HttpClient Logging
Connection request: [route: {}->http://myhost:8080][total kept alive: 0; route allocated: 0 of 50; total allocated: 0 of 100]
A connection to myhost is about to be requested. The metrics (keep-alives and allocations) displayed at this point reflect the state of the connection pool before the request is made.
Connection leased: [id: 0][route: {}->http://myhost:8080][total kept alive: 0; route allocated: 1 of 50; total allocated: 1 of 100]
A connection to myhost has been leased (from the connection pool) and given a unique ID, but not opened. By this point, an allocation has been made for the route (destination).
Connection [id: 0][route: {}->http://myhost:8080] can be kept alive indefinitely
Connection released: [id: 0][route: {}->http://myhost:8080][total kept alive: 1; route allocated: 1 of 50; total allocated: 1 of 100]
Typically seen after a response has been received. A connection to myhost has been opened and released back to (meaning, kept alive in) the connection pool. This will increment the "total kept alive" value. The "total kept alive" value spans across routes.
Connection request: [route: {}->http://myhost:8080][total kept alive: 1; route allocated: 1 of 50; total allocated: 1 of 100]
Connection leased: [id: 1][route: {}->http://myhost:8080][total kept alive: 0; route allocated: 1 of 50; total allocated: 1 of 100]
When a connection is requested and leased, if an existing allocation (connection) for the route is re-used, "total kept alive" will decrement, but the allocation counts will hold steady.
Connection request: [route: {}->http://myhost:8080][total kept alive: 1; route allocated: 1 of 50; total allocated: 2 of 100]
Connection leased: [id: 2][route: {}->http://myhost:8080][total kept alive: 1; route allocated: 2 of 50; total allocated: 3 of 100]
Opening connection {}->http://myhost:8080
When a connection is requested and leased, if all of the existing allocations for the route are in use (e.g., a response is pending), "total kept alive" will hold steady and the allocation counts will increment. In this scenario, a new connection is opened (corresponding to the new allocation).
Connection request: [route: {}->http://myhost:8080][total kept alive: 5; route allocated: 3 of 50; total allocated: 5 of 100]
Connection leased: [id: 56][route: {}->http://myhost:8080[total kept alive: 4; route allocated: 3 of 50; total allocated: 5 of 100]
Stale connection check
http-outgoing-56 << "end of stream"
Stale connection detected
http-outgoing-56: Close connection
Opening connection {}->http://myhost
Connecting to myhost:8080
By default, after leasing (re-using) an already-established connection from the pool, HttpClient will check the connection to see if it is "stale". If so, the leased connection will be closed and a new connection opened to take its place in the pool. As a result, the allocation counts hold steady (not shown).
http-outgoing-58: Shutdown connection
Connection discarded
http-outgoing-58: Close connection
Connection released: [id: 58][route: {}->http://myhost:8080[total kept alive: 6; route allocated: 4 of 50; total allocated: 6 of 100]
Connections will periodically be shut-down and discarded from the pool by HttpClient. This will decrement the allocation counts. In general, this behavior is normal and should be expected. However, if you see this happening on a continual basis for the majority of your requests, it might be because you are closing your connections improperly, thereby negating the benefits of the connection pooling.
Leak-Safe Logging
A good way to get a feel for your application's use of the HttpClient connection pool is by grepping your logs for the following pattern:
grep '\(Connection leased\|Shutdown connection\)' myhost.log
A healthy log snippet yielded by this search pattern looks as follows:
Connection leased: [id: 66][route: {}->http://myhost:8080][total kept alive: 2; route allocated: 3 of 50; total allocated: 5 of 100]
Connection leased: [id: 64][route: {}->http://myhost:8080][total kept alive: 4; route allocated: 3 of 50; total allocated: 5 of 100]
Connection leased: [id: 64][route: {}->http://myhost:8080][total kept alive: 4; route allocated: 3 of 50; total allocated: 5 of 100]
Connection leased: [id: 64][route: {}->http://myhost:8080][total kept alive: 4; route allocated: 3 of 50; total allocated: 5 of 100]
Connection leased: [id: 64][route: {}->http://myhost:8080][total kept alive: 4; route allocated: 3 of 50; total allocated: 5 of 100]
Connection leased: [id: 67][route: {}->http://myhost:8080][total kept alive: 3; route allocated: 3 of 50; total allocated: 5 of 100]
http-outgoing-64: Shutdown connection
Connection leased: [id: 67][route: {}->http://myhost:8080][total kept alive: 3; route allocated: 2 of 50; total allocated: 4 of 100]
Connection leased: [id: 66][route: {}->http://myhost:8080][total kept alive: 2; route allocated: 2 of 50; total allocated: 4 of 100]
http-outgoing-66: Shutdown connection
Connection leased: [id: 67][route: {}->http://myhost:8080][total kept alive: 2; route allocated: 1 of 50; total allocated: 3 of 100]
Connection leased: [id: 67][route: {}->http://myhost:8080][total kept alive: 2; route allocated: 1 of 50; total allocated: 3 of 100]
Connection leased: [id: 68][route: {}->http://myhost:8080][total kept alive: 2; route allocated: 2 of 50; total allocated: 4 of 100]
Connection leased: [id: 67][route: {}->http://myhost:8080][total kept alive: 3; route allocated: 2 of 50; total allocated: 4 of 100]
Connection leased: [id: 68][route: {}->http://myhost:8080][total kept alive: 2; route allocated: 2 of 50; total allocated: 4 of 100]
http-outgoing-68: Shutdown connection
Connection leased: [id: 69][route: {}->http://myhost:8080][total kept alive: 2; route allocated: 2 of 50; total allocated: 4 of 100]
http-outgoing-67: Shutdown connection
Connection leased: [id: 70][route: {}->http://myhost:8080][total kept alive: 2; route allocated: 2 of 50; total allocated: 4 of 100]
In this sequence, connections #64, #66, and #67 are in-use. Connection #64 is then shut-down by HttpClient. The route allocations decrement, as expected. Notice that the connection with this ID no longer appears in the log. Connection #66 is then shut-down, with the route allocations decrementing again. A couple requests later, a new connection (allocation) is established (#68). The route allocations increment. This connection #68 only ends up being used for two requests before being discarded by HttpClient. The rest of the lines show two new connections being created and a third being discarded.
Leaky Logging
Conversely, this is what the log will show when you have a connection leak and your application is starved of connections:
Connection request: [route: {}->http://myhost:8080][total kept alive: 2; route allocated: 50 of 50; total allocated: 52 of 100]
Whenever the number of allocated connections reaches the maximum allowed for a particular route (or all connections, in total), your application will not be allowed to make any more requests via HttpClient until one of the allocated connections is released back to the connection pool. In the best scenario, your application's use of HttpClient is coded correctly and your demand for requests is simply out-stripping supply. In this case (and in this example), the configuration can simply be modified to allow for more connections per route. However, if there is a disconnect between load on the system (minimal) and the allocation of connections (maximal), there's a good chance that your application, as coded, is leaking connections.
In my experience, the typical source of an HTTP connection leak is an InputStream being tapped to access/read the content of an HttpEntity (as provided by a CloseableHttpResponse), but then never closed. Which is, of course, what the HttpClient ResponseHandler is there to prevent. As always, with great power comes great responsibility.
I have created an HttpResponseBackedInputStream class that can be used to help facilitate the proper closure of a response received from HttpClient. You might find it useful. If so, please let me know. 😃
Leave a comment
10 comments
Greate post, thank you very much.
I have a problem with the HttpClient log and need help. Would you please take a look at my problem posted in Stack Overflow?
http://stackoverflow.com/questions/42469280/unexpected-connection-close-in-httpclient
Regards,
Ferez
Thank you this post! It helped me understand the apache http log messages better. I have a related problem, though different from a connection leak, namely that somehow the requests on my connections are timing out the same millisecond they are set up, logging "http-outgoing-104 << "[read] I/O error: Read timed out" right away.
I was thinking of a previous connection not being shut down properly while still being in the pool, so added a "Connection: close" header that the server responds with... So I think I've shut that possibility out now.
Still a mystery why I'm seeing the close, so I posted it on SO: https://stackoverflow.com/questions/52227231/read-i-o-error-read-timed-out-immediately-upon-sending-headers. But your post helped me on the way to understanding the logging entries, thank you.
Thank you this post! It helped me understand the apache http log messages better. I have a related problem of connection leak. I was not closing the connection. It is sorted now.
Hi, great post and analysis!. But I still dont get the next points:
-route allocated: 4=> means that there are 4 http connections now in use?. If this is like this, "total kept alive" should be the same, right?
-total kept alive:3 => means that there are 3 http connections live, right? But these connections can be in the pool waiting for somebody to use them or leased from the pool, right?
2022-05-06 10:24:41.301 DEBUG [conac-springboot-microlito,13c72be0abe1834b,d48772ce6e98624f,true] 1 --- [io-8080-exec-39] h.i.c.PoolingHttpClientConnectionManager : Connection request: [route: {}->http://acelera-springboot-conector-fix-service:8080][total kept alive: 0; route allocated: 0 of 5; total allocated: 0 of 10]
Thanks