diff --git a/core/lib/src/erased.rs b/core/lib/src/erased.rs index 94dcf4f3a5..964f954dda 100644 --- a/core/lib/src/erased.rs +++ b/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> - ) -> Option { + ) -> Option<(T, Box)> + ) -> Option<(T, ErasedIoHandler)> { let parent: Arc = self._request.clone(); - let io: Option> = { + let io: Option<(T, Box)> = { 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 })) } } diff --git a/core/lib/src/lifecycle.rs b/core/lib/src/lifecycle.rs index c3bc5c48c4..d34f4b6b8f 100644 --- a/core/lib/src/lifecycle.rs +++ b/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(name: Option<&str>, run: F) -> Option { 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 { } pub(crate) fn extract_io_handler<'r>( - request: &Request<'_>, + request: &'r Request<'_>, response: &mut Response<'r>, // io_stream: impl Future> + Send, - ) -> Option> { + ) -> Option<(String, Box)> { 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 { // // 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 { req: &'r Request<'s> ) -> Result, Option> { 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)) } } diff --git a/core/lib/src/outcome.rs b/core/lib/src/outcome.rs index 35e67247dc..35521aa36a 100644 --- a/core/lib/src/outcome.rs +++ b/core/lib/src/outcome.rs @@ -86,10 +86,6 @@ //! a type of `Option`. 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 { /// Contains the success value. Success(S), @@ -710,48 +706,6 @@ crate::export! { } } -impl Outcome { - #[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 fmt::Debug for Outcome { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - write!(f, "Outcome::{}", self.dbg_str()) - } -} - -impl fmt::Display for Outcome { - 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 { /// The type to use when returning an `Outcome::Error`. diff --git a/core/lib/src/request/request.rs b/core/lib/src/request/request.rs index 4874b21674..314483481d 100644 --- a/core/lib/src/request/request.rs +++ b/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) -> Segments<'_, Path> { + pub fn routed_segments(&self, range: RangeFrom) -> 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 { diff --git a/core/lib/src/response/response.rs b/core/lib/src/response/response.rs index e3b266f014..7abdaecafc 100644 --- a/core/lib/src/response/response.rs +++ b/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>( &mut self, protocols: I diff --git a/core/lib/src/router/matcher.rs b/core/lib/src/router/matcher.rs index 2d1ee14f1c..1555eae617 100644 --- a/core/lib/src/router/matcher.rs +++ b/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, diff --git a/core/lib/src/server.rs b/core/lib/src/server.rs index c90d0234b6..6c74f9cb09 100644 --- a/core/lib/src/server.rs +++ b/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 = std::result::Result; impl Rocket { #[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 { 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 { ).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 { } } -async fn io_handler_task(stream: S, mut handler: ErasedIoHandler) +#[tracing::instrument("upgrade", skip_all, fields(protocol = proto))] +async fn io_handler_task(proto: String, stream: S, mut handler: ErasedIoHandler) where S: Future> { 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 { } 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]); diff --git a/core/lib/src/trace/subscriber.rs b/core/lib/src/trace/subscriber.rs index 06ac304c5e..80b36806b5 100644 --- a/core/lib/src/trace/subscriber.rs +++ b/core/lib/src/trace/subscriber.rs @@ -59,7 +59,7 @@ pub(crate) fn init(config: Option<&Config>) { pub(crate) struct Data { // start: Instant, - map: TinyVec<[(&'static str, String); 2]>, + map: TinyVec<[(&'static str, String); 3]>, } impl Data { @@ -156,7 +156,7 @@ impl LookupSpan<'a>> RocketFmt { fn indent(&self) -> &'static str { static INDENT: &[&str] = &["", " ", " "]; - INDENT.get(self.depth()).copied().unwrap_or("--") + INDENT.get(self.depth()).copied().unwrap_or(" ") } fn marker(&self) -> &'static str { @@ -168,14 +168,6 @@ impl LookupSpan<'a>> RocketFmt { self.depth.load(Ordering::Acquire) as usize } - // fn increase_depth(&self) { - // self.depth.fetch_add(1, Ordering::AcqRel); - // } - // - // fn decrease_depth(&self) { - // self.depth.fetch_sub(1, Ordering::AcqRel); - // } - fn style(&self, metadata: &Metadata<'_>) -> Style { match *metadata.level() { Level::ERROR => self.default_style.red(), @@ -229,12 +221,17 @@ impl LookupSpan<'a>> RocketFmt { if message.is_some() && fields.len() > 1 { print!("{}{} ", self.indent(), "++".paint(style).dim()); - self.print_compact_fields(metadata, data) + self.println_compact_fields(metadata, data) } else if message.is_none() && !fields.is_empty() { - self.print_compact_fields(metadata, data); + self.println_compact_fields(metadata, data); } } + fn println_compact_fields(&self, metadata: &Metadata<'_>, data: F) { + self.print_compact_fields(metadata, data); + println!(); + } + fn print_compact_fields(&self, metadata: &Metadata<'_>, data: F) { let key_style = self.style(metadata).bold(); let val_style = self.style(metadata).primary(); @@ -248,8 +245,6 @@ impl LookupSpan<'a>> RocketFmt { printed = true; } }); - - println!(); } fn print_fields(&self, metadata: &Metadata<'_>, fields: F) @@ -285,25 +280,44 @@ impl LookupSpan<'a>> Layer for RocketFmt { } } - fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) { - let span = ctx.span(id).expect("new_span: span does not exist"); + fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctxt: Context<'_, S>) { let data = Data::new(attrs); - match span.metadata().name() { - "config" => println!("configured for {}", &data["profile"]), - name => { - self.print_prefix(span.metadata()); - print!("{name} "); + let span = ctxt.span(id).expect("new_span: span does not exist"); + let style = self.style(span.metadata()); + if &data["count"] != "0" { + let name = span.name(); + let emoji = match name { + "config" => "🔧 ", + "routes" => "📬 ", + "catchers" => "🚧 ", + "fairings" => "📦 ", + "shield" => "🛡️ ", + _ => "", + }; + + self.print_prefix(span.metadata()); + print!("{}{}", emoji.paint(style).emoji(), name.paint(style).bold()); + if !attrs.fields().is_empty() { + print!(" {}", "(".paint(style)); self.print_compact_fields(span.metadata(), attrs); + print!("{}", ")".paint(style)); } + + println!(); } span.extensions_mut().replace(data); } fn on_record(&self, id: &Id, values: &Record<'_>, ctxt: Context<'_, S>) { - let metadata = ctxt.span(id).unwrap().metadata(); - self.print_prefix(metadata); - self.print_compact_fields(metadata, values); + let span = ctxt.span(id).expect("new_span: span does not exist"); + match span.extensions_mut().get_mut::() { + Some(data) => values.record(data), + None => span.extensions_mut().insert(Data::new(values)), + } + + self.print_prefix(span.metadata()); + self.println_compact_fields(span.metadata(), values); } fn on_enter(&self, _: &Id, _: Context<'_, S>) { diff --git a/core/lib/src/trace/traceable.rs b/core/lib/src/trace/traceable.rs index 605a4f36a8..74ab1593c2 100644 --- a/core/lib/src/trace/traceable.rs +++ b/core/lib/src/trace/traceable.rs @@ -1,5 +1,5 @@ use crate::fairing::Fairing; -use crate::{route, Catcher, Config, Route}; +use crate::{route, Catcher, Config, Response, Route}; use crate::util::Formatter; use figment::Figment; @@ -46,7 +46,7 @@ impl Traceable for Figment { event! { level, "figment", param, %source.name, - source.source = source.source.as_ref().map(|s| s.to_string()), + source.source = source.source.as_ref().map(display), } } } @@ -58,7 +58,7 @@ impl Traceable for Figment { key, replacement, %source.name, - source.source = source.source.as_ref().map(|s| s.to_string()), + source.source = source.source.as_ref().map(display), "config key `{key}` is deprecated and has no meaning" } } @@ -78,7 +78,7 @@ impl Traceable for Config { ip_header = self.ip_header.as_ref().map(|s| s.as_str()), proxy_proto_header = self.proxy_proto_header.as_ref().map(|s| s.as_str()), limits = %Formatter(|f| f.debug_map() - .entries(self.limits.limits.iter().map(|(k, v)| (k.as_str(), v.to_string()))) + .entries(self.limits.limits.iter().map(|(k, v)| (k.as_str(), display(v)))) .finish()), temp_dir = %self.temp_dir.relative().display(), keep_alive = (self.keep_alive != 0).then_some(self.keep_alive), @@ -210,6 +210,23 @@ impl Traceable for Header<'_> { impl Traceable for route::Outcome<'_> { fn trace(&self, level: Level) { - event!(level, "outcome", outcome = self.dbg_str(), status = self.status().code); + event!(level, "outcome", + outcome = match self { + Self::Success(..) => "success", + Self::Error(..) => "error", + Self::Forward(..) => "forward", + }, + status = match self { + Self::Success(r) => r.status().code, + Self::Error(s) => s.code, + Self::Forward((_, s)) => s.code, + }, + ) + } +} + +impl Traceable for Response<'_> { + fn trace(&self, level: Level) { + event!(level, "response", status = self.status().code); } }