Add filters for emitting Tracing diagnostics

Cargo.toml

@@ -32,6 +32,8 @@ serde = "1.0"
 serde_json = "1.0"
 serde_urlencoded = "0.6"
 tokio = { version = "0.2", features = ["fs", "stream", "sync", "time"] }
+tracing = { version = "0.1", default-features = false, features = ["log", "std"] }
+tracing-futures = { version = "0.2", default-features = false, features = ["std-future"] }
 tower-service = "0.3"
 # tls is enabled by default, we don't want that yet
 tokio-tungstenite = { version = "0.10", default-features = false, optional = true }
@@ -41,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"] }

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)!

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;
+}

src/filter/service.rs

@@ -129,7 +129,7 @@ where
             Poll::Ready(Ok(ok)) => Poll::Ready(Ok(ok.into_response())),
             Poll::Pending => Poll::Pending,
             Poll::Ready(Err(err)) => {
-                log::debug!("rejected: {:?}", err);
+                tracing::debug!("rejected: {:?}", err);
                 Poll::Ready(Ok(err.into_response()))
             }
         }

src/filters/body.rs

@@ -28,7 +28,7 @@ type BoxError = Box<dyn StdError + Send + Sync>;
 pub(crate) fn body() -> impl Filter<Extract = (Body,), Error = Rejection> + Copy {
     filter_fn_one(|route| {
         future::ready(route.take_body().ok_or_else(|| {
-            log::error!("request body already taken in previous filter");
+            tracing::error!("request body already taken in previous filter");
             reject::known(BodyConsumedMultipleTimes { _p: () })
         }))
     })
@@ -51,14 +51,14 @@ pub(crate) fn body() -> impl Filter<Extract = (Body,), Error = Rejection> + Copy
 pub fn content_length_limit(limit: u64) -> impl Filter<Extract = (), Error = Rejection> + Copy {
     crate::filters::header::header2()
         .map_err(crate::filter::Internal, |_| {
-            log::debug!("content-length missing");
+            tracing::debug!("content-length missing");
             reject::length_required()
         })
         .and_then(move |ContentLength(length)| {
             if length <= limit {
                 future::ok(())
             } else {
-                log::debug!("content-length: {} is over limit {}", length, limit);
+                tracing::debug!("content-length: {} is over limit {}", length, limit);
                 future::err(reject::payload_too_large())
             }
         })
@@ -106,7 +106,7 @@ pub fn stream(
 pub fn bytes() -> impl Filter<Extract = (Bytes,), Error = Rejection> + Copy {
     body().and_then(|body: hyper::Body| {
         hyper::body::to_bytes(body).map_err(|err| {
-            log::debug!("to_bytes error: {}", err);
+            tracing::debug!("to_bytes error: {}", err);
             reject::known(BodyReadError(err))
         })
     })
@@ -144,7 +144,7 @@ pub fn bytes() -> impl Filter<Extract = (Bytes,), Error = Rejection> + Copy {
 pub fn aggregate() -> impl Filter<Extract = (impl Buf,), Error = Rejection> + Copy {
     body().and_then(|body: ::hyper::Body| {
         hyper::body::aggregate(body).map_err(|err| {
-            log::debug!("aggregate error: {}", err);
+            tracing::debug!("aggregate error: {}", err);
             reject::known(BodyReadError(err))
         })
     })
@@ -175,7 +175,7 @@ pub fn json<T: DeserializeOwned + Send>() -> impl Filter<Extract = (T,), Error =
         .and(aggregate())
         .and_then(|buf| async move {
             Json::decode(buf).map_err(|err| {
-                log::debug!("request json body error: {}", err);
+                tracing::debug!("request json body error: {}", err);
                 reject::known(BodyDeserializeError { cause: err })
             })
         })
@@ -210,7 +210,7 @@ pub fn form<T: DeserializeOwned + Send>() -> impl Filter<Extract = (T,), Error =
         .and(aggregate())
         .and_then(|buf| async move {
             Form::decode(buf).map_err(|err| {
-                log::debug!("request form body error: {}", err);
+                tracing::debug!("request form body error: {}", err);
                 reject::known(BodyDeserializeError { cause: err })
             })
         })
@@ -254,7 +254,7 @@ fn is_content_type<D: Decode>() -> impl Filter<Extract = (), Error = Rejection>
     filter_fn(move |route| {
         let (type_, subtype) = D::MIME;
         if let Some(value) = route.headers().get(CONTENT_TYPE) {
-            log::trace!("is_content_type {}/{}? {:?}", type_, subtype, value);
+            tracing::trace!("is_content_type {}/{}? {:?}", type_, subtype, value);
             let ct = value
                 .to_str()
                 .ok()
@@ -263,7 +263,7 @@ fn is_content_type<D: Decode>() -> impl Filter<Extract = (), Error = Rejection>
                 if ct.type_() == type_ && ct.subtype() == subtype {
                     future::ok(())
                 } else {
-                    log::debug!(
+                    tracing::debug!(
                         "content-type {:?} doesn't match {}/{}",
                         value,
                         type_,
@@ -272,15 +272,15 @@ fn is_content_type<D: Decode>() -> impl Filter<Extract = (), Error = Rejection>
                     future::err(reject::unsupported_media_type())
                 }
             } else {
-                log::debug!("content-type {:?} couldn't be parsed", value);
+                tracing::debug!("content-type {:?} couldn't be parsed", value);
                 future::err(reject::unsupported_media_type())
             }
         } else if D::WITH_NO_CONTENT_TYPE {
             // Optimistically assume its correct!
-            log::trace!("no content-type header, assuming {}/{}", type_, subtype);
+            tracing::trace!("no content-type header, assuming {}/{}", type_, subtype);
             future::ok(())
         } else {
-            log::debug!("no content-type found");
+            tracing::debug!("no content-type found");
             future::err(reject::unsupported_media_type())
         }
     })

src/filters/cors.rs

@@ -368,7 +368,9 @@ impl Configured {
                         return Err(Forbidden::MethodNotAllowed);
                     }
                 } else {
-                    log::trace!("preflight request missing access-control-request-method header");
+                    tracing::trace!(
+                        "preflight request missing access-control-request-method header"
+                    );
                     return Err(Forbidden::MethodNotAllowed);
                 }
 
@@ -388,7 +390,7 @@ impl Configured {
             (Some(origin), _) => {
                 // Any other method, simply check for a valid origin...
 
-                log::trace!("origin header: {:?}", origin);
+                tracing::trace!("origin header: {:?}", origin);
                 if self.is_origin_allowed(origin) {
                     Ok(Validated::Simple(origin.clone()))
                 } else {

src/filters/fs.rs

@@ -48,7 +48,7 @@ pub fn file(path: impl Into<PathBuf>) -> impl FilterClone<Extract = One<File>, E
     let path = Arc::new(path.into());
     crate::any()
         .map(move || {
-            log::trace!("file: {:?}", path);
+            tracing::trace!("file: {:?}", path);
             ArcPath(path.clone())
         })
         .and(conditionals())
@@ -96,10 +96,10 @@ fn path_from_tail(
                 .unwrap_or(false);
 
             if is_dir {
-                log::debug!("dir: appending index.html to directory path");
+                tracing::debug!("dir: appending index.html to directory path");
                 buf.push("index.html");
             }
-            log::trace!("dir: {:?}", buf);
+            tracing::trace!("dir: {:?}", buf);
             Ok(ArcPath(Arc::new(buf)))
         })
     })
@@ -110,18 +110,18 @@ fn sanitize_path(base: impl AsRef<Path>, tail: &str) -> Result<PathBuf, Rejectio
     let p = match decode(tail) {
         Ok(p) => p,
         Err(err) => {
-            log::debug!("dir: failed to decode route={:?}: {:?}", tail, err);
+            tracing::debug!("dir: failed to decode route={:?}: {:?}", tail, err);
             // FromUrlEncodingError doesn't implement StdError
             return Err(reject::not_found());
         }
     };
-    log::trace!("dir? base={:?}, route={:?}", base.as_ref(), p);
+    tracing::trace!("dir? base={:?}, route={:?}", base.as_ref(), p);
     for seg in p.split('/') {
         if seg.starts_with("..") {
-            log::warn!("dir: rejecting segment starting with '..'");
+            tracing::warn!("dir: rejecting segment starting with '..'");
             return Err(reject::not_found());
         } else if seg.contains('\\') {
-            log::warn!("dir: rejecting segment containing with backslash (\\)");
+            tracing::warn!("dir: rejecting segment containing with backslash (\\)");
             return Err(reject::not_found());
         } else {
             buf.push(seg);
@@ -150,7 +150,7 @@ impl Conditionals {
                 .map(|time| since.precondition_passes(time.into()))
                 .unwrap_or(false);
 
-            log::trace!(
+            tracing::trace!(
                 "if-unmodified-since? {:?} vs {:?} = {}",
                 since,
                 last_modified,
@@ -164,7 +164,7 @@ impl Conditionals {
         }
 
         if let Some(since) = self.if_modified_since {
-            log::trace!(
+            tracing::trace!(
                 "if-modified-since? header = {:?}, file = {:?}",
                 since,
                 last_modified
@@ -181,7 +181,7 @@ impl Conditionals {
         }
 
         if let Some(if_range) = self.if_range {
-            log::trace!("if-range? {:?} vs {:?}", if_range, last_modified);
+            tracing::trace!("if-range? {:?} vs {:?}", if_range, last_modified);
             let can_range = !if_range.is_modified(None, last_modified.as_ref());
 
             if !can_range {
@@ -265,15 +265,15 @@ fn file_reply(
         Err(err) => {
             let rej = match err.kind() {
                 io::ErrorKind::NotFound => {
-                    log::debug!("file not found: {:?}", path.as_ref().display());
+                    tracing::debug!("file not found: {:?}", path.as_ref().display());
                     reject::not_found()
                 }
                 io::ErrorKind::PermissionDenied => {
-                    log::warn!("file permission denied: {:?}", path.as_ref().display());
+                    tracing::warn!("file permission denied: {:?}", path.as_ref().display());
                     reject::known(FilePermissionError { _p: () })
                 }
                 _ => {
-                    log::error!(
+                    tracing::error!(
                         "file open error (path={:?}): {} ",
                         path.as_ref().display(),
                         err
@@ -290,7 +290,7 @@ async fn file_metadata(f: TkFile) -> Result<(TkFile, Metadata), Rejection> {
     match f.metadata().await {
         Ok(meta) => Ok((f, meta)),
         Err(err) => {
-            log::debug!("file metadata error: {}", err);
+            tracing::debug!("file metadata error: {}", err);
             Err(reject::not_found())
         }
     }
@@ -382,7 +382,7 @@ fn bytes_range(range: Option<Range>, max_len: u64) -> Result<(u64, u64), BadRang
             if start < end && end <= max_len {
                 Ok((start, end))
             } else {
-                log::trace!("unsatisfiable byte range: {}-{}/{}", start, end, max_len);
+                tracing::trace!("unsatisfiable byte range: {}-{}/{}", start, end, max_len);
                 Err(BadRange)
             }
         })
@@ -423,13 +423,13 @@ fn file_stream(
                 let n = match ready!(Pin::new(&mut f).poll_read_buf(cx, &mut buf)) {
                     Ok(n) => n as u64,
                     Err(err) => {
-                        log::debug!("file read error: {}", err);
+                        tracing::debug!("file read error: {}", err);
                         return Poll::Ready(Some(Err(err)));
                     }
                 };
 
                 if n == 0 {
-                    log::debug!("file read found EOF before expected length");
+                    tracing::debug!("file read found EOF before expected length");
                     return Poll::Ready(None);
                 }