wip: request/response/outcome tracing

core/lib/src/erased.rs

@@ -140,22 +140,22 @@ impl ErasedResponse {
         f(&mut self.response)
     }
 
-    pub fn make_io_handler<'a>(
+    pub fn make_io_handler<'a, T: 'static>(
         &'a mut self,
         constructor: impl for<'r> FnOnce(
             &'r Request<'r>,
             &'a mut Response<'r>,
-        ) -> Option<Box<dyn IoHandler + 'r>>
-    ) -> Option<ErasedIoHandler> {
+        ) -> Option<(T, Box<dyn IoHandler + 'r>)>
+    ) -> Option<(T, ErasedIoHandler)> {
         let parent: Arc<ErasedRequest> = self._request.clone();
-        let io: Option<Box<dyn IoHandler + '_>> = {
+        let io: Option<(T, Box<dyn IoHandler + '_>)> = {
             let parent: &ErasedRequest = &parent;
             let parent: &'static ErasedRequest = unsafe { transmute(parent) };
             let request: &Request<'_> = &parent.request;
             constructor(request, &mut self.response)
         };
 
-        io.map(|io| ErasedIoHandler { _request: parent, io })
+        io.map(|(v, io)| (v, ErasedIoHandler { _request: parent, io }))
     }
 }
 

core/lib/src/lifecycle.rs

@@ -1,7 +1,7 @@
-use yansi::Paint;
 use futures::future::{FutureExt, Future};
 
 use crate::trace::traceable::Traceable;
+use crate::util::Formatter;
 use crate::{route, Rocket, Orbit, Request, Response, Data};
 use crate::data::IoHandler;
 use crate::http::{Method, Status, Header};
@@ -16,19 +16,17 @@ async fn catch_handle<Fut, T, F>(name: Option<&str>, run: F) -> Option<T>
 {
     macro_rules! panic_info {
         ($name:expr, $e:expr) => {{
-            match $name {
-                Some(name) => error_!("Handler {} panicked.", name.primary()),
-                None => error_!("A handler panicked.")
-            };
-
-            info_!("This is an application bug.");
-            info_!("A panic in Rust must be treated as an exceptional event.");
-            info_!("Panicking is not a suitable error handling mechanism.");
-            info_!("Unwinding, the result of a panic, is an expensive operation.");
-            info_!("Panics will degrade application performance.");
-            info_!("Instead of panicking, return `Option` and/or `Result`.");
-            info_!("Values of either type can be returned directly from handlers.");
-            warn_!("A panic is treated as an internal server error.");
+            error!(handler = name.as_ref().map(display),
+                "handler panicked\n\
+                This is an application bug.\n\
+                A panic in Rust must be treated as an exceptional event.\n\
+                Panicking is not a suitable error handling mechanism.\n\
+                Unwinding, the result of a panic, is an expensive operation.\n\
+                Panics will degrade application performance.\n\
+                Instead of panicking, return `Option` and/or `Result`.\n\
+                Values of either type can be returned directly from handlers.\n\
+                A panic is treated as an internal server error.");
+
             $e
         }}
     }
@@ -154,23 +152,29 @@ impl Rocket<Orbit> {
     }
 
     pub(crate) fn extract_io_handler<'r>(
-        request: &Request<'_>,
+        request: &'r Request<'_>,
         response: &mut Response<'r>,
         // io_stream: impl Future<Output = io::Result<IoStream>> + Send,
-    ) -> Option<Box<dyn IoHandler + 'r>> {
+    ) -> Option<(String, Box<dyn IoHandler + 'r>)> {
         let upgrades = request.headers().get("upgrade");
         let Ok(upgrade) = response.search_upgrades(upgrades) else {
-            warn_!("Request wants upgrade but no I/O handler matched.");
-            info_!("Request is not being upgraded.");
+            info!(
+                upgrades = %Formatter(|f| f.debug_list()
+                    .entries(request.headers().get("upgrade"))
+                    .finish()),
+                "request wants upgrade but no i/o handler matched\n\
+                refusing to upgrade request"
+            );
+
             return None;
         };
 
         if let Some((proto, io_handler)) = upgrade {
-            info_!("Attempting upgrade with {proto} I/O handler.");
+            let proto = proto.to_string();
             response.set_status(Status::SwitchingProtocols);
             response.set_raw_header("Connection", "Upgrade");
-            response.set_raw_header("Upgrade", proto.to_string());
-            return Some(io_handler);
+            response.set_raw_header("Upgrade", proto.clone());
+            return Some((proto, io_handler));
         }
 
         None
@@ -223,6 +227,7 @@ impl Rocket<Orbit> {
     //
     // On catcher error, the 500 error catcher is attempted. If _that_ errors,
     // the (infallible) default 500 error cather is used.
+    #[tracing::instrument("catching", skip_all, fields(status = status.code, uri = %req.uri()))]
     pub(crate) async fn dispatch_error<'r, 's: 'r>(
         &'s self,
         mut status: Status,
@@ -266,14 +271,12 @@ impl Rocket<Orbit> {
         req: &'r Request<'s>
     ) -> Result<Response<'r>, Option<Status>> {
         if let Some(catcher) = self.router.catch(status, req) {
-            warn_!("Responding with registered {} catcher.", catcher);
-            let name = catcher.name.as_deref();
-            catch_handle(name, || catcher.handler.handle(status, req)).await
+            catcher.trace_info();
+            catch_handle(catcher.name.as_deref(), || catcher.handler.handle(status, req)).await
                 .map(|result| result.map_err(Some))
                 .unwrap_or_else(|| Err(None))
         } else {
-            let code = status.code.blue().bold();
-            warn_!("No {} catcher registered. Using Rocket default.", code);
+            info!("no user catcher found: using Rocket default");
             Ok(crate::catcher::default_handler(status, req))
         }
     }

core/lib/src/outcome.rs

@@ -86,10 +86,6 @@
 //! a type of `Option<S>`. If an `Outcome` is a `Forward`, the `Option` will be
 //! `None`.
 
-use std::fmt;
-
-use yansi::{Paint, Color};
-
 use crate::{route, request, response};
 use crate::data::{self, Data, FromData};
 use crate::http::Status;
@@ -101,7 +97,7 @@ use self::Outcome::*;
 ///
 /// See the [top level documentation](crate::outcome) for detailed information.
 #[must_use]
-#[derive(Clone, Copy, PartialEq, PartialOrd, Eq, Ord, Hash)]
+#[derive(Debug, Clone, Copy, PartialEq, PartialOrd, Eq, Ord, Hash)]
 pub enum Outcome<S, E, F> {
     /// Contains the success value.
     Success(S),
@@ -710,48 +706,6 @@ crate::export! {
     }
 }
 
-impl<S, E, F> Outcome<S, E, F> {
-    #[inline]
-    pub(crate) fn dbg_str(&self) -> &'static str {
-        match self {
-            Success(..) => "Success",
-            Error(..) => "Error",
-            Forward(..) => "Forward",
-        }
-    }
-
-    #[inline]
-    fn color(&self) -> Color {
-        match self {
-            Success(..) => Color::Green,
-            Error(..) => Color::Red,
-            Forward(..) => Color::Yellow,
-        }
-    }
-}
-
-impl route::Outcome<'_> {
-    pub(crate) fn status(&self) -> Status {
-        match self {
-            Success(r) => r.status(),
-            Error(s) => *s,
-            Forward((_, s)) => *s,
-        }
-    }
-}
-
-impl<S, E, F> fmt::Debug for Outcome<S, E, F> {
-    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
-        write!(f, "Outcome::{}", self.dbg_str())
-    }
-}
-
-impl<S, E, F> fmt::Display for Outcome<S, E, F> {
-    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
-        write!(f, "{}", self.dbg_str().paint(self.color()))
-    }
-}
-
 /// Conversion trait from some type into an Outcome type.
 pub trait IntoOutcome<Outcome> {
     /// The type to use when returning an `Outcome::Error`.

core/lib/src/request/request.rs

@@ -1041,16 +1041,16 @@ impl<'r> Request<'r> {
         self.routed_segments(0..).get(n)
     }
 
-    /// Get the segments beginning at the `n`th, 0-indexed, after the mount
+    /// Get the segments beginning at the `range`, 0-indexed, after the mount
     /// point for the currently matched route, if they exist. Used by codegen.
     #[inline]
-    pub fn routed_segments(&self, n: RangeFrom<usize>) -> Segments<'_, Path> {
+    pub fn routed_segments(&self, range: RangeFrom<usize>) -> Segments<'_, Path> {
         let mount_segments = self.route()
             .map(|r| r.uri.metadata.base_len)
             .unwrap_or(0);
 
-        trace!("requesting {}.. ({}..) from {}", n.start, mount_segments, self);
-        self.uri().path().segments().skip(mount_segments + n.start)
+        trace!(name: "segments", mount_segments, range.start);
+        self.uri().path().segments().skip(mount_segments + range.start)
     }
 
     // Retrieves the pre-parsed query items. Used by matching and codegen.
@@ -1204,6 +1204,7 @@ impl fmt::Debug for Request<'_> {
     }
 }
 
+// FIXME: Remov me to identify dependent `TRACE` statements.
 impl fmt::Display for Request<'_> {
     /// Pretty prints a Request. Primarily used by Rocket's logging.
     fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {

core/lib/src/response/response.rs

@@ -789,9 +789,9 @@ impl<'r> Response<'r> {
     }
 
     /// Returns `Ok(Some(_))` if `self` contains a suitable handler for any of
-    /// the comma-separated protocols any of the strings in `I`. Returns
-    /// `Ok(None)` if `self` doesn't support any kind of upgrade. Returns
-    /// `Err(_)` if `protocols` is non-empty but no match was found in `self`.
+    /// the comma-separated protocol strings in `I`. Returns `Err(_)` if
+    /// `protocols` is non-empty but no match was found in `self`. If `self`
+    /// doesn't support any kind of upgrade, return `Ok(None)`.
     pub(crate) fn search_upgrades<'a, I: Iterator<Item = &'a str>>(
         &mut self,
         protocols: I

core/lib/src/router/matcher.rs

@@ -65,7 +65,9 @@ impl Route {
     /// // by default, so Rocket would route the request to `b`, not `a`.
     /// assert!(b.rank < a.rank);
     /// ```
+    #[tracing::instrument(level = "trace", name = "matching", skip_all, ret)]
     pub fn matches(&self, request: &Request<'_>) -> bool {
+        trace!(route.method = %self.method, request.method = %request.method());
         self.method == request.method()
             && paths_match(self, request)
             && queries_match(self, request)
@@ -139,7 +141,7 @@ impl Catcher {
 }
 
 fn paths_match(route: &Route, req: &Request<'_>) -> bool {
-    trace!("checking path match: route {} vs. request {}", route, req);
+    trace!(route.uri = %route.uri, request.uri = %req.uri());
     let route_segments = &route.uri.metadata.uri_segments;
     let req_segments = req.uri().path().segments();
 
@@ -169,7 +171,11 @@ fn paths_match(route: &Route, req: &Request<'_>) -> bool {
 }
 
 fn queries_match(route: &Route, req: &Request<'_>) -> bool {
-    trace!("checking query match: route {} vs. request {}", route, req);
+    trace!(
+        route.query = route.uri.query().map(display),
+        request.query = req.uri().query().map(display),
+    );
+
     if matches!(route.uri.metadata.query_color, None | Some(Color::Wild)) {
         return true;
     }
@@ -193,7 +199,11 @@ fn queries_match(route: &Route, req: &Request<'_>) -> bool {
 }
 
 fn formats_match(route: &Route, req: &Request<'_>) -> bool {
-    trace!("checking format match: route {} vs. request {}", route, req);
+    trace!(
+        route.format = route.format.as_ref().map(display),
+        request.format = req.format().map(display),
+    );
+
     let route_format = match route.format {
         Some(ref format) => format,
         None => return true,

core/lib/src/server.rs

@@ -17,12 +17,13 @@ use crate::error::log_server_error;
 use crate::data::{IoStream, RawStream};
 use crate::util::{spawn_inspect, FutureExt, ReaderStream};
 use crate::http::Status;
-use crate::trace::traceable::TraceableCollection;
+use crate::trace::traceable::{Traceable, TraceableCollection};
 
 type Result<T, E = crate::Error> = std::result::Result<T, E>;
 
 impl Rocket<Orbit> {
     #[tracing::instrument("request", skip_all, fields(
+        timestamp = time::OffsetDateTime::now_utc().unix_timestamp_nanos(),
         method = %parts.method,
         uri = %parts.uri,
         autohandled
@@ -38,7 +39,7 @@ impl Rocket<Orbit> {
             Request::from_hyp(rocket, parts, connection).unwrap_or_else(|e| e)
         });
 
-        debug_span!("headers" => request.inner().headers().iter().trace_all_debug());
+        debug_span!("request headers" => request.inner().headers().iter().trace_all_debug());
         let mut response = request.into_response(
             stream,
             |rocket, request, data| Box::pin(rocket.preprocess(request, data)),
@@ -52,10 +53,12 @@ impl Rocket<Orbit> {
         ).await;
 
         // TODO: Should upgrades be handled in dispatch?
+        response.inner().trace_info();
+        debug_span!("response headers" => response.inner().headers().iter().trace_all_debug());
         let io_handler = response.make_io_handler(Rocket::extract_io_handler);
-        if let (Some(handler), Some(upgrade)) = (io_handler, upgrade) {
+        if let (Some((proto, handler)), Some(upgrade)) = (io_handler, upgrade) {
             let upgrade = upgrade.map_ok(IoStream::from).map_err(io::Error::other);
-            tokio::task::spawn(io_handler_task(upgrade, handler));
+            tokio::task::spawn(io_handler_task(proto, upgrade, handler));
         }
 
         let mut builder = hyper::Response::builder();
@@ -80,19 +83,20 @@ impl Rocket<Orbit> {
     }
 }
 
-async fn io_handler_task<S>(stream: S, mut handler: ErasedIoHandler)
+#[tracing::instrument("upgrade", skip_all, fields(protocol = proto))]
+async fn io_handler_task<S>(proto: String, stream: S, mut handler: ErasedIoHandler)
     where S: Future<Output = io::Result<IoStream>>
 {
     let stream = match stream.await {
         Ok(stream) => stream,
-        Err(e) => return warn_!("Upgrade failed: {e}"),
+        Err(e) => return warn!(error = %e, "i/o upgrade failed"),
     };
 
-    info_!("Upgrade succeeded.");
+    info!("i/o upgrade succeeded");
     if let Err(e) = handler.take().io(stream).await {
         match e.kind() {
-            io::ErrorKind::BrokenPipe => warn!("Upgrade I/O handler was closed."),
-            e => error!("Upgrade I/O handler failed: {e}"),
+            io::ErrorKind::BrokenPipe => warn!("i/o handler closed"),
+            _ => warn!(error = %e, "i/o handler terminated unsuccessfully"),
         }
     }
 }
@@ -128,8 +132,8 @@ impl Rocket<Ignite> {
         }
 
         if cfg!(feature = "http3-preview") {
-            warn!("HTTP/3 cannot start without a valid TCP + TLS configuration.");
-            info_!("Falling back to HTTP/1 + HTTP/2 server.");
+            warn!("HTTP/3 cannot start without a valid TCP + TLS configuration.\n\
+                Falling back to HTTP/1 + HTTP/2 server.");
         }
 
         let rocket = self.into_orbit(vec![endpoint]);