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: [email protected]
For additional commands, e-mail: [email protected]
