Auto merge of #2235 - jtgeibel:log-inner-chained-errors, r=pietroalbini

Log inner chained errors

This builds on the logging infrastructure recently added by @pietroalbini.  Whenever a user facing error is chained around an internal error, the router now captures that message and adds it to the log metadata.

In particular, this should allow us to identify errors sent to cargo via `cargo_err` which are sent via a status 200 response and left no indication in the logs that an error has occurred.

r? @pietroalbini

Author: bors

src/controllers.rs

@@ -8,6 +8,8 @@ mod frontend_prelude {
     pub use crate::util::errors::{bad_request, server_error};
 }
 
+pub(crate) use prelude::RequestUtils;
+
 mod prelude {
     pub use super::helpers::ok_true;
     pub use diesel::prelude::*;

src/controllers/krate/publish.rs

@@ -232,7 +232,7 @@ pub fn publish(req: &mut dyn Request) -> AppResult<Response> {
 fn parse_new_headers(req: &mut dyn Request) -> AppResult<EncodableCrateUpload> {
     // Read the json upload request
     let metadata_length = u64::from(read_le_u32(req.body())?);
-    req.mut_extensions().insert(metadata_length);
+    req.log_metadata("metadata_length", metadata_length);
 
     let max = req.app().config.max_upload_size;
     if metadata_length > max {

src/middleware/log_request.rs

@@ -58,6 +58,16 @@ pub fn add_custom_metadata<V: Display>(req: &mut dyn Request, key: &'static str,
     }
 }
 
+#[cfg(test)]
+pub(crate) fn get_log_message(req: &dyn Request, key: &'static str) -> String {
+    for (k, v) in &req.extensions().find::<CustomMetadata>().unwrap().entries {
+        if key == *k {
+            return v.clone();
+        }
+    }
+    panic!("expected log message for {} not found", key);
+}
+
 struct RequestLine<'r> {
     req: &'r dyn Request,
     res: &'r Result<Response>,
@@ -88,10 +98,6 @@ impl Display for RequestLine<'_> {
             }
         }
 
-        if let Some(len) = self.req.extensions().find::<u64>() {
-            line.add_field("metadata_length", len)?;
-        }
-
         if let Err(err) = self.res {
             line.add_quoted_field("error", err)?;
         }

src/router.rs

@@ -143,10 +143,15 @@ impl Handler for C {
         let C(f) = *self;
         match f(req) {
             Ok(resp) => Ok(resp),
-            Err(e) => match e.response() {
-                Some(response) => Ok(response),
-                None => Err(std_error(e)),
-            },
+            Err(e) => {
+                if let Some(cause) = e.cause() {
+                    req.log_metadata("cause", cause.to_string())
+                };
+                match e.response() {
+                    Some(response) => Ok(response),
+                    None => Err(std_error(e)),
+                }
+            }
         }
     }
 }
@@ -181,7 +186,9 @@ impl Handler for R404 {
 #[cfg(test)]
 mod tests {
     use super::*;
-    use crate::util::errors::{bad_request, cargo_err, internal, AppError, NotFound, Unauthorized};
+    use crate::util::errors::{
+        bad_request, cargo_err, internal, AppError, ChainError, NotFound, Unauthorized,
+    };
 
     use conduit_test::MockRequest;
     use diesel::result::Error as DieselError;
@@ -219,6 +226,22 @@ mod tests {
             200
         );
 
+        // Inner errors are captured for logging when wrapped by a user facing error
+        let response = C(|_| {
+            Err("-1"
+                .parse::<u8>()
+                .chain_error(|| internal("middle error"))
+                .chain_error(|| bad_request("outer user facing error"))
+                .unwrap_err())
+        })
+        .call(&mut req)
+        .unwrap();
+        assert_eq!(response.status.0, 400);
+        assert_eq!(
+            crate::middleware::log_request::get_log_message(&req, "cause"),
+            "middle error caused by invalid digit found in string"
+        );
+
         // All other error types are propogated up the middleware, eventually becoming status 500
         assert!(C(|_| Err(internal(""))).call(&mut req).is_err());
         assert!(

src/util/errors.rs

@@ -77,6 +77,16 @@ pub trait AppError: Send + fmt::Display + fmt::Debug + 'static {
     /// where it is eventually logged and turned into a status 500 response.
     fn response(&self) -> Option<Response>;
 
+    /// The cause of an error response
+    ///
+    /// If present, an error provided to the `LogRequests` middleware.
+    ///
+    /// This is intended for use with the `ChainError` trait, where a user facing
+    /// error may wrap an internal error we still want to log.
+    fn cause(&self) -> Option<&dyn AppError> {
+        None
+    }
+
     fn get_type_id(&self) -> TypeId {
         TypeId::of::<Self>()
     }
@@ -108,6 +118,10 @@ impl AppError for Box<dyn AppError> {
     fn response(&self) -> Option<Response> {
         (**self).response()
     }
+
+    fn cause(&self) -> Option<&dyn AppError> {
+        (**self).cause()
+    }
 }
 
 pub type AppResult<T> = Result<T, Box<dyn AppError>>;
@@ -128,19 +142,6 @@ struct ChainedError<E> {
     cause: Box<dyn AppError>,
 }
 
-impl<T, F> ChainError<T> for F
-where
-    F: FnOnce() -> AppResult<T>,
-{
-    fn chain_error<E, C>(self, callback: C) -> AppResult<T>
-    where
-        E: AppError,
-        C: FnOnce() -> E,
-    {
-        self().chain_error(callback)
-    }
-}
-
 impl<T, E: AppError> ChainError<T> for Result<T, E> {
     fn chain_error<E2, C>(self, callback: C) -> AppResult<T>
     where
@@ -173,6 +174,10 @@ impl<E: AppError> AppError for ChainedError<E> {
     fn response(&self) -> Option<Response> {
         self.error.response()
     }
+
+    fn cause(&self) -> Option<&dyn AppError> {
+        Some(&*self.cause)
+    }
 }
 
 impl<E: AppError> fmt::Display for ChainedError<E> {