How to Read HttpClient Logging and Prevent Connection Leaks

by Michael Scepaniak on November 25, 2015 in software development

Fall Splendor

“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]

view raw
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]

view raw
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]

view raw
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]

view raw
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

view raw
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

view raw
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]

view raw
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]

view raw

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]

view raw

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. 🙂

Mike
Want to be notified when new articles are posted?
Enter your email address:

{ 4 comments… read them below or add one }

Ferez February 28, 2017 at 1:47 am

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

Reply

Michael Scepaniak February 28, 2017 at 5:52 am

Thanks, Ferez. While I got close enough to this to be able to understand what the HttpClient library is doing, I didn’t get to the point where I understood why – at least not in depth. So, unfortunately, I’m not able to shed any light on your SO question. Good luck.

Mike….

Reply

Ferez March 18, 2017 at 10:01 am

I appreciate your concern Mike. I finally found the answer, you could check the thread again.

Ferez

Reply

Michael Scepaniak March 18, 2017 at 11:09 am

That’s great, Ferez. Nice job. 🙂

Reply

Leave a Comment

Previous post:

Next post:

Member of The Internet Defense League