Log transient network request failures (#3933)

We retry several kinds of network request failures, but it's often
unclear whether a request was retried or not
(https://github.com/astral-sh/uv/issues/3514#issuecomment-2105485773).
This PR adds a small intermediary layer that logs all transient request
failures, adding the `DEBUG Transient request failure` lines:

```
DEBUG Searching for Python interpreter in virtual environments
DEBUG Found CPython 3.12.3 at `/home/konsti/projects/uv/.venv/bin/python3` (active virtual environment)
DEBUG Using Python 3.12.3 environment at .venv/bin/python3
DEBUG Acquired lock for `.venv`
DEBUG At least one requirement is not satisfied: tqdm
DEBUG Using registry request timeout of 30s
DEBUG Solving with target Python version 3.12.3
DEBUG Adding direct dependency: tqdm*
DEBUG No cache entry for: https://pypi.org/simple/tqdm/
DEBUG Transient request failure for https://pypi.org/simple/tqdm/, retrying: Request error: error sending request for url (https://pypi.org/simple/tqdm/)
  Caused by: error sending request for url (https://pypi.org/simple/tqdm/)
  Caused by: client error (Connect)
  Caused by: dns error: failed to lookup address information: Name or service not known
  Caused by: failed to lookup address information: Name or service not known
DEBUG Transient request failure for https://pypi.org/simple/tqdm/, retrying: Request error: error sending request for url (https://pypi.org/simple/tqdm/)
  Caused by: error sending request for url (https://pypi.org/simple/tqdm/)
  Caused by: client error (Connect)
  Caused by: dns error: failed to lookup address information: Name or service not known
  Caused by: failed to lookup address information: Name or service not known
DEBUG Transient request failure for https://pypi.org/simple/tqdm/, retrying: Request error: error sending request for url (https://pypi.org/simple/tqdm/)
  Caused by: error sending request for url (https://pypi.org/simple/tqdm/)
  Caused by: client error (Connect)
  Caused by: dns error: failed to lookup address information: Name or service not known
  Caused by: failed to lookup address information: Name or service not known
DEBUG Transient request failure for https://pypi.org/simple/tqdm/, retrying: Request error: error sending request for url (https://pypi.org/simple/tqdm/)
  Caused by: error sending request for url (https://pypi.org/simple/tqdm/)
  Caused by: client error (Connect)
  Caused by: dns error: failed to lookup address information: Name or service not known
  Caused by: failed to lookup address information: Name or service not known
error: Could not connect, are you offline?
  Caused by: error sending request for url (https://pypi.org/simple/tqdm/)
  Caused by: client error (Connect)
  Caused by: dns error: failed to lookup address information: Name or service not known
  Caused by: failed to lookup address information: Name or service not known
```

I decided for multi-line logging to show the complete error trace since
only `Transient request failure for https://pypi.org/simple/tqdm/,
retrying: Request error: error sending request for url
(https://pypi.org/simple/tqdm/)` doesn't tell you the actual problem (a
dns error).

Note that running with `-v` will not show messages about retry backoff
timing, but running with `RUST_LOG=debug` now shows a complete picture:

```
DEBUG starting new connection: https://pypi.org/
DEBUG resolving host="pypi.org"
DEBUG Transient request failure for https://pypi.org/simple/tqdm/, retrying: Request error: error sending request for url (https://pypi.org/simple/tqdm/)
  Caused by: error sending request for url (https://pypi.org/simple/tqdm/)
  Caused by: client error (Connect)
  Caused by: dns error: failed to lookup address information: Name or service not known
  Caused by: failed to lookup address information: Name or service not known
WARN Retry attempt #2. Sleeping 528.728192ms before the next attempt
```

Fixes #3572
This commit is contained in:
konsti
2024-06-04 15:39:16 +02:00
committed by GitHub
parent 41ec302557
commit 63c84ed4a6
3 changed files with 46 additions and 8 deletions
Generated
+1
View File
@@ -4530,6 +4530,7 @@ dependencies = [
"hyper-util",
"insta",
"install-wheel-rs",
"itertools 0.13.0",
"pep440_rs",
"pep508_rs",
"platform-tags",
+1
View File
@@ -29,6 +29,7 @@ fs-err = { workspace = true, features = ["tokio"] }
futures = { workspace = true }
html-escape = { workspace = true }
http = { workspace = true }
itertools = { workspace = true }
reqwest = { workspace = true }
reqwest-middleware = { workspace = true }
reqwest-retry = { workspace = true }
+44 -8
View File
@@ -1,14 +1,20 @@
use pep508_rs::MarkerEnvironment;
use platform_tags::Platform;
use reqwest::{Client, ClientBuilder};
use reqwest_middleware::ClientWithMiddleware;
use reqwest_retry::policies::ExponentialBackoff;
use reqwest_retry::RetryTransientMiddleware;
use std::env;
use std::error::Error;
use std::fmt::Debug;
use std::ops::Deref;
use std::path::Path;
use std::{env, iter};
use itertools::Itertools;
use reqwest::{Client, ClientBuilder, Response};
use reqwest_middleware::ClientWithMiddleware;
use reqwest_retry::policies::ExponentialBackoff;
use reqwest_retry::{
DefaultRetryableStrategy, RetryTransientMiddleware, Retryable, RetryableStrategy,
};
use tracing::debug;
use pep508_rs::MarkerEnvironment;
use platform_tags::Platform;
use uv_auth::AuthMiddleware;
use uv_configuration::KeyringProviderType;
use uv_fs::Simplified;
@@ -166,7 +172,10 @@ impl<'a> BaseClientBuilder<'a> {
// Initialize the retry strategy.
let retry_policy =
ExponentialBackoff::builder().build_with_max_retries(self.retries);
let retry_strategy = RetryTransientMiddleware::new_with_policy(retry_policy);
let retry_strategy = RetryTransientMiddleware::new_with_policy_and_strategy(
retry_policy,
LoggingRetryableStrategy,
);
let client = client.with(retry_strategy);
// Initialize the authentication middleware to set headers.
@@ -225,3 +234,30 @@ impl Deref for BaseClient {
&self.client
}
}
/// The same as [`DefaultRetryableStrategy`], but retry attempts on transient request failures are
/// logged, so we can tell whether a request was retried before failing or not.
struct LoggingRetryableStrategy;
impl RetryableStrategy for LoggingRetryableStrategy {
fn handle(&self, res: &Result<Response, reqwest_middleware::Error>) -> Option<Retryable> {
let retryable = DefaultRetryableStrategy.handle(res);
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(|url| url.as_str()).unwrap_or("unknown URL")
);
}
}
}
retryable
}
}