Merge pull request #662 from jbr/only-log-once

Only run the log middleware once per request

Author: yoshuawuyts

src/log/middleware.rs

@@ -3,7 +3,9 @@ use crate::{Middleware, Next, Request};
 
 /// Log all incoming requests and responses.
 ///
-/// This middleware is enabled by default in Tide.
+/// This middleware is enabled by default in Tide. In the case of
+/// nested applications, this middleware will only run once for each
+/// request.
 ///
 /// # Examples
 ///
@@ -16,6 +18,8 @@ pub struct LogMiddleware {
     _priv: (),
 }
 
+struct LogMiddlewareHasBeenRun;
+
 impl LogMiddleware {
     /// Create a new instance of `LogMiddleware`.
     #[must_use]
@@ -26,17 +30,22 @@ impl LogMiddleware {
     /// Log a request and a response.
     async fn log<'a, State: Clone + Send + Sync + 'static>(
         &'a self,
-        ctx: Request<State>,
+        mut req: Request<State>,
         next: Next<'a, State>,
     ) -> crate::Result {
-        let path = ctx.url().path().to_owned();
-        let method = ctx.method().to_string();
+        if req.ext::<LogMiddlewareHasBeenRun>().is_some() {
+            return Ok(next.run(req).await);
+        }
+        req.set_ext(LogMiddlewareHasBeenRun);
+
+        let path = req.url().path().to_owned();
+        let method = req.method().to_string();
         log::info!("<-- Request received", {
             method: method,
             path: path,
         });
         let start = std::time::Instant::now();
-        let response = next.run(ctx).await;
+        let response = next.run(req).await;
         let status = response.status();
         if status.is_server_error() {
             if let Some(error) = response.error() {

tests/log.rs

@@ -2,11 +2,16 @@ use async_std::prelude::*;
 use std::time::Duration;
 
 mod test_utils;
+use test_utils::ServerTestingExt;
 
 #[async_std::test]
-async fn start_server_log() {
+async fn log_tests() {
     let mut logger = logtest::start();
+    test_server_listen(&mut logger).await;
+    test_only_log_once(&mut logger).await;
+}
 
+async fn test_server_listen(logger: &mut logtest::Logger) {
     let port = test_utils::find_port().await;
     let app = tide::new();
     let res = app
@@ -23,3 +28,31 @@ async fn start_server_log() {
         format!("Server listening on http://[::1]:{}", port)
     );
 }
+
+async fn test_only_log_once(logger: &mut logtest::Logger) {
+    let mut app = tide::new();
+    app.at("/").nest({
+        let mut app = tide::new();
+        app.at("/").get(|_| async { Ok("nested") });
+        app
+    });
+    app.get("/").await;
+
+    let entries: Vec<_> = logger.collect();
+
+    assert_eq!(
+        1,
+        entries
+            .iter()
+            .filter(|entry| entry.args() == "<-- Request received")
+            .count()
+    );
+
+    assert_eq!(
+        1,
+        entries
+            .iter()
+            .filter(|entry| entry.args() == "--> Response sent")
+            .count()
+    );
+}