You are viewing a plain text version of this content. The canonical link for it is here.
Posted to httpclient-users@hc.apache.org by Antoine Bonavita <an...@stickyads.tv> on 2014/01/30 13:07:33 UTC
Weird leasing/releasing sequence leading to close
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 ?
* At 18:55:00,384, I see a "-1 bytes read" which seems to trigger a
close. What could be causing this ?
In this case the log is really short but some connection might do
hundreds of requests before hitting this situation.
Thanks for your help.
A.
--
Antoine Bonavita (antoine@stickyads.tv) - CTO StickyADS.tv
Tel: +33 6 72 78 76 31/+33 9 50 68 21 32
Envoy� de mon PC. Moi je suis Fedora.
Re: Weird leasing/releasing sequence leading to close
Posted by Antoine Bonavita <an...@stickyads.tv>.
Hello,
On 01/30/2014 05:15 PM, Oleg Kalnichevski wrote:
> 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
Got it now. Sorry, I'm not that familiar with this code.
> 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.
No need from my standpoint now that I understand it's OK.
>>>> * 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
OK. Got it.
> Hope this helps
A lot. Thank you very much for your time, help and awesome contribution
to the community.
A.
>
> Oleg
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> For additional commands, e-mail: httpclient-users-help@hc.apache.org
>
--
Antoine Bonavita (antoine@stickyads.tv) - CTO StickyADS.tv
Tel: +33 6 72 78 76 31/+33 9 50 68 21 32
Envoyé de mon PC. Moi je suis Fedora.
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
Re: Weird leasing/releasing sequence leading to close
Posted by Oleg Kalnichevski <ol...@apache.org>.
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-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
Re: Weird leasing/releasing sequence leading to close
Posted by Antoine Bonavita <an...@stickyads.tv>.
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 ?
>> * 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.
>> 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.
It does. Thanks a lot.
A.
>
> Oleg
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> For additional commands, e-mail: httpclient-users-help@hc.apache.org
>
--
Antoine Bonavita (antoine@stickyads.tv) - CTO StickyADS.tv
Tel: +33 6 72 78 76 31/+33 9 50 68 21 32
Envoyé de mon PC. Moi je suis Fedora.
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
Re: Weird leasing/releasing sequence leading to close
Posted by Oleg Kalnichevski <ol...@apache.org>.
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