hc-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Kirill Barkunov (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (HTTPASYNC-109) Requests in AbstractNIOConnPool.pending stays forever.
Date Tue, 02 Aug 2016 09:54:20 GMT

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

Kirill Barkunov commented on HTTPASYNC-109:
-------------------------------------------

[~olegk]
Log like this one below? It's just one example request.
{code}
2016-08-02 12:45:16.918 DEBUG org.apache.http.impl.nio.client.MainClientExec  - [exchange:
1] start execution
2016-08-02 12:45:16.927 DEBUG org.apache.http.client.protocol.RequestAddCookies  - CookieSpec
selected: default
2016-08-02 12:45:16.928 DEBUG org.apache.http.client.protocol.RequestAddCookies  - Unsupported
cookie policy: default
2016-08-02 12:45:16.928 DEBUG org.apache.http.client.protocol.RequestAuthCache  - Auth cache
not set in the context
2016-08-02 12:45:16.928 DEBUG org.apache.http.impl.nio.client.InternalHttpAsyncClient  - [exchange:
1] Request connection for {s}->https://www.googleapis.com:443
2016-08-02 12:45:16.930 DEBUG org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager
 - Connection request: [route: {s}->https://www.googleapis.com:443][total kept alive: 0;
route allocated: 0 of 130; total allocated: 0 of 150]
2016-08-02 12:45:17.018 DEBUG org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager
 - Connection leased: [id: http-outgoing-0][route: {s}->https://www.googleapis.com:443][total
kept alive: 0; route allocated: 1 of 130; total allocated: 1 of 150]
2016-08-02 12:45:17.022 DEBUG org.apache.http.impl.nio.client.InternalHttpAsyncClient  - [exchange:
1] Connection allocated: http-outgoing-0 [ACTIVE]
2016-08-02 12:45:17.022 DEBUG org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl
 - http-outgoing-0 10.50.33.37:53915<->108.177.14.95:443[ACTIVE][r:]: Set attribute
http.nio.exchange-handler
2016-08-02 12:45:17.022 DEBUG org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl
 - http-outgoing-0 10.50.33.37:53915<->108.177.14.95:443[ACTIVE][rw:]: Event set [w]
2016-08-02 12:45:17.023 DEBUG org.apache.http.nio.protocol.HttpAsyncRequestExecutor  - http-outgoing-0
[ACTIVE]: Connected
2016-08-02 12:45:17.023 DEBUG org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl
 - http-outgoing-0 10.50.33.37:53915<->108.177.14.95:443[ACTIVE][rw:]: Set attribute
http.nio.http-exchange-state
2016-08-02 12:45:17.024 DEBUG org.apache.http.nio.protocol.HttpAsyncRequestExecutor  - http-outgoing-0
[ACTIVE] Request ready
2016-08-02 12:45:17.024 DEBUG org.apache.http.impl.nio.client.MainClientExec  - Start connection
routing
2016-08-02 12:45:17.032 DEBUG org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl
 - http-outgoing-0 Upgrade session 10.50.33.37:53915<->108.177.14.95:443[ACTIVE][rw:][ACTIVE][rw][NEED_UNWRAP][0][0][181][0]
2016-08-02 12:45:17.032 DEBUG org.apache.http.impl.nio.client.MainClientExec  - Connection
route established
2016-08-02 12:45:17.032 DEBUG org.apache.http.impl.nio.client.MainClientExec  - [exchange:
1] Attempt 1 to execute request
2016-08-02 12:45:17.032 DEBUG org.apache.http.impl.nio.client.MainClientExec  - Proxy auth
state: UNCHALLENGED
2016-08-02 12:45:17.033 DEBUG org.apache.http.headers  - http-outgoing-0 >> GET /gmail/v1/users/me/history?startHistoryId=150767&labelId=INBOX
HTTP/1.1
2016-08-02 12:45:17.033 DEBUG org.apache.http.headers  - http-outgoing-0 >> Authorization:
Bearer ...
2016-08-02 12:45:17.033 DEBUG org.apache.http.headers  - http-outgoing-0 >> Host: www.googleapis.com
2016-08-02 12:45:17.033 DEBUG org.apache.http.headers  - http-outgoing-0 >> Connection:
Keep-Alive
2016-08-02 12:45:17.034 DEBUG org.apache.http.headers  - http-outgoing-0 >> User-Agent:
Apache-HttpAsyncClient/4.0 (java 1.5)
2016-08-02 12:45:17.034 DEBUG org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl
 - http-outgoing-0 10.50.33.37:53915<->108.177.14.95:443[ACTIVE][rw:][ACTIVE][rw][NEED_UNWRAP][0][0][181][0]:
Event set [w]
2016-08-02 12:45:17.034 DEBUG org.apache.http.impl.nio.client.MainClientExec  - [exchange:
1] Request completed
2016-08-02 12:45:17.148 DEBUG org.apache.http.nio.protocol.HttpAsyncRequestExecutor  - http-outgoing-0
[ACTIVE] Request ready
2016-08-02 12:45:17.148 DEBUG org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl
 - http-outgoing-0 10.50.33.37:53915<->108.177.14.95:443[ACTIVE][rw:w][ACTIVE][rw][NOT_HANDSHAKING][0][0][309][0]:
276 bytes written
2016-08-02 12:45:17.148 DEBUG org.apache.http.wire  - http-outgoing-0 >> "GET /gmail/v1/users/me/history?startHistoryId=150767&labelId=INBOX
HTTP/1.1[\r][\n]"
2016-08-02 12:45:17.148 DEBUG org.apache.http.wire  - http-outgoing-0 >> "Authorization:
Bearer ...[\r][\n]"
2016-08-02 12:45:17.148 DEBUG org.apache.http.wire  - http-outgoing-0 >> "Host: www.googleapis.com[\r][\n]"
2016-08-02 12:45:17.148 DEBUG org.apache.http.wire  - http-outgoing-0 >> "Connection:
Keep-Alive[\r][\n]"
2016-08-02 12:45:17.148 DEBUG org.apache.http.wire  - http-outgoing-0 >> "User-Agent:
Apache-HttpAsyncClient/4.0 (java 1.5)[\r][\n]"
2016-08-02 12:45:17.148 DEBUG org.apache.http.wire  - http-outgoing-0 >> "[\r][\n]"
2016-08-02 12:45:17.149 DEBUG org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl
 - http-outgoing-0 10.50.33.37:53915<->108.177.14.95:443[ACTIVE][rw:w][ACTIVE][r][NOT_HANDSHAKING][0][0][309][0]:
Event cleared [w]
2016-08-02 12:45:17.379 DEBUG org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl
 - http-outgoing-0 10.50.33.37:53915<->108.177.14.95:443[ACTIVE][r:r][ACTIVE][r][NOT_HANDSHAKING][0][0][0][0]:
663 bytes read
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << "HTTP/1.1 200
OK[\r][\n]"
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << "Expires: Tue,
02 Aug 2016 09:45:17 GMT[\r][\n]"
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << "Date: Tue,
02 Aug 2016 09:45:17 GMT[\r][\n]"
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << "Cache-Control:
private, max-age=0, must-revalidate, no-transform[\r][\n]"
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << "ETag: "SJIjOPuAzi7meWvLIr4rJgaI0K4/OwVtaRNqY33NMp9e3iVzDTWe6Fo"[\r][\n]"
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << "Vary: Origin[\r][\n]"
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << "Vary: X-Origin[\r][\n]"
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << "Content-Type:
application/json; charset=UTF-8[\r][\n]"
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << "X-Content-Type-Options:
nosniff[\r][\n]"
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << "X-Frame-Options:
SAMEORIGIN[\r][\n]"
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << "X-XSS-Protection:
1; mode=block[\r][\n]"
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << "Content-Length:
125[\r][\n]"
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << "Server: GSE[\r][\n]"
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << "Alternate-Protocol:
443:quic[\r][\n]"
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << "Alt-Svc: quic=":443";
ma=2592000; v="36,35,34,33,32,31,30,29,28,27,26,25"[\r][\n]"
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << "[\r][\n]"
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << "{[\n]"
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << " "history":
[[\n]"
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << "  {[\n]"
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << "   "id": "150769"[\n]"
2016-08-02 12:45:17.380 DEBUG org.apache.http.wire  - http-outgoing-0 << "  },[\n]"
2016-08-02 12:45:17.381 DEBUG org.apache.http.wire  - http-outgoing-0 << "  {[\n]"
2016-08-02 12:45:17.381 DEBUG org.apache.http.wire  - http-outgoing-0 << "   "id": "150772"[\n]"
2016-08-02 12:45:17.381 DEBUG org.apache.http.wire  - http-outgoing-0 << "  },[\n]"
2016-08-02 12:45:17.381 DEBUG org.apache.http.wire  - http-outgoing-0 << "  {[\n]"
2016-08-02 12:45:17.381 DEBUG org.apache.http.wire  - http-outgoing-0 << "   "id": "150773"[\n]"
2016-08-02 12:45:17.381 DEBUG org.apache.http.wire  - http-outgoing-0 << "  }[\n]"
2016-08-02 12:45:17.381 DEBUG org.apache.http.wire  - http-outgoing-0 << " ],[\n]"
2016-08-02 12:45:17.381 DEBUG org.apache.http.wire  - http-outgoing-0 << " "historyId":
"150792"[\n]"
2016-08-02 12:45:17.381 DEBUG org.apache.http.wire  - http-outgoing-0 << "}[\n]"
2016-08-02 12:45:17.388 DEBUG org.apache.http.headers  - http-outgoing-0 << HTTP/1.1
200 OK
2016-08-02 12:45:17.389 DEBUG org.apache.http.headers  - http-outgoing-0 << Expires:
Tue, 02 Aug 2016 09:45:17 GMT
2016-08-02 12:45:17.389 DEBUG org.apache.http.headers  - http-outgoing-0 << Date: Tue,
02 Aug 2016 09:45:17 GMT
2016-08-02 12:45:17.389 DEBUG org.apache.http.headers  - http-outgoing-0 << Cache-Control:
private, max-age=0, must-revalidate, no-transform
2016-08-02 12:45:17.389 DEBUG org.apache.http.headers  - http-outgoing-0 << ETag: "SJIjOPuAzi7meWvLIr4rJgaI0K4/OwVtaRNqY33NMp9e3iVzDTWe6Fo"
2016-08-02 12:45:17.389 DEBUG org.apache.http.headers  - http-outgoing-0 << Vary: Origin
2016-08-02 12:45:17.389 DEBUG org.apache.http.headers  - http-outgoing-0 << Vary: X-Origin
2016-08-02 12:45:17.389 DEBUG org.apache.http.headers  - http-outgoing-0 << Content-Type:
application/json; charset=UTF-8
2016-08-02 12:45:17.389 DEBUG org.apache.http.headers  - http-outgoing-0 << X-Content-Type-Options:
nosniff
2016-08-02 12:45:17.390 DEBUG org.apache.http.headers  - http-outgoing-0 << X-Frame-Options:
SAMEORIGIN
2016-08-02 12:45:17.390 DEBUG org.apache.http.headers  - http-outgoing-0 << X-XSS-Protection:
1; mode=block
2016-08-02 12:45:17.390 DEBUG org.apache.http.headers  - http-outgoing-0 << Content-Length:
125
2016-08-02 12:45:17.390 DEBUG org.apache.http.headers  - http-outgoing-0 << Server:
GSE
2016-08-02 12:45:17.390 DEBUG org.apache.http.headers  - http-outgoing-0 << Alternate-Protocol:
443:quic
2016-08-02 12:45:17.390 DEBUG org.apache.http.headers  - http-outgoing-0 << Alt-Svc:
quic=":443"; ma=2592000; v="36,35,34,33,32,31,30,29,28,27,26,25"
2016-08-02 12:45:17.390 DEBUG org.apache.http.nio.protocol.HttpAsyncRequestExecutor  - http-outgoing-0
[ACTIVE(125)] Response received
2016-08-02 12:45:17.390 DEBUG org.apache.http.impl.nio.client.MainClientExec  - [exchange:
1] Response received HTTP/1.1 200 OK
2016-08-02 12:45:17.390 DEBUG org.apache.http.client.protocol.ResponseProcessCookies  - Cookie
spec not specified in HTTP context
2016-08-02 12:45:17.396 DEBUG org.apache.http.nio.protocol.HttpAsyncRequestExecutor  - http-outgoing-0
[ACTIVE(125)] Input ready
2016-08-02 12:45:17.397 DEBUG org.apache.http.impl.nio.client.MainClientExec  - [exchange:
1] Consume content
2016-08-02 12:45:17.398 DEBUG org.apache.http.impl.nio.client.MainClientExec  - [exchange:
1] Connection can be kept alive indefinitely
2016-08-02 12:45:17.399 DEBUG org.apache.http.impl.nio.client.MainClientExec  - [exchange:
1] Response processed
2016-08-02 12:45:17.399 DEBUG org.apache.http.impl.nio.client.InternalHttpAsyncClient  - [exchange:
1] releasing connection
2016-08-02 12:45:17.399 DEBUG org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl
 - http-outgoing-0 10.50.33.37:53915<->108.177.14.95:443[ACTIVE][r:r][ACTIVE][r][NOT_HANDSHAKING][0][0][0][0]:
Remove attribute http.nio.exchange-handler
2016-08-02 12:45:17.399 DEBUG org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager
 - Connection [id: http-outgoing-0][route: {s}->https://www.googleapis.com:443] can be
kept alive indefinitely
2016-08-02 12:45:17.399 DEBUG org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager
 - Connection released: [id: http-outgoing-0][route: {s}->https://www.googleapis.com:443][total
kept alive: 1; route allocated: 1 of 130; total allocated: 1 of 150]
2016-08-02 12:45:17.409 DEBUG org.apache.http.nio.protocol.HttpAsyncRequestExecutor  - http-outgoing-0
[ACTIVE] [content length: 125; pos: 125; completed: true]
2016-08-02 12:45:47.422 DEBUG org.apache.http.nio.protocol.HttpAsyncRequestExecutor  - http-outgoing-0
[ACTIVE] Timeout
2016-08-02 12:45:47.422 DEBUG org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl
 - http-outgoing-0 10.50.33.37:53915<->108.177.14.95:443[ACTIVE][r:r][ACTIVE][r][NOT_HANDSHAKING][0][0][0][0]:
Close
2016-08-02 12:45:47.468 DEBUG org.apache.http.nio.protocol.HttpAsyncRequestExecutor  - http-outgoing-0
[CLOSED]: Disconnected
{code}

Best regards, Kirill.

> Requests in AbstractNIOConnPool.pending stays forever.
> ------------------------------------------------------
>
>                 Key: HTTPASYNC-109
>                 URL: https://issues.apache.org/jira/browse/HTTPASYNC-109
>             Project: HttpComponents HttpAsyncClient
>          Issue Type: Bug
>    Affects Versions: 4.1.2
>            Reporter: Kirill Barkunov
>
> Hi!
> I have a client built this way:
> {code}
> IOReactorConfig ioReactorConfig = IOReactorConfig.custom()
>             .setIoThreadCount(Runtime.getRuntime().availableProcessors())
>             .setConnectTimeout(30000)
>             .setSoTimeout(30000)
>             .build();
>     private CloseableHttpAsyncClient httpAsyncClient = HttpAsyncClients.custom().setMaxConnTotal(150).setMaxConnPerRoute(130).setDefaultIOReactorConfig(ioReactorConfig).build();
> {code}
> I've noticied that on environment with a firewall enabled (I think it cuts all the socket
connection 5 minutes after their establishing) after some time client stops sending https
request. After a small investigation I've started to monitor insides of the client and noticied
that a few minutes after the client start - AbstractNIOConnPool.pending collection starts
to grow. At start it's 0. After few minutes it's 1-2. Then it starts to grow faster and few
minutes later it reaches maximum number of connections per route. And it stops work forever.
Only AbstractNIOConnPool.leasingRequests grows and no one of the new requests are processed.
> Target for all the requests is www.googleapis.com
> As I can understand from client insides load is like 1-5 request at a time.
> I mean before first "dead" request in AbstractNIOConnPool.pending the number of "leased"
and "available" is not more than 5.
> Best regards, Kirill.



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

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


Mime
View raw message