middleware::log_request: Split request timing code into dedicated middleware

Author: Turbo87

src/middleware.rs

@@ -10,6 +10,7 @@ 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::static_or_continue::StaticOrContinue;
 use self::update_metrics::UpdateMetrics;
 
@@ -23,6 +24,7 @@ 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 static_or_continue;
 mod update_metrics;
@@ -48,6 +50,8 @@ pub fn build_middleware(app: Arc<App>, endpoints: RouteBuilder) -> MiddlewareBui
         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

@@ -7,8 +7,8 @@ use crate::util::request_header;
 use conduit::{header, RequestExt, StatusCode};
 use conduit_cookie::RequestSession;
 
+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;
 
@@ -25,30 +25,7 @@ impl Middleware for LogRequests {
     }
 
     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;
+        let response_time = req.extensions().find::<ResponseTime>().unwrap();
 
         println!(
             "{}",
@@ -59,19 +36,12 @@ impl Middleware for LogRequests {
             }
         );
 
-        report_to_sentry(req, &res, response_time);
+        report_to_sentry(req, &res, response_time.as_millis());
 
         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)>,
 }
@@ -142,7 +112,7 @@ 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,
+    response_time: &'r ResponseTime,
 }
 
 impl Display for RequestLine<'_> {
@@ -175,7 +145,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", self.response_time)?;
         line.add_field("status", status.as_str())?;
         line.add_quoted_field("user_agent", request_header(self.req, header::USER_AGENT))?;
 
@@ -189,7 +159,7 @@ impl Display for RequestLine<'_> {
             line.add_quoted_field("error", err)?;
         }
 
-        if self.response_time > SLOW_REQUEST_THRESHOLD_MS {
+        if self.response_time.as_millis() > SLOW_REQUEST_THRESHOLD_MS {
             line.add_marker("SLOW REQUEST")?;
         }
 
@@ -214,16 +184,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/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()
+}