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 (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.
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager: 2014-01-28 18:54:52,988 DEBUG I/O dispatcher 6 [Req_254] Connection leased: [id: http-outgoing-601][route: {}->http://rtb-lb-eu-west.tubemogul.com:80][total kept alive: 0; route allocated: 90 of 100; total allocated: 590 of 1000]
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-28 18:54:52,988 DEBUG I/O dispatcher 6 [Req_254] http-outgoing-601 176.31.235.26:59028<->46.137.87.196:80[ACTIVE][r:]: Set attribute http.nio.exchange-handler
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-28 18:54:52,988 DEBUG I/O dispatcher 6 [Req_254] http-outgoing-601 176.31.235.26:59028<->46.137.87.196:80[ACTIVE][rw:]: Event set [w]
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-28 18:54:52,988 DEBUG I/O dispatcher 6 [Req_254] http-outgoing-601 176.31.235.26:59028<->46.137.87.196:80[ACTIVE][rw:]: Set attribute http.nio.http-exchange-state
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-28 18:54:52,988 DEBUG I/O dispatcher 6 [Req_254] http-outgoing-601 176.31.235.26:59028<->46.137.87.196:80[ACTIVE][rw:]: Set timeout 60000
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-28 18:54:52,991 DEBUG I/O dispatcher 6 [Req_254] http-outgoing-601 176.31.235.26:59028<->46.137.87.196:80[ACTIVE][rw:]: Event set [w]
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-28 18:54:53,778 DEBUG I/O dispatcher 6 [Req_482] http-outgoing-601 176.31.235.26:59028<->46.137.87.196:80[ACTIVE][rw:w]: 952 bytes written
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-28 18:54:53,787 DEBUG I/O dispatcher 6 [Req_482] http-outgoing-601 176.31.235.26:59028<->46.137.87.196:80[ACTIVE][r:w]: Event cleared [w]
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-28 18:54:56,648 DEBUG I/O dispatcher 6 [Req_1280] http-outgoing-601 176.31.235.26:59028<->46.137.87.196:80[ACTIVE][r:r]: 86 bytes read
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-28 18:54:56,649 DEBUG I/O dispatcher 6 [Req_1280] http-outgoing-601 176.31.235.26:59028<->46.137.87.196:80[ACTIVE][r:r]: Remove attribute http.nio.exchange-handler
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager: 2014-01-28 18:54:56,649 DEBUG I/O dispatcher 6 [Req_1280] Connection [id: http-outgoing-601][route: {}->http://rtb-lb-eu-west.tubemogul.com:80] can be kept alive indefinitely
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager: 2014-01-28 18:54:56,660 DEBUG I/O dispatcher 6 [Req_1280] Connection leased: [id: http-outgoing-601][route: {}->http://rtb-lb-eu-west.tubemogul.com:80][total kept alive: 0; route allocated: 80 of 100; total allocated: 581 of 1000]
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-28 18:54:56,671 DEBUG I/O dispatcher 6 [Req_1280] http-outgoing-601 176.31.235.26:59028<->46.137.87.196:80[ACTIVE][r:r]: Set attribute http.nio.exchange-handler
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-28 18:54:56,680 DEBUG I/O dispatcher 6 [Req_1280] http-outgoing-601 176.31.235.26:59028<->46.137.87.196:80[ACTIVE][rw:r]: Event set [w]
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager: 2014-01-28 18:54:56,682 DEBUG I/O dispatcher 6 [Req_1280] Connection released: [id: http-outgoing-601][route: {}->http://rtb-lb-eu-west.tubemogul.com:80][total kept alive: 0; route allocated: 80 of 100; total allocated: 581 of 1000]
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-28 18:54:58,220 DEBUG I/O dispatcher 6 [Req_1650] http-outgoing-601 176.31.235.26:59028<->46.137.87.196:80[ACTIVE][rw:w]: Set timeout 60000
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-28 18:54:58,222 DEBUG I/O dispatcher 6 [Req_1650] http-outgoing-601 176.31.235.26:59028<->46.137.87.196:80[ACTIVE][rw:w]: Event set [w]
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-28 18:54:58,229 DEBUG I/O dispatcher 6 [Req_1650] http-outgoing-601 176.31.235.26:59028<->46.137.87.196:80[ACTIVE][rw:w]: 1186 bytes written
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-28 18:54:58,230 DEBUG I/O dispatcher 6 [Req_1650] http-outgoing-601 176.31.235.26:59028<->46.137.87.196:80[ACTIVE][r:w]: Event cleared [w]
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-28 18:55:00,374 DEBUG I/O dispatcher 6 [Req_2612] http-outgoing-601 176.31.235.26:59028<->46.137.87.196:80[ACTIVE][r:r]: 1490 bytes read
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-28 18:55:00,384 DEBUG I/O dispatcher 6 [Req_2612] http-outgoing-601 176.31.235.26:59028<->46.137.87.196:80[ACTIVE][r:r]: -1 bytes read
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-28 18:55:00,388 DEBUG I/O dispatcher 6 [Req_2612] http-outgoing-601 176.31.235.26:59028<->46.137.87.196:80[ACTIVE][r:r]: Remove attribute http.nio.exchange-handler
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl: 2014-01-28 18:55:00,390 DEBUG I/O dispatcher 6 [Req_2612] http-outgoing-601 176.31.235.26:59028<->46.137.87.196:80[ACTIVE][r:r]: Close
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager: 2014-01-28 18:55:00,394 DEBUG I/O dispatcher 6 [Req_2612] Connection released: [id: http-outgoing-601][route: {}->http://rtb-lb-eu-west.tubemogul.com:80][total kept alive: 0; route allocated: 97 of 100; total allocated: 601 of 1000]
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscr...@hc.apache.org
For additional commands, e-mail: httpclient-users-h...@hc.apache.org
