From 63c84ed4a630aaedea9061eedd2f489ce0f9aefa Mon Sep 17 00:00:00 2001 From: konsti Date: Tue, 4 Jun 2024 15:39:16 +0200 Subject: [PATCH] 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 --- Cargo.lock | 1 + crates/uv-client/Cargo.toml | 1 + crates/uv-client/src/base_client.rs | 52 ++++++++++++++++++++++++----- 3 files changed, 46 insertions(+), 8 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index bb955e8ad..527e1273b 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4530,6 +4530,7 @@ dependencies = [ "hyper-util", "insta", "install-wheel-rs", + "itertools 0.13.0", "pep440_rs", "pep508_rs", "platform-tags", diff --git a/crates/uv-client/Cargo.toml b/crates/uv-client/Cargo.toml index fdadf59df..85a5fb6e0 100644 --- a/crates/uv-client/Cargo.toml +++ b/crates/uv-client/Cargo.toml @@ -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 } diff --git a/crates/uv-client/src/base_client.rs b/crates/uv-client/src/base_client.rs index 9994b2a97..7c1dcd678 100644 --- a/crates/uv-client/src/base_client.rs +++ b/crates/uv-client/src/base_client.rs @@ -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) -> Option { + 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 + } +}