Auto merge of #4116 - Turbo87:timing-middleware, r=JohnTitor

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

This is generic and not strictly related to the `LogRequest` middleware. The `UpdateMetrics` middleware should probably also use this in the future.

Author: bors

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::response_timing::ResponseTiming;
 use self::static_or_continue::StaticOrContinue;
 use self::update_metrics::UpdateMetrics;
 
@@ -24,6 +25,7 @@ mod log_connection_pool_status;
 pub mod log_request;
 mod normalize_path;
 mod require_user_agent;
+mod response_timing;
 mod static_or_continue;
 mod update_metrics;
 
@@ -48,6 +50,8 @@ pub fn build_middleware(app: Arc<App>, endpoints: RouteBuilder) -> MiddlewareBui
         m.add(log_request::LogRequests::default());
     }
 
+    m.add(ResponseTiming::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::response_timing::ResponseTime;
 use std::fmt::{self, Display, Formatter};
-use std::time::{SystemTime, UNIX_EPOCH};
 
 const SLOW_REQUEST_THRESHOLD_MS: u64 = 1000;
 
@@ -34,53 +34,14 @@ 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;
-
-        println!(
-            "{}",
-            RequestLine {
-                req,
-                res: &res,
-                response_time,
-            }
-        );
+        println!("{}", RequestLine { req, res: &res });
 
-        report_to_sentry(req, &res, response_time);
+        report_to_sentry(req, &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)>,
 }
@@ -99,7 +60,7 @@ pub fn add_custom_metadata<V: Display>(req: &mut dyn RequestExt, key: &'static s
     sentry::configure_scope(|scope| scope.set_extra(key, value.to_string().into()));
 }
 
-fn report_to_sentry(req: &dyn RequestExt, res: &AfterResult, response_time: u64) {
+fn report_to_sentry(req: &dyn RequestExt, res: &AfterResult) {
     sentry::configure_scope(|scope| {
         {
             let id = req.session().get("user_id").map(|str| str.to_string());
@@ -121,7 +82,9 @@ fn report_to_sentry(req: &dyn RequestExt, res: &AfterResult, response_time: u64)
             scope.set_tag("response.status", status.as_str());
         }
 
-        scope.set_extra("Response time [ms]", response_time.into());
+        if let Some(response_time) = req.extensions().find::<ResponseTime>() {
+            scope.set_extra("Response time [ms]", response_time.as_millis().into());
+        }
     });
 }
 
@@ -139,7 +102,6 @@ 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<'_> {
@@ -172,7 +134,11 @@ impl Display for RequestLine<'_> {
         }
 
         line.add_quoted_field("fwd", request_header(self.req, "x-real-ip"))?;
-        line.add_field("service", TimeMs(self.response_time))?;
+
+        let response_time = self.req.extensions().find::<ResponseTime>();
+        if let Some(response_time) = 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))?;
 
@@ -186,8 +152,10 @@ impl Display for RequestLine<'_> {
             line.add_quoted_field("error", err)?;
         }
 
-        if self.response_time > SLOW_REQUEST_THRESHOLD_MS {
-            line.add_marker("SLOW REQUEST")?;
+        if let Some(response_time) = response_time {
+            if response_time.as_millis() > SLOW_REQUEST_THRESHOLD_MS {
+                line.add_marker("SLOW REQUEST")?;
+            }
         }
 
         Ok(())
@@ -211,16 +179,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/response_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 ResponseTiming();
+
+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 ResponseTiming {
+    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()
+}