Split LogRequests middleware into multiple middlewares

src/middleware.rs

@@ -10,6 +10,8 @@ use self::ember_html::EmberHtml;
 use self::head::Head;
 use self::known_error_to_json::KnownErrorToJson;
 use self::log_connection_pool_status::LogConnectionPoolStatus;
+use self::request_timing::RequestTiming;
+use self::sentry::SentryMiddleware as CustomSentryMiddleware;
 use self::static_or_continue::StaticOrContinue;
 use self::update_metrics::UpdateMetrics;
 
@@ -23,7 +25,9 @@ mod known_error_to_json;
 mod log_connection_pool_status;
 pub mod log_request;
 mod normalize_path;
+mod request_timing;
 mod require_user_agent;
+mod sentry;
 mod static_or_continue;
 mod update_metrics;
 
@@ -45,9 +49,12 @@ pub fn build_middleware(app: Arc<App>, endpoints: RouteBuilder) -> MiddlewareBui
 
     if env != Env::Test {
         m.add(log_request::LogRequests::default());
+        m.add(CustomSentryMiddleware::default());
         m.around(SentryMiddleware::default());
     }
 
+    m.add(RequestTiming::default());
+
     if env == Env::Development {
         // Optionally print debug information for each request
         // To enable, set the environment variable: `RUST_LOG=cargo_registry::middleware=debug`

src/middleware/log_request.rs

@@ -5,75 +5,26 @@ use super::prelude::*;
 use crate::util::request_header;
 
 use conduit::{header, RequestExt, StatusCode};
-use conduit_cookie::RequestSession;
 
+use crate::middleware::normalize_path::OriginalPath;
+use crate::middleware::request_timing::ResponseTime;
 use std::fmt::{self, Display, Formatter};
-use std::time::{SystemTime, UNIX_EPOCH};
 
 const SLOW_REQUEST_THRESHOLD_MS: u64 = 1000;
 
 #[derive(Default)]
 pub(super) struct LogRequests();
 
-struct OriginalPath(String);
-
 impl Middleware for LogRequests {
-    fn before(&self, req: &mut dyn RequestExt) -> BeforeResult {
-        let path = OriginalPath(req.path().to_string());
-        req.mut_extensions().insert(path);
-        Ok(())
-    }
-
     fn after(&self, req: &mut dyn RequestExt, res: AfterResult) -> AfterResult {
-        let response_time =
-            if let Ok(start_ms) = request_header(req, "x-request-start").parse::<u128>() {
-                let current_ms = SystemTime::now()
-                    .duration_since(UNIX_EPOCH)
-                    .expect("Time went way backwards")
-                    .as_millis();
-
-                if current_ms > start_ms {
-                    // The result cannot be negative
-                    current_ms - start_ms
-                } else {
-                    // Because our nginx proxy and app run on the same dyno in production, we
-                    // shouldn't have to worry about clock drift. But if something goes wrong,
-                    // calculate the response time based on when the request reached this app.
-                    fallback_response_time(req)
-                }
-            } else {
-                // X-Request-Start header couldn't be parsed.
-                // We are probably running locally and not behind nginx.
-                fallback_response_time(req)
-            };
-
-        // This will only trucate for requests lasting > 500 million years
-        let response_time = response_time as u64;
-
-        println!(
-            "{}",
-            RequestLine {
-                req,
-                res: &res,
-                response_time,
-            }
-        );
-
-        report_to_sentry(req, &res, response_time);
+        println!("{}", RequestLine { req, res: &res });
 
         res
     }
 }
 
-/// Calculate the response time based on when the request reached the in-app web server.
-///
-/// This serves as a fallback in case the `X-Request-Start` header is missing or invalid.
-fn fallback_response_time(req: &mut dyn RequestExt) -> u128 {
-    req.elapsed().as_millis()
-}
-
-struct CustomMetadata {
-    entries: Vec<(&'static str, String)>,
+pub struct CustomMetadata {
+    pub entries: Vec<(&'static str, String)>,
 }
 
 pub fn add_custom_metadata<V: Display>(req: &mut dyn RequestExt, key: &'static str, value: V) {
@@ -88,46 +39,6 @@ pub fn add_custom_metadata<V: Display>(req: &mut dyn RequestExt, key: &'static s
     }
 }
 
-fn report_to_sentry(req: &dyn RequestExt, res: &AfterResult, response_time: u64) {
-    sentry::configure_scope(|scope| {
-        {
-            let id = req.session().get("user_id").map(|str| str.to_string());
-
-            let user = sentry::User {
-                id,
-                ..Default::default()
-            };
-
-            scope.set_user(Some(user));
-        }
-
-        if let Some(request_id) = req
-            .headers()
-            .get("x-request-id")
-            .and_then(|value| value.to_str().ok())
-        {
-            scope.set_tag("request.id", request_id);
-        }
-
-        {
-            let status = res
-                .as_ref()
-                .map(|resp| resp.status())
-                .unwrap_or(StatusCode::INTERNAL_SERVER_ERROR);
-
-            scope.set_tag("response.status", status.as_str());
-        }
-
-        scope.set_extra("Response time [ms]", response_time.into());
-
-        if let Some(metadata) = req.extensions().find::<CustomMetadata>() {
-            for (key, value) in &metadata.entries {
-                scope.set_extra(key, value.to_string().into());
-            }
-        }
-    });
-}
-
 #[cfg(test)]
 pub(crate) fn get_log_message(req: &dyn RequestExt, key: &'static str) -> String {
     // Unwrap shouldn't panic as no other code has access to the private struct to remove it
@@ -142,13 +53,14 @@ pub(crate) fn get_log_message(req: &dyn RequestExt, key: &'static str) -> String
 struct RequestLine<'r> {
     req: &'r dyn RequestExt,
     res: &'r AfterResult,
-    response_time: u64,
 }
 
 impl Display for RequestLine<'_> {
     fn fmt(&self, f: &mut Formatter<'_>) -> fmt::Result {
         let mut line = LogLine::new(f);
 
+        let response_time = self.req.extensions().find::<ResponseTime>().unwrap();
+
         let status = self.res.as_ref().map(|res| res.status());
         let status = status.unwrap_or(StatusCode::INTERNAL_SERVER_ERROR);
 
@@ -175,7 +87,7 @@ impl Display for RequestLine<'_> {
         }
 
         line.add_quoted_field("fwd", request_header(self.req, "x-real-ip"))?;
-        line.add_field("service", TimeMs(self.response_time))?;
+        line.add_field("service", response_time)?;
         line.add_field("status", status.as_str())?;
         line.add_quoted_field("user_agent", request_header(self.req, header::USER_AGENT))?;
 
@@ -189,7 +101,7 @@ impl Display for RequestLine<'_> {
             line.add_quoted_field("error", err)?;
         }
 
-        if self.response_time > SLOW_REQUEST_THRESHOLD_MS {
+        if response_time.as_millis() > SLOW_REQUEST_THRESHOLD_MS {
             line.add_marker("SLOW REQUEST")?;
         }
 
@@ -214,16 +126,6 @@ impl<'a> Display for FullPath<'a> {
     }
 }
 
-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,

src/middleware/normalize_path.rs

@@ -4,12 +4,18 @@ use super::prelude::*;
 
 use std::path::{Component, Path, PathBuf};
 
+pub struct OriginalPath(pub String);
+
 pub struct NormalizePath;
 
 impl Middleware for NormalizePath {
     fn before(&self, req: &mut dyn RequestExt) -> BeforeResult {
         let path = req.path();
+        let original_path = OriginalPath(path.to_string());
+
         if !(path.contains("//") || path.contains("/.")) {
+            req.mut_extensions().insert(original_path);
+
             // Avoid allocations if rewriting is unnecessary
             return Ok(());
         }
@@ -40,6 +46,7 @@ impl Middleware for NormalizePath {
             .to_string(); // non-Unicode is replaced with U+FFFD REPLACEMENT CHARACTER
 
         add_custom_metadata(req, "normalized_path", path.clone());
+        req.mut_extensions().insert(original_path);
         *req.path_mut() = path;
         Ok(())
     }

src/middleware/request_timing.rs

@@ -0,0 +1,66 @@
+use super::prelude::*;
+use crate::util::request_header;
+
+use conduit::RequestExt;
+
+use std::fmt::{self, Display, Formatter};
+use std::time::{SystemTime, UNIX_EPOCH};
+
+#[derive(Default)]
+pub struct RequestTiming();
+
+pub struct ResponseTime(u64);
+
+impl ResponseTime {
+    pub fn as_millis(&self) -> u64 {
+        self.0
+    }
+}
+
+impl Display for ResponseTime {
+    fn fmt(&self, f: &mut Formatter<'_>) -> fmt::Result {
+        self.0.fmt(f)?;
+        f.write_str("ms")?;
+        Ok(())
+    }
+}
+
+impl Middleware for RequestTiming {
+    fn after(&self, req: &mut dyn RequestExt, res: AfterResult) -> AfterResult {
+        let response_time =
+            if let Ok(start_ms) = request_header(req, "x-request-start").parse::<u128>() {
+                let current_ms = SystemTime::now()
+                    .duration_since(UNIX_EPOCH)
+                    .expect("Time went way backwards")
+                    .as_millis();
+
+                if current_ms > start_ms {
+                    // The result cannot be negative
+                    current_ms - start_ms
+                } else {
+                    // Because our nginx proxy and app run on the same dyno in production, we
+                    // shouldn't have to worry about clock drift. But if something goes wrong,
+                    // calculate the response time based on when the request reached this app.
+                    fallback_response_time(req)
+                }
+            } else {
+                // X-Request-Start header couldn't be parsed.
+                // We are probably running locally and not behind nginx.
+                fallback_response_time(req)
+            };
+
+        // This will only trucate for requests lasting > 500 million years
+        let response_time = response_time as u64;
+
+        req.mut_extensions().insert(ResponseTime(response_time));
+
+        res
+    }
+}
+
+/// Calculate the response time based on when the request reached the in-app web server.
+///
+/// This serves as a fallback in case the `X-Request-Start` header is missing or invalid.
+fn fallback_response_time(req: &mut dyn RequestExt) -> u128 {
+    req.elapsed().as_millis()
+}

src/middleware/sentry.rs

@@ -0,0 +1,55 @@
+use super::prelude::*;
+use crate::middleware::log_request::CustomMetadata;
+use crate::middleware::request_timing::ResponseTime;
+use conduit::{RequestExt, StatusCode};
+use conduit_cookie::RequestSession;
+
+#[derive(Default)]
+pub struct SentryMiddleware();
+
+impl Middleware for SentryMiddleware {
+    fn after(&self, req: &mut dyn RequestExt, res: AfterResult) -> AfterResult {
+        sentry::configure_scope(|scope| {
+            {
+                let id = req.session().get("user_id").map(|str| str.to_string());
+
+                let user = sentry::User {
+                    id,
+                    ..Default::default()
+                };
+
+                scope.set_user(Some(user));
+            }
+
+            if let Some(request_id) = req
+                .headers()
+                .get("x-request-id")
+                .and_then(|value| value.to_str().ok())
+            {
+                scope.set_tag("request.id", request_id);
+            }
+
+            {
+                let status = res
+                    .as_ref()
+                    .map(|resp| resp.status())
+                    .unwrap_or(StatusCode::INTERNAL_SERVER_ERROR);
+
+                scope.set_tag("response.status", status.as_str());
+            }
+
+            let response_time = req.extensions().find::<ResponseTime>();
+            if let Some(response_time) = response_time {
+                scope.set_extra("Response time [ms]", response_time.as_millis().into());
+            }
+
+            if let Some(metadata) = req.extensions().find::<CustomMetadata>() {
+                for (key, value) in &metadata.entries {
+                    scope.set_extra(key, value.to_string().into());
+                }
+            }
+        });
+
+        res
+    }
+}