Mailing-List: contact dev-help@hc.apache.org; run by ezmlm
Precedence: bulk
Reply-To: "HttpComponents Project" <dev@hc.apache.org>
Date: Mon, 7 Jul 2014 15:54:34 +0000 (UTC)
From: "Oleg Kalnichevski (JIRA)" <jira@apache.org>
To: dev@hc.apache.org
Message-ID: <JIRA.12725721.1404731937111.12772.1404748474664@arcas>
In-Reply-To: <JIRA.12725721.1404731937111@arcas>
References: <JIRA.12725721.1404731937111@arcas>
Subject: [jira] [Updated] (HTTPCORE-387) 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


     [ https://issues.apache.org/jira/browse/HTTPCORE-387?page=3Dcom.atlass=
ian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Oleg Kalnichevski updated HTTPCORE-387:
---------------------------------------

    Fix Version/s: 4.4-alpha2
                   4.3.3

> Connection leak due to race condition on keep-alive boundary
> ------------------------------------------------------------
>
>                 Key: HTTPCORE-387
>                 URL: https://issues.apache.org/jira/browse/HTTPCORE-387
>             Project: HttpComponents HttpCore
>          Issue Type: Bug
>          Components: HttpCore NIO
>    Affects Versions: 4.3.2
>         Environment: SunOS 5.10
>            Reporter: Przemys=C5=82aw O=C5=82tarzewski
>              Labels: connection, cxf, httpcore, leak
>             Fix For: 4.3.3, 4.4-alpha2
>
>
> 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