HTTP/2 max local stream count exceeded

[qingdaoheze]

Jetty version
9.4.39.v20210325

Java version
1.8

OS type/version
MAC and linux

Description
When the header size reaches some value (In my demo, it's 2237B) and multiple requests send concurrently, some requests will not be sent to remote server and cause an TimeoutException and then an "java.lang.IllegalStateException: Max local stream count 100 exceeded". When the header size is smaller, it's ok. Please refer to this demo project to reproduce it.
https://github.com/qingdaoheze/jetty-gzip-decode

@sbordet

[sbordet]

Cannot reproduce.

I see Jetty's client sending requests, and Tomcat server replying to some but then stopping to reply, so the client times out.

I suggest you change the server to Jetty (SpringBoot supports Jetty too) and see if you still have problems.

[qingdaoheze]

Maybe your computer is stronger than mine, I increase the thread size, please try it again and please use the client code provided in the repo directly. Its path is "jetty9-client-sample/src/main/java/org/sample/jetty/client/http2/HttpClientWithHttp2Transport.java". The problem must be reproduced.

And please refer to the log on my side. https://github.com/qingdaoheze/jetty-gzip-decode/blob/master/detail.log.tar.gz

@sbordet

[sbordet]

As I said, I cannot reproduce.

Your logs show nothing wrong in Jetty.
The IllegalStateException you mention in your first comment is not present in your logs, and I was not able to reproduce it with your code.

The timeouts you see are only due to the (bad) load test that overwhelms the client and the server and eventually the client times out.

[qingdaoheze]

I only uploaded the first part of the log because the whole log is too big. I have re-run and uploaded more logs, please check again. In my case, this question certainly comes up.

https://github.com/qingdaoheze/jetty-gzip-decode/blob/master/detail.log.tar.gz

The first timeout is between 09:05:45.244 and 09:05:50.220. At 09:06:26.269, the first java.lang.IllegalStateException: Max local stream count 100 exceeded.

@sbordet

[RoySunnySean007]

Dear @sbordet,

We also encountered similar issues. Is there any difference between Jetty server and tomcat server regarding HTTP2.0 implementation?

Really appreciate ur great help in advance~

Thanks,
Roy

[lsc1943]

@sbordet
We also met similar issues, we ran some load tests using Jetty HTTP2 client as a middleware and send requests to Tomcat 9 server. We observed some abnormal timeout errors, and we have checked that the timeout was not happened at server side, it seems the Jetty client tried to send request but not succeed, the http exchange got snd = "IDLE" like below:
HttpExchange@625d06a5{req=HttpRequest[POST /xx HTTP/2.0]@871420d[PENDING/null] res=HttpResponse[null 0 null]@48ced718[PENDING/null]} associated true to HttpChannelOverHTTP2@1384fef4(exchange=HttpExchange@625d06a5{req=HttpRequest[POST /xx HTTP/2.0]@871420d[PENDING/null] res=HttpResponse[null 0 null]@48ced718[PENDING/null]})[send=HttpSenderOverHTTP2@11e7b7a3(req=QUEUED,snd=IDLE,failure=null),recv=HttpReceiverOverHTTP2@1b05f314(rsp=IDLE,failure=null)]
And another issue is that if many timeout happened, we encountered another kind of exception like "jetty http2 request failed(java.lang.IllegalStateException: Max local stream count 100 exceeded)", I doubt that if any miscount of the local stream count once the timeout occurred.
Thank you!

[sbordet]

@RoySunnySean007

Is there any difference between Jetty server and tomcat server regarding HTTP2.0 implementation?

Yes the implementations are completely different.
They should be interoperable, because they both implement the same specification, but there could be gray areas that make them differ in behavior.

[sbordet]

@lsc1943 if you use Jetty's low-level HTTP2Client, it is the application responsibility to control that the maximum number of streams is not exceeded.
If you use Jetty's high-level HttpClient, then it controls that the maximum number of streams is not exceeded.

The line of logging that you chose is perfectly normal, and the states that you see are correct.
You should not look at just one log line, but rather report all the DEBUG logs in their entirety and attach them to this issue for analysis.

I need evidence that there is a Jetty issue.
So far, either I cannot reproduce, or it's a bad assumption, or it's a badly written load test.

Take into account that Jetty's HTTP/2 implementation has been quite battle tested; you may have found an issue, but chances are that either it's a bug in your code, or in the server's code.
To be able to tell, I need hard evidence -- saying it or just picking one log line is not enough to help you.

[lsc1943]

@sbordet, thank you for your help. We are using the high-level HttpClient and we checked the debug log but didn't observe any abnormals, it seems the HEADER frames were sent to server but got no response util timeout.
But we do noticed that a lot of evict actions for the hpack like below, and it seems the size reached the limit, anyway we could configure this size to a larger value?
HdrTbl[1f2a7b19] evict {D,17,x-user-id: 36329177,445117b}
HdrTbl[1f2a7b19] entries=36, size=4096, max=4096

[sbordet]

But we do noticed that a lot of evict actions for the hpack like below

They are not relevant.

There is some evidence that I am investigating in @qingdaoheze logs.
@qingdaoheze would be great if you can turn on full DEBUG logging (not only org.eclipse.jetty.client).

Stay tuned for updates.

[qingdaoheze]

@sbordet I have rerun the demo with full DEBUG logging in (org.eclipse.jetty). Please refer to it:
https://github.com/qingdaoheze/jetty-gzip-decode/blob/master/detail.log.tar.gz

[sbordet]

@qingdaoheze we have reproduced the issue and found the bug, it's a quite particular combination of many things that must go wrong. I'll write a report when we have a test case and the fix.
Thanks for the reproducer!

[qingdaoheze]

Do you know what workaround can I use before you fix it? @sbordet BTW, when will you fix it?

[sbordet]

@qingdaoheze

Do you know what workaround can I use before you fix it?

There is no workaround.

The fix is underway.

[sbordet]

FTR, here is what is happening.

The big HEADERS frames, load test being written as it is and the server being overwhelmed caused a connection to TCP congest.

At that point, a HEADERS frame is sent by the client, queued into the HTTP2Flusher, but not sent over the wire because of TCP congestion.

The corresponding request times out and the failure arrives at HttpChannelOverHTTP2.exchangeTerminated(), where it finds that stream=null because the HEADERS frame has not been written yet (the stream field is assigned by the HEADERS write callback, which is not completed yet because the frame has not been written yet).

This causes a release() at the connection pool level, which decrements the pool counter, without the corresponding decrement of the stream counter. From this point the 2 counters are out of sync and later, for an unrelated request, may cause the IllegalStateException: max local stream count exceeded.

@qingdaoheze can you build Jetty from branch jetty-9.4.x-6208-max_streams_exceeded_tcp_congested and verify if it fixes the problem for you?

[qingdaoheze]

@sbordet I have verified it, it worked fine. Thank you! I will do more verification, if I have any other found, I will tell you.