Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

HTTP/2 max local stream count exceeded #6208

Closed
qingdaoheze opened this issue Apr 24, 2021 · 16 comments · Fixed by #6220 or #6225
Closed

HTTP/2 max local stream count exceeded #6208

qingdaoheze opened this issue Apr 24, 2021 · 16 comments · Fixed by #6220 or #6225

Comments

@qingdaoheze
Copy link

qingdaoheze commented Apr 24, 2021

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
Copy link
Contributor

sbordet commented Apr 24, 2021

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
Copy link
Author

qingdaoheze commented Apr 24, 2021

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
Copy link
Contributor

sbordet commented Apr 24, 2021

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
Copy link
Author

qingdaoheze commented Apr 25, 2021

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
Copy link

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
Copy link

lsc1943 commented Apr 25, 2021

@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
Copy link
Contributor

sbordet commented Apr 25, 2021

@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
Copy link
Contributor

sbordet commented Apr 25, 2021

@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
Copy link

lsc1943 commented Apr 26, 2021

@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
Copy link
Contributor

sbordet commented Apr 26, 2021

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
Copy link
Author

@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
Copy link
Contributor

sbordet commented Apr 26, 2021

@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
Copy link
Author

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

@sbordet
Copy link
Contributor

sbordet commented Apr 27, 2021

@qingdaoheze

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

There is no workaround.

The fix is underway.

@sbordet sbordet changed the title Header size is bigger will cause TimeoutException HTTP/2 max local stream count exceeded Apr 28, 2021
sbordet added a commit that referenced this issue Apr 28, 2021
Backported from Jetty 10 the "new stream" event so that the Stream can be set early on the client's `HttpChannelOverHTTP2`.
In this way, when a HEADERS frame stalled due to TCP congestion is failed, the corresponding Stream is closed and the connection released to the pool, fixing the "max stream exceeded" issue.

Signed-off-by: Simone Bordet <simone.bordet@gmail.com>
@sbordet sbordet linked a pull request Apr 28, 2021 that will close this issue
@sbordet
Copy link
Contributor

sbordet commented Apr 28, 2021

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?

@sbordet sbordet added this to To do in Jetty 9.4.41 via automation Apr 28, 2021
sbordet added a commit that referenced this issue Apr 28, 2021
Updates after review.

Signed-off-by: Simone Bordet <simone.bordet@gmail.com>
@qingdaoheze
Copy link
Author

@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.

sbordet added a commit that referenced this issue Apr 29, 2021
* Fixes #6208 - HTTP/2 max local stream count exceeded

Backported from Jetty 10 the "new stream" event so that the Stream can be set early on the client's `HttpChannelOverHTTP2`.
In this way, when a HEADERS frame stalled due to TCP congestion is failed, the corresponding Stream is closed and the connection released to the pool, fixing the "max stream exceeded" issue.

Signed-off-by: Simone Bordet <simone.bordet@gmail.com>
sbordet added a commit that referenced this issue Apr 29, 2021
Forward port of #6220 from jetty-9.4.x to jetty-10.0.x.

Signed-off-by: Simone Bordet <simone.bordet@gmail.com>
(cherry-picked from commit 2f19c67)
@sbordet sbordet linked a pull request Apr 29, 2021 that will close this issue
@sbordet sbordet moved this from To do to Done in Jetty 9.4.41 Apr 29, 2021
@sbordet sbordet added this to To do in Jetty 10.0.3/11.0.3 via automation Apr 29, 2021
Jetty 10.0.3/11.0.3 automation moved this from To do to Done Apr 29, 2021
sbordet added a commit that referenced this issue Apr 29, 2021
Forward port of #6220 from jetty-9.4.x to jetty-10.0.x.

Signed-off-by: Simone Bordet <simone.bordet@gmail.com>
(cherry-picked from commit 2f19c67)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
No open projects
4 participants