[
https://issues.apache.org/jira/browse/HTTPASYNC-79?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14093441#comment-14093441
]
Gerald Turner commented on HTTPASYNC-79:
----------------------------------------
I have a problem with the fix for this bug. After upgrading from 4.0.1 to
4.0.2 a unit test is consistently failing with ConnectionClosedException.
I've checked out the 4.0.x branch, reverted the change, and the unit test
succeeds as before.
{code}
Index:
httpasyncclient/src/main/java/org/apache/http/impl/nio/client/DefaultClientExchangeHandlerImpl.java
===================================================================
---
httpasyncclient/src/main/java/org/apache/http/impl/nio/client/DefaultClientExchangeHandlerImpl.java
(revision 1617360)
+++
httpasyncclient/src/main/java/org/apache/http/impl/nio/client/DefaultClientExchangeHandlerImpl.java
(working copy)
@@ -302,10 +302,11 @@
return;
}
-
managedConn.getContext().setAttribute(HttpAsyncRequestExecutor.HTTP_HANDLER,
this);
- managedConn.requestOutput();
if (!managedConn.isOpen()) {
failed(new ConnectionClosedException("Connection closed"));
+ } else {
+
managedConn.getContext().setAttribute(HttpAsyncRequestExecutor.HTTP_HANDLER,
this);
+ managedConn.requestOutput();
}
} catch (final RuntimeException runex) {
failed(runex);
{code}
Debug output with unmodified 4.0.2:
{noformat}
0 [main] DEBUG com.xo.util.http.HttpClientUtilTest - setUp: Starting
HttpServer on btnwks10.corp.inthosts.net:8181
40 [main] INFO org.mortbay.log - Logging to
org.slf4j.impl.Log4jLoggerAdapter(org.mortbay.log) via org.mortbay.log.Slf4jLog
161 [main] INFO org.mortbay.log - jetty-6.1.26
239 [main] INFO org.mortbay.log - Started [email protected]:8181
941 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
request: [route: {}->http://btnwks10.corp.inthosts.net:8181][total kept alive:
0; route allocated: 0 of 12; total allocated: 0 of 250]
976 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
leased: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 0; route
allocated: 1 of 12; total allocated: 1 of 250]
979 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:]: Set
attribute http.nio.exchange-handler
979 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:]: Event set
[w]
980 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
request: [route: {}->http://btnwks10.corp.inthosts.net:8181][total kept alive:
0; route allocated: 1 of 12; total allocated: 1 of 250]
981 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:]: Set
attribute http.nio.http-exchange-state
981 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
leased: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 0; route
allocated: 2 of 12; total allocated: 2 of 250]
981 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:]: Set
attribute http.nio.exchange-handler
981 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:]: Event set
[w]
981 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:]: Set
attribute http.nio.http-exchange-state
984 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:]: Set
timeout 1000000000
984 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:]: Set
timeout 1000000000
986 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:]: Event set
[w]
986 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:]: Event set
[w]
988 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:w]: 148 bytes
written
988 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:w]: 148 bytes
written
988 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:w]: Event
cleared [w]
988 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:w]: Event
cleared [w]
1057 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: 154 bytes
read
1057 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: 190 bytes
read
1072 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: 36 bytes
read
1078 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: Remove
attribute http.nio.exchange-handler
1078 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: Remove
attribute http.nio.exchange-handler
1078 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Releasing
connection: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 0; route
allocated: 2 of 12; total allocated: 2 of 250]
1078 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Releasing
connection: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 0; route
allocated: 2 of 12; total allocated: 2 of 250]
1078 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
[id: http-outgoing-0][route: {}->http://btnwks10.corp.inthosts.net:8181] can be
kept alive for 30.0 seconds
1078 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
[id: http-outgoing-1][route: {}->http://btnwks10.corp.inthosts.net:8181] can be
kept alive for 30.0 seconds
1078 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
released: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 2; route
allocated: 2 of 12; total allocated: 2 of 250]
1078 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
released: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 2; route
allocated: 2 of 12; total allocated: 2 of 250]
1080 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
request: [route: {}->http://btnwks10.corp.inthosts.net:8181][total kept alive:
2; route allocated: 2 of 12; total allocated: 2 of 250]
1080 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
leased: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 1; route
allocated: 2 of 12; total allocated: 2 of 250]
1080 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: Set
attribute http.nio.exchange-handler
1081 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:r]: Event set
[w]
1081 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:w]: Set
timeout 1000000000
1081 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:w]: Event set
[w]
1081 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
request: [route: {}->http://btnwks10.corp.inthosts.net:8181][total kept alive:
1; route allocated: 2 of 12; total allocated: 2 of 250]
1081 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
leased: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 0; route
allocated: 2 of 12; total allocated: 2 of 250]
1081 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: Set
attribute http.nio.exchange-handler
1082 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:r]: Event set
[w]
1082 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:w]: 148 bytes
written
1082 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:w]: Event
cleared [w]
1082 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:w]: Set
timeout 1000000000
1082 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:w]: Event set
[w]
1083 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:w]: 148 bytes
written
1083 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:w]: Event
cleared [w]
1083 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: 190 bytes
read
1085 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: Remove
attribute http.nio.exchange-handler
1085 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Releasing
connection: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 0; route
allocated: 2 of 12; total allocated: 2 of 250]
1085 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
[id: http-outgoing-0][route: {}->http://btnwks10.corp.inthosts.net:8181] can be
kept alive for 30.0 seconds
1085 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
released: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 1; route
allocated: 2 of 12; total allocated: 2 of 250]
1089 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: 190 bytes
read
1090 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: Remove
attribute http.nio.exchange-handler
1090 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Releasing
connection: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 1; route
allocated: 2 of 12; total allocated: 2 of 250]
1090 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
[id: http-outgoing-1][route: {}->http://btnwks10.corp.inthosts.net:8181] can be
kept alive for 30.0 seconds
1090 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
released: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 2; route
allocated: 2 of 12; total allocated: 2 of 250]
1091 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
request: [route: {}->http://btnwks10.corp.inthosts.net:8181][total kept alive:
2; route allocated: 2 of 12; total allocated: 2 of 250]
1091 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
leased: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 1; route
allocated: 2 of 12; total allocated: 2 of 250]
1091 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: Set
attribute http.nio.exchange-handler
1092 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:r]: Event set
[w]
1092 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
request: [route: {}->http://btnwks10.corp.inthosts.net:8181][total kept alive:
1; route allocated: 2 of 12; total allocated: 2 of 250]
1092 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
leased: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 0; route
allocated: 2 of 12; total allocated: 2 of 250]
1092 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: Set
attribute http.nio.exchange-handler
1093 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:r]: Event set
[w]
1093 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:w]: Set
timeout 1000000000
1093 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:w]: Event set
[w]
1094 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:w]: 148 bytes
written
1094 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:w]: Event
cleared [w]
1094 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: 190 bytes
read
1096 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:w]: Set
timeout 1000000000
1096 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:w]: Event set
[w]
1096 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:w]: 148 bytes
written
1096 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:w]: Event
cleared [w]
1096 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: Remove
attribute http.nio.exchange-handler
1097 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Releasing
connection: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 0; route
allocated: 2 of 12; total allocated: 2 of 250]
1097 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
[id: http-outgoing-0][route: {}->http://btnwks10.corp.inthosts.net:8181] can be
kept alive for 30.0 seconds
1097 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
released: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 1; route
allocated: 2 of 12; total allocated: 2 of 250]
1101 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: 190 bytes
read
1102 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: Remove
attribute http.nio.exchange-handler
1102 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Releasing
connection: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 1; route
allocated: 2 of 12; total allocated: 2 of 250]
1102 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
[id: http-outgoing-1][route: {}->http://btnwks10.corp.inthosts.net:8181] can be
kept alive for 30.0 seconds
1102 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
released: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 2; route
allocated: 2 of 12; total allocated: 2 of 250]
1103 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
request: [route: {}->http://btnwks10.corp.inthosts.net:8181][total kept alive:
2; route allocated: 2 of 12; total allocated: 2 of 250]
1103 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
leased: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 1; route
allocated: 2 of 12; total allocated: 2 of 250]
1103 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: Set
attribute http.nio.exchange-handler
1103 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:r]: Event set
[w]
1103 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:w]: Set
timeout 1000000000
1104 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:w]: Event set
[w]
1104 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
request: [route: {}->http://btnwks10.corp.inthosts.net:8181][total kept alive:
1; route allocated: 2 of 12; total allocated: 2 of 250]
1104 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
leased: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 0; route
allocated: 2 of 12; total allocated: 2 of 250]
1104 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: Set
attribute http.nio.exchange-handler
1104 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:w]: 148 bytes
written
1104 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:r]: Event set
[w]
1105 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:w]: Event
cleared [w]
1105 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:w]: Set
timeout 1000000000
1105 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: 190 bytes
read
1105 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:w]: Event set
[w]
1106 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: Remove
attribute http.nio.exchange-handler
1106 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:w]: 148 bytes
written
1106 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Releasing
connection: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 0; route
allocated: 2 of 12; total allocated: 2 of 250]
1106 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:w]: Event
cleared [w]
1106 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
[id: http-outgoing-1][route: {}->http://btnwks10.corp.inthosts.net:8181] can be
kept alive for 30.0 seconds
1106 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
released: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 1; route
allocated: 2 of 12; total allocated: 2 of 250]
1106 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: 190 bytes
read
1107 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: Remove
attribute http.nio.exchange-handler
1107 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Releasing
connection: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 1; route
allocated: 2 of 12; total allocated: 2 of 250]
1107 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
[id: http-outgoing-0][route: {}->http://btnwks10.corp.inthosts.net:8181] can be
kept alive for 30.0 seconds
1107 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
released: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 2; route
allocated: 2 of 12; total allocated: 2 of 250]
1108 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
request: [route: {}->http://btnwks10.corp.inthosts.net:8181][total kept alive:
2; route allocated: 2 of 12; total allocated: 2 of 250]
1108 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
leased: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 1; route
allocated: 2 of 12; total allocated: 2 of 250]
1108 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: Set
attribute http.nio.exchange-handler
1108 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:r]: Event set
[w]
1108 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:w]: Set
timeout 1000000000
1109 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:w]: Event set
[w]
1109 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
request: [route: {}->http://btnwks10.corp.inthosts.net:8181][total kept alive:
1; route allocated: 2 of 12; total allocated: 2 of 250]
1109 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:w]: 148 bytes
written
1110 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:w]: Event
cleared [w]
1110 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: 190 bytes
read
1111 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: Remove
attribute http.nio.exchange-handler
1114 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Releasing
connection: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 0; route
allocated: 2 of 12; total allocated: 2 of 250]
1114 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
leased: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 0; route
allocated: 2 of 12; total allocated: 2 of 250]
1114 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
[id: http-outgoing-0][route: {}->http://btnwks10.corp.inthosts.net:8181] can be
kept alive for 30.0 seconds
1114 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: Set
attribute http.nio.exchange-handler
1114 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
released: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 1; route
allocated: 2 of 12; total allocated: 2 of 250]
1114 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:r]: Event set
[w]
1114 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:w]: Set
timeout 1000000000
1114 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:w]: Event set
[w]
1115 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:w]: 148 bytes
written
1115 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:w]: Event
cleared [w]
1115 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: 190 bytes
read
1116 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: Remove
attribute http.nio.exchange-handler
1116 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Releasing
connection: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 1; route
allocated: 2 of 12; total allocated: 2 of 250]
1116 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
[id: http-outgoing-1][route: {}->http://btnwks10.corp.inthosts.net:8181] can be
kept alive for 30.0 seconds
1116 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
released: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 2; route
allocated: 2 of 12; total allocated: 2 of 250]
1117 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
request: [route: {}->http://btnwks10.corp.inthosts.net:8181][total kept alive:
2; route allocated: 2 of 12; total allocated: 2 of 250]
1117 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
leased: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 1; route
allocated: 2 of 12; total allocated: 2 of 250]
1117 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: Set
attribute http.nio.exchange-handler
1118 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:r]: Event set
[w]
1118 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:w]: Set
timeout 1000000000
1118 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:w]: Event set
[w]
1118 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:w]: 148 bytes
written
1118 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:w]: Event
cleared [w]
1119 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: 190 bytes
read
1119 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
request: [route: {}->http://btnwks10.corp.inthosts.net:8181][total kept alive:
1; route allocated: 2 of 12; total allocated: 2 of 250]
1119 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
leased: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 0; route
allocated: 2 of 12; total allocated: 2 of 250]
1119 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: Set
attribute http.nio.exchange-handler
1119 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:r]: Event set
[w]
1120 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: Remove
attribute http.nio.exchange-handler
1120 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:w]: Set
timeout 1000000000
1120 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Releasing
connection: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 0; route
allocated: 2 of 12; total allocated: 2 of 250]
1120 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
[id: http-outgoing-1][route: {}->http://btnwks10.corp.inthosts.net:8181] can be
kept alive for 30.0 seconds
1120 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:w]: Event set
[w]
1120 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
released: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 1; route
allocated: 2 of 12; total allocated: 2 of 250]
1121 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:w]: 148 bytes
written
1121 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:w]: Event
cleared [w]
1121 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: 190 bytes
read
1122 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: Remove
attribute http.nio.exchange-handler
1122 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Releasing
connection: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 1; route
allocated: 2 of 12; total allocated: 2 of 250]
1122 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
[id: http-outgoing-0][route: {}->http://btnwks10.corp.inthosts.net:8181] can be
kept alive for 30.0 seconds
1122 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
released: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 2; route
allocated: 2 of 12; total allocated: 2 of 250]
1123 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
request: [route: {}->http://btnwks10.corp.inthosts.net:8181][total kept alive:
2; route allocated: 2 of 12; total allocated: 2 of 250]
1123 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
leased: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 1; route
allocated: 2 of 12; total allocated: 2 of 250]
1123 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: Set
attribute http.nio.exchange-handler
1123 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:r]: Event set
[w]
1123 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:w]: Set
timeout 1000000000
1123 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:w]: Event set
[w]
1123 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][rw:w]: 148 bytes
written
1124 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:w]: Event
cleared [w]
1124 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: 190 bytes
read
1124 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
request: [route: {}->http://btnwks10.corp.inthosts.net:8181][total kept alive:
1; route allocated: 2 of 12; total allocated: 2 of 250]
1124 [main] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
leased: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 0; route
allocated: 2 of 12; total allocated: 2 of 250]
1125 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: Set
attribute http.nio.exchange-handler
1125 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: Remove
attribute http.nio.exchange-handler
1125 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:w]: Set
timeout 1000000000
1125 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:w]: Event set
[w]
1126 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][rw:w]: 148 bytes
written
1126 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:w]: Event
cleared [w]
1126 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Releasing
connection: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 0; route
allocated: 2 of 12; total allocated: 2 of 250]
1126 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
[id: http-outgoing-0][route: {}->http://btnwks10.corp.inthosts.net:8181] can be
kept alive for 30.0 seconds
1126 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: 190 bytes
read
1127 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
released: [id: http-outgoing-0][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 1; route
allocated: 2 of 12; total allocated: 2 of 250]
1127 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: Remove
attribute http.nio.exchange-handler
1127 [main] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: Event set
[w]
1128 [main] FATAL com.xo.util.http.HttpClientUtilTest -
org.apache.http.HttpException: Failed to download
http://btnwks10.corp.inthosts.net:8181/test/Test/URL1:
ConnectionClosedException: Connection closed
1128 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Releasing
connection: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 1; route
allocated: 2 of 12; total allocated: 2 of 250]
1128 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
[id: http-outgoing-1][route: {}->http://btnwks10.corp.inthosts.net:8181] can be
kept alive for 30.0 seconds
1128 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
released: [id: http-outgoing-1][route:
{}->http://btnwks10.corp.inthosts.net:8181][total kept alive: 2; route
allocated: 2 of 12; total allocated: 2 of 250]
1135 [main] INFO org.mortbay.log - Stopped [email protected]:8181
1137 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: -1 bytes
read
1137 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-0] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-0 10.88.34.128:60998<->10.88.34.128:8181[ACTIVE][r:r]: Close
1137 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: -1 bytes
read
1137 [HttpClientUtilTest/2.0;HttpClient/4.3.5-Reactor-1] DEBUG
org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl -
http-outgoing-1 10.88.34.128:60999<->10.88.34.128:8181[ACTIVE][r:r]: Close
{noformat}
> 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ław Ołtarzewski
> 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.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]
