wip: route tracing

core/lib/src/config/config.rs

@@ -435,5 +435,5 @@ pub fn bail_with_config_error<T>(error: figment::Error) -> T {
 #[doc(hidden)]
 // FIXME: Remove this funtion.
 pub fn pretty_print_error(error: figment::Error) {
-    error.trace()
+    error.trace_error()
 }

core/lib/src/erased.rs

@@ -77,6 +77,11 @@ impl ErasedRequest {
         ErasedRequest { _rocket: rocket, _parts: parts, request, }
     }
 
+    pub fn inner(&self) -> &Request<'_> {
+        static_assert_covariance!(Request);
+        &self.request
+    }
+
     pub async fn into_response<T, D>(
         self,
         raw_stream: D,

core/lib/src/lifecycle.rs

@@ -1,6 +1,7 @@
 use yansi::Paint;
 use futures::future::{FutureExt, Future};
 
+use crate::trace::traceable::Traceable;
 use crate::{route, Rocket, Orbit, Request, Response, Data};
 use crate::data::IoHandler;
 use crate::http::{Method, Status, Header};
@@ -96,16 +97,14 @@ impl Rocket<Orbit> {
         data: Data<'r>,
         // io_stream: impl Future<Output = io::Result<IoStream>> + Send,
     ) -> Response<'r> {
-        info!("{}:", request);
-
         // Remember if the request is `HEAD` for later body stripping.
         let was_head_request = request.method() == Method::Head;
 
         // Route the request and run the user's handlers.
         let mut response = match self.route(request, data).await {
             Outcome::Success(response) => response,
             Outcome::Forward((data, _)) if request.method() == Method::Head => {
-                info_!("Autohandling {} request.", "HEAD".primary().bold());
+                tracing::Span::current().record("autohandled", true);
 
                 // Dispatch the request again with Method `GET`.
                 request._set_method(Method::Get);
@@ -181,6 +180,11 @@ impl Rocket<Orbit> {
     /// returns success or error, or there are no additional routes to try, in
     /// which case a `Forward` with the last forwarding state is returned.
     #[inline]
+    #[tracing::instrument("routing", skip_all, fields(
+        method = %request.method(),
+        uri = %request.uri(),
+        format = request.format().map(display),
+    ))]
     async fn route<'s, 'r: 's>(
         &'s self,
         request: &'r Request<'s>,
@@ -191,7 +195,6 @@ impl Rocket<Orbit> {
         let mut status = Status::NotFound;
         for route in self.router.route(request) {
             // Retrieve and set the requests parameters.
-            info_!("Matched: {}", route);
             request.set_route(route);
 
             let name = route.name.as_deref();
@@ -200,16 +203,17 @@ impl Rocket<Orbit> {
 
             // Check if the request processing completed (Some) or if the
             // request needs to be forwarded. If it does, continue the loop
-            // (None) to try again.
-            info_!("{}", outcome.log_display());
+            route.trace_info();
+            outcome.trace_info();
             match outcome {
                 o@Outcome::Success(_) | o@Outcome::Error(_) => return o,
                 Outcome::Forward(forwarded) => (data, status) = forwarded,
             }
         }
 
-        error_!("No matching routes for {}.", request);
-        Outcome::Forward((data, status))
+        let outcome = Outcome::Forward((data, status));
+        outcome.trace_info();
+        outcome
     }
 
     // Invokes the catcher for `status`. Returns the response on success.

core/lib/src/outcome.rs

@@ -712,7 +712,7 @@ crate::export! {
 
 impl<S, E, F> Outcome<S, E, F> {
     #[inline]
-    fn dbg_str(&self) -> &'static str {
+    pub(crate) fn dbg_str(&self) -> &'static str {
         match self {
             Success(..) => "Success",
             Error(..) => "Error",
@@ -730,27 +730,16 @@ impl<S, E, F> Outcome<S, E, F> {
     }
 }
 
-pub(crate) struct Display<'a, 'r>(&'a route::Outcome<'r>);
-
-impl fmt::Display for Display<'_, '_> {
-    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
-        write!(f, "{}", "Outcome: ".primary().bold())?;
-
-        let color = self.0.color();
-        match self.0 {
-            Success(r) => write!(f, "{}({})", "Success".paint(color), r.status().primary()),
-            Error(s) => write!(f, "{}({})", "Error".paint(color), s.primary()),
-            Forward((_, s)) => write!(f, "{}({})", "Forward".paint(color), s.primary()),
+impl route::Outcome<'_> {
+    pub(crate) fn status(&self) -> Status {
+        match self {
+            Success(r) => r.status(),
+            Error(s) => *s,
+            Forward((_, s)) => *s,
         }
     }
 }
 
-impl<'r> route::Outcome<'r> {
-    pub(crate) fn log_display(&self) -> Display<'_, 'r> {
-        Display(self)
-    }
-}
-
 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())

core/lib/src/request/request.rs

@@ -1112,10 +1112,14 @@ impl<'r> Request<'r> {
                 // a security issue with Hyper, there isn't much we can do.
                 #[cfg(debug_assertions)]
                 if Origin::parse(uri.as_str()).is_err() {
-                    warn!("Hyper/Rocket URI validity discord: {:?}", uri.as_str());
-                    info_!("Hyper believes the URI is valid while Rocket disagrees.");
-                    info_!("This is likely a Hyper bug with potential security implications.");
-                    warn_!("Please report this warning to Rocket's GitHub issue tracker.");
+                    warn!(
+                        name: "uri_discord",
+                        %uri,
+                        "Hyper/Rocket URI validity discord: {uri}\n\
+                        Hyper believes the URI is valid while Rocket disagrees.\n\
+                        This is likely a Hyper bug with potential security implications.\n\
+                        Please report this warning to Rocket's GitHub issue tracker."
+                    )
                 }
 
                 Origin::new(uri.path(), uri.query().map(Cow::Borrowed))

core/lib/src/rocket.rs

@@ -563,45 +563,20 @@ impl Rocket<Build> {
         self.catchers.clone().into_iter().for_each(|c| router.add_catcher(c));
         router.finalize().map_err(ErrorKind::Collisions)?;
 
-        // Finally, freeze managed state.
+        // Finally, freeze managed state for faster access later.
         self.state.freeze();
 
         // Log everything we know: config, routes, catchers, fairings.
         // TODO: Store/print managed state type names?
         let fairings = self.fairings.unique_set();
         info_span!("config" [profile = %self.figment().profile()] => {
-            config.trace();
-            self.figment().trace();
+            config.trace_info();
+            self.figment().trace_debug();
         });
 
-        info_span!("routes" [count = self.routes.len()] => self.routes().trace_all());
-        info_span!("catchers" [count = self.catchers.len()] => self.catchers().trace_all());
-        info_span!("fairings" [count = fairings.len()] => fairings.trace_all());
-
-        // trace::all("routes", self.routes());
-        // tracing::info_span!("routes").in_scope(|| self.routes().for_each(|r| r.trace()));
-        // tracing::info_span!("catchers").in_scope(|| self.catchers().for_each(|c| c.trace()));
-        //     for header in self.policies.values() {
-        //         info!(name: "header", name = header.name().as_str(), value = header.value());
-        //     }
-        //
-        //     warn!("Detected TLS-enabled liftoff without enabling HSTS.");
-        //     warn!("Shield has enabled a default HSTS policy.");
-        //     info!("To remove this warning, configure an HSTS policy.");
-        // });
-
-        // tracing::info_span!("routes")
-        //     .in_scope(|| self.routes().for_each(|r| r.trace()));
-        //     // self.polices.values().trace();
-        //     // for header in self.policies.values() {
-        //     //     info!(name: "header", name = header.name().as_str(), value = header.value());
-        //     // }
-
-        // TODO: Store/print managed state type names?
-        // trace::collection_info!("routes" => self.routes());
-        // trace::collection_info!("catchers" => self.catchers());
-        // trace::collection_info!("fairings" => self.fairings.active_set());
-        // trace::collection_info!("state" => self.active_set());
+        info_span!("routes" [count = self.routes.len()] => self.routes().trace_all_info());
+        info_span!("catchers" [count = self.catchers.len()] => self.catchers().trace_all_info());
+        info_span!("fairings" [count = fairings.len()] => fairings.trace_all_info());
 
         // Ignite the rocket.
         let rocket: Rocket<Ignite> = Rocket(Igniting {

core/lib/src/server.rs

@@ -17,10 +17,12 @@ 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;
 
 type Result<T, E = crate::Error> = std::result::Result<T, E>;
 
 impl Rocket<Orbit> {
+    #[tracing::instrument("request", skip_all, fields(method = %parts.method, uri = %parts.uri, autohandled))]
     async fn service<T: for<'a> Into<RawStream<'a>>>(
         self: Arc<Self>,
         parts: http::request::Parts,
@@ -32,6 +34,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());
         let mut response = request.into_response(
             stream,
             |rocket, request, data| Box::pin(rocket.preprocess(request, data)),

core/lib/src/shield/shield.rs

@@ -194,7 +194,7 @@ impl Fairing for Shield {
             && !self.is_enabled::<Hsts>();
 
         info_span!("shield" [policies = self.policies.len()] => {
-            self.policies.values().trace_all();
+            self.policies.values().trace_all_info();
 
             if force_hsts {
                 warn!("Detected TLS-enabled liftoff without enabling HSTS.");

core/lib/src/trace/macros.rs

@@ -21,7 +21,6 @@ macro_rules! declare_macro {
             ($d ($t:tt)*) => ({
                 #[allow(unused_imports)]
                 use $crate::trace::macros::PaintExt as _;
-
                 $crate::tracing::$level!($d ($t)*);
             })
         }
@@ -52,4 +51,20 @@ macro_rules! declare_span_macro {
     );
 }
 
-declare_span_macro!(info_span INFO, trace_span TRACE);
+declare_span_macro!(info_span INFO, trace_span TRACE, debug_span DEBUG);
+
+macro_rules! event {
+    ($level:expr, $($args:tt)*) => {{
+        match $level {
+            $crate::tracing::Level::ERROR => event!(@$crate::tracing::Level::ERROR, $($args)*),
+            $crate::tracing::Level::WARN => event!(@$crate::tracing::Level::WARN, $($args)*),
+            $crate::tracing::Level::INFO => event!(@$crate::tracing::Level::INFO, $($args)*),
+            $crate::tracing::Level::DEBUG => event!(@$crate::tracing::Level::DEBUG, $($args)*),
+            $crate::tracing::Level::TRACE => event!(@$crate::tracing::Level::TRACE, $($args)*),
+        }
+    }};
+
+    (@$level:expr, $n:expr, $($args:tt)*) => {{
+        $crate::tracing::event!(name: $n, target: concat!("rocket::", $n), $level, $($args)*);
+    }};
+}