[
https://issues.apache.org/jira/browse/HTTPCORE-777?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17933008#comment-17933008
]
Oleksandr Kriuchenko commented on HTTPCORE-777:
-----------------------------------------------
[~olegk] thank you very much for your response with all the details and the
fix! I am really sorry - I shouldn't had raised this ticket while being sick
with high temperature, as I made so many errors in the test. That's my bad.
Thank you for spotting them all!
I tried to follow you advise and added a connect timeout to the test and of
course fixed the host in request to mock server to localhost.
I also added a trace level logging for everything.
I also tried to do my best to verify this time the test behaves correct, but
still doesn't complete the future.
Could you please take last look on
[https://github.com/oleksandr-kriuchenko-lohika/httpcore5-issue/blob/main/src/test/java/ApacheHttpClient5TransportIT.java]
Here are the logs I am getting (I've manually stopped the test after ~12
minutes of execution):
{noformat}
2025-03-06 15:57:52,903 DEBUG
[org.apache.hc.client5.http.impl.async.InternalAbstractHttpAsyncClient]
ex-0000000001 preparing request execution
2025-03-06 15:57:52,903 DEBUG
[org.apache.hc.client5.http.impl.async.InternalAbstractHttpAsyncClient]
ex-0000000001 preparing request execution
2025-03-06 15:57:52,907 DEBUG
[org.apache.hc.client5.http.impl.async.AsyncProtocolExec] ex-0000000001 target
auth state: UNCHALLENGED
2025-03-06 15:57:52,907 DEBUG
[org.apache.hc.client5.http.impl.async.AsyncProtocolExec] ex-0000000001 target
auth state: UNCHALLENGED
2025-03-06 15:57:52,907 DEBUG
[org.apache.hc.client5.http.impl.async.AsyncProtocolExec] ex-0000000001 proxy
auth state: UNCHALLENGED
2025-03-06 15:57:52,907 DEBUG
[org.apache.hc.client5.http.impl.async.AsyncProtocolExec] ex-0000000001 proxy
auth state: UNCHALLENGED
2025-03-06 15:57:52,908 DEBUG
[org.apache.hc.client5.http.impl.async.AsyncConnectExec] ex-0000000001
acquiring connection with route {}->[http://localhost:1080]
2025-03-06 15:57:52,908 DEBUG
[org.apache.hc.client5.http.impl.async.AsyncConnectExec] ex-0000000001
acquiring connection with route {}->[http://localhost:1080]
2025-03-06 15:57:52,908 DEBUG
[org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient] ex-0000000001
acquiring endpoint (3 MINUTES)
2025-03-06 15:57:52,908 DEBUG
[org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient] ex-0000000001
acquiring endpoint (3 MINUTES)
2025-03-06 15:57:52,909 DEBUG
[org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ex-0000000001 endpoint lease request (3 MINUTES) [route:
{}->[http://localhost:1080]][total available: 0; route allocated: 0 of 5; total
allocated: 0 of 25]
2025-03-06 15:57:52,909 DEBUG
[org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ex-0000000001 endpoint lease request (3 MINUTES) [route:
{}->[http://localhost:1080]][total available: 0; route allocated: 0 of 5; total
allocated: 0 of 25]
2025-03-06 15:57:52,911 DEBUG
[org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ex-0000000001 endpoint leased [route: {}->[http://localhost:1080]][total
available: 0; route allocated: 1 of 5; total allocated: 1 of 25]
2025-03-06 15:57:52,911 DEBUG
[org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ex-0000000001 endpoint leased [route: {}->[http://localhost:1080]][total
available: 0; route allocated: 1 of 5; total allocated: 1 of 25]
2025-03-06 15:57:52,911 DEBUG
[org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ex-0000000001 acquired ep-0000000001
2025-03-06 15:57:52,911 DEBUG
[org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ex-0000000001 acquired ep-0000000001
2025-03-06 15:57:52,911 DEBUG
[org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient] ex-0000000001
acquired endpoint ep-0000000001
2025-03-06 15:57:52,911 DEBUG
[org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient] ex-0000000001
acquired endpoint ep-0000000001
2025-03-06 15:57:52,912 DEBUG
[org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient] ep-0000000001
connecting endpoint (null)
2025-03-06 15:57:52,912 DEBUG
[org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient] ep-0000000001
connecting endpoint (null)
2025-03-06 15:57:52,912 DEBUG
[org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ep-0000000001 connecting endpoint to http://localhost:1080 (15 SECONDS)
2025-03-06 15:57:52,912 DEBUG
[org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ep-0000000001 connecting endpoint to http://localhost:1080 (15 SECONDS)
2025-03-06 15:57:52,913 DEBUG
[org.apache.hc.client5.http.impl.nio.DefaultAsyncClientConnectionOperator]
http://localhost:1080 connecting null->null (15 SECONDS)
2025-03-06 15:57:52,913 DEBUG
[org.apache.hc.client5.http.impl.nio.DefaultAsyncClientConnectionOperator]
http://localhost:1080 connecting null->null (15 SECONDS)
2025-03-06 15:57:52,913 DEBUG
[org.apache.hc.client5.http.impl.nio.MultihomeIOSessionRequester] localhost
resolving remote address
2025-03-06 15:57:52,913 DEBUG
[org.apache.hc.client5.http.impl.nio.MultihomeIOSessionRequester] localhost
resolving remote address
2025-03-06 15:57:52,913 DEBUG
[org.apache.hc.client5.http.impl.nio.MultihomeIOSessionRequester] localhost
resolved to [localhost/127.0.0.1, localhost/0:0:0:0:0:0:0:1]
2025-03-06 15:57:52,913 DEBUG
[org.apache.hc.client5.http.impl.nio.MultihomeIOSessionRequester] localhost
resolved to [localhost/127.0.0.1, localhost/0:0:0:0:0:0:0:1]
2025-03-06 15:57:52,913 DEBUG
[org.apache.hc.client5.http.impl.nio.MultihomeIOSessionRequester]
localhost:1080 connecting null->localhost/127.0.0.1:1080 (15 SECONDS)
2025-03-06 15:57:52,913 DEBUG
[org.apache.hc.client5.http.impl.nio.MultihomeIOSessionRequester]
localhost:1080 connecting null->localhost/127.0.0.1:1080 (15 SECONDS)
2025-03-06 15:57:52,923 DEBUG [org.apache.hc.core5.reactor.IOSessionImpl]
c-0000000000[ACTIVE][rc:c] protocol upgrade class
org.apache.hc.core5.http.impl.nio.ClientHttp1IOEventHandler
2025-03-06 15:57:52,923 DEBUG
[org.apache.hc.client5.http.impl.nio.MultihomeIOSessionRequester]
localhost:1080 connected null->localhost/127.0.0.1:1080 as c-0000000000
2025-03-06 15:57:52,923 DEBUG
[org.apache.hc.client5.http.impl.nio.MultihomeIOSessionRequester]
localhost:1080 connected null->localhost/127.0.0.1:1080 as c-0000000000
2025-03-06 15:57:52,924 DEBUG
[org.apache.hc.client5.http.impl.nio.DefaultAsyncClientConnectionOperator]
c-0000000000 http://localhost:1080 connected
/127.0.0.1:60616->localhost/127.0.0.1:1080
2025-03-06 15:57:52,924 DEBUG
[org.apache.hc.client5.http.impl.nio.DefaultAsyncClientConnectionOperator]
c-0000000000 http://localhost:1080 connected
/127.0.0.1:60616->localhost/127.0.0.1:1080
2025-03-06 15:57:52,924 DEBUG
[org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ep-0000000001 connected c-0000000000
2025-03-06 15:57:52,924 DEBUG
[org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ep-0000000001 connected c-0000000000
2025-03-06 15:57:52,924 DEBUG
[org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient] ep-0000000001
endpoint connected
2025-03-06 15:57:52,924 DEBUG
[org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient] ep-0000000001
endpoint connected
2025-03-06 15:57:52,924 DEBUG
[org.apache.hc.client5.http.impl.async.AsyncConnectExec] ex-0000000001
connected to target
2025-03-06 15:57:52,924 DEBUG
[org.apache.hc.client5.http.impl.async.AsyncConnectExec] ex-0000000001
connected to target
2025-03-06 15:57:52,924 DEBUG
[org.apache.hc.client5.http.impl.async.AsyncConnectExec] ex-0000000001 route
fully established
2025-03-06 15:57:52,924 DEBUG
[org.apache.hc.client5.http.impl.async.AsyncConnectExec] ex-0000000001 route
fully established
2025-03-06 15:57:52,924 DEBUG
[org.apache.hc.client5.http.impl.async.HttpAsyncMainClientExec] ex-0000000001
executing GET /
2025-03-06 15:57:52,924 DEBUG
[org.apache.hc.client5.http.impl.async.HttpAsyncMainClientExec] ex-0000000001
executing GET /
2025-03-06 15:57:52,925 DEBUG
[org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient] ep-0000000001
start execution ex-0000000001
2025-03-06 15:57:52,925 DEBUG
[org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient] ep-0000000001
start execution ex-0000000001
2025-03-06 15:57:52,925 DEBUG
[org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ep-0000000001 executing exchange ex-0000000001 over c-0000000000
2025-03-06 15:57:52,925 DEBUG
[org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ep-0000000001 executing exchange ex-0000000001 over c-0000000000
2025-03-06 15:57:52,925 DEBUG
[org.apache.hc.client5.http.impl.nio.DefaultManagedAsyncClientConnection]
c-0000000000 RequestExecutionCommand with NORMAL priority
2025-03-06 15:57:52,925 DEBUG
[org.apache.hc.client5.http.impl.nio.DefaultManagedAsyncClientConnection]
c-0000000000 RequestExecutionCommand with NORMAL priority
2025-03-06 15:57:52,925 DEBUG [org.apache.hc.core5.reactor.IOSessionImpl]
c-0000000000[ACTIVE][rwc:c] Enqueued RequestExecutionCommand with priority
IMMEDIATE
2025-03-06 15:57:52,926 DEBUG [org.apache.hc.core5.reactor.IOSessionImpl]
c-0000000000[ACTIVE][rw:c] Event cleared [c]
2025-03-06 15:57:52,927 DEBUG
[org.apache.hc.client5.http.protocol.RequestAddCookies] ex-0000000001 Cookie
spec selected: strict
2025-03-06 15:57:52,927 DEBUG
[org.apache.hc.client5.http.protocol.RequestAddCookies] ex-0000000001 Cookie
spec selected: strict
2025-03-06 15:57:52,930 DEBUG
[org.apache.hc.client5.http.impl.async.HttpAsyncMainClientExec] ex-0000000001
send request GET /, null entity
2025-03-06 15:57:52,930 DEBUG
[org.apache.hc.client5.http.impl.async.HttpAsyncMainClientExec] ex-0000000001
send request GET /, null entity
2025-03-06 15:57:52,930 DEBUG [org.apache.hc.client5.http.headers] c-0000000000
>> GET / HTTP/1.1
2025-03-06 15:57:52,930 DEBUG [org.apache.hc.client5.http.headers] c-0000000000
>> GET / HTTP/1.1
2025-03-06 15:57:52,930 DEBUG [org.apache.hc.client5.http.headers] c-0000000000
>> Host: localhost:1080
2025-03-06 15:57:52,930 DEBUG [org.apache.hc.client5.http.headers] c-0000000000
>> Host: localhost:1080
2025-03-06 15:57:52,930 DEBUG [org.apache.hc.client5.http.headers] c-0000000000
>> Connection: keep-alive
2025-03-06 15:57:52,930 DEBUG [org.apache.hc.client5.http.headers] c-0000000000
>> Connection: keep-alive
2025-03-06 15:57:52,930 DEBUG [org.apache.hc.client5.http.headers] c-0000000000
>> User-Agent: Apache-HttpAsyncClient/5.4.2 (Java/21.0.5)
2025-03-06 15:57:52,930 DEBUG [org.apache.hc.client5.http.headers] c-0000000000
>> User-Agent: Apache-HttpAsyncClient/5.4.2 (Java/21.0.5)
2025-03-06 15:57:52,931 DEBUG [org.apache.hc.core5.reactor.IOSessionImpl]
c-0000000000[ACTIVE][rw:c] 120 bytes written
2025-03-06 15:57:52,931 DEBUG [org.apache.hc.client5.http.wire]
c-0000000000[ACTIVE][rw:c] >> GET / HTTP/1.1 47 45 54 20 2f 20 48 54 54 50
2f 31 2e 31 0d 0a
2025-03-06 15:57:52,931 DEBUG [org.apache.hc.client5.http.wire]
c-0000000000[ACTIVE][rw:c] >> GET / HTTP/1.1 47 45 54 20 2f 20 48 54 54 50
2f 31 2e 31 0d 0a
2025-03-06 15:57:52,931 DEBUG [org.apache.hc.client5.http.wire]
c-0000000000[ACTIVE][rw:c] >> Host: localhost: 48 6f 73 74 3a 20 6c 6f 63 61
6c 68 6f 73 74 3a
2025-03-06 15:57:52,931 DEBUG [org.apache.hc.client5.http.wire]
c-0000000000[ACTIVE][rw:c] >> Host: localhost: 48 6f 73 74 3a 20 6c 6f 63 61
6c 68 6f 73 74 3a
2025-03-06 15:57:52,931 DEBUG [org.apache.hc.client5.http.wire]
c-0000000000[ACTIVE][rw:c] >> 1080 Connection 31 30 38 30 0d 0a 43 6f 6e 6e
65 63 74 69 6f 6e
2025-03-06 15:57:52,931 DEBUG [org.apache.hc.client5.http.wire]
c-0000000000[ACTIVE][rw:c] >> 1080 Connection 31 30 38 30 0d 0a 43 6f 6e 6e
65 63 74 69 6f 6e
2025-03-06 15:57:52,931 DEBUG [org.apache.hc.client5.http.wire]
c-0000000000[ACTIVE][rw:c] >> : keep-alive Us 3a 20 6b 65 65 70 2d 61 6c 69
76 65 0d 0a 55 73
2025-03-06 15:57:52,931 DEBUG [org.apache.hc.client5.http.wire]
c-0000000000[ACTIVE][rw:c] >> : keep-alive Us 3a 20 6b 65 65 70 2d 61 6c 69
76 65 0d 0a 55 73
2025-03-06 15:57:52,931 DEBUG [org.apache.hc.client5.http.wire]
c-0000000000[ACTIVE][rw:c] >> er-Agent: Apache 65 72 2d 41 67 65 6e 74 3a 20
41 70 61 63 68 65
2025-03-06 15:57:52,931 DEBUG [org.apache.hc.client5.http.wire]
c-0000000000[ACTIVE][rw:c] >> er-Agent: Apache 65 72 2d 41 67 65 6e 74 3a 20
41 70 61 63 68 65
2025-03-06 15:57:52,931 DEBUG [org.apache.hc.client5.http.wire]
c-0000000000[ACTIVE][rw:c] >> -HttpAsyncClient 2d 48 74 74 70 41 73 79 6e 63
43 6c 69 65 6e 74
2025-03-06 15:57:52,931 DEBUG [org.apache.hc.client5.http.wire]
c-0000000000[ACTIVE][rw:c] >> -HttpAsyncClient 2d 48 74 74 70 41 73 79 6e 63
43 6c 69 65 6e 74
2025-03-06 15:57:52,931 DEBUG [org.apache.hc.client5.http.wire]
c-0000000000[ACTIVE][rw:c] >> /5.4.2 (Java/21. 2f 35 2e 34 2e 32 20 28 4a 61
76 61 2f 32 31 2e
2025-03-06 15:57:52,931 DEBUG [org.apache.hc.client5.http.wire]
c-0000000000[ACTIVE][rw:c] >> /5.4.2 (Java/21. 2f 35 2e 34 2e 32 20 28 4a 61
76 61 2f 32 31 2e
2025-03-06 15:57:52,931 DEBUG [org.apache.hc.client5.http.wire]
c-0000000000[ACTIVE][rw:c] >> 0.5) 30 2e 35 29 0d 0a 0d 0a
2025-03-06 15:57:52,931 DEBUG [org.apache.hc.client5.http.wire]
c-0000000000[ACTIVE][rw:c] >> 0.5) 30 2e 35 29 0d 0a 0d 0a
2025-03-06 15:57:52,931 DEBUG [org.apache.hc.core5.reactor.IOSessionImpl]
c-0000000000[ACTIVE][rw:c] Event set [w]
2025-03-06 15:57:52,931 DEBUG [org.apache.hc.core5.reactor.IOSessionImpl]
c-0000000000[ACTIVE][r:c] Event cleared [w]
2025-03-06 15:57:52,935 INFO [org.mockserver.log.MockServerEventLog] 1080
received request: {
"method" : "GET",
"path" : "/",
"headers" : {
"content-length" : [ "0" ],
"User-Agent" : [ "Apache-HttpAsyncClient/5.4.2 (Java/21.0.5)" ],
"Host" : [ "localhost:1080" ],
"Connection" : [ "keep-alive" ]
},
"keepAlive" : true,
"secure" : false,
"protocol" : "HTTP_1_1",
"localAddress" : "127.0.0.1:1080",
"remoteAddress" : "127.0.0.1:60616"
}2025-03-06 15:57:52,936 INFO [org.mockserver.log.MockServerEventLog] 1080
request: {
"method" : "GET",
"path" : "/",
"headers" : {
"content-length" : [ "0" ],
"User-Agent" : [ "Apache-HttpAsyncClient/5.4.2 (Java/21.0.5)" ],
"Host" : [ "localhost:1080" ],
"Connection" : [ "keep-alive" ]
},
"keepAlive" : true,
"secure" : false,
"protocol" : "HTTP_1_1",
"localAddress" : "127.0.0.1:1080",
"remoteAddress" : "127.0.0.1:60616"
} matched expectation: {
"httpError" : {
"dropConnection" : true
},
"httpRequest" : { },
"id" : "81362a3f-4883-4ea2-a402-5e8d6ff9896e",
"priority" : 0,
"timeToLive" : {
"unlimited" : true
},
"times" : {
"unlimited" : true
}
}2025-03-06 15:57:52,937 DEBUG [org.apache.hc.core5.reactor.IOSessionImpl]
c-0000000000[ACTIVE][r:r] -1 bytes read
2025-03-06 15:57:52,938 INFO [org.mockserver.log.MockServerEventLog] 1080
returning error: {
"dropConnection" : true
} for request: {
"method" : "GET",
"path" : "/",
"headers" : {
"content-length" : [ "0" ],
"User-Agent" : [ "Apache-HttpAsyncClient/5.4.2 (Java/21.0.5)" ],
"Host" : [ "localhost:1080" ],
"Connection" : [ "keep-alive" ]
},
"keepAlive" : true,
"secure" : false,
"protocol" : "HTTP_1_1",
"localAddress" : "127.0.0.1:1080",
"remoteAddress" : "127.0.0.1:60616"
} for action: {
"dropConnection" : true
} from expectation: 81362a3f-4883-4ea2-a402-5e8d6ff9896e2025-03-06
15:57:52,938 DEBUG [org.apache.hc.core5.reactor.IOSessionImpl]
c-0000000000[ACTIVE][rw:r] Event set [w]
2025-03-06 15:57:52,938 DEBUG [org.apache.hc.core5.reactor.IOSessionImpl]
c-0000000000[ACTIVE][r:r] Event cleared [w]
2025-03-06 15:57:52,938 DEBUG [org.apache.hc.core5.reactor.IOSessionImpl]
c-0000000000[ACTIVE][:r] Event cleared [r]
2025-03-06 16:09:34,157 INFO [org.mockserver.log.MockServerEventLog] stopped
for port: 1080
2025-03-06 16:09:34,169 DEBUG [io.netty.buffer.PoolThreadCache] Freed 4
thread-local buffer(s) from thread: MockServer-MockServer-workerEventLoop4
2025-03-06 16:09:34,169 DEBUG [io.netty.buffer.PoolThreadCache] Freed 2
thread-local buffer(s) from thread: MockServer-MockServer-workerEventLoop5
2025-03-06 16:09:34,284 DEBUG [io.netty.buffer.PoolThreadCache] Freed 3
thread-local buffer(s) from thread:
MockServer-ClientAndServer-eventLoop3Process finished with exit code 130
(interrupted by signal 2:SIGINT)
{noformat}
> CloseableHttpAsyncClient.execute hangs forever upon connection reset
> --------------------------------------------------------------------
>
> Key: HTTPCORE-777
> URL: https://issues.apache.org/jira/browse/HTTPCORE-777
> Project: HttpComponents HttpCore
> Issue Type: Bug
> Components: HttpCore
> Affects Versions: 5.3.3
> Reporter: Oleksandr Kriuchenko
> Priority: Major
>
> There seems to be an issue with async http client request execution:
> if connection is closed during request execution then the future
> returned by the CloseableHttpAsyncClient.execute never completes.
> Please find a test setup to reproduce the issue (along with the
> conditions description under which the issue reproduces) in
> [https://github.com/oleksandr-kriuchenko-lohika/httpcore5-issue]
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
