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

[Jaikiran Pai]

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/20230721/ab0adfa7/attachment-0001.htm>