http2 GOAWAY causes client to drop requests
Nobody has claimed this yet.
- Dominant language
- Rust
- Stars
- 16.3k
- Forks
- 1.8k
- Avg merge
- 1d 22h
- Merged PRs (30d)
- 14
Description
It's possible this is an h2 issue but I don't know the crates well enough to know.
If a GOAWAY is received while multiple requests are in flight some of them fail with the error:
http2 error: protocol error: not a result of an error
I can reproduce this by running the following code:
use anyhow::Result;
use hyper::{client::HttpConnector, Body, Client, Uri};
use tracing::{span, warn, Instrument as _, Level, Span};
#[tokio::main]
async fn main() -> Result<()> {
tracing_subscriber::fmt()
.with_max_level(Level::DEBUG)
.init();
let connector = HttpConnector::new();
let client: Client<_, Body> = Client::builder().http2_only(true).build(connector);
let uri: Uri = "http://127.0.0.1:8080".parse().unwrap();
let mut requests = Vec::new();
for i in 0u32..2 {
let client = client.clone();
let uri = uri.clone();
let span = span!(Level::INFO, "request", i);
span.follows_from(Span::current());
requests.push(tokio::spawn(
async move {
match client.get(uri).await {
Ok(res) => {
let _ = hyper::body::to_bytes(res.into_body()).await.unwrap();
}
Err(e) => warn!("{}", e),
}
}
.instrument(span),
));
}
for request in requests {
let _ = request.await;
}
Ok(())
}
I ran this against an nginx instance with the following config to force http2 and send a GOAWAY after every single request.
events {}
http {
server {
listen 80 http2;
keepalive_requests 1;
location / {
root /data;
}
}
}
This program generates the logs (edit: I've added in the trace level logs too if they're useful trace.log):
Apr 12 15:44:42.887 DEBUG request{i=0}: hyper::client::connect::http: connecting to 127.0.0.1:8080
Apr 12 15:44:42.888 DEBUG request{i=0}: hyper::client::connect::http: connected to 127.0.0.1:8080
Apr 12 15:44:42.888 DEBUG request{i=0}: h2::client: binding client connection
Apr 12 15:44:42.889 DEBUG request{i=0}: h2::client: client connection bound
Apr 12 15:44:42.889 DEBUG request{i=0}: h2::codec::framed_write: send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
Apr 12 15:44:42.889 DEBUG request{i=0}: hyper::client::pool: pooling idle connection for ("http", 127.0.0.1:8080)
Apr 12 15:44:42.889 DEBUG request{i=0}:Connection{peer=Client}: h2::codec::framed_read: received frame=Settings { flags: (0x0), max_concurrent_streams: 128, initial_window_size: 65536, max_frame_size: 16777215 }
Apr 12 15:44:42.890 DEBUG request{i=0}:Connection{peer=Client}: h2::codec::framed_write: send frame=Settings { flags: (0x1: ACK) }
Apr 12 15:44:42.890 DEBUG request{i=1}: hyper::client::pool: reuse idle connection for ("http", 127.0.0.1:8080)
Apr 12 15:44:42.890 DEBUG request{i=0}:Connection{peer=Client}: h2::codec::framed_read: received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 2147418112 }
Apr 12 15:44:42.891 DEBUG request{i=0}:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
Apr 12 15:44:42.891 DEBUG request{i=0}:Connection{peer=Client}: h2::codec::framed_write: send frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }
Apr 12 15:44:42.891 DEBUG request{i=0}:Connection{peer=Client}: h2::codec::framed_write: send frame=Headers { stream_id: StreamId(3), flags: (0x5: END_HEADERS | END_STREAM) }
Apr 12 15:44:42.892 DEBUG request{i=0}:Connection{peer=Client}: h2::codec::framed_read: received frame=Settings { flags: (0x1: ACK) }
Apr 12 15:44:42.892 DEBUG request{i=0}:Connection{peer=Client}: h2::proto::settings: received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
Apr 12 15:44:42.893 DEBUG request{i=0}:Connection{peer=Client}: h2::codec::framed_read: received frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(1) }
Apr 12 15:44:42.894 DEBUG request{i=0}:Connection{peer=Client}: h2::codec::framed_read: received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
Apr 12 15:44:42.894 DEBUG request{i=0}:Connection{peer=Client}: h2::codec::framed_read: received frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
Apr 12 15:44:42.895 DEBUG hyper::proto::h2::client: client response error: protocol error: not a result of an error
Apr 12 15:44:42.896 WARN request{i=1}: hyper_test: http2 error: protocol error: not a result of an error
Rampant speculation
My suspicion is that any stream after the final stream inidicated in the HTTP2 GOAWAY frame, that were spawned before hyper received the goaway, throw this error. I would expect hyper to retry them on a new connection, as it does for any connection spawned later on (I assume after the client has marked the old connection as closed).
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Research direction
Run the provided Rust reproducer against the nginx configuration with keepalive_requests 1, and inspect the linked trace.log alongside the h2 and hyper HTTP/2 client behavior. Verify how streams beyond the GOAWAY last-stream ID are handled; done means those in-flight requests are retried on a new connection instead of returning the protocol error.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- rust
- Domain
- api, networking
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 45/100