hc-httpclient-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Oleg Kalnichevski <ol...@apache.org>
Subject Re: Weird leasing/releasing sequence leading to close
Date Thu, 30 Jan 2014 12:43:50 GMT
On Thu, 2014-01-30 at 13:07 +0100, Antoine Bonavita wrote:
> Hello,
> 
> I'm investigating an issue with our application (it intermittently stops 
> responding and we have to restart it).
> 
> To give you a bit of background, it's a Tomcat7 application using 
> AsyncServlet and connecting to a number of other servers using HTTP as a 
> transport layer (for each HTTP request we get, we do 3 to 5 requests in 
> parallel to the upstream servers). Of course, we are using 
> http-components and more specifically http-async-client for the 
> communication to the upstream servers.
> We are using: httpasynclient-4.0, httpclient-4.3.2, httpcore-4.3.1 and 
> httpcore-nio-4.3.2-20140116 (that's 4.3.2 with the fix for 
> https://issues.apache.org/jira/browse/HTTPCORE-370).
> 
> My current investigation led me to enable logging at the connection 
> level and look at some of the connections.
> 
> You will find attached the logs for a specific connection 
> (http-outgoing-601). There are two things that "look wierd" to me but 
> I'm not at all an expert so I would like to have your point of view:
> * The connection is leased at 18:54:52,988, then again at 18:54:56,660. 
> After that it is released at 18:54:56,682 and at 18:55:00,394. To me, 
> one http-outgoing should be released before it can be leased again. Am I 
> missing something ?

Connection pool logging takes place outside of the pool lock. Under
certain conditions the connection being released can get grabbed almost
immediately by another thread. As a result log entries may look mixed
up. However, as you can see the second 'release' entry is preceded by
'west.tubemogul.com:80] can be kept alive indefinitely' entry. This
basically means the connection was in the process of being released at
the same time.  


> * At 18:55:00,384, I see a "-1 bytes read" which seems to trigger a 
> close. What could be causing this ?
> 

The opposite endpoint closing the connection on its end, for whatever
reason.

> In this case the log is really short but some connection might do 
> hundreds of requests before hitting this situation.
> 

I would venture to say the logs look pretty ordinary to me.

Hope this helps.

Oleg



---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


Mime
View raw message