Repository: seanmonstar/warp (language: rust)

Issue:
Add tracing support
I'd like to use [`tracing`](https://github.com/tokio-rs/tracing/) with a `warp` API. Do you have any recommendations about the best way to do this? Should there be a `Wrap` for tracing like the `Log` one, or should `Filter` implement `tracing-futures::Instrument`?

I'm happy to work on a PR for this if I can figure out the right direction (and if you think this should be added to warp).

Thank you!


Discussion / hints:
Once https://github.com/tokio-rs/tracing/pull/386 is merged, it will be possible to enable support for tracing by implementing:

```
impl<T> Filter for Instrumented<T>
where
  T: Filter
{
...
}
```

This would allow `warp` users to call `filter.instrument(debug_span!("in warp filter"))` and include all events logged (with `log` or `tracing`) when the filter is called in a given `span`.
@seanmonstar if you'd be open to a PR on this, I'd be happy to put one together

Let me know if you have any thoughts on how it should be implemented
Sorry, my context of exactly how `tracing` works is quite low. What would warp need to provide for it to work? It can't work without warp doing something?
I'm not an expert on it either but I think the three options for how it could be integrated would be:
- Implement `FilterBase` for [`Instrumented<T: FilterBase>`](https://docs.rs/tracing-futures/0.1.0/tracing_futures/struct.Instrumented.html)
- Make `FilterBase` public to allow writing custom `Filter`s
- Add a way to wrap a `Filter` with some function that has access to the request and response when that `Filter` is called
I took a stab at implementing the first option [here](https://github.com/emschwartz/warp/commit/45cf5f802f7a32dc1056c3e00794d1301b7dcefd) but can't seem to figure out why the `tracing` `Span` isn't being propagated all the way through. If anyone has ideas, I'd be very open to suggestions!

Fix patch:
diff --git a/Cargo.toml b/Cargo.toml
index d52eb83bb..f4273f024 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -43,6 +43,8 @@ tokio-rustls = { version = "0.13.1", optional = true }
 
 [dev-dependencies]
 pretty_env_logger = "0.4"
+tracing-subscriber = "0.2.7"
+tracing-log = "0.1"
 serde_derive = "1.0"
 handlebars = "3.0.0"
 tokio = { version = "0.2", features = ["macros"] }
diff --git a/examples/README.md b/examples/README.md
index 3f5ecb95e..2c7ddc2b4 100644
--- a/examples/README.md
+++ b/examples/README.md
@@ -39,3 +39,7 @@ Hooray! `warp` also includes built-in support for WebSockets
 ### Autoreloading
 
 - [`autoreload.rs`](./autoreload.rs) - Change some code and watch the server reload automatically!
+
+### Debugging
+
+- [`tracing.rs`](./tracing.rs) - Warp has built-in support for rich diagnostics with [`tracing`](https://docs.rs/tracing)!
\ No newline at end of file
diff --git a/examples/tracing.rs b/examples/tracing.rs
new file mode 100644
index 000000000..1e0ecd384
--- /dev/null
+++ b/examples/tracing.rs
@@ -0,0 +1,59 @@
+//! [`tracing`] is a framework for instrumenting Rust programs to
+//! collect scoped, structured, and async-aware diagnostics. This example
+//! demonstrates how the `warp::trace` module can be used to instrument `warp`
+//! applications with `tracing`.
+//!
+//! [`tracing`]: https://crates.io/tracing
+#![deny(warnings)]
+use tracing_subscriber::fmt::format::FmtSpan;
+use warp::Filter;
+
+#[tokio::main]
+async fn main() {
+    // Filter traces based on the RUST_LOG env var, or, if it's not set,
+    // default to show the output of the example.
+    let filter = std::env::var("RUST_LOG").unwrap_or_else(|_| "tracing=info,warp=debug".to_owned());
+
+    // Configure the default `tracing` subscriber.
+    // The `fmt` subscriber from the `tracing-subscriber` crate logs `tracing`
+    // events to stdout. Other subscribers are available for integrating with
+    // distributed tracing systems such as OpenTelemetry.
+    tracing_subscriber::fmt()
+        // Use the filter we built above to determine which traces to record.
+        .with_env_filter(filter)
+        // Record an event when each span closes. This can be used to time our
+        // routes' durations!
+        .with_span_events(FmtSpan::CLOSE)
+        .init();
+
+    let hello = warp::path("hello")
+        .and(warp::get())
+        // When the `hello` route is called, emit a `tracing` event.
+        .map(|| {
+            tracing::info!("saying hello...");
+            "Hello, World!"
+        })
+        // Wrap the route in a `tracing` span to add the route's name as context
+        // to any events that occur inside it.
+        .with(warp::trace::named("hello"));
+
+    let goodbye = warp::path("goodbye")
+        .and(warp::get())
+        .map(|| {
+            tracing::info!("saying goodbye...");
+            "So long and thanks for all the fish!"
+        })
+        // We can also provide our own custom `tracing` spans to wrap a route.
+        .with(warp::trace(|info| {
+            // Construct our own custom span for this route.
+            tracing::info_span!("goodbye", req.path = ?info.path())
+        }));
+
+    let routes = hello
+        .or(goodbye)
+        // Wrap all the routes with a filter that creates a `tracing` span for
+        // each request we receive, including data about the request.
+        .with(warp::trace::request());
+
+    warp::serve(routes).run(([127, 0, 0, 1], 3030)).await;
+}
diff --git a/src/filters/mod.rs b/src/filters/mod.rs
index 9aee786cf..4e7a9208a 100644
--- a/src/filters/mod.rs
+++ b/src/filters/mod.rs
@@ -21,6 +21,7 @@ pub mod path;
 pub mod query;
 pub mod reply;
 pub mod sse;
+pub mod trace;
 #[cfg(feature = "websocket")]
 pub mod ws;
 
diff --git a/src/filters/trace.rs b/src/filters/trace.rs
new file mode 100644
index 000000000..7a0f63459
--- /dev/null
+++ b/src/filters/trace.rs
@@ -0,0 +1,308 @@
+//! [`tracing`] filters.
+//!
+//! [`tracing`] is a framework for instrumenting Rust programs to
+//! collect scoped, structured, and async-aware diagnostics. This module
+//! provides a set of filters for instrumenting Warp applications with `tracing`
+//! spans. [`Spans`] can be used to associate individual events  with a request,
+//! and track contexts through the application.
+//!
+//! [`tracing`]: https://crates.io/tracing
+//! [`Spans`]: https://docs.rs/tracing/latest/tracing/#spans
+use tracing::Span;
+
+use std::net::SocketAddr;
+
+use http::{self, header};
+
+use crate::filter::{Filter, WrapSealed};
+use crate::reject::IsReject;
+use crate::reply::Reply;
+use crate::route::Route;
+
+use self::internal::WithTrace;
+
+/// Create a wrapping filter that instruments every request with a `tracing`
+/// [`Span`] at the [`INFO`] level, containing a summary of the request.
+/// Additionally, if the [`DEBUG`] level is enabled, the span will contain an
+/// event recording the request's headers.
+///
+/// # Example
+///
+/// ```
+/// use warp::Filter;
+///
+/// let route = warp::any()
+///     .map(warp::reply)
+///     .with(warp::trace::request());
+/// ```
+///
+/// [`Span`]: https://docs.rs/tracing/latest/tracing/#spans
+/// [`INFO`]: https://docs.rs/tracing/0.1.16/tracing/struct.Level.html#associatedconstant.INFO
+/// [`DEBUG`]: https://docs.rs/tracing/0.1.16/tracing/struct.Level.html#associatedconstant.DEBUG
+pub fn request() -> Trace<impl Fn(Info) -> Span + Clone> {
+    use tracing::field::{display, Empty};
+    trace(|info: Info| {
+        let span = tracing::info_span!(
+            "request",
+            remote.addr = Empty,
+            method = %info.method(),
+            path = %info.path(),
+            version = ?info.route.version(),
+            referer = Empty,
+        );
+
+        // Record optional fields.
+        if let Some(remote_addr) = info.remote_addr() {
+            span.record("remote.addr", &display(remote_addr));
+        }
+
+        if let Some(referer) = info.referer() {
+            span.record("referer", &display(referer));
+        }
+
+        // The the headers are, potentially, quite long, so let's record them in
+        // an event within the generated span, rather than including them as
+        // context on *every* request.
+        tracing::debug!(parent: &span, headers = ?info.headers(), "received request");
+
+        span
+    })
+}
+
+/// Create a wrapping filter that instruments every request with a custom
+/// `tracing` [`Span`] provided by a function.
+///
+///
+/// # Example
+///
+/// ```
+/// use warp::Filter;
+///
+/// let route = warp::any()
+///     .map(warp::reply)
+///     .with(warp::trace(|info| {
+///         // Create a span using tracing macros
+///         tracing::info_span!(
+///             "request",
+///             method = %info.method(),
+///             path = %info.path(),
+///         )
+///     }));
+/// ```
+///
+/// [`Span`]: https://docs.rs/tracing/latest/tracing/#spans
+pub fn trace<F>(func: F) -> Trace<F>
+where
+    F: Fn(Info) -> Span + Clone,
+{
+    Trace { func }
+}
+
+/// Create a wrapping filter that instruments every request with a `tracing`
+/// [`Span`] at the [`DEBUG`] level representing a named context.
+///
+/// This can be used to instrument multiple routes with their own sub-spans in a
+/// per-request trace.
+///
+/// # Example
+///
+/// ```
+/// use warp::Filter;
+///
+/// let hello = warp::path("hello")
+///     .map(warp::reply)
+///     .with(warp::trace::named("hello"));
+///
+/// let goodbye = warp::path("goodbye")
+///     .map(warp::reply)
+///     .with(warp::trace::named("goodbye"));
+///
+/// let routes = hello.or(goodbye);
+/// ```
+///
+/// [`Span`]: https://docs.rs/tracing/latest/tracing/#spans
+/// [`DEBUG`]: https://docs.rs/tracing/0.1.16/tracing/struct.Level.html#associatedconstant.DEBUG
+pub fn named(name: &'static str) -> Trace<impl Fn(Info<'_>) -> Span + Copy> {
+    trace(move |_| tracing::debug_span!("context", "{}", name,))
+}
+
+/// Decorates a [`Filter`](crate::Filter) to create a [`tracing`] [span] for
+/// requests and responses.
+///
+/// [`tracing`]: https://crates.io/tracing
+/// [span]: https://docs.rs/tracing/latest/tracing/#spans
+#[derive(Clone, Copy, Debug)]
+pub struct Trace<F> {
+    func: F,
+}
+
+/// Information about the request/response that can be used to prepare log lines.
+#[allow(missing_debug_implementations)]
+pub struct Info<'a> {
+    route: &'a Route,
+}
+
+impl<FN, F> WrapSealed<F> for Trace<FN>
+where
+    FN: Fn(Info) -> Span + Clone + Send,
+    F: Filter + Clone + Send,
+    F::Extract: Reply,
+    F::Error: IsReject,
+{
+    type Wrapped = WithTrace<FN, F>;
+
+    fn wrap(&self, filter: F) -> Self::Wrapped {
+        WithTrace {
+            filter,
+            trace: self.clone(),
+        }
+    }
+}
+
+impl<'a> Info<'a> {
+    /// View the remote `SocketAddr` of the request.
+    pub fn remote_addr(&self) -> Option<SocketAddr> {
+        self.route.remote_addr()
+    }
+
+    /// View the `http::Method` of the request.
+    pub fn method(&self) -> &http::Method {
+        self.route.method()
+    }
+
+    /// View the URI path of the request.
+    pub fn path(&self) -> &str {
+        self.route.full_path()
+    }
+
+    /// View the `http::Version` of the request.
+    pub fn version(&self) -> http::Version {
+        self.route.version()
+    }
+
+    /// View the referer of the request.
+    pub fn referer(&self) -> Option<&str> {
+        self.route
+            .headers()
+            .get(header::REFERER)
+            .and_then(|v| v.to_str().ok())
+    }
+
+    /// View the user agent of the request.
+    pub fn user_agent(&self) -> Option<&str> {
+        self.route
+            .headers()
+            .get(header::USER_AGENT)
+            .and_then(|v| v.to_str().ok())
+    }
+
+    /// View the host of the request
+    pub fn host(&self) -> Option<&str> {
+        self.route
+            .headers()
+            .get(header::HOST)
+            .and_then(|v| v.to_str().ok())
+    }
+
+    /// View the request headers.
+    pub fn headers(&self) -> &http::HeaderMap {
+        self.route.headers()
+    }
+}
+
+mod internal {
+    use futures::{future::Inspect, future::MapOk, FutureExt, TryFutureExt};
+
+    use super::{Info, Trace};
+    use crate::filter::{Filter, FilterBase, Internal};
+    use crate::reject::IsReject;
+    use crate::reply::Reply;
+    use crate::reply::Response;
+    use crate::route;
+
+    #[allow(missing_debug_implementations)]
+    pub struct Traced(pub(super) Response);
+
+    impl Reply for Traced {
+        #[inline]
+        fn into_response(self) -> Response {
+            self.0
+        }
+    }
+
+    #[allow(missing_debug_implementations)]
+    #[derive(Clone, Copy)]
+    pub struct WithTrace<FN, F> {
+        pub(super) filter: F,
+        pub(super) trace: Trace<FN>,
+    }
+
+    use tracing::Span;
+    use tracing_futures::{Instrument, Instrumented};
+
+    fn finished_logger<E: IsReject>(reply: &Result<(Traced,), E>) {
+        match reply {
+            Ok((Traced(resp),)) => {
+                tracing::info!(target: "warp::filters::trace", status = resp.status().as_u16(), "finished processing with success");
+            }
+            Err(e) if e.status().is_server_error() => {
+                tracing::error!(
+                    target: "warp::filters::trace",
+                    status = e.status().as_u16(),
+                    error = ?e,
+                    "unable to process request (internal error)"
+                );
+            }
+            Err(e) if e.status().is_client_error() => {
+                tracing::warn!(
+                    target: "warp::filters::trace",
+                    status = e.status().as_u16(),
+                    error = ?e,
+                    "unable to serve request (client error)"
+                );
+            }
+            Err(e) => {
+                // Either informational or redirect
+                tracing::info!(
+                    target: "warp::filters::trace",
+                    status = e.status().as_u16(),
+                    result = ?e,
+                    "finished processing with status"
+                );
+            }
+        }
+    }
+
+    fn convert_reply<R: Reply>(reply: R) -> (Traced,) {
+        (Traced(reply.into_response()),)
+    }
+
+    impl<FN, F> FilterBase for WithTrace<FN, F>
+    where
+        FN: Fn(Info) -> Span + Clone + Send,
+        F: Filter + Clone + Send,
+        F::Extract: Reply,
+        F::Error: IsReject,
+    {
+        type Extract = (Traced,);
+        type Error = F::Error;
+        type Future = Instrumented<
+            Inspect<
+                MapOk<F::Future, fn(F::Extract) -> Self::Extract>,
+                fn(&Result<Self::Extract, F::Error>),
+            >,
+        >;
+
+        fn filter(&self, _: Internal) -> Self::Future {
+            let span = route::with(|route| (self.trace.func)(Info { route }));
+            let _entered = span.enter();
+
+            tracing::info!(target: "warp::filters::trace", "processing request");
+            self.filter
+                .filter(Internal)
+                .map_ok(convert_reply as fn(F::Extract) -> Self::Extract)
+                .inspect(finished_logger as fn(&Result<Self::Extract, F::Error>))
+                .instrument(span.clone())
+        }
+    }
+}
diff --git a/src/lib.rs b/src/lib.rs
index d19343aec..28874f088 100644
--- a/src/lib.rs
+++ b/src/lib.rs
@@ -143,6 +143,9 @@ pub use self::filters::{
     // query() function
     query::query,
     sse,
+    trace,
+    // trace() function
+    trace::trace,
 };
 // ws() function
 #[cfg(feature = "websocket")]


Test patch:
diff --git a/tests/tracing.rs b/tests/tracing.rs
new file mode 100644
index 000000000..0ae88fbc3
--- /dev/null
+++ b/tests/tracing.rs
@@ -0,0 +1,48 @@
+use warp::Filter;
+
+#[tokio::test]
+async fn uses_tracing() {
+    // Setup a log subscriber (responsible to print to output)
+    let subscriber = tracing_subscriber::fmt::Subscriber::builder()
+        .with_env_filter("trace")
+        .without_time()
+        .finish();
+
+    // Set the previously created subscriber as the global subscriber
+    tracing::subscriber::set_global_default(subscriber).unwrap();
+    // Redirect normal log messages to the tracing subscriber
+    tracing_log::LogTracer::init().unwrap();
+
+    // Start a span with some metadata (fields)
+    let span = tracing::info_span!("app", domain = "www.example.org");
+    let _guard = span.enter();
+
+    log::info!("logged using log macro");
+
+    let ok = warp::any()
+        .map(|| {
+            tracing::info!("printed for every request");
+        })
+        .untuple_one()
+        .and(warp::path("aa"))
+        .map(|| {
+            tracing::info!("only printed when path '/aa' matches");
+        })
+        .untuple_one()
+        .map(warp::reply)
+        // Here we add the tracing logger which will ensure that all requests has a span with
+        // useful information about the request (method, url, version, remote_addr, etc.)
+        .with(warp::trace::request());
+
+    tracing::info!("logged using tracing macro");
+
+    // Send a request for /
+    let req = warp::test::request();
+    let resp = req.reply(&ok);
+    assert_eq!(resp.await.status(), 404);
+
+    // Send a request for /aa
+    let req = warp::test::request().path("/aa");
+    let resp = req.reply(&ok);
+    assert_eq!(resp.await.status(), 200);
+}