Hello Nicolas,
I have been able to reproduce this issue in a test case and I realize
what's going on. I'll be working on a fix.
I'm just curious if you were able to workaround this issue with the use
of a non-default idle timeout using the system properties I noted.
-Jaikiran
On 20/07/23 1:01 pm, Jaikiran Pai wrote:
On 20/07/23 12:19 pm, Nicolas Henneaux wrote:
Hi Jaikiran!
Thanks for your quick feedback!
It happens on a regular and consistent basis mostly when execution
health checks between microservices. On about 100 microservices
deployed on 100 VM, it happens ~400 times every hours.
I haven't find a consistent pattern for now. I cannot attach the
whole stacktrace as it is a closed source code. I can provide some
details. A ScheduleExecutor is launching a check on healthiness HTTP
call every 29s (was 30s but I desync it to avoid idle timeout of 30s
alignment with HttpClient). This is the biggest source of those
errors but not the only one, there are regular HTTP calls received on
a Jetty server and calling another service that are failing.
I have already tried to enable full debug without much help for now.
Is there something in particular you are willing to check?
Thank you for these additional details. I don't have any specific log
message in mind for now. I'll look into the code and try to reproduce
this in a test case.
From the stacktrace it appears that this affects HTTP2 connection in
your application. One workaround would be to increase the idle
connection timeout for these connections, to reduce the chances of
this issue. There are system properties that control this value. If
you want to configure this only for HTTP2 connections, then
jdk.httpclient.keepalive.timeout.h2 is the system property to set, the
value represents number of seconds (and defaults to 30). More details
about this and other system properties applicable for HttpClient are
available here
https://docs.oracle.com/en/java/javase/20/docs/api/java.net.http/module-summary.html
-Jaikiran
Best regards,
Nicolas
On Thu, 20 Jul 2023 at 08:11, Jaikiran Pai <[email protected]>
wrote:
Hello Nicolas,
This looks like it will need to be investigated. I've opened
https://bugs.openjdk.org/browse/JDK-8312433 to tracking this. It
would help further if you could attach the complete exception
logs along with timestamps, if any.
Is this consistently reproducible? Perhaps you could launch your
application passing it the -Djdk.internal.httpclient.debug=true
system property? That will generate very verbose logs, so you
might want to use that sparingly and remove that system property
when you have collected the logs for this issue.
-Jaikiran
On 20/07/23 11:00 am, Nicolas Henneaux wrote:
Hi all,
Since I updated Java from 19.0.2 to 20.0.1, I got some errors
with connection idle shutdown or closed stream usage when trying
to send HTTP requests with java.net.http.HttpClient.
The two following errors are happening. I suspect those are
linked even if they don't trigger together.
1. java.net.http.HttpConnectTimeoutException: HTTP connection
idle, no active streams. Shutting down.
at
jdk.internal.net.http.HttpClientImpl.send(HttpClientImpl.java:890)
~[java.net.http:?]
2. java.io.IOException: Stream 9 cancelled
at jdk.internal.net.http.Stream.cancel(Stream.java:1229)
~[java.net.http:?]
The detailed stacks are copied below.
Error 1. is caused by an idle connection trying to be used to
send the request from what I understood from the code. Error 2.
despite saying it is a cancelled streamed is actually happening
when the stream is closed if I haven't missed something in the code.
I suspect either the idle connections are not always properly
discarded to create a new one or there is a race condition when
discarding the idle connections.
I was not able so far to find where this could happen and I hope
you could help me to find where the problem lies.
Thank you in advance for your help,
Best regards,
Nicolas Henneaux
Detailed stacks
1. Caused by: java.net.http.HttpConnectTimeoutException: HTTP
connection idle, no active streams. Shutting down.
at
jdk.internal.net.http.HttpClientImpl.send(HttpClientImpl.java:890)
~[java.net.http:?]
at
jdk.internal.net.http.HttpClientFacade.send(HttpClientFacade.java:133)
~[java.net.http:?]
(...)
Caused by: java.net.http.HttpConnectTimeoutException: HTTP
connection idle, no active streams. Shutting down.
at
jdk.internal.net.http.Http2Connection$IdleConnectionTimeoutEvent.handle(Http2Connection.java:204)
~[java.net.http:?]
at
jdk.internal.net.http.HttpClientImpl.purgeTimeoutsAndReturnNextDeadline(HttpClientImpl.java:1689)
~[java.net.http:?]
at
jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:1299)
~[java.net.http:?]
2. Caused by: java.io.IOException: Stream 9 cancelled
at jdk.internal.net.http.Stream.cancel(Stream.java:1229)
~[java.net.http:?]
at
jdk.internal.net.http.Http2Connection.putStream(Http2Connection.java:1237)
~[java.net.http:?]
at jdk.internal.net.http.Stream.registerStream(Stream.java:851)
~[java.net.http:?]
at
jdk.internal.net.http.Http2Connection.registerNewStream(Http2Connection.java:1337)
~[java.net.http:?]
at
jdk.internal.net.http.Http2Connection.sendFrame(Http2Connection.java:1361)
~[java.net.http:?]
at
jdk.internal.net.http.Stream.sendHeadersAsync(Stream.java:823)
~[java.net.http:?]
at
jdk.internal.net.http.Exchange.lambda$responseAsyncImpl0$8(Exchange.java:550)
~[java.net.http:?]
at jdk.internal.net.http.Exchange.checkFor407(Exchange.java:430)
~[java.net.http:?]
at
jdk.internal.net.http.Exchange.lambda$responseAsyncImpl0$9(Exchange.java:554)
~[java.net.http:?]
at
java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:934)
~[?:?]
at
java.util.concurrent.CompletableFuture.uniHandleStage(CompletableFuture.java:950)
~[?:?]
at
java.util.concurrent.CompletableFuture.handle(CompletableFuture.java:2372)
~[?:?]
at
jdk.internal.net.http.Exchange.responseAsyncImpl0(Exchange.java:554)
~[java.net.http:?]
at
jdk.internal.net.http.Exchange.responseAsyncImpl(Exchange.java:406)
~[java.net.http:?]
at
jdk.internal.net.http.Exchange.responseAsync(Exchange.java:398)
~[java.net.http:?]
at
jdk.internal.net.http.MultiExchange.responseAsyncImpl(MultiExchange.java:409)
~[java.net.http:?]
at
jdk.internal.net.http.MultiExchange.lambda$responseAsync0$2(MultiExchange.java:342)
~[java.net.http:?]
at
java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1150)
~[?:?]
at
java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
~[?:?]
at
java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1773)
~[?:?]
at
jdk.internal.net.http.HttpClientImpl$DelegatingExecutor.execute(HttpClientImpl.java:177)
~[java.net.http:?]
at
java.util.concurrent.CompletableFuture.completeAsync(CompletableFuture.java:2719)
~[?:?]
at
jdk.internal.net.http.MultiExchange.responseAsync(MultiExchange.java:295)
~[java.net.http:?]
at
jdk.internal.net.http.HttpClientImpl.sendAsync(HttpClientImpl.java:983)
~[java.net.http:?]
at
jdk.internal.net.http.HttpClientImpl.send(HttpClientImpl.java:875)
~[java.net.http:?]
at
jdk.internal.net.http.HttpClientFacade.send(HttpClientFacade.java:133)
~[java.net.http:?]
