[java.net.http.HttpClient] Error on idle/closed stream when sending requests

Sat Jul 22 12:05:17 UTC 2023

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 <jai.forums2013 at gmail.com> 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 <jai.forums2013 at gmail.com>
> 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:?]
>>
>>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/net-dev/attachments/20230722/5b72b822/attachment-0001.htm>