awc reuses connections with connection errors from H2

[kevin-logan]

When an awc client makes repeated requests to a single downstream service using an optimistic timeout, it can be expected these timeouts will unfortunately trigger rather regularly. When awc enforces a timeout it tells h2 to reset the stream.

h2 has a "num_local_error_resets" it keeps track of towards a default limit of 1024. Once this limit is reached h2 will inject GoAway errors into any attempt to use that connection going forward.

Expected Behavior

It is expected when attempting to re-use a connection awc will observe this GoAway (returned from either io.poll_ready and io.send_request, both in send_request in h2proto.rs and decide not to return the connection to the pool by call io.on_release(true).

This way, once the connection is effectively poisoned by h2 further requests with the client will create a new connection and no further issues (beyond the timeouts) will be experienced by the user.

Current Behavior

Currently when handling errors from either io.poll_ready or io.send_request io.on_release is called with the parameter err.is_io(), which means errors always return the connection the pool unless it was an IO error.

GoAway errors are not an IO error, so the connection is returned to the pool and immediately re-used for the next request, which fails in microseconds as io.poll_ready immediately returns the GoAway error. This causes the client to start experiencing repeated instantaneous errors when trying to repeatedly request downstream.

This invalid state can take a long time to recover. The conn_lifetime from the connector being one mechanism to put a cap on the possible duration of the invalid state, but setting it too low is rather unfortunate and creates otherwise unnecessary connection pressure in high performance systems and doesn't stop the invalid state from existing, just reduces its impact. Experimenting with high conn_lifetime values around 1 hour (as in my case I'm making server-to-server calls and expect very solid connections, I see no need for a lifetime limit at all) I do see it seems these errors happen regularly and the invalid state was observed to persist for sometimes 15 minutes, sometimes 45 minutes, and seems likely a function of how long into the connection lifetime it took for the connection to be poisoned by h2.

Possible Solution

I think this may be as easy as changing the two error handling on_release calls in send_request in h2proto.rs from:

io.on_release(err.is_io());

to

io.on_release(err.is_io() || err.is_go_away());

That said, I'm certainly not a protocol expert and don't know if this would be overly pessimistic and cause otherwise-healthy connections to be dropped, and there could certainly be other mechanisms that need to be considered that I am unaware of.

I would be happy to create this PR myself but for my above mentioned lack of domain expertise, as I don't feel confident I know of all the potential knock-on effects.

Steps to Reproduce (for bugs)

1. Make continuous requests to the same downstream system with some timing variance (due to networking, load, caching, etc).
2. Use a tight-ish timeout (8ms in my case) that will sometimes be exceeded. Set this timeout both on the ClientRequest object and the ClientResponse to respect upstream response-time SLAs.
3. Ensure either enough volume is generated and/or the conn_lifetime is high enough that >1024 timeouts occur during a connection lifetime. If logging is enabled you will see a log from h2 that will indicate the error condition has been triggered, e.g. WARN h2::proto::streams::streams:actix-rt|system:0|arbiter:4] locally-reset streams reached limit (1024)
4. Observe that future connections after the 1024th timeout can fail immediately (microseconds-to-fail rather than 8ms). Due to potentially having multiple open HTTP/2 connections it's not necessarily true that all requests will fail, but failures will be proportional to the number of connections versus how many are poisoned.

Context

I maintain a service which calls multiple downstream services server-to-server very regularly using HTTP/2. This service transacts millions of QPS and needs to perform very well to keep costs down.

Upstream and downstream of my application are both first-party services from the same organization and connections are usually very healthy. I have been attempting to migrate away from reqwest as the service is built on actix-web and I have seen performance issues using reqwest as I believe that reqwest doesn't follow the cooperative programming principles required for working in a thread-per-core framework like actix (principally how reqwest / hyper backgrounds tasks while awaiting a new HTTP/2 connection).

In my transition to awc I have immediately seen slightly better tail latency times but I didn't manage to test under proper production load as the aforementioned issues with invalid connection reuse appeared and has derailed the test with an unfortunately unacceptable increase in error rates. If I can resolve this issue I believe awc will cooperate with the application much better than reqwest, particularly in heavily loaded scenarios.

Your Environment

dockerized within a debian:bullseye-slim container.
Rust: 1.88
awc: 3.8.0
actix-web: 4.11.0
actix-rt: 2.10.0

[kevin-logan]

I've created a very rudimentary reproducer here. Disclaimer: it's not great. This issue only comes up when a host of things occur in a specific order in a world where other things can also randomly go wrong.

That said, this test works reliably to exhibit the issue on my machine. Due to needing HTTP/2 it just requests google so you might want to point it towards a local or more reliable HTTP/2 endpoint.

The point of the reproducer is to go through a few steps and demonstrate the issue:

1. Setup a client with ALPN and only "h2" protocol supported - this is because I'm not aware of a way to force prior-knowledge h2c in awc. If that's just me missing something this reproducer could be simplified
2. send a request to the url (currently "https://www.google.com") without any timeouts - as long as your internet is working this request should succeed and get your typical google response. The content of the response isn't verified, so swapping google with something better is encouraged
3. Make 2000 (just some number much larger than 1024) requests to the same url (presumably using the same connection, as the connection limit was set to 1). The requests have no ClientRequest::timeout but do have an unreasonable 1ms ClientResponse::timeout (it is expected that all ClientResponses should time out to trigger the bug).
4. As long as requests are working we'd expect the request to never resolve in <1ms as you're not going to be that close to google.com - this intends to demonstrate the internet was actually used
5. As soon as there is one error (which is presumed to be a GO_AWAY from too many local-resets) we expect nothing but errors going forward. If you happen to have a hiccup (non local-reset based error) this will cause the reproducer to fail. Any error that happens before the 100th request will cause a failure as I want to demonstrate that things work properly for some time before they suddenly fail and then stay in that failed state.
6. All requests after the first failure are asserted to be a failure and asserted to fail within 1ms (demonstrating the failure occurs without any actual networking)
7. Finally, it asserts that at least one error triggered during the 2000. If the entire "test" passes then it demonstrates that eventually an error occurred, and from then on consistent and immediate errors occured.

For me this consistently reproduces, but surprisingly not with the same numbers. I would have anticipated it'd take exactly 1024 timeouts to trigger the error but this is not the case. I've seen various numbers which tend to be in the range of several hundred (for example, on requests 404 and 462 on my last two runs).

If you inspect the first error, what you'll see is exactly the trigger condition mentioned:

thread 'http::tests::test_awc_client_resets' panicked:
Request 462 should not fail (before 1024 timeouts): H2(Error { kind: GoAway(b"too_many_internal_resets", ENHANCE_YOUR_CALM, Library) })

NOTE: this test may take a couple minutes to run

Here is the complete rudimentary reproducer:

    #[actix_web::test]
    async fn test_awc_client_resets() {
        use rustls_platform_verifier::ConfigVerifierExt as _;

        rustls::crypto::aws_lc_rs::default_provider()
            .install_default()
            .expect("Failed to install AWS LC RS provider");

        let mut config =
            rustls::ClientConfig::with_platform_verifier().expect("Failed to create Rustls config");
        config.alpn_protocols = vec![b"h2".to_vec()];

        let connector = awc::Connector::new()
            .rustls_0_23(Arc::new(config))
            .limit(1) // ensure all requests are using the same connection for the test
            // set lifetime to certainly longer than the duration of the test
            .conn_lifetime(std::time::Duration::from_secs(3600));
        let client = awc::Client::builder()
            .add_default_header((awc::http::header::USER_AGENT, "test-client"))
            .connector(connector)
            .finish();

        // just use google as the test URL, but we need https so ALPN negotation for h2 happens
        let url = "https://www.google.com";

        // issue one request at the start to negatiate the connection, without any timeout
        let mut response = client
            .get(url)
            .send()
            .await
            .expect("Failed to issue initial request");
        assert_eq!(response.status(), awc::http::StatusCode::OK);
        let _ = response.body().await.expect("Failed to read body");

        let mut has_had_error = false;

        // at least 1024 requests using a _very_ unrealistic 1ms timeout, need to cause enough local resets to trigger a GO_AWAY
        for i in 0..2000 {
            let start = std::time::Instant::now();
            let response = client.get(url).send().await;
            let time_elapsed = start.elapsed();

            // obviously this test depends on non-local-reset errors not happening, but once we've had an error we
            // expect to see nothing but errors from then on (rather than a new connection being created)
            if !has_had_error {
                if let Err(e) = response {
                    assert!(
                        i >= 100,
                        "At least 100 requests should be able to complete successfully"
                    );

                    has_had_error = true;
                    continue;
                }

                // we didn't have any errors yet, the time must indicate an actual request was made
                assert!(time_elapsed > std::time::Duration::from_millis(1));

                let response = response.expect(&format!(
                    "Request {i} should not fail (before 1024 timeouts)"
                ));

                // timeout getting the body with the unrealistic timeout - these timeouts are what causes the
                // local-resets to occur which trigger a GO_AWAY from h2
                let body = response
                    .timeout(std::time::Duration::from_millis(1))
                    .body()
                    .await;

                // we expect the unrealistic timeout to occur
                assert!(body.is_err());
            } else {
                // the failures have now become instant
                assert!(time_elapsed < std::time::Duration::from_millis(1));

                response.expect_err("Request should fail after GO_AWAY");
            }
        }

        // with one connection and many requests the error condition will have occurred
        // which in turn demonstrates that every request after the error failed, too
        assert!(has_had_error);
    }

expected output (indicating there is an issue):

running 1 test
test http::tests::test_awc_client_resets has been running for over 60 seconds
test http::tests::test_awc_client_resets ... ok

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 114.80s

[kevin-logan]

I've created the above PR (#3790) after seeing a related PR (#3678). I still feel there could be unintentional side-effects of this change but I'm struggling to think of a situation where a GO_AWAY is received and we wouldn't want to respect that and close the connection.

I've partially created the PR to ensure the fix is more general (not isolated to remote or local GO_AWAY issues) and also so I can test in the meantime and see if this indeed resolves the issues I've seen while not creating any new issues.