diff --git a/core/lib/Cargo.toml b/core/lib/Cargo.toml index 1c651e44..1c3a3433 100644 --- a/core/lib/Cargo.toml +++ b/core/lib/Cargo.toml @@ -33,7 +33,7 @@ uuid = ["uuid_", "rocket_http/uuid"] tls = ["rustls", "tokio-rustls", "rustls-pemfile"] mtls = ["tls", "x509-parser"] tokio-macros = ["tokio/macros"] -trace = ["tracing-subscriber", "tinyvec", "rustls?/logging", "tokio-rustls?/logging", "multer/log"] +trace = ["tracing-subscriber", "tinyvec", "thread_local", "rustls?/logging", "tokio-rustls?/logging", "multer/log"] [dependencies] # Optional serialization dependencies. @@ -78,6 +78,7 @@ state = "0.6" # tracing tracing = { version = "0.1.40", default-features = false, features = ["std", "attributes"] } tinyvec = { version = "1.6", optional = true, features = ["std", "rustc_1_57"] } +thread_local = { version = "1.1", optional = true } [dependencies.tracing-subscriber] version = "0.3.18" diff --git a/core/lib/src/config/config.rs b/core/lib/src/config/config.rs index 30cf1434..220cabdc 100644 --- a/core/lib/src/config/config.rs +++ b/core/lib/src/config/config.rs @@ -10,7 +10,7 @@ use crate::config::{ShutdownConfig, Ident, CliColors}; use crate::request::{self, Request, FromRequest}; use crate::http::uncased::Uncased; use crate::data::Limits; -use crate::util::Formatter; +use crate::trace::traceable::Traceable; /// Rocket server configuration. /// @@ -303,98 +303,6 @@ impl Config { pub fn from(provider: T) -> Self { Self::try_from(provider).unwrap_or_else(bail_with_config_error) } - - #[cfg(feature = "secrets")] - fn known_secret_key_used(&self) -> bool { - const KNOWN_SECRET_KEYS: &[&str] = &[ - "hPRYyVRiMyxpw5sBB1XeCMN1kFsDCqKvBi2QJxBVHQk=" - ]; - - KNOWN_SECRET_KEYS.iter().any(|&key_str| { - let value = figment::value::Value::from(key_str); - self.secret_key == value.deserialize().expect("known key is valid") - }) - } - - #[tracing::instrument(name = "config", skip_all, fields(profile = %figment.profile()))] - pub(crate) fn pretty_print(&self, figment: &Figment) { - info! { - name: "values", - http2 = cfg!(feature = "http2"), - log_level = self.log_level.map(|l| l.as_str()), - cli_colors = %self.cli_colors, - workers = self.workers, - max_blocking = self.max_blocking, - ident = %self.ident, - 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()))) - .finish()), - temp_dir = %self.temp_dir.relative().display(), - keep_alive = (self.keep_alive != 0).then_some(self.keep_alive), - shutdown.ctrlc = self.shutdown.ctrlc, - shutdown.signals = %{ - #[cfg(not(unix))] { - "disabled (not unix)" - } - - #[cfg(unix)] { - Formatter(|f| f.debug_set() - .entries(self.shutdown.signals.iter().map(|s| s.as_str())) - .finish()) - } - }, - shutdown.grace = self.shutdown.grace, - shutdown.mercy = self.shutdown.mercy, - shutdown.force = self.shutdown.force, - }; - - for param in Self::PARAMETERS { - if let Some(source) = figment.find_metadata(param) { - trace! { - param, - %source.name, - source.source = source.source.as_ref().map(|s| s.to_string()), - } - } - } - - // Check for now deprecated config values. - for (key, replacement) in Self::DEPRECATED_KEYS { - if let Some(source) = figment.find_metadata(key) { - warn! { - name: "deprecated", - key, - replacement, - %source.name, - source.source = source.source.as_ref().map(|s| s.to_string()), - "config key `{key}` is deprecated and has no meaning" - } - } - } - - #[cfg(feature = "secrets")] { - if !self.secret_key.is_provided() { - warn! { - name: "volatile_secret_key", - "secrets enabled without configuring a stable `secret_key`; \ - private/signed cookies will become unreadable after restarting; \ - disable the `secrets` feature or configure a `secret_key`; \ - this becomes a hard error in non-debug profiles", - } - } - - if self.known_secret_key_used() { - warn! { - name: "insecure_secret_key", - "The configured `secret_key` is exposed and insecure. \ - The configured key is publicly published and thus insecure. \ - Try generating a new key with `head -c64 /dev/urandom | base64`." - } - } - } - } } /// Associated constants for default profiles. @@ -416,11 +324,6 @@ impl Config { /// Associated constants for stringy versions of configuration parameters. impl Config { - /// The stringy parameter name for setting/extracting [`Config::profile`]. - /// - /// This isn't `pub` because setting it directly does nothing. - const PROFILE: &'static str = "profile"; - /// The stringy parameter name for setting/extracting [`Config::workers`]. pub const WORKERS: &'static str = "workers"; @@ -465,12 +368,22 @@ impl Config { Self::CLI_COLORS, ]; + /// The stringy parameter name for setting/extracting [`Config::profile`]. + /// + /// This isn't `pub` because setting it directly does nothing. + const PROFILE: &'static str = "profile"; + /// An array of deprecated stringy parameter names. - const DEPRECATED_KEYS: &'static [(&'static str, Option<&'static str>)] = &[ + pub(crate) const DEPRECATED_KEYS: &'static [(&'static str, Option<&'static str>)] = &[ ("env", Some(Self::PROFILE)), ("log", Some(Self::LOG_LEVEL)), ("read_timeout", None), ("write_timeout", None), ]; + /// Secret keys that have been used in docs or leaked otherwise. + #[cfg(feature = "secrets")] + pub(crate) const KNOWN_SECRET_KEYS: &'static [&'static str] = &[ + "hPRYyVRiMyxpw5sBB1XeCMN1kFsDCqKvBi2QJxBVHQk=" + ]; } impl Provider for Config { @@ -520,34 +433,7 @@ pub fn bail_with_config_error(error: figment::Error) -> T { } #[doc(hidden)] +// FIXME: Remove this funtion. pub fn pretty_print_error(error: figment::Error) { - use figment::error::{OneOf as V, Kind::*}; - - for e in error { - let span = tracing::error_span! { - "error: configuration", - key = (!e.path.is_empty()).then_some(&e.path).and_then(|path| { - let (profile, metadata) = (e.profile.as_ref()?, e.metadata.as_ref()?); - Some(metadata.interpolate(profile, path)) - }), - source.name = e.metadata.as_ref().map(|m| &*m.name), - source.source = e.metadata.as_ref().and_then(|m| Some(m.source.as_ref()?.to_string())), - }; - - let _scope = span.enter(); - match e.kind { - Message(message) => error!(message), - InvalidType(actual, expected) => error!(name: "invalid type", %actual, expected), - InvalidValue(actual, expected) => error!(name: "invalid value", %actual, expected), - InvalidLength(actual, expected) => error!(name: "invalid length", %actual, expected), - UnknownVariant(actual, v) => error!(name: "unknown variant", actual, expected = %V(v)), - UnknownField(actual, v) => error!(name: "unknown field", actual, expected = %V(v)), - UnsupportedKey(actual, v) => error!(name: "unsupported key", %actual, expected = &*v), - MissingField(value) => error!(name: "missing field", value = &*value), - DuplicateField(value) => error!(name: "duplicate field", value), - ISizeOutOfRange(value) => error!(name: "out of range signed integer", value), - USizeOutOfRange(value) => error!(name: "out of range unsigned integer", value), - Unsupported(value) => error!(name: "unsupported type", %value), - } - } + error.trace_error() } diff --git a/core/lib/src/erased.rs b/core/lib/src/erased.rs index 1c0900a8..964f954d 100644 --- a/core/lib/src/erased.rs +++ b/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( self, raw_stream: D, @@ -135,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/fairing/fairings.rs b/core/lib/src/fairing/fairings.rs index 59a1839c..0d508372 100644 --- a/core/lib/src/fairing/fairings.rs +++ b/core/lib/src/fairing/fairings.rs @@ -47,6 +47,22 @@ impl Fairings { .chain(self.shutdown.iter()) } + pub fn unique_set(&self) -> Vec<&dyn Fairing> { + iter!(self, self.active().collect::>().into_iter()) + .map(|v| v.1) + .collect() + // .into_iter() + // .map(|i| ) + // if !active_fairings.is_empty() { + // tracing::info_span!("fairings").in_scope(|| { + // for (_, fairing) in iter!(self, active_fairings.into_iter()) { + // let (name, kind) = (fairing.info().name, fairing.info().kind); + // info!(name: "fairing", name, %kind) + // } + // }); + // } + } + pub fn add(&mut self, fairing: Box) { let this = &fairing; let this_info = this.info(); @@ -166,18 +182,6 @@ impl Fairings { false => Err(&self.failures) } } - - pub fn pretty_print(&self) { - let active_fairings = self.active().collect::>(); - if !active_fairings.is_empty() { - tracing::info_span!("fairings").in_scope(|| { - for (_, fairing) in iter!(self, active_fairings.into_iter()) { - let (name, kind) = (fairing.info().name, fairing.info().kind); - info!(name: "fairing", name, %kind) - } - }); - } - } } impl std::fmt::Debug for Fairings { diff --git a/core/lib/src/fs/server.rs b/core/lib/src/fs/server.rs index 45300db5..faa95f11 100644 --- a/core/lib/src/fs/server.rs +++ b/core/lib/src/fs/server.rs @@ -142,20 +142,20 @@ impl FileServer { /// ``` #[track_caller] pub fn new>(path: P, options: Options) -> Self { - use crate::yansi::Paint; - let path = path.as_ref(); if !options.contains(Options::Missing) { if !options.contains(Options::IndexFile) && !path.is_dir() { - let path = path.display(); - error!("FileServer path '{}' is not a directory.", path.primary()); - warn_!("Aborting early to prevent inevitable handler error."); - panic!("invalid directory: refusing to continue"); + error!(path = %path.display(), + "FileServer path does not point to a directory.\n\ + Aborting early to prevent inevitable handler runtime errors."); + + panic!("invalid directory path: refusing to continue"); } else if !path.exists() { - let path = path.display(); - error!("FileServer path '{}' is not a file.", path.primary()); - warn_!("Aborting early to prevent inevitable handler error."); - panic!("invalid file: refusing to continue"); + error!(path = %path.display(), + "FileServer path does not point to a file.\n\ + Aborting early to prevent inevitable handler runtime errors."); + + panic!("invalid file path: refusing to continue"); } } diff --git a/core/lib/src/fs/temp_file.rs b/core/lib/src/fs/temp_file.rs index 5a61298b..0464dd46 100644 --- a/core/lib/src/fs/temp_file.rs +++ b/core/lib/src/fs/temp_file.rs @@ -554,17 +554,16 @@ impl<'r> FromData<'r> for Capped> { type Error = io::Error; async fn from_data(req: &'r Request<'_>, data: Data<'r>) -> data::Outcome<'r, Self> { - use yansi::Paint; - let has_form = |ty: &ContentType| ty.is_form_data() || ty.is_form(); if req.content_type().map_or(false, has_form) { - let (tf, form) = ("TempFile<'_>".primary(), "Form>".primary()); - warn_!("Request contains a form that will not be processed."); - info_!("Bare `{}` data guard writes raw, unprocessed streams to disk.", tf); - info_!("Did you mean to use `{}` instead?", form); + warn!(request.content_type = req.content_type().map(display), + "Request contains a form that is not being processed.\n\ + Bare `TempFile` data guard writes raw, unprocessed streams to disk\n\ + Perhaps you meant to use `Form>` instead?"); } - TempFile::from(req, data, None, req.content_type().cloned()).await + TempFile::from(req, data, None, req.content_type().cloned()) + .await .or_error(Status::BadRequest) } } diff --git a/core/lib/src/lifecycle.rs b/core/lib/src/lifecycle.rs index 3508e1bf..72eac73c 100644 --- a/core/lib/src/lifecycle.rs +++ b/core/lib/src/lifecycle.rs @@ -1,7 +1,8 @@ -use yansi::Paint; use futures::future::{FutureExt, Future}; -use crate::{route, Rocket, Orbit, Request, Response, Data}; +use crate::{route, catcher, Rocket, Orbit, Request, Response, Data}; +use crate::trace::traceable::Traceable; +use crate::util::Formatter; use crate::data::IoHandler; use crate::http::{Method, Status, Header}; use crate::outcome::Outcome; @@ -15,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.") - }; + 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."); - 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."); $e }} } @@ -96,8 +95,6 @@ impl Rocket { data: Data<'r>, // io_stream: impl Future> + Send, ) -> Response<'r> { - info!("{}:", request); - // Remember if the request is `HEAD` for later body stripping. let was_head_request = request.method() == Method::Head; @@ -105,7 +102,7 @@ impl Rocket { 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); @@ -155,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 @@ -181,6 +184,11 @@ impl Rocket { /// 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 +199,6 @@ impl Rocket { 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 +207,17 @@ impl Rocket { // 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. @@ -219,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, @@ -227,23 +236,22 @@ impl Rocket { // We may wish to relax this in the future. req.cookies().reset_delta(); - // Dispatch to the `status` catcher. - if let Ok(r) = self.invoke_catcher(status, req).await { - return r; - } - - // If it fails and it's not a 500, try the 500 catcher. - if status != Status::InternalServerError { - error_!("Catcher failed. Attempting 500 error catcher."); - status = Status::InternalServerError; - if let Ok(r) = self.invoke_catcher(status, req).await { - return r; + loop { + // Dispatch to the `status` catcher. + match self.invoke_catcher(status, req).await { + Ok(r) => return r, + // If the catcher failed, try `500` catcher, unless this is it. + Err(e) if status.code != 500 => { + warn!(status = e.map(|r| r.code), "catcher failed: trying 500 catcher"); + status = Status::InternalServerError; + } + // The 500 catcher failed. There's no recourse. Use default. + Err(e) => { + error!(status = e.map(|r| r.code), "500 catcher failed"); + return catcher::default_handler(Status::InternalServerError, req); + } } } - - // If it failed again or if it was already a 500, use Rocket's default. - error_!("{} catcher failed. Using Rocket default 500.", status.code); - crate::catcher::default_handler(Status::InternalServerError, req) } /// Invokes the handler with `req` for catcher with status `status`. @@ -262,16 +270,14 @@ 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); - Ok(crate::catcher::default_handler(status, req)) + info!(name: "catcher", name = "rocket::default", code = status.code, + "no registered catcher: using Rocket default"); + Ok(catcher::default_handler(status, req)) } } - } diff --git a/core/lib/src/outcome.rs b/core/lib/src/outcome.rs index 98debf30..35521aa3 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,59 +706,6 @@ crate::export! { } } -impl Outcome { - #[inline] - 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, - } - } -} - -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<'r> route::Outcome<'r> { - pub(crate) fn log_display(&self) -> Display<'_, 'r> { - Display(self) - } -} - -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 989d7106..31448348 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. @@ -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)) @@ -1200,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/flash.rs b/core/lib/src/response/flash.rs index 688e6d0e..279ec854 100644 --- a/core/lib/src/response/flash.rs +++ b/core/lib/src/response/flash.rs @@ -244,10 +244,7 @@ impl<'r> FromRequest<'r> for FlashMessage<'r> { type Error = (); async fn from_request(req: &'r Request<'_>) -> request::Outcome { - trace_!("Flash: attempting to retrieve message."); req.cookies().get(FLASH_COOKIE_NAME).ok_or(()).and_then(|cookie| { - trace_!("Flash: retrieving message: {:?}", cookie); - // Parse the flash message. let content = cookie.value(); let (len_str, kv) = match content.find(FLASH_COOKIE_DELIM) { diff --git a/core/lib/src/response/responder.rs b/core/lib/src/response/responder.rs index 3c1ba956..8ff963ea 100644 --- a/core/lib/src/response/responder.rs +++ b/core/lib/src/response/responder.rs @@ -484,7 +484,7 @@ impl<'r, 'o: 'r, R: Responder<'r, 'o>> Responder<'r, 'o> for Option { match self { Some(r) => r.respond_to(req), None => { - warn_!("Response was `None`."); + debug!("{} responder returned `None`", std::any::type_name::()); Err(Status::NotFound) }, } diff --git a/core/lib/src/response/response.rs b/core/lib/src/response/response.rs index e3b266f0..7abdaeca 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/rocket.rs b/core/lib/src/rocket.rs index 41404961..b2278ab9 100644 --- a/core/lib/src/rocket.rs +++ b/core/lib/src/rocket.rs @@ -11,6 +11,7 @@ use figment::{Figment, Provider}; use futures::TryFutureExt; use crate::shutdown::{Stages, Shutdown}; +use crate::trace::traceable::{Traceable, TraceableCollection}; use crate::{sentinel, shield::Shield, Catcher, Config, Route}; use crate::listener::{Bind, DefaultListener, Endpoint, Listener}; use crate::router::Router; @@ -562,15 +563,20 @@ impl Rocket { 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? - config.pretty_print(self.figment()); - log_items("routes", self.routes(), |r| &r.uri.base, |r| &r.uri); - log_items("catchers", self.catchers(), |c| &c.base, |c| &c.base); - self.fairings.pretty_print(); + let fairings = self.fairings.unique_set(); + info_span!("config" [profile = %self.figment().profile()] => { + config.trace_info(); + self.figment().trace_debug(); + }); + + 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 = Rocket(Igniting { @@ -759,7 +765,7 @@ impl Rocket { info_!("Forced shutdown is disabled. Runtime settings may be suboptimal."); } - tracing::info!(target: "rocket::liftoff", endpoint = %rocket.endpoints[0]); + tracing::info!(name: "liftoff", endpoint = %rocket.endpoints[0]); } /// Returns the finalized, active configuration. This is guaranteed to diff --git a/core/lib/src/router/matcher.rs b/core/lib/src/router/matcher.rs index 2d1ee14f..e0dd66d3 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,22 +171,25 @@ 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), + route.query.color = route.uri.metadata.query_color.map(debug), + request.query = req.uri().query().map(display), + ); + if matches!(route.uri.metadata.query_color, None | Some(Color::Wild)) { return true; } - let route_query_fields = route.uri.metadata.static_query_fields.iter() - .map(|(k, v)| (k.as_str(), v.as_str())); - - for route_seg in route_query_fields { + let route_query_fields = route.uri.metadata.static_query_fields.iter(); + for (key, val) in route_query_fields { if let Some(query) = req.uri().query() { - if !query.segments().any(|req_seg| req_seg == route_seg) { - trace_!("request {} missing static query {:?}", req, route_seg); + if !query.segments().any(|req_seg| req_seg == (key, val)) { + debug!(key, val, request.query = %query, "missing static query"); return false; } } else { - trace_!("query-less request {} missing static query {:?}", req, route_seg); + debug!(key, val, "missing static query (queryless request)"); return false; } } @@ -193,7 +198,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 f6796b38..9711963f 100644 --- a/core/lib/src/server.rs +++ b/core/lib/src/server.rs @@ -17,10 +17,16 @@ 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::{Traceable, TraceableCollection}; type Result = std::result::Result; impl Rocket { + #[tracing::instrument("request", skip_all, fields( + method = %parts.method, + uri = %parts.uri, + autohandled + ))] async fn service Into>>( self: Arc, parts: http::request::Parts, @@ -32,6 +38,7 @@ impl Rocket { Request::from_hyp(rocket, parts, connection).unwrap_or_else(|e| e) }); + 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)), @@ -45,10 +52,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(); @@ -73,19 +82,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"), } } } @@ -121,8 +131,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/shield/shield.rs b/core/lib/src/shield/shield.rs index 61b97caa..803b5939 100644 --- a/core/lib/src/shield/shield.rs +++ b/core/lib/src/shield/shield.rs @@ -5,6 +5,7 @@ use crate::{Rocket, Request, Response, Orbit, Config}; use crate::fairing::{Fairing, Info, Kind}; use crate::http::{Header, uncased::UncasedStr}; use crate::shield::*; +use crate::trace::traceable::*; /// A [`Fairing`] that injects browser security and privacy headers into all /// outgoing responses. @@ -192,15 +193,32 @@ impl Fairing for Shield { && rocket.figment().profile() != Config::DEBUG_PROFILE && !self.is_enabled::(); - tracing::info_span!("shield", force_hsts).in_scope(|| { - for header in self.policies.values() { - info!(name: "header", name = header.name().as_str(), value = header.value()); - } + info_span!("shield" [policies = self.policies.len()] => { + self.policies.values().trace_all_info(); - 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."); - }); + if force_hsts { + 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."); + } + }) + + // trace::collection_info!("shield", force_hsts => self.polices.values(), { + // 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!("shield", force_hsts).in_scope(|| { + // // self.polices.values().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."); + // }); } async fn on_response<'r>(&self, _: &'r Request<'_>, response: &mut Response<'r>) { diff --git a/core/lib/src/state.rs b/core/lib/src/state.rs index 9ecf24e1..58c9c626 100644 --- a/core/lib/src/state.rs +++ b/core/lib/src/state.rs @@ -3,7 +3,6 @@ use std::ops::Deref; use std::any::type_name; use ref_cast::RefCast; -use yansi::Paint; use crate::{Phase, Rocket, Ignite, Sentinel}; use crate::request::{self, FromRequest, Request}; @@ -211,9 +210,10 @@ impl<'r, T: Send + Sync + 'static> FromRequest<'r> for &'r State { impl Sentinel for &State { fn abort(rocket: &Rocket) -> bool { if rocket.state::().is_none() { - let type_name = type_name::(); - error!("launching with unmanaged `{}` state.", type_name.primary().bold()); - info_!("Using `State` requires managing it with `.manage()`."); + error!(type_name = type_name::(), + "unmanaged state detected\n\ + ensure type is being managed via `rocket.manage()`"); + return true; } diff --git a/core/lib/src/trace/macros.rs b/core/lib/src/trace/macros.rs new file mode 100644 index 00000000..a3ec72b9 --- /dev/null +++ b/core/lib/src/trace/macros.rs @@ -0,0 +1,71 @@ +pub trait PaintExt: Sized { + fn emoji(self) -> yansi::Painted; +} + +impl PaintExt for &str { + /// Paint::masked(), but hidden on Windows due to broken output. See #1122. + fn emoji(self) -> yansi::Painted { + #[cfg(windows)] { yansi::Paint::new("").mask() } + #[cfg(not(windows))] { yansi::Paint::new(self).mask() } + } +} + +macro_rules! declare_macro { + ($($name:ident $level:ident),* $(,)?) => ( + $(declare_macro!([$] $name $level);)* + ); + + ([$d:tt] $name:ident $level:ident) => ( + #[macro_export] + macro_rules! $name { + ($d ($t:tt)*) => ({ + #[allow(unused_imports)] + use $crate::trace::macros::PaintExt as _; + $crate::tracing::$level!($d ($t)*); + }) + } + ); +} + +declare_macro!( + // launch_meta INFO, launch_meta_ INFO, + error error, error_ error, + info info, info_ info, + trace trace, trace_ trace, + debug debug, debug_ debug, + warn warn, warn_ warn, +); + +macro_rules! declare_span_macro { + ($($name:ident $level:ident),* $(,)?) => ( + $(declare_span_macro!([$] $name $level);)* + ); + + ([$d:tt] $name:ident $level:ident) => ( + #[macro_export] + macro_rules! $name { + ($n:literal $d ([ $d ($f:tt)* ])? => $in_scope:expr) => ({ + $crate::tracing::span!(tracing::Level::$level, $n $d (, $d ($f)* )?) + .in_scope(|| $in_scope); + }) + } + ); +} + +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)*); + }}; +} diff --git a/core/lib/src/trace/mod.rs b/core/lib/src/trace/mod.rs index 0f88780f..1f0bb234 100644 --- a/core/lib/src/trace/mod.rs +++ b/core/lib/src/trace/mod.rs @@ -1,49 +1,14 @@ -use rocket::Config; - +#[macro_use] +pub mod macros; #[cfg(feature = "trace")] pub mod subscriber; pub mod level; +pub mod traceable; -pub trait PaintExt: Sized { - fn emoji(self) -> yansi::Painted; -} - -impl PaintExt for &str { - /// Paint::masked(), but hidden on Windows due to broken output. See #1122. - fn emoji(self) -> yansi::Painted { - #[cfg(windows)] { yansi::Paint::new("").mask() } - #[cfg(not(windows))] { yansi::Paint::new(self).mask() } - } -} - -macro_rules! declare_macro { - ($($name:ident $level:ident),* $(,)?) => ( - $(declare_macro!([$] $name $level);)* - ); - - ([$d:tt] $name:ident $level:ident) => ( - #[macro_export] - macro_rules! $name { - ($d ($t:tt)*) => ({ - #[allow(unused_imports)] - use $crate::trace::PaintExt as _; - - $crate::tracing::$level!($d ($t)*); - }) - } - ); -} - -declare_macro!( - // launch_meta INFO, launch_meta_ INFO, - error error, error_ error, - info info, info_ info, - trace trace, trace_ trace, - debug debug, debug_ debug, - warn warn, warn_ warn, -); - -pub fn init<'a, T: Into>>(_config: T) { - #[cfg(feature = "trace")] - subscriber::init(_config.into()); +pub fn init<'a, T: Into>>(_config: T) { + #[cfg(all(feature = "trace", debug_assertions))] + subscriber::RocketFmt::::init(_config.into()); + + #[cfg(all(feature = "trace", not(debug_assertions)))] + subscriber::RocketFmt::::init(_config.into()); } diff --git a/core/lib/src/trace/subscriber.rs b/core/lib/src/trace/subscriber.rs deleted file mode 100644 index aa2020f7..00000000 --- a/core/lib/src/trace/subscriber.rs +++ /dev/null @@ -1,325 +0,0 @@ -use std::marker::PhantomData; -use std::ops::Index; -use std::sync::OnceLock; -use std::sync::atomic::{AtomicU8, Ordering}; -use std::fmt::{self, Debug, Display}; -// use std::time::Instant; - -use tracing::{Event, Level, Metadata, Subscriber}; -use tracing::level_filters::LevelFilter; -use tracing::field::{Field, Visit}; -use tracing::span::{Attributes, Id}; - -use tracing_subscriber::prelude::*; -use tracing_subscriber::layer::Context; -use tracing_subscriber::registry::LookupSpan; -use tracing_subscriber::{reload, filter, Layer, Registry}; -use tracing_subscriber::field::RecordFields; - -use figment::Source::File as RelPath; -use yansi::{Condition, Paint, Painted, Style}; -use tinyvec::TinyVec; - -use crate::config::{Config, CliColors}; -use crate::util::Formatter; - -pub trait PaintExt: Sized { - fn emoji(self) -> Painted; -} - -impl PaintExt for &str { - /// Paint::masked(), but hidden on Windows due to broken output. See #1122. - fn emoji(self) -> Painted { - #[cfg(windows)] { Paint::new("").mask() } - #[cfg(not(windows))] { Paint::new(self).mask() } - } -} - -pub(crate) fn init(config: Option<&Config>) { - static HANDLE: OnceLock, Registry>> = OnceLock::new(); - - // Do nothing if there's no config and we've already initialized. - if config.is_none() && HANDLE.get().is_some() { - return; - } - - let cli_colors = config.map(|c| c.cli_colors).unwrap_or(CliColors::Auto); - let log_level = config.map(|c| c.log_level).unwrap_or(Some(Level::INFO)); - let (layer, reload_handle) = reload::Layer::new(RocketFmt::new(cli_colors, log_level)); - let result = tracing_subscriber::registry() - .with(layer) - .try_init(); - - if result.is_ok() { - assert!(HANDLE.set(reload_handle).is_ok()); - } if let Some(handle) = HANDLE.get() { - assert!(handle.modify(|layer| layer.set(cli_colors, log_level)).is_ok()); - } -} - -pub(crate) struct Data { - // start: Instant, - map: TinyVec<[(&'static str, String); 2]>, -} - -impl Data { - pub fn new(attrs: &T) -> Self { - let mut data = Data { - // start: Instant::now(), - map: TinyVec::new(), - }; - - attrs.record(&mut data); - data - } - - pub fn get(&self, key: &str) -> Option<&str> { - self.map.iter() - .find(|(k, _)| k == &key) - .map(|(_, v)| v.as_str()) - } -} - -impl Index<&str> for Data { - type Output = str; - - fn index(&self, index: &str) -> &Self::Output { - self.get(index).unwrap_or("[internal error: missing key]") - } -} - -impl Visit for Data { - fn record_debug(&mut self, field: &Field, value: &dyn Debug) { - self.map.push((field.name(), format!("{:?}", value))); - } - - fn record_str(&mut self, field: &Field, value: &str) { - self.map.push((field.name(), value.into())); - } -} - -#[derive(Default)] -struct RocketFmt { - depth: AtomicU8, - filter: filter::Targets, - default_style: Style, - _subscriber: PhantomData S> -} - -// struct Printer { -// level: Level, -// } -// -// impl Printer { -// fn print(event: &Event) -// -// } - -macro_rules! log { - ($this:expr, $event:expr => $fmt:expr $(, $($t:tt)*)?) => { - let metadata = $event.metadata(); - let (i, s, t) = ($this.indent(), $this.style($event), metadata.target()); - match *metadata.level() { - Level::WARN => print!( - concat!("{}{} ", $fmt), - i, "warning:".paint(s).yellow().bold() $(, $($t)*)? - ), - Level::ERROR => print!( - concat!("{}{} ", $fmt), - i, "error:".paint(s).red().bold() $(, $($t)*)? - ), - level@(Level::DEBUG | Level::TRACE) => match (metadata.file(), metadata.line()) { - (Some(f), Some(l)) => print!( - concat!("{}[{} {}{}{} {}] ", $fmt), - i, level.paint(s).bold(), - RelPath(f.into()).underline(), ":".paint(s).dim(), l, t.paint(s).dim() - $(, $($t)*)? - ), - (_, _) => print!( - concat!("{}[{} {}] ", $fmt), - i, level.paint(s).bold(), t $(, $($t)*)? - ), - } - _ => print!(concat!("{}", $fmt), i $(, $($t)*)?), - } - }; -} - -macro_rules! logln { - ($this:expr, $event:expr => $fmt:literal $($t:tt)*) => { - log!($this, $event => concat!($fmt, "\n") $($t)*); - }; -} - -struct DisplayVisit(F); - -impl Visit for DisplayVisit { - fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { - (self.0)(field, &Formatter(|f| value.fmt(f))); - } - - fn record_str(&mut self, field: &Field, value: &str) { - (self.0)(field, &value) - } -} - -trait DisplayFields { - fn record_display(&self, f: F); -} - -impl DisplayFields for T { - fn record_display(&self, f: F) { - self.record(&mut DisplayVisit(f)); - } -} - -impl LookupSpan<'a>> RocketFmt { - fn new(cli_colors: CliColors, level: impl Into) -> Self { - let mut this = Self { - depth: AtomicU8::new(0), - filter: filter::Targets::new(), - default_style: Style::new(), - _subscriber: PhantomData, - }; - - this.set(cli_colors, level.into()); - this - } - - fn set(&mut self, cli_colors: CliColors, level: impl Into) { - self.default_style = Style::new().whenever(match cli_colors { - CliColors::Always => Condition::ALWAYS, - CliColors::Auto => Condition::DEFAULT, - CliColors::Never => Condition::NEVER, - }); - - self.filter = filter::Targets::new() - .with_default(level.into()) - .with_target("rustls", LevelFilter::OFF) - .with_target("hyper", LevelFilter::OFF); - } - - fn indent(&self) -> &'static str { - match self.depth.load(Ordering::Acquire) { - 0 => "", - 1 => " >> ", - 2 => " >> ", - _ => " >> ", - } - } - - fn style(&self, event: &Event<'_>) -> Style { - match *event.metadata().level() { - Level::ERROR => self.default_style.red(), - Level::WARN => self.default_style.yellow(), - Level::INFO => self.default_style.blue(), - Level::DEBUG => self.default_style.green(), - Level::TRACE => self.default_style.magenta(), - } - } - - fn print(&self, event: &Event<'_>) { - let style = self.style(event); - let fields = event.metadata().fields(); - if let Some(msg) = fields.field("message") { - event.record_display(|field: &Field, value: &dyn Display| { - if field == &msg { - log!(self, event => "{}", value.paint(style)); - } - }); - - if fields.len() > 1 { print!(" ("); } - self.print_fields_compact(false, event); - if fields.len() > 1 { print!(")"); } - } else if !fields.is_empty() { - self.print_fields_compact(true, event); - } - - if !fields.is_empty() { - println!(""); - } - } - - fn print_fields_compact(&self, prefix: bool, event: &Event<'_>) { - let key_style = self.style(event).bold(); - let val_style = self.style(event).primary(); - let mut printed = false; - event.record_display(|field: &Field, val: &dyn Display| { - let key = field.name(); - if key != "message" { - if !printed && prefix { - log!(self, event => "{}: {}", key.paint(key_style), val.paint(val_style)); - } else { - if printed { print!(" "); } - print!("{}: {}", key.paint(key_style), val.paint(val_style)); - } - - printed = true; - } - }); - } - - fn print_fields(&self, event: &Event<'_>) { - let style = self.style(event); - event.record_display(|key: &Field, value: &dyn Display| { - if key.name() != "message" { - logln!(self, event => "{}: {}", key.paint(style), value.paint(style).primary()); - } - }) - } - - fn write_config(&self, event: &Event<'_>) { - // eprintln!(" > config [name = {}]", event.metadata().name()); - match event.metadata().name() { - "values" => self.print_fields(event), - _ => self.print(event), - } - } -} - -impl LookupSpan<'a>> Layer for RocketFmt { - fn enabled(&self, metadata: &Metadata<'_>, _: Context<'_, S>) -> bool { - self.filter.would_enable(metadata.target(), metadata.level()) - } - - fn on_event(&self, event: &Event<'_>, ctxt: Context<'_, S>) { - // let metadata = event.metadata(); - // eprintln!("[name = {}, target = {}]", metadata.name(), metadata.target()); - if let Some(span) = ctxt.event_span(event) { - // eprintln!(" > [name = {}, target = {}]", span.name(), span.metadata().target()); - return match span.name() { - "config" => self.write_config(event), - _ => self.print(event), - }; - } - - self.print(event); - } - - fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) { - let span = ctx.span(id).expect("new_span: span does not exist"); - let data = Data::new(attrs); - match span.metadata().name() { - "config" => println!("configured for {}", &data["profile"]), - name => println!("{name} {:?}", Formatter(|f| { - f.debug_map().entries(data.map.iter().map(|(k, v)| (k, v))).finish() - })) - } - - span.extensions_mut().replace(data); - } - - fn on_enter(&self, _: &Id, _: Context<'_, S>) { - self.depth.fetch_add(1, Ordering::AcqRel); - // let metadata = ctxt.span(id).unwrap().metadata(); - // eprintln!("enter [name={}] [target={}] {:?}", metadata.name(), - // metadata.target(), metadata.fields()); - } - - fn on_exit(&self, _: &Id, _: Context<'_, S>) { - self.depth.fetch_sub(1, Ordering::AcqRel); - // let metadata = ctxt.span(id).unwrap().metadata(); - // eprintln!("exit [name={}] [target={}] {:?}", metadata.name(), - // metadata.target(), metadata.fields()); - } -} diff --git a/core/lib/src/trace/subscriber/common.rs b/core/lib/src/trace/subscriber/common.rs new file mode 100644 index 00000000..a35be827 --- /dev/null +++ b/core/lib/src/trace/subscriber/common.rs @@ -0,0 +1,184 @@ +use std::fmt; +use std::cell::Cell; +use std::sync::OnceLock; + +use tracing::{Level, Metadata}; +use tracing::field::Field; + +use tracing_subscriber::prelude::*; +use tracing_subscriber::layer::Layered; +use tracing_subscriber::{reload, filter, Layer, Registry}; +use tracing_subscriber::field::RecordFields; + +use thread_local::ThreadLocal; +use yansi::{Condition, Paint, Style}; + +use crate::config::{Config, CliColors}; +use crate::trace::subscriber::{RecordDisplay, RequestId, RequestIdLayer}; +use crate::util::Formatter; + +mod private { + pub trait FmtKind: Default + Copy + Send + Sync + 'static { } + + impl FmtKind for crate::trace::subscriber::Pretty {} + impl FmtKind for crate::trace::subscriber::Compact {} +} + +#[derive(Default)] +pub struct RocketFmt { + state: ThreadLocal>, + pub(crate) level: Option, + pub(crate) filter: filter::Targets, + pub(crate) style: Style, +} + +pub type Handle = reload::Handle, Layered>; + +impl RocketFmt { + pub(crate) fn state(&self) -> K { + self.state.get_or_default().get() + } + + pub(crate) fn update_state(&self, update: F) { + let cell = self.state.get_or_default(); + let mut old = cell.get(); + update(&mut old); + cell.set(old); + } + + pub(crate) fn init_with(config: Option<&Config>, handle: &OnceLock>) + where Self: Layer> + { + // Do nothing if there's no config and we've already initialized. + if config.is_none() && handle.get().is_some() { + return; + } + + let workers = config.map(|c| c.workers).unwrap_or(num_cpus::get()); + let cli_colors = config.map(|c| c.cli_colors).unwrap_or(CliColors::Auto); + let log_level = config.map(|c| c.log_level).unwrap_or(Some(Level::INFO)); + + let formatter = RocketFmt::new(workers, cli_colors, log_level); + let (layer, reload_handle) = reload::Layer::new(formatter); + let result = tracing_subscriber::registry() + .with(RequestId::layer()) + .with(layer) + .try_init(); + + if result.is_ok() { + assert!(handle.set(reload_handle).is_ok()); + } if let Some(handle) = handle.get() { + assert!(handle.modify(|layer| layer.reset(cli_colors, log_level)).is_ok()); + } + } + + pub fn new(workers: usize, cli_colors: CliColors, level: Option) -> Self { + Self { + state: ThreadLocal::with_capacity(workers), + level, + filter: filter::Targets::new() + .with_default(level) + .with_target("rustls", level.filter(|&l| l == Level::TRACE)) + .with_target("hyper", level.filter(|&l| l == Level::TRACE)), + style: match cli_colors { + CliColors::Always => Style::new().whenever(Condition::ALWAYS), + CliColors::Auto => Style::new().whenever(Condition::DEFAULT), + CliColors::Never => Style::new().whenever(Condition::NEVER), + } + } + } + + pub fn reset(&mut self, cli_colors: CliColors, level: Option) { + let state = std::mem::take(&mut self.state); + *self = Self { state, ..Self::new(0, cli_colors, level) }; + } + + pub fn style(&self, metadata: &Metadata<'_>) -> Style { + match *metadata.level() { + Level::ERROR => self.style.red(), + Level::WARN => self.style.yellow(), + Level::INFO => self.style.blue(), + Level::DEBUG => self.style.green(), + Level::TRACE => self.style.magenta(), + } + } + + pub fn has_message(&self, meta: &Metadata<'_>) -> bool { + meta.fields().field("message").is_some() + } + + pub fn has_data_fields(&self, meta: &Metadata<'_>) -> bool { + meta.fields().iter().any(|f| f.name() != "message") + } + + pub fn message<'a, F: RecordFields + 'a>(&self, + init_prefix: &'a dyn fmt::Display, + cont_prefix: &'a dyn fmt::Display, + meta: &'a Metadata<'_>, + data: F + ) -> impl fmt::Display + 'a { + let style = self.style(meta); + Formatter(move |f| { + let fields = meta.fields(); + let message = fields.field("message"); + if let Some(message_field) = &message { + data.record_display(|field: &Field, value: &dyn fmt::Display| { + if field != message_field { + return; + } + + for (i, line) in value.to_string().lines().enumerate() { + let line = line.paint(style); + if i == 0 { + let _ = writeln!(f, "{init_prefix}{line}"); + } else { + let _ = writeln!(f, "{cont_prefix}{line}"); + } + } + }); + } + + Ok(()) + }) + } + + pub fn compact_fields<'a, F>(&self, meta: &'a Metadata<'_>, data: F) -> impl fmt::Display + 'a + where F: RecordFields + 'a + { + let key_style = self.style(meta).bold(); + let val_style = self.style(meta).primary(); + + Formatter(move |f| { + let mut printed = false; + data.record_display(|field: &Field, val: &dyn fmt::Display| { + let key = field.name(); + if key != "message" { + if printed { let _ = write!(f, " "); } + let _ = write!(f, "{}: {}", key.paint(key_style), val.paint(val_style)); + printed = true; + } + }); + + Ok(()) + }) + } + + pub fn print( + &self, + prefix: &dyn fmt::Display, + cont_prefix: &dyn fmt::Display, + m: &Metadata<'_>, + data: F + ) { + if self.has_message(m) { + let message = self.message(prefix, cont_prefix, m, &data); + if self.has_data_fields(m) { + println!("{message}{cont_prefix}{}", self.compact_fields(m, &data)); + } else { + print!("{message}"); + } + } else if self.has_data_fields(m) { + println!("{prefix}{}", self.compact_fields(m, &data)); + } + } +} diff --git a/core/lib/src/trace/subscriber/compact.rs b/core/lib/src/trace/subscriber/compact.rs new file mode 100644 index 00000000..5dee0b03 --- /dev/null +++ b/core/lib/src/trace/subscriber/compact.rs @@ -0,0 +1,191 @@ +use std::num::NonZeroU64; + +use std::fmt; +use std::sync::OnceLock; +use std::time::Instant; + +use time::OffsetDateTime; +use tracing::{Event, Level, Metadata, Subscriber}; +use tracing::span::{Attributes, Id, Record}; + +use tracing_subscriber::layer::{Layer, Context}; +use tracing_subscriber::registry::LookupSpan; +use tracing_subscriber::field::RecordFields; + +use yansi::{Paint, Painted}; + +use crate::util::Formatter; +use crate::trace::subscriber::{Data, Handle, RocketFmt}; + +#[derive(Debug, Default, Copy, Clone)] +pub struct Compact { + /// The `tracing::Span::Id` of the request we're in, if any. + request: Option, +} + +#[derive(Debug)] +pub struct RequestData { + start: Instant, + fields: Data, +} + +impl RequestData { + pub fn new(attrs: T) -> Self { + Self { + start: Instant::now(), + fields: Data::new(attrs), + } + } +} + +impl RocketFmt { + pub fn init(config: Option<&crate::Config>) { + static HANDLE: OnceLock> = OnceLock::new(); + + Self::init_with(config, &HANDLE); + } + + fn request_span_id(&self) -> Option { + self.state().request.map(Id::from_non_zero_u64) + } + + fn timestamp_for(&self, datetime: OffsetDateTime) -> impl fmt::Display { + Formatter(move |f| { + let (date, time) = (datetime.date(), datetime.time()); + let (year, month, day) = (date.year(), date.month() as u8, date.day()); + let (h, m, s, l) = (time.hour(), time.minute(), time.second(), time.millisecond()); + write!(f, "{year:04}-{month:02}-{day:02}T{h:02}:{m:02}:{s:02}.{l:03}Z") + }) + } + + fn in_debug(&self) -> bool { + self.level.map_or(false, |l| l >= Level::DEBUG) + } + + fn prefix<'a>(&self, meta: &'a Metadata<'_>) -> impl fmt::Display + 'a { + let style = self.style(meta); + let name = meta.name() + .starts_with("event ") + .then_some(meta.target()) + .unwrap_or(meta.name()); + + let timestamp = self.timestamp_for(OffsetDateTime::now_utc()); + Formatter(move |f| write!(f, "{} {:>5} {} ", + timestamp.paint(style).primary().dim(), + meta.level().paint(style), + name.paint(style).primary())) + } + + fn chevron(&self, meta: &Metadata<'_>) -> Painted<&'static str> { + "›".paint(self.style(meta)).bold() + } + + fn print_compact(&self, m: &Metadata<'_>, data: F) { + let style = self.style(m); + let prefix = self.prefix(m); + let chevron = self.chevron(m); + let init_prefix = Formatter(|f| write!(f, "{prefix}{chevron} ")); + let cont_prefix = Formatter(|f| write!(f, "{prefix}{} ", "+".paint(style).dim())); + self.print(&init_prefix, &cont_prefix, m, data); + } +} + +impl LookupSpan<'a>> Layer for RocketFmt { + fn enabled(&self, metadata: &Metadata<'_>, _: Context<'_, S>) -> bool { + self.filter.would_enable(metadata.target(), metadata.level()) + && (self.in_debug() + || self.request_span_id().is_none() + || metadata.name() == "request" + || metadata.name() == "response") + } + + fn on_event(&self, event: &Event<'_>, ctxt: Context<'_, S>) { + if let Some(id) = self.request_span_id() { + if event.metadata().name() == "response" { + let req_span = ctxt.span(&id).expect("on_event: req does not exist"); + let mut exts = req_span.extensions_mut(); + let data = exts.get_mut::().unwrap(); + event.record(&mut data.fields); + } + + if !self.in_debug() { + return; + } + } + + self.print_compact(event.metadata(), event); + } + + fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctxt: Context<'_, S>) { + let span = ctxt.span(id).expect("new_span: span does not exist"); + + if span.name() == "request" { + let data = RequestData::new(attrs); + span.extensions_mut().replace(data); + + if !self.in_debug() { + return; + } + } + + if self.state().request.is_none() { + self.print_compact(span.metadata(), attrs); + } + } + + fn on_record(&self, id: &Id, values: &Record<'_>, ctxt: Context<'_, S>) { + let span = ctxt.span(id).expect("record: span does not exist"); + if self.request_span_id().as_ref() == Some(id) { + let mut extensions = span.extensions_mut(); + match extensions.get_mut::() { + Some(data) => values.record(&mut data.fields), + None => span.extensions_mut().insert(RequestData::new(values)), + } + } + + if self.in_debug() { + println!("{}{} {}", + self.prefix(span.metadata()), + self.chevron(span.metadata()), + self.compact_fields(span.metadata(), values)); + } + } + + fn on_enter(&self, id: &Id, ctxt: Context<'_, S>) { + let span = ctxt.span(id).expect("new_span: span does not exist"); + if span.name() == "request" { + self.update_state(|state| state.request = Some(id.into_non_zero_u64())); + } + } + + fn on_exit(&self, id: &Id, ctxt: Context<'_, S>) { + let span = ctxt.span(id).expect("new_span: span does not exist"); + if span.name() == "request" { + self.update_state(|state| state.request = None); + } + } + + fn on_close(&self, id: Id, ctxt: Context<'_, S>) { + let span = ctxt.span(&id).expect("new_span: span does not exist"); + if span.name() == "request" { + let extensions = span.extensions(); + let data = extensions.get::().unwrap(); + + let elapsed = data.start.elapsed(); + let datetime = OffsetDateTime::now_utc() - elapsed; + let timestamp = self.timestamp_for(datetime); + + let style = self.style(span.metadata()); + let prefix = self.prefix(span.metadata()); + let chevron = self.chevron(span.metadata()); + + println!("{prefix}{chevron} ({} {}ms) {} {} => {}", + timestamp.paint(style).primary().dim(), + elapsed.as_millis(), + &data.fields["method"].paint(style), + &data.fields["uri"], + &data.fields["status"], + ); + } + } +} diff --git a/core/lib/src/trace/subscriber/mod.rs b/core/lib/src/trace/subscriber/mod.rs new file mode 100644 index 00000000..d7a2e66d --- /dev/null +++ b/core/lib/src/trace/subscriber/mod.rs @@ -0,0 +1,13 @@ +mod visit; +mod pretty; +mod compact; +mod common; +mod request_id; + +pub use visit::{RecordDisplay, Data}; +pub use pretty::Pretty; +pub use compact::Compact; +pub use common::RocketFmt; +pub use request_id::{RequestId, RequestIdLayer}; + +pub(crate) use common::Handle; diff --git a/core/lib/src/trace/subscriber/pretty.rs b/core/lib/src/trace/subscriber/pretty.rs new file mode 100644 index 00000000..2b5e5469 --- /dev/null +++ b/core/lib/src/trace/subscriber/pretty.rs @@ -0,0 +1,146 @@ +use std::fmt; +use std::sync::OnceLock; + +use tracing::{Event, Level, Metadata, Subscriber}; +use tracing::span::{Attributes, Id, Record}; +use tracing::field::Field; + +use tracing_subscriber::layer::{Layer, Context}; +use tracing_subscriber::registry::LookupSpan; +use tracing_subscriber::field::RecordFields; + +use yansi::{Paint, Painted}; + +use crate::trace::subscriber::{Data, RecordDisplay, Handle, RocketFmt}; +use crate::util::Formatter; + +#[derive(Debug, Default, Copy, Clone)] +pub struct Pretty { + depth: u32, +} + +impl RocketFmt { + pub fn init(config: Option<&crate::Config>) { + static HANDLE: OnceLock> = OnceLock::new(); + + Self::init_with(config, &HANDLE); + } + + fn indent(&self) -> &'static str { + static INDENT: &[&str] = &["", " ", " "]; + INDENT.get(self.state().depth as usize).copied().unwrap_or(" ") + } + + fn marker(&self) -> &'static str { + static MARKER: &[&str] = &["", ">> ", ":: "]; + MARKER.get(self.state().depth as usize).copied().unwrap_or("-- ") + } + + fn emoji(&self, emoji: &'static str) -> Painted<&'static str> { + #[cfg(windows)] { "".paint(self.style).mask() } + #[cfg(not(windows))] { emoji.paint(self.style).mask() } + } + + fn prefix<'a>(&self, meta: &'a Metadata<'_>) -> impl fmt::Display + 'a { + let (i, m, s) = (self.indent(), self.marker(), self.style(meta)); + Formatter(move |f| match *meta.level() { + Level::WARN => write!(f, "{i}{m}{} ", "warning:".paint(s).bold()), + Level::ERROR => write!(f, "{i}{m}{} ", "error:".paint(s).bold()), + Level::INFO => write!(f, "{i}{m}"), + level => write!(f, "{i}{m}[{} {}] ", level.paint(s).bold(), meta.target()), + }) + } + + fn print_pretty(&self, m: &Metadata<'_>, data: F) { + let prefix = self.prefix(m); + let cont_prefix = Formatter(|f| { + let style = self.style(m); + write!(f, "{}{} ", self.indent(), "++".paint(style).dim()) + }); + + self.print(&prefix, &cont_prefix, m, data); + } + + fn print_fields(&self, metadata: &Metadata<'_>, fields: F) + where F: RecordFields + { + let style = self.style(metadata); + let prefix = self.prefix(metadata); + fields.record_display(|key: &Field, value: &dyn fmt::Display| { + if key.name() != "message" { + println!("{prefix}{}: {}", key.paint(style), value.paint(style).primary()); + } + }) + } +} + +impl LookupSpan<'a>> Layer for RocketFmt { + fn enabled(&self, metadata: &Metadata<'_>, _: Context<'_, S>) -> bool { + self.filter.would_enable(metadata.target(), metadata.level()) + } + + fn on_event(&self, event: &Event<'_>, _: Context<'_, S>) { + let (meta, data) = (event.metadata(), Data::new(event)); + let style = self.style(meta); + match meta.name() { + "config" => self.print_fields(meta, event), + "liftoff" => { + let prefix = self.prefix(meta); + println!("{prefix}{}{} {}", self.emoji("🚀 "), + "Rocket has launched from".paint(style).primary().bold(), + &data["endpoint"].paint(style).primary().bold().underline()); + } + _ => self.print_pretty(meta, event), + } + } + + fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctxt: Context<'_, S>) { + let data = Data::new(attrs); + let span = ctxt.span(id).expect("new_span: span does not exist"); + if &data["count"] != "0" { + let name = span.name(); + let icon = match name { + "config" => "🔧 ", + "routes" => "📬 ", + "catchers" => "🚧 ", + "fairings" => "📦 ", + "shield" => "🛡️ ", + "request" => "● ", + _ => "", + }; + + let meta = span.metadata(); + let style = self.style(meta); + let prefix = self.prefix(meta); + let emoji = self.emoji(icon); + let name = name.paint(style).bold(); + + if !attrs.fields().is_empty() { + println!("{prefix}{emoji}{name} ({})", self.compact_fields(meta, attrs)) + } else { + println!("{prefix}{emoji}{name}"); + } + } + + span.extensions_mut().replace(data); + } + + fn on_record(&self, id: &Id, values: &Record<'_>, ctxt: Context<'_, S>) { + 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)), + } + + let meta = span.metadata(); + println!("{}{}", self.prefix(meta), self.compact_fields(meta, values)); + } + + fn on_enter(&self, _: &Id, _: Context<'_, S>) { + self.update_state(|state| state.depth = state.depth.saturating_add(1)); + } + + fn on_exit(&self, _: &Id, _: Context<'_, S>) { + self.update_state(|state| state.depth = state.depth.saturating_sub(1)); + } +} diff --git a/core/lib/src/trace/subscriber/request_id.rs b/core/lib/src/trace/subscriber/request_id.rs new file mode 100644 index 00000000..b40924d1 --- /dev/null +++ b/core/lib/src/trace/subscriber/request_id.rs @@ -0,0 +1,136 @@ +use std::fmt; +use std::hash::{Hash, Hasher}; +use std::thread::ThreadId; +use std::cell::Cell; + +use tracing::Subscriber; +use tracing::span::{Attributes, Id}; +use tracing_subscriber::{layer::Context, Layer}; +use tracing_subscriber::registry::{LookupSpan, SpanRef}; + +pub struct RequestIdLayer; + +#[derive(Debug, Copy, Clone, Hash, PartialEq, Eq)] +pub struct RequestId(u128); + +#[derive(Default)] +pub struct IdentHasher(u128); + +impl RequestId { + fn new() -> Self { + thread_local! { + pub static COUNTER: Cell = Cell::new(0); + pub static THREAD_ID: Cell> = Cell::new(None); + } + + let thread_id = THREAD_ID.get().unwrap_or_else(|| { + let id = std::thread::current().id(); + THREAD_ID.set(Some(id)); + id + }); + + let local_id = COUNTER.get(); + COUNTER.set(local_id.wrapping_add(1)); + + let mut hasher = IdentHasher::default(); + thread_id.hash(&mut hasher); + local_id.hash(&mut hasher); + RequestId(hasher.0) + } + + pub fn of LookupSpan<'a>>(span: &SpanRef<'_, R>) -> Option { + span.extensions().get::().copied() + } + + pub fn current() -> Option { + RequestIdLayer::current() + } + + fn short(&self) -> u32 { + let mut x = ((self.0 & (0xFFFFFFFF << 48)) >> 48) as u32; + x = (x ^ (x >> 16)).wrapping_mul(0x21f0aaad); + x = (x ^ (x >> 15)).wrapping_mul(0x735a2d97); + x = x ^ (x >> 15); + x + } + + pub fn layer() -> RequestIdLayer { + RequestIdLayer + } +} + +impl RequestIdLayer { + thread_local! { + pub static CURRENT_REQUEST_ID: Cell> = Cell::new(None); + } + + fn current() -> Option { + Self::CURRENT_REQUEST_ID.get() + } +} + +impl LookupSpan<'a>> Layer for RequestIdLayer { + fn on_new_span(&self, _: &Attributes<'_>, id: &Id, ctxt: Context<'_, S>) { + let span = ctxt.span(id).expect("new_span: span does not exist"); + if span.name() == "request" { + span.extensions_mut().replace(RequestId::new()); + } + } + + fn on_enter(&self, id: &Id, ctxt: Context<'_, S>) { + let span = ctxt.span(id).expect("enter: span does not exist"); + if span.name() == "request" { + Self::CURRENT_REQUEST_ID.set(RequestId::of(&span)); + } + } + + fn on_exit(&self, id: &Id, ctxt: Context<'_, S>) { + let span = ctxt.span(id).expect("enter: span does not exist"); + if span.name() == "request" { + Self::CURRENT_REQUEST_ID.set(None); + } + } +} + +impl fmt::Display for RequestId { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + fmt::Display::fmt(&self.short(), f) + } +} + +impl fmt::LowerHex for RequestId { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + fmt::LowerHex::fmt(&self.short(), f) + } +} + +impl fmt::UpperHex for RequestId { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + fmt::UpperHex::fmt(&self.short(), f) + } +} + +impl Hasher for IdentHasher { + fn finish(&self) -> u64 { + self.0 as u64 + } + + fn write(&mut self, bytes: &[u8]) { + for &byte in bytes { + self.0 = (self.0 << 8) | (byte as u128); + } + } + + fn write_u64(&mut self, i: u64) { + // https://github.com/skeeto/hash-prospector + fn shuffle(mut x: u64) -> u64 { + x = x.wrapping_add(1); + x = (x ^ (x >> 30)).wrapping_mul(0xbf58476d1ce4e5b9); + x = (x ^ (x >> 27)).wrapping_mul(0x94d049bb133111eb); + x = x ^ (x >> 31); + x + } + + self.0 = (self.0 << 64) | shuffle(i) as u128; + } +} diff --git a/core/lib/src/trace/subscriber/visit.rs b/core/lib/src/trace/subscriber/visit.rs new file mode 100644 index 00000000..eeafc312 --- /dev/null +++ b/core/lib/src/trace/subscriber/visit.rs @@ -0,0 +1,71 @@ +use std::fmt; + +use tinyvec::TinyVec; +use tracing::field::{Field, Visit}; +use tracing_subscriber::field::RecordFields; + +use crate::util::Formatter; + +pub trait RecordDisplay: RecordFields { + fn record_display(&self, f: F); +} + +#[derive(Debug)] +pub struct Data { + // start: Instant, + map: TinyVec<[(&'static str, String); 3]>, +} + +impl Data { + pub fn new(attrs: T) -> Self { + let mut data = Data { + // start: Instant::now(), + map: TinyVec::new(), + }; + + attrs.record(&mut data); + data + } + + pub fn get(&self, key: &str) -> Option<&str> { + self.map.iter() + .find(|(k, _)| k == &key) + .map(|(_, v)| v.as_str()) + } +} + +impl std::ops::Index<&str> for Data { + type Output = str; + + fn index(&self, index: &str) -> &Self::Output { + self.get(index).unwrap_or("[internal error: missing key]") + } +} + +impl Visit for Data { + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + self.map.push((field.name(), format!("{:?}", value))); + } + + fn record_str(&mut self, field: &Field, value: &str) { + self.map.push((field.name(), value.into())); + } +} + +impl RecordDisplay for T { + fn record_display(&self, f: F) { + struct DisplayVisit(F); + + impl Visit for DisplayVisit { + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + (self.0)(field, &Formatter(|f| value.fmt(f))); + } + + fn record_str(&mut self, field: &Field, value: &str) { + (self.0)(field, &value) + } + } + + self.record(&mut DisplayVisit(f)); + } +} diff --git a/core/lib/src/trace/traceable.rs b/core/lib/src/trace/traceable.rs new file mode 100644 index 00000000..df45f4cf --- /dev/null +++ b/core/lib/src/trace/traceable.rs @@ -0,0 +1,239 @@ +use crate::fairing::Fairing; +use crate::{route, Catcher, Config, Response, Route}; +use crate::util::Formatter; + +use figment::Figment; +use rocket::http::Header; +use tracing::Level; + +pub trait Traceable { + fn trace(&self, level: Level); + + #[inline(always)] fn trace_info(&self) { self.trace(Level::INFO) } + #[inline(always)] fn trace_warn(&self) { self.trace(Level::WARN) } + #[inline(always)] fn trace_error(&self) { self.trace(Level::ERROR) } + #[inline(always)] fn trace_debug(&self) { self.trace(Level::DEBUG) } + #[inline(always)] fn trace_trace(&self) { self.trace(Level::TRACE) } +} + +pub trait TraceableCollection: Sized { + fn trace_all(self, level: Level); + + #[inline(always)] fn trace_all_info(self) { self.trace_all(Level::INFO) } + #[inline(always)] fn trace_all_warn(self) { self.trace_all(Level::WARN) } + #[inline(always)] fn trace_all_error(self) { self.trace_all(Level::ERROR) } + #[inline(always)] fn trace_all_debug(self) { self.trace_all(Level::DEBUG) } + #[inline(always)] fn trace_all_trace(self) { self.trace_all(Level::TRACE) } +} + +impl> TraceableCollection for I { + fn trace_all(self, level: Level) { + self.into_iter().for_each(|i| i.trace(level)) + } +} + +impl Traceable for &T { + #[inline(always)] + fn trace(&self, level: Level) { + T::trace(self, level) + } +} + +impl Traceable for Figment { + fn trace(&self, level: Level) { + for param in Config::PARAMETERS { + if let Some(source) = self.find_metadata(param) { + event! { level, "figment", + param, + %source.name, + source.source = source.source.as_ref().map(display), + } + } + } + + // Check for now deprecated config values. + for (key, replacement) in Config::DEPRECATED_KEYS { + if let Some(source) = self.find_metadata(key) { + event! { Level::WARN, "deprecated", + key, + replacement, + %source.name, + source.source = source.source.as_ref().map(display), + "config key `{key}` is deprecated and has no meaning" + } + } + } + } +} + +impl Traceable for Config { + fn trace(&self, level: Level) { + event! { level, "config", + http2 = cfg!(feature = "http2"), + log_level = self.log_level.map(|l| l.as_str()), + cli_colors = %self.cli_colors, + workers = self.workers, + max_blocking = self.max_blocking, + ident = %self.ident, + 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(), display(v)))) + .finish()), + temp_dir = %self.temp_dir.relative().display(), + keep_alive = (self.keep_alive != 0).then_some(self.keep_alive), + shutdown.ctrlc = self.shutdown.ctrlc, + shutdown.signals = %{ + #[cfg(not(unix))] { + "disabled (not unix)" + } + + #[cfg(unix)] { + Formatter(|f| f.debug_set() + .entries(self.shutdown.signals.iter().map(|s| s.as_str())) + .finish()) + } + }, + shutdown.grace = self.shutdown.grace, + shutdown.mercy = self.shutdown.mercy, + shutdown.force = self.shutdown.force, + } + + #[cfg(feature = "secrets")] { + if !self.secret_key.is_provided() { + warn! { + name: "volatile_secret_key", + "secrets enabled without configuring a stable `secret_key`\n\ + private/signed cookies will become unreadable after restarting\n\ + disable the `secrets` feature or configure a `secret_key`\n\ + this becomes a hard error in non-debug profiles", + } + } + + let secret_key_is_known = Config::KNOWN_SECRET_KEYS.iter().any(|&key_str| { + let value = figment::value::Value::from(key_str); + self.secret_key == value.deserialize().expect("known key is valid") + }); + + if secret_key_is_known { + warn! { + name: "insecure_secret_key", + "The configured `secret_key` is exposed and insecure. \ + The configured key is publicly published and thus insecure. \ + Try generating a new key with `head -c64 /dev/urandom | base64`." + } + } + } + } +} + +impl Traceable for Route { + fn trace(&self, level: Level) { + event! { level, "route", + name = self.name.as_ref().map(|n| &**n), + method = %self.method, + rank = self.rank, + uri = %self.uri, + uri.base = %self.uri.base(), + uri.unmounted = %self.uri.unmounted(), + format = self.format.as_ref().map(display), + } + + event! { Level::DEBUG, "route", + route = self.name.as_ref().map(|n| &**n), + sentinels = %Formatter(|f| { + f.debug_set() + .entries(self.sentinels.iter().filter(|s| s.specialized).map(|s| s.type_name)) + .finish() + }) + } + } +} + +impl Traceable for Catcher { + fn trace(&self, level: Level) { + event! { level, "catcher", + name = self.name.as_ref().map(|n| &**n), + status = %Formatter(|f| match self.code { + Some(code) => write!(f, "{}", code), + None => write!(f, "default"), + }), + rank = self.rank, + uri.base = %self.base(), + } + } +} + +impl Traceable for &dyn Fairing { + fn trace(&self, level: Level) { + event!(level, "fairing", name = self.info().name, kind = %self.info().kind) + } +} + +impl Traceable for figment::error::Kind { + fn trace(&self, _: Level) { + use figment::error::{OneOf as V, Kind::*}; + + match self { + Message(message) => error!(message), + InvalidType(actual, expected) => error!(name: "invalid type", %actual, expected), + InvalidValue(actual, expected) => error!(name: "invalid value", %actual, expected), + InvalidLength(actual, expected) => error!(name: "invalid length", %actual, expected), + UnknownVariant(actual, v) => error!(name: "unknown variant", actual, expected = %V(v)), + UnknownField(actual, v) => error!(name: "unknown field", actual, expected = %V(v)), + UnsupportedKey(actual, v) => error!(name: "unsupported key", %actual, expected = &**v), + MissingField(value) => error!(name: "missing field", value = &**value), + DuplicateField(value) => error!(name: "duplicate field", value), + ISizeOutOfRange(value) => error!(name: "out of range signed integer", value), + USizeOutOfRange(value) => error!(name: "out of range unsigned integer", value), + Unsupported(value) => error!(name: "unsupported type", %value), + } + } +} + +impl Traceable for figment::Error { + fn trace(&self, _: Level) { + for e in self.clone() { + let span = tracing::error_span! { + "config", + key = (!e.path.is_empty()).then_some(&e.path).and_then(|path| { + let (profile, metadata) = (e.profile.as_ref()?, e.metadata.as_ref()?); + Some(metadata.interpolate(profile, path)) + }), + source.name = e.metadata.as_ref().map(|m| &*m.name), + source.source = e.metadata.as_ref().and_then(|m| m.source.as_ref()).map(display), + }; + + span.in_scope(|| e.kind.trace_error()); + } + } +} + +impl Traceable for Header<'_> { + fn trace(&self, level: Level) { + event!(level, "header", name = self.name().as_str(), value = self.value()); + } +} + +impl Traceable for route::Outcome<'_> { + fn trace(&self, level: Level) { + 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); + } +} diff --git a/examples/hello/Cargo.toml b/examples/hello/Cargo.toml index 747887f7..03a01b1b 100644 --- a/examples/hello/Cargo.toml +++ b/examples/hello/Cargo.toml @@ -7,4 +7,3 @@ publish = false [dependencies] rocket = { path = "../../core/lib", features = ["secrets"] } -tracing-subscriber = "0.3" diff --git a/examples/hello/src/main.rs b/examples/hello/src/main.rs index 3efa6e75..10dbc09e 100644 --- a/examples/hello/src/main.rs +++ b/examples/hello/src/main.rs @@ -51,7 +51,7 @@ fn wave(name: &str, age: u8) -> String { // http://127.0.0.1:8000/?name=Rocketeer&lang=en&emoji // http://127.0.0.1:8000/?lang=ru&emoji&name=Rocketeer #[get("/?&")] -fn hello(lang: Option, opt: Options<'_>) -> String { +async fn hello(lang: Option, opt: Options<'_>) -> String { let mut greeting = String::new(); if opt.emoji { greeting.push_str("👋 "); @@ -74,8 +74,6 @@ fn hello(lang: Option, opt: Options<'_>) -> String { #[launch] fn rocket() -> _ { - // tracing_subscriber::fmt::init(); - // rocket::build() .mount("/", routes![hello]) .mount("/hello", routes![world, mir])