From c7c9b8f32b4665544514b5e6969f42a6d12eee5c Mon Sep 17 00:00:00 2001 From: Eric Huss Date: Tue, 21 Mar 2023 20:45:21 -0700 Subject: [PATCH 1/4] Show some HTTP headers in error messages. --- src/cargo/core/package.rs | 21 +++- src/cargo/sources/registry/http_remote.rs | 11 +- src/cargo/util/errors.rs | 21 +++- src/cargo/util/network/retry.rs | 5 + tests/testsuite/registry.rs | 145 ++++++++++++++++++++++ 5 files changed, 197 insertions(+), 6 deletions(-) diff --git a/src/cargo/core/package.rs b/src/cargo/core/package.rs index 912c80cc461..ff91e4a8b96 100644 --- a/src/cargo/core/package.rs +++ b/src/cargo/core/package.rs @@ -26,7 +26,7 @@ use crate::core::{Dependency, Manifest, PackageId, SourceId, Target}; use crate::core::{SourceMap, Summary, Workspace}; use crate::ops; use crate::util::config::PackageCacheLock; -use crate::util::errors::{CargoResult, HttpNotSuccessful}; +use crate::util::errors::{CargoResult, HttpNotSuccessful, DEBUG_HEADERS}; use crate::util::interning::InternedString; use crate::util::network::retry::{Retry, RetryResult}; use crate::util::network::sleep::SleepTracker; @@ -379,6 +379,9 @@ struct Download<'cfg> { /// Actual downloaded data, updated throughout the lifetime of this download. data: RefCell>, + /// HTTP headers for debugging. + headers: RefCell>, + /// The URL that we're downloading from, cached here for error messages and /// reenqueuing. url: String, @@ -762,6 +765,19 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> { }); Ok(buf.len()) })?; + handle.header_function(move |data| { + tls::with(|downloads| { + if let Some(downloads) = downloads { + // Headers contain trailing \r\n, trim them to make it easier + // to work with. + let h = String::from_utf8_lossy(data).trim().to_string(); + if DEBUG_HEADERS.iter().any(|p| h.starts_with(p)) { + downloads.pending[&token].0.headers.borrow_mut().push(h); + } + } + }); + true + })?; handle.progress(true)?; handle.progress_function(move |dl_total, dl_cur, _, _| { @@ -787,6 +803,7 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> { let dl = Download { token, data: RefCell::new(Vec::new()), + headers: RefCell::new(Vec::new()), id, url, descriptor, @@ -826,6 +843,7 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> { .remove(&token) .expect("got a token for a non-in-progress transfer"); let data = mem::take(&mut *dl.data.borrow_mut()); + let headers = mem::take(&mut *dl.headers.borrow_mut()); let mut handle = self.set.multi.remove(handle)?; self.pending_ids.remove(&dl.id); @@ -867,6 +885,7 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> { code, url: url.to_string(), body: data, + headers, } .into()); } diff --git a/src/cargo/sources/registry/http_remote.rs b/src/cargo/sources/registry/http_remote.rs index ae89b629dfc..a9b20e2d423 100644 --- a/src/cargo/sources/registry/http_remote.rs +++ b/src/cargo/sources/registry/http_remote.rs @@ -7,7 +7,7 @@ use crate::ops::{self}; use crate::sources::registry::download; use crate::sources::registry::MaybeLock; use crate::sources::registry::{LoadResponse, RegistryConfig, RegistryData}; -use crate::util::errors::{CargoResult, HttpNotSuccessful}; +use crate::util::errors::{CargoResult, HttpNotSuccessful, DEBUG_HEADERS}; use crate::util::network::retry::{Retry, RetryResult}; use crate::util::network::sleep::SleepTracker; use crate::util::{auth, Config, Filesystem, IntoUrl, Progress, ProgressStyle}; @@ -142,6 +142,7 @@ struct Headers { last_modified: Option, etag: Option, www_authenticate: Vec, + others: Vec, } enum StatusCode { @@ -293,6 +294,7 @@ impl<'cfg> HttpRegistry<'cfg> { code, url: url.to_owned(), body: data, + headers: download.header_map.take().others, } .into()); } @@ -546,6 +548,7 @@ impl<'cfg> RegistryData for HttpRegistry<'cfg> { code: 401, body: result.data, url: self.full_url(path), + headers: result.header_map.others, } .into()); if self.auth_required { @@ -665,7 +668,11 @@ impl<'cfg> RegistryData for HttpRegistry<'cfg> { LAST_MODIFIED => header_map.last_modified = Some(value.to_string()), ETAG => header_map.etag = Some(value.to_string()), WWW_AUTHENTICATE => header_map.www_authenticate.push(value.to_string()), - _ => {} + _ => { + if DEBUG_HEADERS.iter().any(|prefix| tag.starts_with(prefix)) { + header_map.others.push(format!("{tag}: {value}")); + } + } } } }); diff --git a/src/cargo/util/errors.rs b/src/cargo/util/errors.rs index fb63f6ae2dd..99ac492cb24 100644 --- a/src/cargo/util/errors.rs +++ b/src/cargo/util/errors.rs @@ -8,11 +8,22 @@ use super::truncate_with_ellipsis; pub type CargoResult = anyhow::Result; +/// These are headers that are included in error messages to help with +/// diagnosing issues. +pub const DEBUG_HEADERS: &[&str] = &[ + "x-amz-cf-id", + "x-amz-cf-pop", + "x-amz-id-2", + "x-cache", + "x-served-by", +]; + #[derive(Debug)] pub struct HttpNotSuccessful { pub code: u32, pub url: String, pub body: Vec, + pub headers: Vec, } impl fmt::Display for HttpNotSuccessful { @@ -23,9 +34,13 @@ impl fmt::Display for HttpNotSuccessful { write!( f, - "failed to get successful HTTP response from `{}`, got {}\nbody:\n{body}", - self.url, self.code - ) + "failed to get successful HTTP response from `{}`, got {}\n", + self.url, self.code, + )?; + if !self.headers.is_empty() { + write!(f, "debug headers:\n{}\n", self.headers.join("\n"))?; + } + write!(f, "body:\n{body}",) } } diff --git a/src/cargo/util/network/retry.rs b/src/cargo/util/network/retry.rs index 2ee2c1223ab..9d293b672a7 100644 --- a/src/cargo/util/network/retry.rs +++ b/src/cargo/util/network/retry.rs @@ -151,12 +151,14 @@ fn with_retry_repeats_the_call_then_works() { code: 501, url: "Uri".to_string(), body: Vec::new(), + headers: Vec::new(), } .into(); let error2 = HttpNotSuccessful { code: 502, url: "Uri".to_string(), body: Vec::new(), + headers: Vec::new(), } .into(); let mut results: Vec> = vec![Ok(()), Err(error1), Err(error2)]; @@ -176,12 +178,14 @@ fn with_retry_finds_nested_spurious_errors() { code: 501, url: "Uri".to_string(), body: Vec::new(), + headers: Vec::new(), }); let error1 = anyhow::Error::from(error1.context("A non-spurious wrapping err")); let error2 = anyhow::Error::from(HttpNotSuccessful { code: 502, url: "Uri".to_string(), body: Vec::new(), + headers: Vec::new(), }); let error2 = anyhow::Error::from(error2.context("A second chained error")); let mut results: Vec> = vec![Ok(()), Err(error1), Err(error2)]; @@ -200,6 +204,7 @@ fn default_retry_schedule() { code: 500, url: "Uri".to_string(), body: Vec::new(), + headers: Vec::new(), })) }; let config = Config::default().unwrap(); diff --git a/tests/testsuite/registry.rs b/tests/testsuite/registry.rs index 68a16d222b6..d369295001e 100644 --- a/tests/testsuite/registry.rs +++ b/tests/testsuite/registry.rs @@ -3274,3 +3274,148 @@ or use environment variable CARGO_REGISTRY_TOKEN .with_status(101) .run(); } + +const SAMPLE_HEADERS: &[&str] = &[ + "x-amz-cf-pop: SFO53-P2", + "x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA==", + "x-cache: Hit from cloudfront", + "server: AmazonS3", + "x-amz-version-id: pvsJYY_JGsWiSETZvLJKb7DeEW5wWq1W", + "x-amz-server-side-encryption: AES256", + "content-type: text/plain", + "via: 1.1 bcbc5b46216015493e082cfbcf77ef10.cloudfront.net (CloudFront)", +]; + +#[cargo_test] +fn debug_header_message_index() { + // The error message should include some headers for debugging purposes. + let _server = RegistryBuilder::new() + .http_index() + .add_responder("/index/3/b/bar", |_, _| Response { + code: 503, + headers: SAMPLE_HEADERS.iter().map(|s| s.to_string()).collect(), + body: b"Please slow down".to_vec(), + }) + .build(); + Package::new("bar", "1.0.0").publish(); + + let p = project() + .file( + "Cargo.toml", + r#" + [package] + name = "foo" + version = "0.1.0" + + [dependencies] + bar = "1.0" + "#, + ) + .file("src/lib.rs", "") + .build(); + p.cargo("fetch").with_status(101).with_stderr("\ +[UPDATING] `dummy-registry` index +warning: spurious network error (3 tries remaining): failed to get successful HTTP response from `http://127.0.0.1:[..]/index/3/b/bar`, got 503 +debug headers: +x-amz-cf-pop: SFO53-P2 +x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== +x-cache: Hit from cloudfront +body: +Please slow down +warning: spurious network error (2 tries remaining): failed to get successful HTTP response from `http://127.0.0.1:[..]/index/3/b/bar`, got 503 +debug headers: +x-amz-cf-pop: SFO53-P2 +x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== +x-cache: Hit from cloudfront +body: +Please slow down +warning: spurious network error (1 tries remaining): failed to get successful HTTP response from `http://127.0.0.1:[..]/index/3/b/bar`, got 503 +debug headers: +x-amz-cf-pop: SFO53-P2 +x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== +x-cache: Hit from cloudfront +body: +Please slow down +error: failed to get `bar` as a dependency of package `foo v0.1.0 ([ROOT]/foo)` + +Caused by: + failed to query replaced source registry `crates-io` + +Caused by: + download of 3/b/bar failed + +Caused by: + failed to get successful HTTP response from `http://127.0.0.1:[..]/index/3/b/bar`, got 503 + debug headers: + x-amz-cf-pop: SFO53-P2 + x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== + x-cache: Hit from cloudfront + body: + Please slow down +").run(); +} + +#[cargo_test] +fn debug_header_message_dl() { + // Same as debug_header_message_index, but for the dl endpoint which goes + // through a completely different code path. + let _server = RegistryBuilder::new() + .http_index() + .add_responder("/dl/bar/1.0.0/download", |_, _| Response { + code: 503, + headers: SAMPLE_HEADERS.iter().map(|s| s.to_string()).collect(), + body: b"Please slow down".to_vec(), + }) + .build(); + Package::new("bar", "1.0.0").publish(); + let p = project() + .file( + "Cargo.toml", + r#" + [package] + name = "foo" + version = "0.1.0" + + [dependencies] + bar = "1.0" + "#, + ) + .file("src/lib.rs", "") + .build(); + + p.cargo("fetch").with_status(101).with_stderr("\ +[UPDATING] `dummy-registry` index +[DOWNLOADING] crates ... +warning: spurious network error (3 tries remaining): failed to get successful HTTP response from `http://127.0.0.1:[..]/dl/bar/1.0.0/download`, got 503 +debug headers: +x-amz-cf-pop: SFO53-P2 +x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== +x-cache: Hit from cloudfront +body: +Please slow down +warning: spurious network error (2 tries remaining): failed to get successful HTTP response from `http://127.0.0.1:[..]/dl/bar/1.0.0/download`, got 503 +debug headers: +x-amz-cf-pop: SFO53-P2 +x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== +x-cache: Hit from cloudfront +body: +Please slow down +warning: spurious network error (1 tries remaining): failed to get successful HTTP response from `http://127.0.0.1:[..]/dl/bar/1.0.0/download`, got 503 +debug headers: +x-amz-cf-pop: SFO53-P2 +x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== +x-cache: Hit from cloudfront +body: +Please slow down +error: failed to download from `http://127.0.0.1:[..]/dl/bar/1.0.0/download` + +Caused by: + failed to get successful HTTP response from `http://127.0.0.1:[..]/dl/bar/1.0.0/download`, got 503 + debug headers: + x-amz-cf-pop: SFO53-P2 + x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== + x-cache: Hit from cloudfront + body: + Please slow down +").run(); +} From 4702fa3ad310c79165b897f1188edbe6b9ec8d13 Mon Sep 17 00:00:00 2001 From: Eric Huss Date: Wed, 22 Mar 2023 08:18:57 -0700 Subject: [PATCH 2/4] Include the IP address in HTTP errors. --- src/cargo/core/package.rs | 11 ++++--- src/cargo/sources/registry/http_remote.rs | 16 +++++----- src/cargo/util/errors.rs | 34 +++++++++++++++++++-- src/cargo/util/network/retry.rs | 5 ++++ tests/testsuite/registry.rs | 36 ++++++++++++++--------- tests/testsuite/registry_auth.rs | 4 +-- 6 files changed, 74 insertions(+), 32 deletions(-) diff --git a/src/cargo/core/package.rs b/src/cargo/core/package.rs index ff91e4a8b96..40ba9cdf894 100644 --- a/src/cargo/core/package.rs +++ b/src/cargo/core/package.rs @@ -880,13 +880,12 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> { let code = handle.response_code()?; if code != 200 && code != 0 { - let url = handle.effective_url()?.unwrap_or(url); - return Err(HttpNotSuccessful { - code, - url: url.to_string(), - body: data, + return Err(HttpNotSuccessful::new_from_handle( + &mut handle, + &url, + data, headers, - } + ) .into()); } Ok(data) diff --git a/src/cargo/sources/registry/http_remote.rs b/src/cargo/sources/registry/http_remote.rs index a9b20e2d423..7e1f2a58740 100644 --- a/src/cargo/sources/registry/http_remote.rs +++ b/src/cargo/sources/registry/http_remote.rs @@ -288,14 +288,13 @@ impl<'cfg> HttpRegistry<'cfg> { 304 => StatusCode::NotModified, 401 => StatusCode::Unauthorized, 404 | 410 | 451 => StatusCode::NotFound, - code => { - let url = handle.effective_url()?.unwrap_or(&url); - return Err(HttpNotSuccessful { - code, - url: url.to_owned(), - body: data, - headers: download.header_map.take().others, - } + _ => { + return Err(HttpNotSuccessful::new_from_handle( + &mut handle, + &url, + data, + download.header_map.take().others, + ) .into()); } }; @@ -548,6 +547,7 @@ impl<'cfg> RegistryData for HttpRegistry<'cfg> { code: 401, body: result.data, url: self.full_url(path), + ip: None, headers: result.header_map.others, } .into()); diff --git a/src/cargo/util/errors.rs b/src/cargo/util/errors.rs index 99ac492cb24..973269cb69c 100644 --- a/src/cargo/util/errors.rs +++ b/src/cargo/util/errors.rs @@ -1,6 +1,7 @@ #![allow(unknown_lints)] use anyhow::Error; +use curl::easy::Easy; use std::fmt; use std::path::PathBuf; @@ -22,10 +23,35 @@ pub const DEBUG_HEADERS: &[&str] = &[ pub struct HttpNotSuccessful { pub code: u32, pub url: String, + pub ip: Option, pub body: Vec, pub headers: Vec, } +impl HttpNotSuccessful { + pub fn new_from_handle( + handle: &mut Easy, + initial_url: &str, + body: Vec, + headers: Vec, + ) -> HttpNotSuccessful { + let ip = handle.primary_ip().ok().flatten().map(|s| s.to_string()); + let url = handle + .effective_url() + .ok() + .flatten() + .unwrap_or(initial_url) + .to_string(); + HttpNotSuccessful { + code: handle.response_code().unwrap_or(0), + url, + ip, + body, + headers, + } + } +} + impl fmt::Display for HttpNotSuccessful { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { let body = std::str::from_utf8(&self.body) @@ -34,9 +60,13 @@ impl fmt::Display for HttpNotSuccessful { write!( f, - "failed to get successful HTTP response from `{}`, got {}\n", - self.url, self.code, + "failed to get successful HTTP response from `{}`", + self.url )?; + if let Some(ip) = &self.ip { + write!(f, " ({ip})")?; + } + write!(f, ", got {}\n", self.code,)?; if !self.headers.is_empty() { write!(f, "debug headers:\n{}\n", self.headers.join("\n"))?; } diff --git a/src/cargo/util/network/retry.rs b/src/cargo/util/network/retry.rs index 9d293b672a7..feb8e6db26d 100644 --- a/src/cargo/util/network/retry.rs +++ b/src/cargo/util/network/retry.rs @@ -150,6 +150,7 @@ fn with_retry_repeats_the_call_then_works() { let error1 = HttpNotSuccessful { code: 501, url: "Uri".to_string(), + ip: None, body: Vec::new(), headers: Vec::new(), } @@ -157,6 +158,7 @@ fn with_retry_repeats_the_call_then_works() { let error2 = HttpNotSuccessful { code: 502, url: "Uri".to_string(), + ip: None, body: Vec::new(), headers: Vec::new(), } @@ -177,6 +179,7 @@ fn with_retry_finds_nested_spurious_errors() { let error1 = anyhow::Error::from(HttpNotSuccessful { code: 501, url: "Uri".to_string(), + ip: None, body: Vec::new(), headers: Vec::new(), }); @@ -184,6 +187,7 @@ fn with_retry_finds_nested_spurious_errors() { let error2 = anyhow::Error::from(HttpNotSuccessful { code: 502, url: "Uri".to_string(), + ip: None, body: Vec::new(), headers: Vec::new(), }); @@ -203,6 +207,7 @@ fn default_retry_schedule() { Err(anyhow::Error::from(HttpNotSuccessful { code: 500, url: "Uri".to_string(), + ip: None, body: Vec::new(), headers: Vec::new(), })) diff --git a/tests/testsuite/registry.rs b/tests/testsuite/registry.rs index d369295001e..189ca60688a 100644 --- a/tests/testsuite/registry.rs +++ b/tests/testsuite/registry.rs @@ -2743,10 +2743,10 @@ fn sparse_retry_single() { .with_stderr( "\ [UPDATING] `dummy-registry` index -warning: spurious network error (3 tries remaining): failed to get successful HTTP response from `[..]`, got 500 +warning: spurious network error (3 tries remaining): failed to get successful HTTP response from `[..]` (127.0.0.1), got 500 body: internal server error -warning: spurious network error (2 tries remaining): failed to get successful HTTP response from `[..]`, got 500 +warning: spurious network error (2 tries remaining): failed to get successful HTTP response from `[..]` (127.0.0.1), got 500 body: internal server error [DOWNLOADING] crates ... @@ -2816,7 +2816,7 @@ fn sparse_retry_multiple() { &mut expected, "warning: spurious network error ({remain} tries remaining): \ failed to get successful HTTP response from \ - `http://127.0.0.1:[..]/{ab}/{cd}/{name}`, got 500\n\ + `http://127.0.0.1:[..]/{ab}/{cd}/{name}` (127.0.0.1), got 500\n\ body:\n\ internal server error\n" ) @@ -2876,10 +2876,12 @@ fn dl_retry_single() { .with_stderr("\ [UPDATING] `dummy-registry` index [DOWNLOADING] crates ... -warning: spurious network error (3 tries remaining): failed to get successful HTTP response from `http://127.0.0.1:[..]/dl/bar/1.0.0/download`, got 500 +warning: spurious network error (3 tries remaining): \ + failed to get successful HTTP response from `http://127.0.0.1:[..]/dl/bar/1.0.0/download` (127.0.0.1), got 500 body: internal server error -warning: spurious network error (2 tries remaining): failed to get successful HTTP response from `http://127.0.0.1:[..]/dl/bar/1.0.0/download`, got 500 +warning: spurious network error (2 tries remaining): \ + failed to get successful HTTP response from `http://127.0.0.1:[..]/dl/bar/1.0.0/download` (127.0.0.1), got 500 body: internal server error [DOWNLOADED] bar v1.0.0 (registry `dummy-registry`) @@ -2954,7 +2956,7 @@ fn dl_retry_multiple() { &mut expected, "warning: spurious network error ({remain} tries remaining): \ failed to get successful HTTP response from \ - `http://127.0.0.1:[..]/dl/{name}/1.0.0/download`, got 500\n\ + `http://127.0.0.1:[..]/dl/{name}/1.0.0/download` (127.0.0.1), got 500\n\ body:\n\ internal server error\n" ) @@ -3315,21 +3317,24 @@ fn debug_header_message_index() { .build(); p.cargo("fetch").with_status(101).with_stderr("\ [UPDATING] `dummy-registry` index -warning: spurious network error (3 tries remaining): failed to get successful HTTP response from `http://127.0.0.1:[..]/index/3/b/bar`, got 503 +warning: spurious network error (3 tries remaining): \ + failed to get successful HTTP response from `http://127.0.0.1:[..]/index/3/b/bar` (127.0.0.1), got 503 debug headers: x-amz-cf-pop: SFO53-P2 x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== x-cache: Hit from cloudfront body: Please slow down -warning: spurious network error (2 tries remaining): failed to get successful HTTP response from `http://127.0.0.1:[..]/index/3/b/bar`, got 503 +warning: spurious network error (2 tries remaining): \ + failed to get successful HTTP response from `http://127.0.0.1:[..]/index/3/b/bar` (127.0.0.1), got 503 debug headers: x-amz-cf-pop: SFO53-P2 x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== x-cache: Hit from cloudfront body: Please slow down -warning: spurious network error (1 tries remaining): failed to get successful HTTP response from `http://127.0.0.1:[..]/index/3/b/bar`, got 503 +warning: spurious network error (1 tries remaining): \ + failed to get successful HTTP response from `http://127.0.0.1:[..]/index/3/b/bar` (127.0.0.1), got 503 debug headers: x-amz-cf-pop: SFO53-P2 x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== @@ -3345,7 +3350,7 @@ Caused by: download of 3/b/bar failed Caused by: - failed to get successful HTTP response from `http://127.0.0.1:[..]/index/3/b/bar`, got 503 + failed to get successful HTTP response from `http://127.0.0.1:[..]/index/3/b/bar` (127.0.0.1), got 503 debug headers: x-amz-cf-pop: SFO53-P2 x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== @@ -3386,21 +3391,24 @@ fn debug_header_message_dl() { p.cargo("fetch").with_status(101).with_stderr("\ [UPDATING] `dummy-registry` index [DOWNLOADING] crates ... -warning: spurious network error (3 tries remaining): failed to get successful HTTP response from `http://127.0.0.1:[..]/dl/bar/1.0.0/download`, got 503 +warning: spurious network error (3 tries remaining): \ + failed to get successful HTTP response from `http://127.0.0.1:[..]/dl/bar/1.0.0/download` (127.0.0.1), got 503 debug headers: x-amz-cf-pop: SFO53-P2 x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== x-cache: Hit from cloudfront body: Please slow down -warning: spurious network error (2 tries remaining): failed to get successful HTTP response from `http://127.0.0.1:[..]/dl/bar/1.0.0/download`, got 503 +warning: spurious network error (2 tries remaining): \ + failed to get successful HTTP response from `http://127.0.0.1:[..]/dl/bar/1.0.0/download` (127.0.0.1), got 503 debug headers: x-amz-cf-pop: SFO53-P2 x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== x-cache: Hit from cloudfront body: Please slow down -warning: spurious network error (1 tries remaining): failed to get successful HTTP response from `http://127.0.0.1:[..]/dl/bar/1.0.0/download`, got 503 +warning: spurious network error (1 tries remaining): \ + failed to get successful HTTP response from `http://127.0.0.1:[..]/dl/bar/1.0.0/download` (127.0.0.1), got 503 debug headers: x-amz-cf-pop: SFO53-P2 x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== @@ -3410,7 +3418,7 @@ Please slow down error: failed to download from `http://127.0.0.1:[..]/dl/bar/1.0.0/download` Caused by: - failed to get successful HTTP response from `http://127.0.0.1:[..]/dl/bar/1.0.0/download`, got 503 + failed to get successful HTTP response from `http://127.0.0.1:[..]/dl/bar/1.0.0/download` (127.0.0.1), got 503 debug headers: x-amz-cf-pop: SFO53-P2 x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== diff --git a/tests/testsuite/registry_auth.rs b/tests/testsuite/registry_auth.rs index 27d967b98fb..7779e285a89 100644 --- a/tests/testsuite/registry_auth.rs +++ b/tests/testsuite/registry_auth.rs @@ -57,7 +57,7 @@ fn requires_nightly() { error: failed to download from `[..]/dl/bar/0.0.1/download` Caused by: - failed to get successful HTTP response from `[..]`, got 401 + failed to get successful HTTP response from `[..]` (127.0.0.1), got 401 body: Unauthorized message from server. "#, @@ -415,7 +415,7 @@ fn incorrect_token_git() { [ERROR] failed to download from `http://[..]/dl/bar/0.0.1/download` Caused by: - failed to get successful HTTP response from `http://[..]/dl/bar/0.0.1/download`, got 401 + failed to get successful HTTP response from `http://[..]/dl/bar/0.0.1/download` (127.0.0.1), got 401 body: Unauthorized message from server.", ) From c00a633bd63e51c19a0897e25c8da0ea70b22c73 Mon Sep 17 00:00:00 2001 From: Eric Huss Date: Mon, 3 Apr 2023 14:10:36 -0700 Subject: [PATCH 3/4] Don't display headers in spurious warning message. The headers can significantly contribute to noise in the output, drowning out the rest of the output. Most investigation will likely be focused on the case where cargo completely fails to download, so this only shows the full detail in the final error message. --- src/cargo/util/errors.rs | 36 +++++++++++++++++++++++---------- src/cargo/util/network/retry.rs | 7 +++++-- tests/testsuite/registry.rs | 24 ---------------------- 3 files changed, 30 insertions(+), 37 deletions(-) diff --git a/src/cargo/util/errors.rs b/src/cargo/util/errors.rs index 973269cb69c..816649f1620 100644 --- a/src/cargo/util/errors.rs +++ b/src/cargo/util/errors.rs @@ -2,7 +2,7 @@ use anyhow::Error; use curl::easy::Easy; -use std::fmt; +use std::fmt::{self, Write}; use std::path::PathBuf; use super::truncate_with_ellipsis; @@ -50,27 +50,41 @@ impl HttpNotSuccessful { headers, } } -} -impl fmt::Display for HttpNotSuccessful { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + /// Renders the error in a compact form. + pub fn display_short(&self) -> String { + self.render(false) + } + + fn render(&self, show_headers: bool) -> String { + let mut result = String::new(); let body = std::str::from_utf8(&self.body) .map(|s| truncate_with_ellipsis(s, 512)) .unwrap_or_else(|_| format!("[{} non-utf8 bytes]", self.body.len())); write!( - f, + result, "failed to get successful HTTP response from `{}`", self.url - )?; + ) + .unwrap(); if let Some(ip) = &self.ip { - write!(f, " ({ip})")?; + write!(result, " ({ip})").unwrap(); } - write!(f, ", got {}\n", self.code,)?; - if !self.headers.is_empty() { - write!(f, "debug headers:\n{}\n", self.headers.join("\n"))?; + write!(result, ", got {}\n", self.code).unwrap(); + if show_headers { + if !self.headers.is_empty() { + write!(result, "debug headers:\n{}\n", self.headers.join("\n")).unwrap(); + } } - write!(f, "body:\n{body}",) + write!(result, "body:\n{body}").unwrap(); + result + } +} + +impl fmt::Display for HttpNotSuccessful { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.write_str(&self.render(true)) } } diff --git a/src/cargo/util/network/retry.rs b/src/cargo/util/network/retry.rs index feb8e6db26d..42c38ab9f80 100644 --- a/src/cargo/util/network/retry.rs +++ b/src/cargo/util/network/retry.rs @@ -44,10 +44,13 @@ impl<'a> Retry<'a> { pub fn r#try(&mut self, f: impl FnOnce() -> CargoResult) -> RetryResult { match f() { Err(ref e) if maybe_spurious(e) && self.retries < self.max_retries => { + let err_msg = e + .downcast_ref::() + .map(|http_err| http_err.display_short()) + .unwrap_or_else(|| e.root_cause().to_string()); let msg = format!( - "spurious network error ({} tries remaining): {}", + "spurious network error ({} tries remaining): {err_msg}", self.max_retries - self.retries, - e.root_cause(), ); if let Err(e) = self.config.shell().warn(msg) { return RetryResult::Err(e); diff --git a/tests/testsuite/registry.rs b/tests/testsuite/registry.rs index 189ca60688a..8bbb983c19d 100644 --- a/tests/testsuite/registry.rs +++ b/tests/testsuite/registry.rs @@ -3319,26 +3319,14 @@ fn debug_header_message_index() { [UPDATING] `dummy-registry` index warning: spurious network error (3 tries remaining): \ failed to get successful HTTP response from `http://127.0.0.1:[..]/index/3/b/bar` (127.0.0.1), got 503 -debug headers: -x-amz-cf-pop: SFO53-P2 -x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== -x-cache: Hit from cloudfront body: Please slow down warning: spurious network error (2 tries remaining): \ failed to get successful HTTP response from `http://127.0.0.1:[..]/index/3/b/bar` (127.0.0.1), got 503 -debug headers: -x-amz-cf-pop: SFO53-P2 -x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== -x-cache: Hit from cloudfront body: Please slow down warning: spurious network error (1 tries remaining): \ failed to get successful HTTP response from `http://127.0.0.1:[..]/index/3/b/bar` (127.0.0.1), got 503 -debug headers: -x-amz-cf-pop: SFO53-P2 -x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== -x-cache: Hit from cloudfront body: Please slow down error: failed to get `bar` as a dependency of package `foo v0.1.0 ([ROOT]/foo)` @@ -3393,26 +3381,14 @@ fn debug_header_message_dl() { [DOWNLOADING] crates ... warning: spurious network error (3 tries remaining): \ failed to get successful HTTP response from `http://127.0.0.1:[..]/dl/bar/1.0.0/download` (127.0.0.1), got 503 -debug headers: -x-amz-cf-pop: SFO53-P2 -x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== -x-cache: Hit from cloudfront body: Please slow down warning: spurious network error (2 tries remaining): \ failed to get successful HTTP response from `http://127.0.0.1:[..]/dl/bar/1.0.0/download` (127.0.0.1), got 503 -debug headers: -x-amz-cf-pop: SFO53-P2 -x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== -x-cache: Hit from cloudfront body: Please slow down warning: spurious network error (1 tries remaining): \ failed to get successful HTTP response from `http://127.0.0.1:[..]/dl/bar/1.0.0/download` (127.0.0.1), got 503 -debug headers: -x-amz-cf-pop: SFO53-P2 -x-amz-cf-id: vEc3osJrCAXVaciNnF4Vev-hZFgnYwmNZtxMKRJ5bF6h9FTOtbTMnA== -x-cache: Hit from cloudfront body: Please slow down error: failed to download from `http://127.0.0.1:[..]/dl/bar/1.0.0/download` From 84bcf0e24795e39761a7db5d15e361675f448379 Mon Sep 17 00:00:00 2001 From: Eric Huss Date: Wed, 12 Apr 2023 11:50:53 -0700 Subject: [PATCH 4/4] Add x-amz-request-id (for the S3 side of things) and add comments. --- src/cargo/util/errors.rs | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/src/cargo/util/errors.rs b/src/cargo/util/errors.rs index 816649f1620..5c7eebcdb71 100644 --- a/src/cargo/util/errors.rs +++ b/src/cargo/util/errors.rs @@ -12,10 +12,20 @@ pub type CargoResult = anyhow::Result; /// These are headers that are included in error messages to help with /// diagnosing issues. pub const DEBUG_HEADERS: &[&str] = &[ + // This is the unique ID that identifies the request in CloudFront which + // can be used for looking at the AWS logs. "x-amz-cf-id", + // This is the CloudFront POP (Point of Presence) that identifies the + // region where the request was routed. This can help identify if an issue + // is region-specific. "x-amz-cf-pop", + // The unique token used for troubleshooting S3 requests via AWS logs or support. + "x-amz-request-id", + // Another token used in conjunction with x-amz-request-id. "x-amz-id-2", + // Whether or not there was a cache hit or miss (both CloudFront and Fastly). "x-cache", + // The cache server that processed the request (Fastly). "x-served-by", ];