diff --git a/src/cargo/core/package.rs b/src/cargo/core/package.rs index 912c80cc461..40ba9cdf894 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); @@ -862,12 +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 ae89b629dfc..7e1f2a58740 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 { @@ -287,13 +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, - } + _ => { + return Err(HttpNotSuccessful::new_from_handle( + &mut handle, + &url, + data, + download.header_map.take().others, + ) .into()); } }; @@ -546,6 +547,8 @@ impl<'cfg> RegistryData for HttpRegistry<'cfg> { code: 401, body: result.data, url: self.full_url(path), + ip: None, + 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..5c7eebcdb71 100644 --- a/src/cargo/util/errors.rs +++ b/src/cargo/util/errors.rs @@ -1,31 +1,100 @@ #![allow(unknown_lints)] use anyhow::Error; -use std::fmt; +use curl::easy::Easy; +use std::fmt::{self, Write}; use std::path::PathBuf; 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] = &[ + // 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", +]; + #[derive(Debug)] pub struct HttpNotSuccessful { pub code: u32, pub url: String, + pub ip: Option, pub body: Vec, + pub headers: Vec, } -impl fmt::Display for HttpNotSuccessful { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { +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, + } + } + + /// 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, - "failed to get successful HTTP response from `{}`, got {}\nbody:\n{body}", - self.url, self.code + result, + "failed to get successful HTTP response from `{}`", + self.url ) + .unwrap(); + if let Some(ip) = &self.ip { + write!(result, " ({ip})").unwrap(); + } + 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!(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 2ee2c1223ab..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); @@ -150,13 +153,17 @@ 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(), } .into(); let error2 = HttpNotSuccessful { code: 502, url: "Uri".to_string(), + ip: None, body: Vec::new(), + headers: Vec::new(), } .into(); let mut results: Vec> = vec![Ok(()), Err(error1), Err(error2)]; @@ -175,13 +182,17 @@ 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(), }); let error1 = anyhow::Error::from(error1.context("A non-spurious wrapping err")); let error2 = anyhow::Error::from(HttpNotSuccessful { code: 502, url: "Uri".to_string(), + ip: None, 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)]; @@ -199,7 +210,9 @@ fn default_retry_schedule() { Err(anyhow::Error::from(HttpNotSuccessful { code: 500, url: "Uri".to_string(), + ip: None, 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..8bbb983c19d 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" ) @@ -3274,3 +3276,130 @@ 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` (127.0.0.1), got 503 +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 +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 +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` (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 +").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` (127.0.0.1), got 503 +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 +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 +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` (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 +").run(); +} 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.", )