Return-Path: X-Original-To: apmail-hc-dev-archive@www.apache.org Delivered-To: apmail-hc-dev-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id DA53D11DF7 for ; Wed, 16 Jul 2014 16:16:06 +0000 (UTC) Received: (qmail 53560 invoked by uid 500); 16 Jul 2014 16:16:06 -0000 Delivered-To: apmail-hc-dev-archive@hc.apache.org Received: (qmail 53523 invoked by uid 500); 16 Jul 2014 16:16:06 -0000 Mailing-List: contact dev-help@hc.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: "HttpComponents Project" Delivered-To: mailing list dev@hc.apache.org Received: (qmail 53511 invoked by uid 99); 16 Jul 2014 16:16:06 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 16 Jul 2014 16:16:06 +0000 Date: Wed, 16 Jul 2014 16:16:06 +0000 (UTC) From: =?utf-8?Q?Przemys=C5=82aw_O=C5=82tarzewski_=28JIRA=29?= To: dev@hc.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (HTTPASYNC-79) Connection leak due to race condition on keep-alive boundary MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/HTTPASYNC-79?page=3Dcom.atlassi= an.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=3D14= 063668#comment-14063668 ]=20 Przemys=C5=82aw O=C5=82tarzewski commented on HTTPASYNC-79: ------------------------------------------------- Oleg, Thank you for a quick response and for providing the patch. We have build an experimental version of our solution and deployed it on se= veral nodes of the production environment. We will need a couple of days to= observe the results and verify if the patch fixes our problem. Przemek > Connection leak due to race condition on keep-alive boundary > ------------------------------------------------------------ > > Key: HTTPASYNC-79 > URL: https://issues.apache.org/jira/browse/HTTPASYNC-79 > Project: HttpComponents HttpAsyncClient > Issue Type: Bug > Affects Versions: 4.0.1 > Environment: SunOS 5.10 > Reporter: Przemys=C5=82aw O=C5=82tarzewski > Labels: connection, cxf, httpcore, leak > Fix For: 4.0.2, 4.1-alpha1 > > > We are experiencing a race condition between: > 1. I/O dispatcher closing a connection due to keep-alive expiry > 2. PoolingNHttpClientConnectionManager leasing the same connection > Consider valid exchange 1 provided below: > {noformat} > 2014.07.07 08:01:59.282 org.apache.http.impl.nio.conn.PoolingNHttpClientC= onnectionManager DEBUG [HLAPI-52] PoolingNHttpClientConnectionManager:245 C= onnection request: [route: {}->http://10.250.32.140:8082][total kept alive:= 1; route allocated: 7 of 1000; total allocated: 7 of 5000] > 2014.07.07 08:01:59.283 org.apache.http.impl.nio.conn.PoolingNHttpClientC= onnectionManager DEBUG [HLAPI-52] PoolingNHttpClientConnectionManager$Inter= nalPoolEntryCallback:462 Connection leased: [id: http-outgoing-20156][route= : {}->http://10.250.32.140:8082][total kept alive: 0; route allocated: 7 of= 1000; total allocated: 7 of 5000] > 2014.07.07 08:01:59.283 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [HLAPI-52] LoggingIOSession:164 http-outgoing-20156 10.= 252.152.177:61023<->10.250.32.140:8082[ACTIVE][r:r]: Set attribute http.nio= .exchange-handler > 2014.07.07 08:01:59.285 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [I/O dispatcher 61] LoggingIOSession:141 http-outgoing-= 20156 10.252.152.177:61023<->10.250.32.140:8082[ACTIVE][rw:w]: Set timeout = 20000 > 2014.07.07 08:01:59.285 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [HLAPI-52] LoggingIOSession:102 http-outgoing-20156 10.= 252.152.177:61023<->10.250.32.140:8082[ACTIVE][rw:r]: Event set [w] > 2014.07.07 08:01:59.286 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [I/O dispatcher 61] LoggingIOSession:102 http-outgoing-= 20156 10.252.152.177:61023<->10.250.32.140:8082[ACTIVE][rw:w]: Event set [w= ] > 2014.07.07 08:01:59.286 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [I/O dispatcher 61] LoggingIOSession$LoggingByteChannel= :201 http-outgoing-20156 10.252.152.177:61023<->10.250.32.140:8082[ACTIVE][= rw:w]: 1111 bytes written > 2014.07.07 08:01:59.287 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [I/O dispatcher 61] LoggingIOSession:109 http-outgoing-= 20156 10.252.152.177:61023<->10.250.32.140:8082[ACTIVE][r:w]: Event cleared= [w] > 2014.07.07 08:01:59.688 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [I/O dispatcher 61] LoggingIOSession$LoggingByteChannel= :186 http-outgoing-20156 10.252.152.177:61023<->10.250.32.140:8082[ACTIVE][= r:r]: 8443 bytes read > 2014.07.07 08:01:59.690 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [I/O dispatcher 61] LoggingIOSession$LoggingByteChannel= :186 http-outgoing-20156 10.252.152.177:61023<->10.250.32.140:8082[ACTIVE][= r:r]: 8140 bytes read > 2014.07.07 08:01:59.690 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [I/O dispatcher 61] LoggingIOSession$LoggingByteChannel= :186 http-outgoing-20156 10.252.152.177:61023<->10.250.32.140:8082[ACTIVE][= r:r]: 8190 bytes read > 2014.07.07 08:01:59.691 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [I/O dispatcher 61] LoggingIOSession:109 http-outgoing-= 20156 10.252.152.177:61023<->10.250.32.140:8082[ACTIVE][:r]: Event cleared = [r] > 2014.07.07 08:01:59.692 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [HLAPI-52] LoggingIOSession:102 http-outgoing-20156 10.= 252.152.177:61023<->10.250.32.140:8082[ACTIVE][r:r]: Event set [r] > 2014.07.07 08:01:59.693 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [I/O dispatcher 61] LoggingIOSession$LoggingByteChannel= :186 http-outgoing-20156 10.252.152.177:61023<->10.250.32.140:8082[ACTIVE][= r:r]: 8124 bytes read > 2014.07.07 08:01:59.693 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [I/O dispatcher 61] LoggingIOSession$LoggingByteChannel= :186 http-outgoing-20156 10.252.152.177:61023<->10.250.32.140:8082[ACTIVE][= r:r]: 0 bytes read > 2014.07.07 08:01:59.694 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [I/O dispatcher 61] LoggingIOSession:109 http-outgoing-= 20156 10.252.152.177:61023<->10.250.32.140:8082[ACTIVE][:r]: Event cleared = [r] > 2014.07.07 08:01:59.695 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [HLAPI-52] LoggingIOSession:102 http-outgoing-20156 10.= 252.152.177:61023<->10.250.32.140:8082[ACTIVE][r:r]: Event set [r] > 2014.07.07 08:01:59.695 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [HLAPI-52] LoggingIOSession:102 http-outgoing-20156 10.= 252.152.177:61023<->10.250.32.140:8082[ACTIVE][r:r]: Event set [r] > 2014.07.07 08:01:59.696 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [HLAPI-52] LoggingIOSession:102 http-outgoing-20156 10.= 252.152.177:61023<->10.250.32.140:8082[ACTIVE][r:r]: Event set [r] > 2014.07.07 08:01:59.697 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [I/O dispatcher 61] LoggingIOSession$LoggingByteChannel= :186 http-outgoing-20156 10.252.152.177:61023<->10.250.32.140:8082[ACTIVE][= r:r]: 0 bytes read > 2014.07.07 08:01:59.697 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [I/O dispatcher 61] LoggingIOSession$LoggingByteChannel= :186 http-outgoing-20156 10.252.152.177:61023<->10.250.32.140:8082[ACTIVE][= r:r]: 0 bytes read > 2014.07.07 08:01:59.698 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [I/O dispatcher 61] LoggingIOSession:171 http-outgoing-= 20156 10.252.152.177:61023<->10.250.32.140:8082[ACTIVE][r:r]: Remove attrib= ute http.nio.exchange-handler > 2014.07.07 08:01:59.699 org.apache.http.impl.nio.conn.PoolingNHttpClientC= onnectionManager DEBUG [I/O dispatcher 61] PoolingNHttpClientConnectionMana= ger:279 Releasing connection: [id: http-outgoing-20156][route: {}->http://1= 0.250.32.140:8082][total kept alive: 0; route allocated: 7 of 1000; total a= llocated: 7 of 5000] > 2014.07.07 08:01:59.699 org.apache.http.impl.nio.conn.PoolingNHttpClientC= onnectionManager DEBUG [I/O dispatcher 61] PoolingNHttpClientConnectionMana= ger:293 Connection [id: http-outgoing-20156][route: {}->http://10.250.32.14= 0:8082] can be kept alive for 5.0 seconds > 2014.07.07 08:01:59.700 org.apache.http.impl.nio.conn.PoolingNHttpClientC= onnectionManager DEBUG [I/O dispatcher 61] PoolingNHttpClientConnectionMana= ger:299 Connection released: [id: http-outgoing-20156][route: {}->http://10= .250.32.140:8082][total kept alive: 1; route allocated: 7 of 1000; total al= located: 7 of 5000] > {noformat} > Connection id=3D20156 has been used for communication, returned to the Po= olingNHttpClientConnectionManager (and underlying AbstractNIOConnectionPool= ). The connection may be kept alive for 5 seconds. > Now analyze the second provided exchange using the same connection: > {noformat} > 2014.07.07 08:02:04.689 org.apache.http.impl.nio.conn.PoolingNHttpClientC= onnectionManager DEBUG [HLAPI-60] PoolingNHttpClientConnectionManager:245 C= onnection request: [route: {}->http://10.250.32.140:8082][total kept alive:= 1; route allocated: 7 of 1000; total allocated: 7 of 5000] > 2014.07.07 08:02:04.690 org.apache.http.impl.nio.conn.PoolingNHttpClientC= onnectionManager DEBUG [HLAPI-60] PoolingNHttpClientConnectionManager$Inter= nalPoolEntryCallback:462 Connection leased: [id: http-outgoing-20156][route= : {}->http://10.250.32.140:8082][total kept alive: 0; route allocated: 7 of= 1000; total allocated: 7 of 5000] > 2014.07.07 08:02:04.691 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [I/O dispatcher 61] LoggingIOSession$LoggingByteChannel= :186 http-outgoing-20156 10.252.152.177:61023<->10.250.32.140:8082[ACTIVE][= r:r]: -1 bytes read > 2014.07.07 08:02:04.691 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [HLAPI-60] LoggingIOSession:164 http-outgoing-20156 10.= 252.152.177:61023<->10.250.32.140:8082[ACTIVE][r:r]: Set attribute http.nio= .exchange-handler > 2014.07.07 08:02:04.692 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [I/O dispatcher 61] LoggingIOSession:115 http-outgoing-= 20156 10.252.152.177:61023<->10.250.32.140:8082[ACTIVE][r:r]: Close > 2014.07.07 08:02:04.692 org.apache.http.impl.nio.conn.ManagedNHttpClientC= onnectionImpl DEBUG [HLAPI-60] LoggingIOSession:102 http-outgoing-20156 10.= 252.152.177:61023<->10.250.32.140:8082[ACTIVE][rw:r]: Event set [w] > {noformat} > Notice the time difference between exchanges being about 5 seconds. > 1. At the keep-alive boundary, the connection is requested and leased fro= m the PoolingNHttpClientConnectionManager. > 2. Then, the I/O Dispatcher with id=3D61, which performed previous exchan= ge, attempts to read from the connection, receiving no data (-1 bytes). > 3. In the meantime, HLAPI-60 thread that requested the connection, sets t= he http.nio.exchange-handler attribute. > 4. However the connection is already recognized as 'dead' by the I/O disp= atcher and is then closed. > 5. In the end, the PoolingNHttpClientConnectionManager prepares to write = to the connection. This is the last activity for connection id=3D20156. It = is never released to the connection pool. > We use Http Components in conjunction with CXF and in the end get a Socke= tTimeoutException from Async Transport: > {noformat} > Caused by: java.net.SocketTimeoutException: Read Timeout > at org.apache.cxf.transport.http.asyncclient.AsyncHTTPConduit$Asy= ncWrappedOutputStream.getHttpResponse(AsyncHTTPConduit.java:614) > at org.apache.cxf.transport.http.asyncclient.AsyncHTTPConduit$Asy= ncWrappedOutputStream.getResponseCode(AsyncHTTPConduit.java:699) > at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.= handleResponseInternal(HTTPConduit.java:1555) > at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.= handleResponse(HTTPConduit.java:1525) > at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.= close(HTTPConduit.java:1330) > ... 25 common frames omitted > {noformat} > This scenario is non-deterministic. There are about 10-15 connections lea= ked this way from the connection pool of 1000 each day. The connection pool= slowly degrades and in the end requires a restart of the whole component. = Our solution is suppose to be HA, so this is a major problem for us and for= our business client. > We have also noticed, that: > 1. If the connection is reused earlier (i.e. after 3-4 seconds), there is= no read attempt from the I/O dispatcher that causes the '-1' result in the= negative scenario. Connection is used to perform a valid exchange and may = be further kept alive. Maybe it is a matter of setting the 'http.nio.exchan= ge-handler' attribute before the I/O dispatcher attempts to read from conne= ction due to keep-alive timeout? > 2. Also, if around the keep-alive time boundary the connection is not reu= sed, it does not leak from the connection pool (it is never leased after be= ing closed by the I/O dispatcher). > The negative scenario occurs only if there is an interleave between the I= /O dispatcher closing the connection and the connection being leased from P= oolingNHttpClientConnectionManager at the keep-alive boundary - about 5 sec= onds in our case. -- This message was sent by Atlassian JIRA (v6.2#6252) --------------------------------------------------------------------- To unsubscribe, e-mail: dev-unsubscribe@hc.apache.org For additional commands, e-mail: dev-help@hc.apache.org