Show some HTTP headers in error messages.

This commit is contained in:
Eric Huss 2023-03-21 20:45:21 -07:00
parent 96f8d6ced8
commit c7c9b8f32b
5 changed files with 197 additions and 6 deletions

View File

@ -26,7 +26,7 @@ use crate::core::{Dependency, Manifest, PackageId, SourceId, Target};
use crate::core::{SourceMap, Summary, Workspace}; use crate::core::{SourceMap, Summary, Workspace};
use crate::ops; use crate::ops;
use crate::util::config::PackageCacheLock; 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::interning::InternedString;
use crate::util::network::retry::{Retry, RetryResult}; use crate::util::network::retry::{Retry, RetryResult};
use crate::util::network::sleep::SleepTracker; use crate::util::network::sleep::SleepTracker;
@ -379,6 +379,9 @@ struct Download<'cfg> {
/// Actual downloaded data, updated throughout the lifetime of this download. /// Actual downloaded data, updated throughout the lifetime of this download.
data: RefCell<Vec<u8>>, data: RefCell<Vec<u8>>,
/// HTTP headers for debugging.
headers: RefCell<Vec<String>>,
/// The URL that we're downloading from, cached here for error messages and /// The URL that we're downloading from, cached here for error messages and
/// reenqueuing. /// reenqueuing.
url: String, url: String,
@ -762,6 +765,19 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> {
}); });
Ok(buf.len()) 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(true)?;
handle.progress_function(move |dl_total, dl_cur, _, _| { handle.progress_function(move |dl_total, dl_cur, _, _| {
@ -787,6 +803,7 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> {
let dl = Download { let dl = Download {
token, token,
data: RefCell::new(Vec::new()), data: RefCell::new(Vec::new()),
headers: RefCell::new(Vec::new()),
id, id,
url, url,
descriptor, descriptor,
@ -826,6 +843,7 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> {
.remove(&token) .remove(&token)
.expect("got a token for a non-in-progress transfer"); .expect("got a token for a non-in-progress transfer");
let data = mem::take(&mut *dl.data.borrow_mut()); 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)?; let mut handle = self.set.multi.remove(handle)?;
self.pending_ids.remove(&dl.id); self.pending_ids.remove(&dl.id);
@ -867,6 +885,7 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> {
code, code,
url: url.to_string(), url: url.to_string(),
body: data, body: data,
headers,
} }
.into()); .into());
} }

View File

@ -7,7 +7,7 @@ use crate::ops::{self};
use crate::sources::registry::download; use crate::sources::registry::download;
use crate::sources::registry::MaybeLock; use crate::sources::registry::MaybeLock;
use crate::sources::registry::{LoadResponse, RegistryConfig, RegistryData}; 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::retry::{Retry, RetryResult};
use crate::util::network::sleep::SleepTracker; use crate::util::network::sleep::SleepTracker;
use crate::util::{auth, Config, Filesystem, IntoUrl, Progress, ProgressStyle}; use crate::util::{auth, Config, Filesystem, IntoUrl, Progress, ProgressStyle};
@ -142,6 +142,7 @@ struct Headers {
last_modified: Option<String>, last_modified: Option<String>,
etag: Option<String>, etag: Option<String>,
www_authenticate: Vec<String>, www_authenticate: Vec<String>,
others: Vec<String>,
} }
enum StatusCode { enum StatusCode {
@ -293,6 +294,7 @@ impl<'cfg> HttpRegistry<'cfg> {
code, code,
url: url.to_owned(), url: url.to_owned(),
body: data, body: data,
headers: download.header_map.take().others,
} }
.into()); .into());
} }
@ -546,6 +548,7 @@ impl<'cfg> RegistryData for HttpRegistry<'cfg> {
code: 401, code: 401,
body: result.data, body: result.data,
url: self.full_url(path), url: self.full_url(path),
headers: result.header_map.others,
} }
.into()); .into());
if self.auth_required { if self.auth_required {
@ -665,7 +668,11 @@ impl<'cfg> RegistryData for HttpRegistry<'cfg> {
LAST_MODIFIED => header_map.last_modified = Some(value.to_string()), LAST_MODIFIED => header_map.last_modified = Some(value.to_string()),
ETAG => header_map.etag = Some(value.to_string()), ETAG => header_map.etag = Some(value.to_string()),
WWW_AUTHENTICATE => header_map.www_authenticate.push(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}"));
}
}
} }
} }
}); });

View File

@ -8,11 +8,22 @@ use super::truncate_with_ellipsis;
pub type CargoResult<T> = anyhow::Result<T>; pub type CargoResult<T> = anyhow::Result<T>;
/// 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)] #[derive(Debug)]
pub struct HttpNotSuccessful { pub struct HttpNotSuccessful {
pub code: u32, pub code: u32,
pub url: String, pub url: String,
pub body: Vec<u8>, pub body: Vec<u8>,
pub headers: Vec<String>,
} }
impl fmt::Display for HttpNotSuccessful { impl fmt::Display for HttpNotSuccessful {
@ -23,9 +34,13 @@ impl fmt::Display for HttpNotSuccessful {
write!( write!(
f, f,
"failed to get successful HTTP response from `{}`, got {}\nbody:\n{body}", "failed to get successful HTTP response from `{}`, got {}\n",
self.url, self.code self.url, self.code,
) )?;
if !self.headers.is_empty() {
write!(f, "debug headers:\n{}\n", self.headers.join("\n"))?;
}
write!(f, "body:\n{body}",)
} }
} }

View File

@ -151,12 +151,14 @@ fn with_retry_repeats_the_call_then_works() {
code: 501, code: 501,
url: "Uri".to_string(), url: "Uri".to_string(),
body: Vec::new(), body: Vec::new(),
headers: Vec::new(),
} }
.into(); .into();
let error2 = HttpNotSuccessful { let error2 = HttpNotSuccessful {
code: 502, code: 502,
url: "Uri".to_string(), url: "Uri".to_string(),
body: Vec::new(), body: Vec::new(),
headers: Vec::new(),
} }
.into(); .into();
let mut results: Vec<CargoResult<()>> = vec![Ok(()), Err(error1), Err(error2)]; let mut results: Vec<CargoResult<()>> = vec![Ok(()), Err(error1), Err(error2)];
@ -176,12 +178,14 @@ fn with_retry_finds_nested_spurious_errors() {
code: 501, code: 501,
url: "Uri".to_string(), url: "Uri".to_string(),
body: Vec::new(), body: Vec::new(),
headers: Vec::new(),
}); });
let error1 = anyhow::Error::from(error1.context("A non-spurious wrapping err")); let error1 = anyhow::Error::from(error1.context("A non-spurious wrapping err"));
let error2 = anyhow::Error::from(HttpNotSuccessful { let error2 = anyhow::Error::from(HttpNotSuccessful {
code: 502, code: 502,
url: "Uri".to_string(), url: "Uri".to_string(),
body: Vec::new(), body: Vec::new(),
headers: Vec::new(),
}); });
let error2 = anyhow::Error::from(error2.context("A second chained error")); let error2 = anyhow::Error::from(error2.context("A second chained error"));
let mut results: Vec<CargoResult<()>> = vec![Ok(()), Err(error1), Err(error2)]; let mut results: Vec<CargoResult<()>> = vec![Ok(()), Err(error1), Err(error2)];
@ -200,6 +204,7 @@ fn default_retry_schedule() {
code: 500, code: 500,
url: "Uri".to_string(), url: "Uri".to_string(),
body: Vec::new(), body: Vec::new(),
headers: Vec::new(),
})) }))
}; };
let config = Config::default().unwrap(); let config = Config::default().unwrap();

View File

@ -3274,3 +3274,148 @@ or use environment variable CARGO_REGISTRY_TOKEN
.with_status(101) .with_status(101)
.run(); .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();
}