On Thu, 2014-01-30 at 15:59 +0100, Antoine Bonavita wrote: > Hello, > > On 01/30/2014 01:43 PM, Oleg Kalnichevski wrote: > > 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. > I understand what you are saying. However, this is the same thread. We > include in our log files the name of the thread after the severity and > all logs have the thread name "I/O dispatcher 6". Did I miss something ? >
It is the same story. The lease request callback gets executed before the release operation is fully completed. http://hc.apache.org/httpcomponents-asyncclient-4.0.x/httpasyncclient/xref/org/apache/http/impl/nio/conn/PoolingNHttpClientConnectionManager.html#456 If you think this is a problem please raise a JIRA and i'll try to tweak the logging to make it appear more deterministic. > > >> * 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. > OK. That makes sense. Is there an easy way (i.e. without enabling > logging at the wire level) to distinguish between the two situations: > 1 - Opposite end closed the connection at the end of an HTTP answer. > 2 - Opposite end closed the connection in the middle of an HTTP answer. > This distinction is made by the protocol handler http://hc.apache.org/httpcomponents-core-4.3.x/httpcore-nio/xref/org/apache/http/nio/protocol/HttpAsyncRequestExecutor.html#243 In the former case the protocol handler should recover gracefully. In the latter case the request producer and response consumer should receive ConnectionClosedException exception through their #failed methods by way of #failed method of the exchange handler. http://hc.apache.org/httpcomponents-asyncclient-4.0.x/httpasyncclient/xref/org/apache/http/impl/nio/client/DefaultClientExchangeHandlerImpl.html#187 Hope this helps Oleg --------------------------------------------------------------------- To unsubscribe, e-mail: httpclient-users-unsubscr...@hc.apache.org For additional commands, e-mail: httpclient-users-h...@hc.apache.org
