uv should be retrying on transient error of 429

[chrisirhc]

This is on uv 0.2.34.

I'd expect 429 errors to be retried, but it seems to be not being retried, despite being specified in https://github.com/astral-sh/reqwest-middleware/blob/21ceec9a5fd2e8d6f71c3ea2999078fecbd13cbe/reqwest-retry/src/retryable_strategy.rs#L125

Sample trace logs:

           44.515293s   1s  TRACE hyper_util::client::legacy::pool put; add idle connection for ("https", artifacts.uberinternal.com)                                                                          
           44.515313s   1s  DEBUG hyper_util::client::legacy::pool pooling idle connection for ("https", artifacts.uberinternal.com)                                                                           
           44.515350s   1s  DEBUG uv_client::base_client Transient request failure for: …/46/b3/d906c67382b8711d9612a8aff1e685f6b04
d97bd18991e21fabc197660eb/pydantic_core-2.14.4-cp311-cp311-macosx_11_0_arm64.whl#sha256=bccd5af7f05290da715623ec3e71f25d70ddb09da7925a4c2eea883f2610bad2                                                       
error: Failed to download `pydantic-core==2.14.4`
  Caused by: HTTP status client error (429 Too Many Requests) for url (…/46/b3/d906c67382b8711d9612a8aff1e685f6b04d97bd18991e21fabc
197660eb/pydantic_core-2.14.4-cp311-cp311-macosx_11_0_arm64.whl#sha256=bccd5af7f05290da715623ec3e71f25d70ddb09da7925a4c2eea883f2610bad2) 

I'm not seeing the "retrying" logs that were added in 63c84ed .

[zanieb]

Thanks for the report! Not sure why this would be happening yet.

[zanieb]

What happens after that?

[charliermarsh]

impl RetryableStrategy for UvRetryableStrategy {
    fn handle(&self, res: &Result<Response, reqwest_middleware::Error>) -> Option<Retryable> {
        // Use the default strategy and check for additional transient error cases.
        let retryable = match DefaultRetryableStrategy.handle(res) {
            None | Some(Retryable::Fatal) if is_extended_transient_error(res) => {
                Some(Retryable::Transient)
            }
            default => default,
        };

        // Log on transient errors
        if retryable == Some(Retryable::Transient) {
            match res {
                Ok(response) => {
                    debug!("Transient request failure for: {}", response.url());
                }
                Err(err) => {
                    let context = iter::successors(err.source(), |&err| err.source())
                        .map(|err| format!("  Caused by: {err}"))
                        .join("\n");
                    debug!(
                        "Transient request failure for {}, retrying: {err}\n{context}",
                        err.url().map(reqwest::Url::as_str).unwrap_or("unknown URL")
                    );
                }
            }
        }
        retryable
    }
}

I do see the Transient request failure logging above though.

[charliermarsh]

I think we're probably missing a retry case here. It's going to be hard to test and reproduce though.

[charliermarsh]

If you have any tips for successfully triggering this, LMK.

[zanieb]

Yeah weird this pretty clearly looks like it's being marked as a transient failure. Can you share more logs?

[charliermarsh]

My guess is we aren’t handling this properly because it’s a download failure (as opposed to any other HTTP request).

[charliermarsh]

Ok, so I've actually confirmed that we do seem to retry on 429:

...
127.0.0.1 - - [12/Aug/2024 14:15:53] "GET /packages/31/80/3a54838c3fb461f6fec263ebf3a3a41771bd05190238de3486aae8540c36/jinja2-3.1.4-py3-none-any.whl.metadata HTTP/1.1" 200 -
127.0.0.1 - - [12/Aug/2024 14:15:53] "GET /packages/00/2e/d53fa4befbf2cfa713304affc7ca780ce4fc1fd8710527771b58311a3229/click-8.1.7-py3-none-any.whl.metadata HTTP/1.1" 200 -
127.0.0.1 - - [12/Aug/2024 14:15:53] "GET /packages/04/96/92447566d16df59b2a776c0fb82dbc4d9e07cd95062562af01e408583fc4/itsdangerous-2.2.0-py3-none-any.whl.metadata HTTP/1.1" 200 -
127.0.0.1 - - [12/Aug/2024 14:15:53] "GET /packages/bb/2a/10164ed1f31196a2f7f3799368a821765c62851ead0e630ab52b8e14b4d0/blinker-1.8.2-py3-none-any.whl.metadata HTTP/1.1" 200 -
127.0.0.1 - - [12/Aug/2024 14:15:53] "GET /packages/6a/4a/a4d49415e600bacae038c67f9fecc1d5433b9d3c71a4de6f33537b89654c/MarkupSafe-2.1.5-cp310-cp310-macosx_10_9_x86_64.whl.metadata HTTP/1.1" 429 -
127.0.0.1 - - [12/Aug/2024 14:15:53] "GET /packages/6a/4a/a4d49415e600bacae038c67f9fecc1d5433b9d3c71a4de6f33537b89654c/MarkupSafe-2.1.5-cp310-cp310-macosx_10_9_x86_64.whl.metadata HTTP/1.1" 200 -
127.0.0.1 - - [12/Aug/2024 14:15:53] "GET /packages/6a/4a/a4d49415e600bacae038c67f9fecc1d5433b9d3c71a4de6f33537b89654c/MarkupSafe-2.1.5-cp310-cp310-macosx_10_9_x86_64.whl HTTP/1.1" 429 -
127.0.0.1 - - [12/Aug/2024 14:15:53] "GET /packages/04/96/92447566d16df59b2a776c0fb82dbc4d9e07cd95062562af01e408583fc4/itsdangerous-2.2.0-py3-none-any.whl HTTP/1.1" 200 -
127.0.0.1 - - [12/Aug/2024 14:15:53] "GET /packages/bb/2a/10164ed1f31196a2f7f3799368a821765c62851ead0e630ab52b8e14b4d0/blinker-1.8.2-py3-none-any.whl HTTP/1.1" 200 -
127.0.0.1 - - [12/Aug/2024 14:15:53] "GET /packages/00/2e/d53fa4befbf2cfa713304affc7ca780ce4fc1fd8710527771b58311a3229/click-8.1.7-py3-none-any.whl HTTP/1.1" 200 -
127.0.0.1 - - [12/Aug/2024 14:15:53] "GET /packages/61/80/ffe1da13ad9300f87c93af113edd0638c75138c42a0994becfacac078c06/flask-3.0.3-py3-none-any.whl HTTP/1.1" 200 -
127.0.0.1 - - [12/Aug/2024 14:15:53] "GET /packages/31/80/3a54838c3fb461f6fec263ebf3a3a41771bd05190238de3486aae8540c36/jinja2-3.1.4-py3-none-any.whl HTTP/1.1" 200 -
127.0.0.1 - - [12/Aug/2024 14:15:53] "GET /packages/9d/6e/e792999e816d19d7fcbfa94c730936750036d65656a76a5a688b57a656c4/werkzeug-3.0.3-py3-none-any.whl HTTP/1.1" 200 -
127.0.0.1 - - [12/Aug/2024 14:15:53] "GET /packages/6a/4a/a4d49415e600bacae038c67f9fecc1d5433b9d3c71a4de6f33537b89654c/MarkupSafe-2.1.5-cp310-cp310-macosx_10_9_x86_64.whl HTTP/1.1" 200 -

Is it possible that you hit the retry limit? Do you see multiple of those "Transient request failure for..." messages?