Migrate internal diagnostics to tracing (#655)

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 }

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

src/filters/header.rs

@@ -38,7 +38,7 @@ pub fn header<T: FromStr + Send + 'static>(
     name: &'static str,
 ) -> impl Filter<Extract = One<T>, Error = Rejection> + Copy {
     filter_fn_one(move |route| {
-        log::trace!("header({:?})", name);
+        tracing::trace!("header({:?})", name);
         let route = route
             .headers()
             .get(name)
@@ -52,7 +52,7 @@ pub fn header<T: FromStr + Send + 'static>(
 pub(crate) fn header2<T: Header + Send + 'static>(
 ) -> impl Filter<Extract = One<T>, Error = Rejection> + Copy {
     filter_fn_one(move |route| {
-        log::trace!("header2({:?})", T::name());
+        tracing::trace!("header2({:?})", T::name());
         let route = route
             .headers()
             .typed_get()
@@ -80,7 +80,7 @@ where
     T: FromStr + Send + 'static,
 {
     filter_fn_one(move |route| {
-        log::trace!("optional({:?})", name);
+        tracing::trace!("optional({:?})", name);
         let result = route.headers().get(name).map(|value| {
             value
                 .to_str()
@@ -110,7 +110,7 @@ where
     T: Header + PartialEq + Clone + Send,
 {
     filter_fn(move |route| {
-        log::trace!("exact2({:?})", T::NAME);
+        tracing::trace!("exact2({:?})", T::NAME);
         route.headers()
             .typed_get::<T>()
             .and_then(|val| if val == header {
@@ -139,7 +139,7 @@ pub fn exact(
     value: &'static str,
 ) -> impl Filter<Extract = (), Error = Rejection> + Copy {
     filter_fn(move |route| {
-        log::trace!("exact?({:?}, {:?})", name, value);
+        tracing::trace!("exact?({:?}, {:?})", name, value);
         let route = route
             .headers()
             .get(name)
@@ -171,7 +171,7 @@ pub fn exact_ignore_case(
     value: &'static str,
 ) -> impl Filter<Extract = (), Error = Rejection> + Copy {
     filter_fn(move |route| {
-        log::trace!("exact_ignore_case({:?}, {:?})", name, value);
+        tracing::trace!("exact_ignore_case({:?}, {:?})", name, value);
         let route = route
             .headers()
             .get(name)
@@ -203,7 +203,7 @@ pub fn value(
     name: &'static str,
 ) -> impl Filter<Extract = One<HeaderValue>, Error = Rejection> + Copy {
     filter_fn_one(move |route| {
-        log::trace!("value({:?})", name);
+        tracing::trace!("value({:?})", name);
         let route = route
             .headers()
             .get(name)

src/filters/method.rs

@@ -131,7 +131,7 @@ where
 {
     filter_fn(move |route| {
         let method = func();
-        log::trace!("method::{:?}?: {:?}", method, route.method());
+        tracing::trace!("method::{:?}?: {:?}", method, route.method());
         if route.method() == method {
             future::ok(())
         } else {

src/filters/path.rs

@@ -179,7 +179,7 @@ where
     Exact(Opaque(p))
     /*
     segment(move |seg| {
-        log::trace!("{:?}?: {:?}", p, seg);
+        tracing::trace!("{:?}?: {:?}", p, seg);
         if seg == p {
             Ok(())
         } else {
@@ -209,7 +209,7 @@ where
         route::with(|route| {
             let p = self.0.as_ref();
             future::ready(with_segment(route, |seg| {
-                log::trace!("{:?}?: {:?}", p, seg);
+                tracing::trace!("{:?}?: {:?}", p, seg);
 
                 if seg == p {
                     Ok(())
@@ -266,7 +266,7 @@ pub fn end() -> impl Filter<Extract = (), Error = Rejection> + Copy {
 pub fn param<T: FromStr + Send + 'static>(
 ) -> impl Filter<Extract = One<T>, Error = Rejection> + Copy {
     filter_segment(|seg| {
-        log::trace!("param?: {:?}", seg);
+        tracing::trace!("param?: {:?}", seg);
         if seg.is_empty() {
             return Err(reject::not_found());
         }

src/filters/query.rs

@@ -14,12 +14,12 @@ pub fn query<T: DeserializeOwned + Send + 'static>(
 ) -> impl Filter<Extract = One<T>, Error = Rejection> + Copy {
     filter_fn_one(|route| {
         let query_string = route.query().unwrap_or_else(|| {
-            log::debug!("route was called without a query string, defaulting to empty");
+            tracing::debug!("route was called without a query string, defaulting to empty");
             ""
         });
 
         let query_encoded = serde_urlencoded::from_str(query_string).map_err(|e| {
-            log::debug!("failed to decode query string '{}': {:?}", query_string, e);
+            tracing::debug!("failed to decode query string '{}': {:?}", query_string, e);
             reject::invalid_query()
         });
         future::ready(query_encoded)