Auto merge of #11878 - ehuss:header-diagnostics, r=weihanglo

Add more information to HTTP errors to help with debugging.

This adds some extra information to the HTTP error message about some headers and the remote IP address that could potentially be useful in diagnosing issues.

Closes #8691

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<Vec<u8>>,
 
+    /// HTTP headers for debugging.
+    headers: RefCell<Vec<String>>,
+
     /// 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)

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<String>,
     etag: Option<String>,
     www_authenticate: Vec<String>,
+    others: Vec<String>,
 }
 
 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}"));
+                                }
+                            }
                         }
                     }
                 });

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<T> = anyhow::Result<T>;
 
+/// 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<String>,
     pub body: Vec<u8>,
+    pub headers: Vec<String>,
 }
 
-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<u8>,
+        headers: Vec<String>,
+    ) -> 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))
     }
 }
 

src/cargo/util/network/retry.rs

@@ -44,10 +44,13 @@ impl<'a> Retry<'a> {
     pub fn r#try<T>(&mut self, f: impl FnOnce() -> CargoResult<T>) -> RetryResult<T> {
         match f() {
             Err(ref e) if maybe_spurious(e) && self.retries < self.max_retries => {
+                let err_msg = e
+                    .downcast_ref::<HttpNotSuccessful>()
+                    .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<CargoResult<()>> = 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<CargoResult<()>> = 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();