add support for custom log metadata

Author: pietroalbini

src/controllers.rs

@@ -77,6 +77,17 @@ mod prelude {
             format!("?{}", query_string)
         }
     }
+
+    pub trait ResponseUtils {
+        fn with_log_metadata<V: std::fmt::Display>(self, key: &str, value: V) -> Self;
+    }
+
+    impl ResponseUtils for Response {
+        fn with_log_metadata<V: std::fmt::Display>(mut self, key: &str, value: V) -> Self {
+            crate::middleware::log_request::add_custom_metadata(&mut self, key, value);
+            self
+        }
+    }
 }
 
 pub mod helpers;

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

@@ -7,8 +7,16 @@ use conduit::Request;
 use std::fmt::{self, Display, Formatter};
 use std::time::Instant;
 
+const LOG_METADATA_HEADER_PREFIX: &str = "X-CratesIo-Log-Metadata-";
 const SLOW_REQUEST_THRESHOLD_MS: u64 = 1000;
 
+pub fn add_custom_metadata<K: Display, V: Display>(resp: &mut Response, key: K, value: V) {
+    resp.headers.insert(
+        format!("{}{}", LOG_METADATA_HEADER_PREFIX, key),
+        vec![value.to_string()],
+    );
+}
+
 #[allow(missing_debug_implementations)] // We can't
 #[derive(Default)]
 pub struct LogRequests {
@@ -24,17 +32,45 @@ impl AroundMiddleware for LogRequests {
 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 mut res = self.handler.as_ref().unwrap().call(req);
         let response_time = request_start.elapsed();
         let response_time =
             response_time.as_secs() * 1000 + u64::from(response_time.subsec_nanos()) / 1_000_000;
 
+        // To aid debugging issues in production, some routes attach extra metadata to the log
+        // line. An example of this is the crate publishing route, which adds the published crate
+        // name and version to the line.
+        //
+        // This is implemented as special HTTP headers:
+        //
+        //     X-CratesIo-Log-Metadata-{key}: {value}
+        //
+        // When this middleware finds those headers in the response, it removes them (so the user
+        // can't see them) and adds the key/value pair at the end of the log line.
+        let mut custom_metadata = Vec::new();
+        if let Ok(resp) = &mut res {
+            resp.headers.retain(|key, value| {
+                if key.starts_with(LOG_METADATA_HEADER_PREFIX) {
+                    if let Some(value) = value.get(0) {
+                        custom_metadata.push((
+                            key[LOG_METADATA_HEADER_PREFIX.len()..].to_string(),
+                            value.clone(),
+                        ));
+                    }
+                    false
+                } else {
+                    true
+                }
+            });
+        }
+
         println!(
             "{}",
             RequestLine {
                 req,
                 res: &res,
                 response_time,
+                custom_metadata,
             }
         );
 
@@ -45,6 +81,7 @@ impl Handler for LogRequests {
 struct RequestLine<'r> {
     req: &'r dyn Request,
     res: &'r Result<Response>,
+    custom_metadata: Vec<(String, String)>,
     response_time: u64,
 }
 
@@ -66,6 +103,10 @@ impl Display for RequestLine<'_> {
         line.add_field("status", status)?;
         line.add_quoted_field("user_agent", request_header(self.req, "User-Agent"))?;
 
+        for (key, value) in &self.custom_metadata {
+            line.add_quoted_field(key, value)?;
+        }
+
         if let Some(len) = self.req.extensions().find::<u64>() {
             line.add_field("metadata_length", len)?;
         }