Auto merge of #2234 - pietroalbini:log-publish-crate, r=jtgeibel

Include crate name and version in the publish API's log entries

This PR includes the crate name and version in the log entries of the publish API, to fix #2228 and to aid debugging issues in production. This is done in three steps.

First, the log entry generation code was refactored to easily allow adding new fields to it. Now, instead of hardcoding the list of fields in a `format!` macro, there is a builder with methods to add individual fields.

~~Then, a way to attach custom log fields to a response was added. This is implemented by setting HTTP headers in the response starting with `X-CratesIo-Log-Metadata-`, and by changing the middleware responsible for request logging to strip those headers and add their content to the log line instead.~~

Then, a way to attach custom log fields to a response was added. This is implemented as a "request extension", with a convenience method in the `ResponseExt` trait to add the custom log fields to all responses generated by that request.

Finally, this new feature was used to attach the crate name and version to the publish API's log entries.

r? @sgrif

Author: bors

src/controllers.rs

@@ -38,6 +38,8 @@ mod prelude {
         fn query(&self) -> IndexMap<String, String>;
         fn wants_json(&self) -> bool;
         fn query_with_params(&self, params: IndexMap<String, String>) -> String;
+
+        fn log_metadata<V: std::fmt::Display>(&mut self, key: &'static str, value: V);
     }
 
     impl<'a> RequestUtils for dyn Request + 'a {
@@ -76,6 +78,10 @@ mod prelude {
                 .finish();
             format!("?{}", query_string)
         }
+
+        fn log_metadata<V: std::fmt::Display>(&mut self, key: &'static str, value: V) {
+            crate::middleware::log_request::add_custom_metadata(self, key, value);
+        }
     }
 }
 

src/controllers/krate/publish.rs

@@ -41,6 +41,9 @@ pub fn publish(req: &mut dyn Request) -> AppResult<Response> {
 
     let new_crate = parse_new_headers(req)?;
 
+    req.log_metadata("crate_name", new_crate.name.to_string());
+    req.log_metadata("crate_version", new_crate.vers.to_string());
+
     let conn = app.primary_database.get()?;
     let ids = req.authenticate(&conn)?;
     let user = ids.find_user(&conn)?;

src/middleware.rs

@@ -25,7 +25,7 @@ mod ember_index_rewrite;
 mod ensure_well_formed_500;
 mod head;
 mod log_connection_pool_status;
-mod log_request;
+pub mod log_request;
 mod require_user_agent;
 mod static_or_continue;
 

src/middleware/log_request.rs

@@ -4,9 +4,11 @@
 use super::prelude::*;
 use crate::util::request_header;
 use conduit::Request;
-use std::fmt;
+use std::fmt::{self, Display, Formatter};
 use std::time::Instant;
 
+const SLOW_REQUEST_THRESHOLD_MS: u64 = 1000;
+
 #[allow(missing_debug_implementations)] // We can't
 #[derive(Default)]
 pub struct LogRequests {
@@ -23,61 +25,151 @@ impl Handler for LogRequests {
     fn call(&self, req: &mut dyn Request) -> Result<Response> {
         let request_start = Instant::now();
         let res = self.handler.as_ref().unwrap().call(req);
-        let (level, response_code) = match res {
-            Ok(ref r) => ("info", r.status.0),
-            Err(_) => ("error", 500),
-        };
         let response_time = request_start.elapsed();
         let response_time =
             response_time.as_secs() * 1000 + u64::from(response_time.subsec_nanos()) / 1_000_000;
 
-        let metadata_length = req
-            .extensions()
-            .find::<u64>()
-            .map_or(String::new(), |l| format!(" metadata_length={}", l));
+        println!(
+            "{}",
+            RequestLine {
+                req,
+                res: &res,
+                response_time,
+            }
+        );
 
-        let slow_request = if response_time > 1000 {
-            " SLOW REQUEST"
-        } else {
-            ""
+        res
+    }
+}
+
+struct CustomMetadata {
+    entries: Vec<(&'static str, String)>,
+}
+
+pub fn add_custom_metadata<V: Display>(req: &mut dyn Request, key: &'static str, value: V) {
+    if let Some(metadata) = req.mut_extensions().find_mut::<CustomMetadata>() {
+        metadata.entries.push((key, value.to_string()));
+    } else {
+        let mut metadata = CustomMetadata {
+            entries: Vec::new(),
         };
+        metadata.entries.push((key, value.to_string()));
+        req.mut_extensions().insert(metadata);
+    }
+}
+
+struct RequestLine<'r> {
+    req: &'r dyn Request,
+    res: &'r Result<Response>,
+    response_time: u64,
+}
 
-        let error = if let Err(ref e) = res {
-            format!(" error=\"{}\"", e)
-        } else {
-            String::new()
+impl Display for RequestLine<'_> {
+    fn fmt(&self, f: &mut Formatter<'_>) -> fmt::Result {
+        let mut line = LogLine::new(f);
+
+        let (at, status) = match self.res {
+            Ok(resp) => ("info", resp.status.0),
+            Err(_) => ("error", 500),
         };
 
-        println!(
-            "at={level} method={method} path=\"{path}\" \
-             request_id={request_id} fwd=\"{ip}\" service={time_ms}ms \
-             status={status} user_agent=\"{user_agent}\"\
-             {metadata_length}{error}{slow_request}",
-            level = level,
-            method = req.method(),
-            path = FullPath(req),
-            ip = request_header(req, "X-Real-Ip"),
-            time_ms = response_time,
-            user_agent = request_header(req, "User-Agent"),
-            request_id = request_header(req, "X-Request-Id"),
-            status = response_code,
-            metadata_length = metadata_length,
-            error = error,
-            slow_request = slow_request,
-        );
+        line.add_field("at", at)?;
+        line.add_field("method", self.req.method())?;
+        line.add_quoted_field("path", FullPath(self.req))?;
+        line.add_field("request_id", request_header(self.req, "X-Request-Id"))?;
+        line.add_quoted_field("fwd", request_header(self.req, "X-Real-Ip"))?;
+        line.add_field("service", TimeMs(self.response_time))?;
+        line.add_field("status", status)?;
+        line.add_quoted_field("user_agent", request_header(self.req, "User-Agent"))?;
 
-        res
+        if let Some(metadata) = self.req.extensions().find::<CustomMetadata>() {
+            for (key, value) in &metadata.entries {
+                line.add_quoted_field(key, value)?;
+            }
+        }
+
+        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)?;
+        }
+
+        if self.response_time > SLOW_REQUEST_THRESHOLD_MS {
+            line.add_marker("SLOW REQUEST")?;
+        }
+
+        Ok(())
     }
 }
 
 struct FullPath<'a>(&'a dyn Request);
 
-impl<'a> fmt::Display for FullPath<'a> {
-    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+impl<'a> Display for FullPath<'a> {
+    fn fmt(&self, f: &mut Formatter<'_>) -> fmt::Result {
         write!(f, "{}", self.0.path())?;
         if let Some(q_string) = self.0.query_string() {
             write!(f, "?{}", q_string)?;
         }
         Ok(())
     }
 }
+
+struct TimeMs(u64);
+
+impl Display for TimeMs {
+    fn fmt(&self, f: &mut Formatter<'_>) -> fmt::Result {
+        self.0.fmt(f)?;
+        f.write_str("ms")?;
+        Ok(())
+    }
+}
+
+struct LogLine<'f, 'g> {
+    f: &'f mut Formatter<'g>,
+    first: bool,
+}
+
+impl<'f, 'g> LogLine<'f, 'g> {
+    fn new(f: &'f mut Formatter<'g>) -> Self {
+        Self { f, first: true }
+    }
+
+    fn add_field<K: Display, V: Display>(&mut self, key: K, value: V) -> fmt::Result {
+        self.start_item()?;
+
+        key.fmt(self.f)?;
+        self.f.write_str("=")?;
+        value.fmt(self.f)?;
+
+        Ok(())
+    }
+
+    fn add_quoted_field<K: Display, V: Display>(&mut self, key: K, value: V) -> fmt::Result {
+        self.start_item()?;
+
+        key.fmt(self.f)?;
+        self.f.write_str("=\"")?;
+        value.fmt(self.f)?;
+        self.f.write_str("\"")?;
+
+        Ok(())
+    }
+
+    fn add_marker<M: Display>(&mut self, marker: M) -> fmt::Result {
+        self.start_item()?;
+
+        marker.fmt(self.f)?;
+
+        Ok(())
+    }
+
+    fn start_item(&mut self) -> fmt::Result {
+        if !self.first {
+            self.f.write_str(" ")?;
+        }
+        self.first = false;
+        Ok(())
+    }
+}