hyperium / hyperium/hyper

http2 GOAWAY causes client to drop requests

Open
#2,500 4 comments 1 reaction 0 assignees View on GitHub

Nobody has claimed this yet.

A-client A-http2
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

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.