HTTP/2: Hyper communication is stuck if too many requests are spawned.

[kundu-subhajit]

Version
0.14.27

Platform
Linux ubuntu 4.15.0-213-generic # 224-Ubuntu SMP Mon Jun 19 13:30:12 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

Short Description of the issue
Client network communications using Rust hyper library continues to stuck if too many requests are spawned.

Description
I see this bug has been earlier reported in #2419 and also has another manifestation in #3041.
Both are marked fixed. #3041 also says the fix is tested with 100 requests on 50 streams.

Generally speaking, HTTP2 Servers allows 250 parallel streams. However, client can create unlimited streams. The RFC has the following recommendation: "It is recommended that this value be no smaller than 100, so as to not unnecessarily limit parallelism."

We have a RUST client implementation, using hyper 0.14.27, along with a GoLang Server. Client requests are restricted to 400 at any point of time. Go Client runs smoothly. hyper client gets stuck every time. The bug is easily reproducible. Both RUST client and Go Server implementation can be found in the link below.

Where is the sample code that hits the issue?
Sample Code Link: https://github.com/kundu-subhajit/hyper-stuck
It has a GoLang Server implementation, Rust Client implementation using Hyper-0.14.27 & a GoLang Client implementation.
The build instructions are very straightforward

Any known workaround with the sample code?
We do acknowledge that this same issue isn't reproducible with semaphore count below 250 in the sample code shared.

Why we cant use smaller number of parallel streams as workaround?
In our local setup we have 100 as max number of HTTP/2 streams at server. But even if we try with semaphore count of 90, network communications through hyper are stuck. Trying to isolate that we arrived here and at the sample code.

What we have done differently in the sample code compared to previous reporting?
Nothing much. We have done only two minor things differently here:

1. We have run the Go Lang server and Rust client on different machines. With at-the-most 400 requests spawned, client gets stuck every time. We have reproduced this issue in two different client machines, both Ubuntu Linux and both the machines hit the issue every time.
2. We have enabled trace logging to capture logs.

CC: @jeromegn, @seanmonstar, @jfourie1
Please help us fix this bug at your earliest. Any help with this is highly appreciated. I thank you in anticipation. Thanks.

[seanmonstar]

Hey there!

It looks like the linked repo is missing the server code.

I'm also curious, does it work if you don't use a waitgroup/semaphore? Just relying on hyper to automatically not go over the concurrent streams?

[kundu-subhajit]

Firstly, Appreciate your prompt response.
Secondly, My bad. Thanks for pointing out.
Repositories are now updated, checked out, compiled and tested for successful reproduction of the issue.

[kundu-subhajit]

I removed code parts using waitgroup in my personal space and ran the code. It still gets stuck. We still hit the issue. Semaphore is needed to keep check on number of parallel attempts at a time. So kept it.

If you want I can update the repo with waitgroup removed. Code with waitgroup is tested though, for successful runs.

[seanmonstar]

Ok, I was just trying to figure out how small we can make the test case.

Do you have the trace logs? Could you paste them in a comment here inside <details></details>?

[kundu-subhajit]

For 2-3 seconds of runtime, its pretty big log.
I unable to share the way you asked. Most log files were little more than 25 MB and drag&drop has limit of 25MB.

After couple of runs I arrived at a log file within that limit:
hyper-stuck.log.2023-10-12.log

I will still suggest that please run it from the sample code so that you can have bigger runtime to capture any log that is printed while things are stuck.

[kundu-subhajit]

@jeromegn, @seanmonstar, @jfourie1: Ping.

[seanmonstar]

Please don't ping, especially the others. We're all busy and balancing different things.

If you wish it would get solved faster, you can try digging into the logs and the source code and determining exactly what has it stuck.

[kundu-subhajit]

Noted.

[izderadicka]

Problem was with hyper-openssl, which is probably bit outdated. With hyper-rustls works as expected (and is actually faster by app. %50%, number of clients does not play a role - I guess it already enough parallel on one client).

Can check here https://github.com/izderadicka/hyper-stuck

[izderadicka]

I was too too quick with conclusions sorry. Previous example worked because it uses HTTP/1.1.
Just switching to HTTP/2.0 causes same problem as reported, so it's not TLS implementation probably.

It demonstrates like this:

• with several hundreds concurrent tasks app. >= 300
• few initial requests - between 4 - 8 are processed immediately
• then it stucks, no further requests are received by server
• for less then 300 concurrent, say 250 - few initial requests are done quickly - 5-8 similar to above. Then it pauses for few seconds, then it catches up and finishes all remaining

Updated version which demonstrates problem will be on https://github.com/izderadicka/hyper-stuck

[izderadicka]

I've done one more test - against Rust hyper server (added to repo) instead and now client works fine, without problems.
So it must be something between Go server and Rust client on HTTP/2.0 protocol. I know very little of Go, however it looks like server is simple - all defaults, nothing suspicious there.

Also one interesting finding - client against Rust server on HTTP/2.0 is about 4 times slower, then on HTTP/1.1 - against same server, only switched protocols, this is bit contra-intuitive. Go client on the other hand is little bit faster against Rust server, that it was against Go server.

I wanted to try hyper 1.0 in client, but do not know yet how to setup TLS - 1.0 is still very fresh, hyper-rustls is on 0.14 and did not have time to dig deeper how to manually create appropriate connector.

[izderadicka]

And one more final finding - from trace log - the log from stuck run against Go server have a lot of stream capacity is 0 messages at the end of log, when communication got stuck , I do not see anything like this in the log of successful run against Rust server. Here is excerpt from the log:

2023-11-18T16:49:56.726566Z TRACE Connection{peer=Client}:poll: h2::proto::streams::prioritize: schedule_pending_open
2023-11-18T16:49:56.726571Z TRACE Connection{peer=Client}:poll:pop_frame:popped{stream.id=StreamId(515) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }}: h2::proto::streams::prioritize: is_pending_reset=false
2023-11-18T16:49:56.726575Z TRACE Connection{peer=Client}:poll:pop_frame:popped{stream.id=StreamId(515) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }}: h2::proto::streams::prioritize: data frame sz=235335 eos=true window=0 available=0 requested=235335 buffered=235335
2023-11-18T16:49:56.726580Z TRACE Connection{peer=Client}:poll:pop_frame:popped{stream.id=StreamId(515) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }}: h2::proto::streams::prioritize: stream capacity is 0
2023-11-18T16:49:56.726585Z TRACE Connection{peer=Client}:poll:pop_frame:popped{stream.id=StreamId(517) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }}: h2::proto::streams::prioritize: is_pending_reset=false
2023-11-18T16:49:56.726590Z TRACE Connection{peer=Client}:poll:pop_frame:popped{stream.id=StreamId(517) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }}: h2::proto::streams::prioritize: data frame sz=238437 eos=true window=0 available=0 requested=238437 buffered=238437
2023-11-18T16:49:56.726594Z TRACE Connection{peer=Client}:poll:pop_frame:popped{stream.id=StreamId(517) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }}: h2::proto::streams::prioritize: stream capacity is 0
2023-11-18T16:49:56.726599Z TRACE Connection{peer=Client}:poll:FramedWrite::flush: h2::codec::framed_write: flushing buffer
2023-11-18T16:49:56.726603Z TRACE Connection{peer=Client}:poll: tokio::task::waker: op="waker.clone" task.id=5
2023-11-18T16:49:56.726607Z TRACE Connection{peer=Client}:poll: tokio::task::waker: op="waker.drop" task.id=5

[izderadicka]

I've done bit of additional exploration:

• happens also on hyper v1 (updated demo repo to hyper 1.0.1)
• on server side following Go server influences the problem:
  • MaxConcurrentStreams - if increased to 1000 then client is not stuck completely - it's just hangs up after few requests, for 10 secs or so than catches up, but overall is quite slow, still see stream capacity is 0 in log
  • MaxUploadBufferPerConnection is set up to app. 32M then problem completely disappears, no stream capacity is 0 in log
• as already explained above problem is best demonstrated when there is single http2 client, which spawn app. 300 requests in separate tokio tasks. If the are multiple clients (say 10), problems appears too, but much later, after some thousands of requests
• go client does not have this problem - at least the one provided there, it should have about 600 spawned requests in parallel in go function.

[seanmonstar]

Excellent work investigating! So, is it related to flow control? Is there connection window available, but not stream? It's fine to investigate with hyper v0.14, it's most likely something in the h2 dependency, which is the same in both cases.