Hi Jaikiran, Great news you nailed down the issue and already working on a fix!
I have set the idle timeout to 60s and there was not a single occurrence of those errors for 2 days. This is effectively the trigger of those errors. I would prefer to avoid using a non-default idle timeout but I can live with it for some time. Once you'll manage to get a fix on that, could you indicate the schedule delivery for it? Thanks a lot for the help, Best regards, Nicolas On Fri, 21 Jul 2023 at 12:35, Jaikiran Pai <[email protected]> wrote: > 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:?] >> >>
