Rewrite tide-slog to setup a per-request logger instance and support slog-scope

Author: Nemo157

.travis.yml

@@ -54,3 +54,8 @@ matrix:
   - name: cargo test
     script:
     - cargo test -Zmtime-on-use --all --verbose
+
+  - name: cargo test --all-features
+    script:
+    - cargo test -Zmtime-on-use --all-features
+    - cargo test -Zmtime-on-use --manifest-path tide-slog/Cargo.toml --all-features

tide-slog/Cargo.toml

@@ -1,7 +1,5 @@
 [package]
-authors = [
-    "Tide Developers"
-]
+authors = ["Tide Developers"]
 description = "Logging middleware for Tide based on slog"
 documentation = "https://docs.rs/tide-slog"
 keywords = ["tide", "web", "middleware", "logging", "slog"]
@@ -17,14 +15,23 @@ readme = "README.md"
 repository = "https://github.com/rustasync/tide"
 version = "0.1.0"
 
+[package.metadata.docs.rs]
+all-features = true
+rustdoc-args = ["--cfg docrs"]
+
+[features]
+scope = ["slog-scope", "slog-scope-futures"]
+
 [dependencies]
 tide-core = { path = "../tide-core", default-features = false  }
 futures-preview = "0.3.0-alpha.17"
 http = "0.1"
-log = "0.4.6"
 slog = "2.4.1"
-slog-async = "2.3.0"
-slog-term = "2.4.0"
+slog-scope = { version = "4.1.1", optional = true }
+slog-scope-futures = { version = "0.1.1", optional = true }
 
 [dev-dependencies]
 tide = { path = "../", default-features = false }
+uuid = { version = "0.7.4", default-features = false, features = ["v4"] }
+slog-stdlog = "3.0.2"
+slog-scope = "4.1.1"

tide-slog/src/lib.rs

@@ -1,6 +1,7 @@
 //! Crate that provides helpers and/or middlewares for Tide
 //! related to structured logging with slog.
 
+#![cfg_attr(docrs, feature(doc_cfg))]
 #![feature(async_await)]
 #![warn(
     nonstandard_style,
@@ -9,65 +10,33 @@
     missing_debug_implementations
 )]
 
-use slog::{info, o, trace, Drain};
-use slog_async;
-use slog_term;
-
-use futures::future::BoxFuture;
-
-use tide_core::{
-    middleware::{Middleware, Next},
-    Context, Response,
-};
-
-/// RequestLogger based on slog.SimpleLogger
-#[derive(Debug)]
-pub struct RequestLogger {
-    // drain: dyn slog::Drain,
-    inner: slog::Logger,
-}
-
-impl RequestLogger {
-    pub fn new() -> Self {
-        Default::default()
-    }
-
-    pub fn with_logger(logger: slog::Logger) -> Self {
-        Self { inner: logger }
-    }
-}
-
-impl Default for RequestLogger {
-    fn default() -> Self {
-        let decorator = slog_term::TermDecorator::new().build();
-        let drain = slog_term::CompactFormat::new(decorator).build().fuse();
-        let drain = slog_async::Async::new(drain).build().fuse();
-
-        let log = slog::Logger::root(drain, o!());
-        Self { inner: log }
-    }
+mod per_request_logger;
+mod request_logger;
+#[cfg(feature = "scope")]
+mod set_slog_scope_logger;
+
+pub use per_request_logger::PerRequestLogger;
+pub use request_logger::RequestLogger;
+#[cfg(feature = "scope")]
+pub use set_slog_scope_logger::SetSlogScopeLogger;
+
+use tide_core::Context;
+
+/// An extension to [`Context`] that provides access to a per-request [`slog::Logger`]
+pub trait ContextExt {
+    /// Returns a [`slog::Logger`] scoped to this request.
+    ///
+    /// # Panics
+    ///
+    /// Will panic if no [`PerRequestLogger`] middleware has been used to setup the request scoped
+    /// logger.
+    fn logger(&self) -> &slog::Logger;
 }
 
-/// Stores information during request phase and logs information once the response
-/// is generated.
-impl<State: Send + Sync + 'static> Middleware<State> for RequestLogger {
-    fn handle<'a>(&'a self, cx: Context<State>, next: Next<'a, State>) -> BoxFuture<'a, Response> {
-        Box::pin(async move {
-            let path = cx.uri().path().to_owned();
-            let method = cx.method().as_str().to_owned();
-            trace!(self.inner, "IN => {} {}", method, path);
-            let start = std::time::Instant::now();
-            let res = next.run(cx).await;
-            let status = res.status();
-            info!(
-                self.inner,
-                "{} {} {} {}ms",
-                method,
-                path,
-                status.as_str(),
-                start.elapsed().as_millis()
-            );
-            res
-        })
+impl<State> ContextExt for Context<State> {
+    fn logger(&self) -> &slog::Logger {
+        self.extensions()
+            .get::<slog::Logger>()
+            .expect("PerRequestLogger must be used to populate request logger")
     }
 }

tide-slog/src/per_request_logger.rs

@@ -0,0 +1,89 @@
+use futures::future::BoxFuture;
+use tide_core::{
+    middleware::{Middleware, Next},
+    Context, Response,
+};
+
+/// Middleware that injects a per-request [`slog::Logger`] onto the request [`Context`].
+pub struct PerRequestLogger<State> {
+    setup: Box<dyn (Fn(&mut Context<State>) -> slog::Logger) + Send + Sync + 'static>,
+}
+
+impl<State> PerRequestLogger<State> {
+    /// Initialize this middleware with a function to create a per-request logger.
+    ///
+    /// # Examples
+    ///
+    /// ## Adding a base16 encoded per-request UUID onto the logger context
+    ///
+    /// ```
+    /// use slog::o;
+    ///
+    /// let mut app = tide::App::new();
+    ///
+    /// let request_id = || uuid::Uuid::new_v4().to_simple().to_string();
+    ///
+    /// let root_logger = slog::Logger::root(slog::Discard, o!());
+    /// app.middleware(tide_slog::PerRequestLogger::with_setup(move |_cx| root_logger.new(o! {
+    ///     "request" => request_id(),
+    /// })));
+    /// ```
+    ///
+    /// ## Taking an externally provided request id from headers for the logger context
+    ///
+    /// ```
+    /// use slog::o;
+    ///
+    /// let mut app = tide::App::new();
+    ///
+    /// let root_logger = slog::Logger::root(slog::Discard, o!());
+    /// app.middleware(tide_slog::PerRequestLogger::with_setup(move |cx| root_logger.new(o! {
+    ///     "request" => cx.headers().get("Request-Id").unwrap().to_str().unwrap().to_owned(),
+    /// })));
+    /// ```
+    pub fn with_setup(
+        setup: impl (Fn(&mut Context<State>) -> slog::Logger) + Send + Sync + 'static,
+    ) -> Self {
+        Self {
+            setup: Box::new(setup),
+        }
+    }
+
+    /// Initialize this middleware with a logger that will provided to each request.
+    ///
+    /// # Examples
+    ///
+    /// ```
+    /// use slog::o;
+    ///
+    /// let mut app = tide::App::new();
+    ///
+    /// let root_logger = slog::Logger::root(slog::Discard, o!());
+    /// app.middleware(tide_slog::PerRequestLogger::with_logger(root_logger));
+    /// ```
+    pub fn with_logger(logger: slog::Logger) -> Self {
+        Self {
+            setup: Box::new(move |_cx| logger.clone()),
+        }
+    }
+}
+
+impl<State: Send + Sync + 'static> Middleware<State> for PerRequestLogger<State> {
+    fn handle<'a>(
+        &'a self,
+        mut cx: Context<State>,
+        next: Next<'a, State>,
+    ) -> BoxFuture<'a, Response> {
+        let logger = (self.setup)(&mut cx);
+        cx.extensions_mut().insert(logger);
+        next.run(cx)
+    }
+}
+
+impl<State> std::fmt::Debug for PerRequestLogger<State> {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        f.debug_struct("PerRequestLogger")
+            .field("setup", &"[closure]")
+            .finish()
+    }
+}

tide-slog/src/request_logger.rs

@@ -0,0 +1,74 @@
+use crate::ContextExt;
+use futures::future::BoxFuture;
+use slog::{info, trace};
+use tide_core::{
+    middleware::{Middleware, Next},
+    Context, Response,
+};
+
+/// Middleware that logs minimal request details to the current request's [`slog::Logger`].
+///
+/// Relies on having a [`PerRequestLogger`][crate::PerRequestLogger] middleware instance setup
+/// beforehand to get the logger from.
+///
+/// # Examples
+///
+/// ```
+/// use slog::o;
+///
+/// let mut app = tide::App::new();
+///
+/// let root_logger = slog::Logger::root(slog::Discard, o!());
+/// app.middleware(tide_slog::PerRequestLogger::with_logger(root_logger));
+/// app.middleware(tide_slog::RequestLogger::new());
+/// ```
+#[derive(Debug)]
+pub struct RequestLogger {
+    // In case we want to make this configurable in the future
+    _reserved: (),
+}
+
+impl RequestLogger {
+    /// Create a new [`RequestLogger`] instance.
+    pub fn new() -> Self {
+        Self { _reserved: () }
+    }
+}
+
+impl<State: Send + Sync + 'static> Middleware<State> for RequestLogger {
+    fn handle<'a>(&'a self, cx: Context<State>, next: Next<'a, State>) -> BoxFuture<'a, Response> {
+        Box::pin(async move {
+            let logger = cx.logger().clone();
+            let path = cx.uri().path().to_owned();
+            let method = cx.method().as_str().to_owned();
+
+            trace!(
+                logger,
+                "IN => {method} {path}",
+                method = &method,
+                path = &path
+            );
+
+            let start = std::time::Instant::now();
+            let res = next.run(cx).await;
+            let status = res.status();
+
+            info!(
+                logger,
+                "{method} {path} {status} {elapsed}ms",
+                method = &method,
+                path = &path,
+                status = status.as_str(),
+                elapsed = start.elapsed().as_millis(),
+            );
+
+            res
+        })
+    }
+}
+
+impl Default for RequestLogger {
+    fn default() -> Self {
+        Self::new()
+    }
+}

tide-slog/src/set_slog_scope_logger.rs

@@ -0,0 +1,51 @@
+use crate::ContextExt;
+use futures::future::{BoxFuture, FutureExt as _};
+use slog_scope_futures::FutureExt as _;
+use tide_core::{
+    middleware::{Middleware, Next},
+    Response,
+};
+
+#[cfg_attr(docrs, doc(cfg(feature = "scope")))]
+/// Middleware that ensures the current request's [`slog::Logger`] will be accessible using
+/// [`slog-scope::logger`] during all following processing of the request.
+///
+/// Relies on having a [`PerRequestLogger`][crate::PerRequestLogger] middleware instance setup
+/// beforehand to get the logger from.
+///
+/// This can be used along with [`slog-stdlog`](https://docs.rs/slog-stdlog/) to
+/// integrate per-request logging with middleware that use [`log`](https://docs.rs/log)`.
+///
+/// # Examples
+///
+/// ```
+/// use slog::o;
+///
+/// let root_logger = slog::Logger::root(slog::Discard, o!());
+///
+/// let _guard = slog_scope::set_global_logger(root_logger.clone());
+/// slog_stdlog::init()?;
+///
+/// let mut app = tide::App::new();
+///
+/// app.middleware(tide_slog::PerRequestLogger::with_logger(root_logger));
+/// app.middleware(tide_slog::SetSlogScopeLogger);
+///
+/// // The default tide request logger uses `log`, but since we are using `slog-stdlog` and run
+/// // `SetSlogScopeLogger` first it will be redirected into the per-request logger instance.
+/// app.middleware(tide::middleware::RequestLogger::new());
+/// # Ok::<(), Box<dyn std::error::Error>>(())
+/// ```
+#[derive(Debug)]
+pub struct SetSlogScopeLogger;
+
+impl<State: Send + Sync + 'static> Middleware<State> for SetSlogScopeLogger {
+    fn handle<'a>(
+        &'a self,
+        cx: tide_core::Context<State>,
+        next: Next<'a, State>,
+    ) -> BoxFuture<'a, Response> {
+        let logger = cx.logger().clone();
+        next.run(cx).with_logger(logger).boxed()
+    }
+}