Auto merge of #2383 - jtgeibel:move-logging-near-top-of-middleware, r…

…=JohnTitor

Move request logging near the top of the middleware stack

By converting to a regular `Middleware` (instead of `AroundMiddleware`),
the logging can now sit near the top of the middleware stack.
Previously logging occurred at the top of the around stack, which sits
under the layers added via `add()`.

This change ensures that middleware sitting below the request logger
in the stack are able to add logging metadata in a call to `after()`.

r? @JohnTitor

src/middleware.rs

@@ -46,6 +46,7 @@ pub fn build_middleware(app: Arc<App>, endpoints: R404) -> MiddlewareBuilder {
 
     if env != Env::Test {
         m.add(ensure_well_formed_500::EnsureWellFormed500);
+        m.add(log_request::LogRequests::default());
     }
 
     if env == Env::Development {
@@ -94,9 +95,5 @@ pub fn build_middleware(app: Arc<App>, endpoints: R404) -> MiddlewareBuilder {
 
     m.around(require_user_agent::RequireUserAgent::default());
 
-    if env != Env::Test {
-        m.around(log_request::LogRequests::default());
-    }
-
     m
 }

src/middleware/log_request.rs

@@ -9,22 +9,21 @@ use std::time::Instant;
 
 const SLOW_REQUEST_THRESHOLD_MS: u64 = 1000;
 
-#[allow(missing_debug_implementations)] // We can't
 #[derive(Default)]
-pub struct LogRequests {
-    handler: Option<Box<dyn Handler>>,
-}
+pub(super) struct LogRequests();
+
+struct RequestStart(Instant);
 
-impl AroundMiddleware for LogRequests {
-    fn with_handler(&mut self, handler: Box<dyn Handler>) {
-        self.handler = Some(handler);
+impl Middleware for LogRequests {
+    fn before(&self, req: &mut dyn Request) -> Result<()> {
+        req.mut_extensions().insert(RequestStart(Instant::now()));
+        Ok(())
     }
-}
 
-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);
+    fn after(&self, req: &mut dyn Request, res: Result<Response>) -> Result<Response> {
+        // Unwrap shouldn't panic as no other code has access to the private struct to remove it
+        let request_start = req.extensions().find::<RequestStart>().unwrap().0;
+
         let response_time = request_start.elapsed();
         let response_time =
             response_time.as_secs() * 1000 + u64::from(response_time.subsec_nanos()) / 1_000_000;