hc-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Oleg Kalnichevski (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (HTTPCLIENT-1396) PoolingClientConnectionManager seems to create one connection too many?
Date Mon, 09 Sep 2013 15:36:52 GMT

    [ https://issues.apache.org/jira/browse/HTTPCLIENT-1396?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13761936#comment-13761936
] 

Oleg Kalnichevski commented on HTTPCLIENT-1396:
-----------------------------------------------

{noformat}
2013-09-09 17:14:14.282:INFO::Logging to STDERR via org.mortbay.log.StdErrLog
2013-09-09 17:14:14.283:INFO::jetty-6.1.26
2013-09-09 17:14:14.293:INFO::Started SocketConnector@0.0.0.0:50116
sending requests to http://localhost:50116/
[DEBUG] PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 0 of 3; total allocated: 0 of 100]
[DEBUG] PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 0 of 3; total allocated: 0 of 100]
[DEBUG] PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 0 of 3; total allocated: 0 of 100]
[DEBUG] PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 0 of 3; total allocated: 0 of 100]
[DEBUG] PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 0 of 3; total allocated: 0 of 100]
[DEBUG] PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 0 of 3; total allocated: 0 of 100]
[DEBUG] PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 0 of 3; total allocated: 0 of 100]
[DEBUG] PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 0 of 3; total allocated: 0 of 100]
[DEBUG] PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 0 of 3; total allocated: 0 of 100]
[DEBUG] PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 0 of 3; total allocated: 0 of 100]
[DEBUG] PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 0 of 3; total allocated: 0 of 100]
[DEBUG] PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 0 of 3; total allocated: 0 of 100]
[DEBUG] PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 0 of 3; total allocated: 0 of 100]
[DEBUG] PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 0 of 3; total allocated: 0 of 100]
[DEBUG] PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 0 of 3; total allocated: 0 of 100]
[DEBUG] PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 0 of 3; total allocated: 0 of 100]
[DEBUG] PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 0 of 3; total allocated: 0 of 100]
[DEBUG] PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 0 of 3; total allocated: 0 of 100]
[DEBUG] PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 0 of 3; total allocated: 0 of 100]
[DEBUG] PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 0 of 3; total allocated: 0 of 100]
[DEBUG] PoolingClientConnectionManager - Connection leased: [id: 1][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] PoolingClientConnectionManager - Connection leased: [id: 2][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] PoolingClientConnectionManager - Connection leased: [id: 0][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnectionOperator - Connecting to localhost:50116
[DEBUG] DefaultClientConnectionOperator - Connecting to localhost:50116
[DEBUG] DefaultClientConnectionOperator - Connecting to localhost:50116
[DEBUG] DefaultClientConnection - Sending request: GET /?p=10 HTTP/1.1
[DEBUG] DefaultClientConnection - Sending request: GET /?p=5 HTTP/1.1
[DEBUG] DefaultClientConnection - Sending request: GET /?p=11 HTTP/1.1
[DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK
[DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK
[DEBUG] PoolingClientConnectionManager - Connection [id: 2][route: {}->http://localhost:50116]
can be kept alive indefinitely
[DEBUG] PoolingClientConnectionManager - Connection [id: 1][route: {}->http://localhost:50116]
can be kept alive indefinitely
[DEBUG] PoolingClientConnectionManager - Connection leased: [id: 2][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] PoolingClientConnectionManager - Connection released: [id: 2][route: {}->http://localhost:50116][total
kept alive: 1; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] PoolingClientConnectionManager - Connection leased: [id: 1][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] PoolingClientConnectionManager - Connection released: [id: 1][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnection - Sending request: GET /?p=9 HTTP/1.1
[DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK
[DEBUG] DefaultClientConnection - Sending request: GET /?p=12 HTTP/1.1
[DEBUG] PoolingClientConnectionManager - Connection [id: 2][route: {}->http://localhost:50116]
can be kept alive indefinitely
[DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK
[DEBUG] PoolingClientConnectionManager - Connection leased: [id: 2][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] PoolingClientConnectionManager - Connection released: [id: 2][route: {}->http://localhost:50116][total
kept alive: 1; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] PoolingClientConnectionManager - Connection [id: 1][route: {}->http://localhost:50116]
can be kept alive indefinitely
[DEBUG] PoolingClientConnectionManager - Connection released: [id: 1][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnection - Sending request: GET /?p=6 HTTP/1.1
[DEBUG] PoolingClientConnectionManager - Connection leased: [id: 1][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK
[DEBUG] PoolingClientConnectionManager - Connection [id: 2][route: {}->http://localhost:50116]
can be kept alive indefinitely
[DEBUG] PoolingClientConnectionManager - Connection released: [id: 2][route: {}->http://localhost:50116][total
kept alive: 1; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] PoolingClientConnectionManager - Connection leased: [id: 2][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnection - Sending request: GET /?p=20 HTTP/1.1
[DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK
[DEBUG] PoolingClientConnectionManager - Connection [id: 1][route: {}->http://localhost:50116]
can be kept alive indefinitely
[DEBUG] PoolingClientConnectionManager - Connection released: [id: 1][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnection - Sending request: GET /?p=19 HTTP/1.1
[DEBUG] PoolingClientConnectionManager - Connection leased: [id: 1][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK
[DEBUG] PoolingClientConnectionManager - Connection [id: 2][route: {}->http://localhost:50116]
can be kept alive indefinitely
[DEBUG] PoolingClientConnectionManager - Connection released: [id: 2][route: {}->http://localhost:50116][total
kept alive: 1; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] PoolingClientConnectionManager - Connection leased: [id: 2][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnection - Sending request: GET /?p=14 HTTP/1.1
[DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK
[DEBUG] PoolingClientConnectionManager - Connection [id: 1][route: {}->http://localhost:50116]
can be kept alive indefinitely
[DEBUG] PoolingClientConnectionManager - Connection leased: [id: 1][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnection - Sending request: GET /?p=17 HTTP/1.1
[DEBUG] PoolingClientConnectionManager - Connection released: [id: 1][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK
[DEBUG] PoolingClientConnectionManager - Connection [id: 2][route: {}->http://localhost:50116]
can be kept alive indefinitely
[DEBUG] DefaultClientConnection - Sending request: GET /?p=7 HTTP/1.1
[DEBUG] PoolingClientConnectionManager - Connection leased: [id: 2][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] PoolingClientConnectionManager - Connection released: [id: 2][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK
[DEBUG] PoolingClientConnectionManager - Connection [id: 1][route: {}->http://localhost:50116]
can be kept alive indefinitely
[DEBUG] PoolingClientConnectionManager - Connection released: [id: 1][route: {}->http://localhost:50116][total
kept alive: 1; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnection - Sending request: GET /?p=8 HTTP/1.1
[DEBUG] PoolingClientConnectionManager - Connection leased: [id: 1][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK
[DEBUG] PoolingClientConnectionManager - Connection [id: 2][route: {}->http://localhost:50116]
can be kept alive indefinitely
[DEBUG] PoolingClientConnectionManager - Connection released: [id: 2][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] PoolingClientConnectionManager - Connection leased: [id: 2][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnection - Sending request: GET /?p=18 HTTP/1.1
[DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK
[DEBUG] PoolingClientConnectionManager - Connection [id: 1][route: {}->http://localhost:50116]
can be kept alive indefinitely
[DEBUG] PoolingClientConnectionManager - Connection released: [id: 1][route: {}->http://localhost:50116][total
kept alive: 1; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] PoolingClientConnectionManager - Connection leased: [id: 1][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnection - Sending request: GET /?p=13 HTTP/1.1
[DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK
[DEBUG] PoolingClientConnectionManager - Connection [id: 2][route: {}->http://localhost:50116]
can be kept alive indefinitely
[DEBUG] PoolingClientConnectionManager - Connection released: [id: 2][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnection - Sending request: GET /?p=1 HTTP/1.1
[DEBUG] PoolingClientConnectionManager - Connection leased: [id: 2][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK
[DEBUG] PoolingClientConnectionManager - Connection [id: 1][route: {}->http://localhost:50116]
can be kept alive indefinitely
[DEBUG] PoolingClientConnectionManager - Connection released: [id: 1][route: {}->http://localhost:50116][total
kept alive: 1; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] PoolingClientConnectionManager - Connection leased: [id: 1][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnection - Sending request: GET /?p=15 HTTP/1.1
[DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK
[DEBUG] PoolingClientConnectionManager - Connection [id: 2][route: {}->http://localhost:50116]
can be kept alive indefinitely
[DEBUG] PoolingClientConnectionManager - Connection released: [id: 2][route: {}->http://localhost:50116][total
kept alive: 1; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnection - Sending request: GET /?p=4 HTTP/1.1
[DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK
[DEBUG] PoolingClientConnectionManager - Connection [id: 1][route: {}->http://localhost:50116]
can be kept alive indefinitely
[DEBUG] PoolingClientConnectionManager - Connection released: [id: 1][route: {}->http://localhost:50116][total
kept alive: 2; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] PoolingClientConnectionManager - Connection leased: [id: 1][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] PoolingClientConnectionManager - Connection leased: [id: 2][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
response  OK: 1
response  OK: 2
response  OK: 3
response  OK: 4
response  OK: 5
response  OK: 6
response  OK: 7
response  OK: 8
response  OK: 9
[DEBUG] DefaultClientConnection - Sending request: GET /?p=3 HTTP/1.1
[DEBUG] DefaultClientConnection - Sending request: GET /?p=16 HTTP/1.1
[DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK
[DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK
[DEBUG] PoolingClientConnectionManager - Connection [id: 1][route: {}->http://localhost:50116]
can be kept alive indefinitely
[DEBUG] PoolingClientConnectionManager - Connection [id: 2][route: {}->http://localhost:50116]
can be kept alive indefinitely
[DEBUG] PoolingClientConnectionManager - Connection leased: [id: 1][route: {}->http://localhost:50116][total
kept alive: 0; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] PoolingClientConnectionManager - Connection released: [id: 1][route: {}->http://localhost:50116][total
kept alive: 1; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] PoolingClientConnectionManager - Connection released: [id: 2][route: {}->http://localhost:50116][total
kept alive: 1; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnection - Sending request: GET /?p=2 HTTP/1.1
[DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1 200 OK
[DEBUG] PoolingClientConnectionManager - Connection [id: 1][route: {}->http://localhost:50116]
can be kept alive indefinitely
[DEBUG] PoolingClientConnectionManager - Connection released: [id: 1][route: {}->http://localhost:50116][total
kept alive: 2; route allocated: 3 of 3; total allocated: 3 of 100]
[DEBUG] DefaultClientConnection - Connection 0.0.0.0:49116<->127.0.0.1:50116 closed
[DEBUG] DefaultClientConnection - Connection 0.0.0.0:49116<->127.0.0.1:50116 closed
[DEBUG] DefaultClientConnection - Connection 0.0.0.0:49116<->127.0.0.1:50116 shut down
[DEBUG] DefaultClientConnection - Connection 0.0.0.0:49116<->127.0.0.1:50116 closed
[DEBUG] PoolingClientConnectionManager - Connection released: [id: 0][route: {}->http://localhost:50116][total
kept alive: 2; route allocated: 2 of 3; total allocated: 2 of 100]
[DEBUG] PoolingClientConnectionManager - Connection manager is shutting down
[DEBUG] DefaultClientConnection - Connection 0.0.0.0:49114<->127.0.0.1:50116 closed
[DEBUG] DefaultClientConnection - Connection 0.0.0.0:49113<->127.0.0.1:50116 closed
[DEBUG] DefaultClientConnection - Connection 0.0.0.0:49114<->127.0.0.1:50116 closed
[DEBUG] DefaultClientConnection - Connection 0.0.0.0:49113<->127.0.0.1:50116 closed
[DEBUG] PoolingClientConnectionManager - Connection manager shut down
2013-09-09 17:14:20.447:INFO::Stopped SocketConnector@0.0.0.0:50116
response NOK: java.net.SocketTimeoutException: Read timed out
response  OK: 11
response  OK: 12
response  OK: 13
response  OK: 14
response  OK: 15
response  OK: 16
response  OK: 17
response  OK: 18
response  OK: 19
response  OK: 20

{noformat}

As far as I can tell HttpClient makes use of three concurrent connections only (see connection
ids in the log)

Please also note that the request that fails is the first one that gets executed. So, it seems
that Jetty does not handle it in time and it times out.

Oleg  
                
> PoolingClientConnectionManager seems to create one connection too many?
> -----------------------------------------------------------------------
>
>                 Key: HTTPCLIENT-1396
>                 URL: https://issues.apache.org/jira/browse/HTTPCLIENT-1396
>             Project: HttpComponents HttpClient
>          Issue Type: Bug
>          Components: HttpClient
>    Affects Versions: 4.2.5
>         Environment: Any
>            Reporter: Neeme Praks
>            Priority: Minor
>         Attachments: TestPoolingConnManagerWithJetty.java
>
>
> See attached Junit test.
> You'll also need Jetty dependency:
>     <dependency>
>       <groupId>org.mortbay.jetty</groupId>
>       <artifactId>jetty</artifactId>
>       <version>6.1.26</version>
>       <scope>test</scope>
>     </dependency>
> What the test does:
> * sets up a HTTP server (Jetty) with N number of threads processing requests (MAX_CONNECTIONS
constant).
> * sets up HttpClient with same N number of max connections (PoolingClientConnectionManager)
> * sets up X workers, trying to connect to the server at the same time.
> *Expected result*: although throughput is throttled (limited number of threads and connections),
all workers should get successful response.
> *Actual result:* at least one of the workers will get "java.net.SocketTimeoutException:
Read timed out" error.
> *Workaround:* limit HttpClient max connections to MAX_CONNECTIONS-1 and the test will
pass.
> Seems to be some off-by-one bug somewhere in PoolingClientConnectionManager.

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@hc.apache.org
For additional commands, e-mail: dev-help@hc.apache.org


Mime
View raw message