hc-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Przemysław Ołtarzewski (JIRA) <j...@apache.org>
Subject [jira] [Created] (HTTPCORE-387) Connection leak due to race condition on keep-alive boundary
Date Mon, 07 Jul 2014 11:20:33 GMT
Przemysław Ołtarzewski created HTTPCORE-387:
-----------------------------------------------

             Summary: 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ław Ołtarzewski


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.PoolingNHttpClientConnectionManager
DEBUG [HLAPI-52] PoolingNHttpClientConnectionManager:245 Connection 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.PoolingNHttpClientConnectionManager
DEBUG [HLAPI-52] PoolingNHttpClientConnectionManager$InternalPoolEntryCallback: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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl DEBUG
[I/O dispatcher 61] LoggingIOSession:171 http-outgoing-20156 10.252.152.177:61023<->10.250.32.140:8082[ACTIVE][r:r]:
Remove attribute http.nio.exchange-handler
2014.07.07 08:01:59.699 org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager
DEBUG [I/O dispatcher 61] PoolingNHttpClientConnectionManager:279 Releasing connection: [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.699 org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager
DEBUG [I/O dispatcher 61] PoolingNHttpClientConnectionManager:293 Connection [id: http-outgoing-20156][route:
{}->http://10.250.32.140:8082] can be kept alive for 5.0 seconds
2014.07.07 08:01:59.700 org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager
DEBUG [I/O dispatcher 61] PoolingNHttpClientConnectionManager:299 Connection released: [id:
http-outgoing-20156][route: {}->http://10.250.32.140:8082][total kept alive: 1; route allocated:
7 of 1000; total allocated: 7 of 5000]
{noformat}

Connection id=20156 has been used for communication, returned to the PoolingNHttpClientConnectionManager
(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.PoolingNHttpClientConnectionManager
DEBUG [HLAPI-60] PoolingNHttpClientConnectionManager:245 Connection 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.PoolingNHttpClientConnectionManager
DEBUG [HLAPI-60] PoolingNHttpClientConnectionManager$InternalPoolEntryCallback: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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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.ManagedNHttpClientConnectionImpl 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 from the PoolingNHttpClientConnectionManager.

2. Then, the I/O Dispatcher with id=61, which performed previous exchange, attempts to read
from the connection, receiving no data (-1 bytes).

3. In the meantime, HLAPI-60 thread that requested the connection, sets the http.nio.exchange-handler
attribute.

4. However the connection is already recognized as 'dead' by the I/O dispatcher and is then
closed.

5. In the end, the PoolingNHttpClientConnectionManager prepares to write to the connection.
This is the last activity for connection id=20156. It is never released to the connection
pool.

We use Http Components in conjunction with CXF and in the end get a SocketTimeoutException
from Async Transport:

{noformat}
Caused by: java.net.SocketTimeoutException: Read Timeout
        at org.apache.cxf.transport.http.asyncclient.AsyncHTTPConduit$AsyncWrappedOutputStream.getHttpResponse(AsyncHTTPConduit.java:614)
        at org.apache.cxf.transport.http.asyncclient.AsyncHTTPConduit$AsyncWrappedOutputStream.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 leaked 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.exchange-handler' attribute before the I/O dispatcher attempts to read from
connection due to keep-alive timeout?

2. Also, if around the keep-alive time boundary the connection is not reused, it does not
leak from the connection pool (it is never leased after being 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 PoolingNHttpClientConnectionManager at
the keep-alive boundary - about 5 seconds 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


Mime
View raw message