Re: Weird leasing/releasing sequence leading to close
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-unsubscr...@hc.apache.org For additional commands, e-mail: httpclient-users-h...@hc.apache.org
Re: Weird leasing/releasing sequence leading to close
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-unsubscr...@hc.apache.org For additional commands, e-mail: httpclient-users-h...@hc.apache.org -- Antoine Bonavita (anto...@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-unsubscr...@hc.apache.org For additional commands, e-mail: httpclient-users-h...@hc.apache.org
Re: Weird leasing/releasing sequence leading to close
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
Re: Weird leasing/releasing sequence leading to close
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-unsubscr...@hc.apache.org For additional commands, e-mail: httpclient-users-h...@hc.apache.org -- Antoine Bonavita (anto...@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-unsubscr...@hc.apache.org For additional commands, e-mail: httpclient-users-h...@hc.apache.org
