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