From 3816fe18bee7c47d6c9510b48c0ef656ba17d996 Mon Sep 17 00:00:00 2001 From: Sergio Benitez Date: Thu, 9 May 2024 04:56:16 -0700 Subject: [PATCH] wip: route tracing --- core/lib/src/config/config.rs | 2 +- core/lib/src/erased.rs | 5 + core/lib/src/lifecycle.rs | 20 ++-- core/lib/src/outcome.rs | 25 ++-- core/lib/src/request/request.rs | 12 +- core/lib/src/rocket.rs | 37 +----- core/lib/src/server.rs | 7 ++ core/lib/src/shield/shield.rs | 2 +- core/lib/src/trace/macros.rs | 22 +++- core/lib/src/trace/subscriber.rs | 198 +++++++++++++++---------------- core/lib/src/trace/traceable.rs | 80 ++++++++----- 11 files changed, 209 insertions(+), 201 deletions(-) diff --git a/core/lib/src/config/config.rs b/core/lib/src/config/config.rs index accac5aefd..220cabdc12 100644 --- a/core/lib/src/config/config.rs +++ b/core/lib/src/config/config.rs @@ -435,5 +435,5 @@ pub fn bail_with_config_error(error: figment::Error) -> T { #[doc(hidden)] // FIXME: Remove this funtion. pub fn pretty_print_error(error: figment::Error) { - error.trace() + error.trace_error() } diff --git a/core/lib/src/erased.rs b/core/lib/src/erased.rs index 1c0900a897..94dcf4f3a5 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, diff --git a/core/lib/src/lifecycle.rs b/core/lib/src/lifecycle.rs index 3508e1bf1c..c3bc5c48c4 100644 --- a/core/lib/src/lifecycle.rs +++ b/core/lib/src/lifecycle.rs @@ -1,6 +1,7 @@ use yansi::Paint; use futures::future::{FutureExt, Future}; +use crate::trace::traceable::Traceable; use crate::{route, Rocket, Orbit, Request, Response, Data}; use crate::data::IoHandler; use crate::http::{Method, Status, Header}; @@ -96,8 +97,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 +104,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); @@ -181,6 +180,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 +195,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 +203,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. diff --git a/core/lib/src/outcome.rs b/core/lib/src/outcome.rs index 98debf3079..35e67247dc 100644 --- a/core/lib/src/outcome.rs +++ b/core/lib/src/outcome.rs @@ -712,7 +712,7 @@ crate::export! { impl Outcome { #[inline] - fn dbg_str(&self) -> &'static str { + pub(crate) fn dbg_str(&self) -> &'static str { match self { Success(..) => "Success", Error(..) => "Error", @@ -730,27 +730,16 @@ impl Outcome { } } -pub(crate) struct Display<'a, 'r>(&'a route::Outcome<'r>); - -impl fmt::Display for Display<'_, '_> { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - write!(f, "{}", "Outcome: ".primary().bold())?; - - let color = self.0.color(); - match self.0 { - Success(r) => write!(f, "{}({})", "Success".paint(color), r.status().primary()), - Error(s) => write!(f, "{}({})", "Error".paint(color), s.primary()), - Forward((_, s)) => write!(f, "{}({})", "Forward".paint(color), s.primary()), +impl route::Outcome<'_> { + pub(crate) fn status(&self) -> Status { + match self { + Success(r) => r.status(), + Error(s) => *s, + Forward((_, s)) => *s, } } } -impl<'r> route::Outcome<'r> { - pub(crate) fn log_display(&self) -> Display<'_, 'r> { - Display(self) - } -} - impl fmt::Debug for Outcome { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { write!(f, "Outcome::{}", self.dbg_str()) diff --git a/core/lib/src/request/request.rs b/core/lib/src/request/request.rs index 989d7106e5..4874b21674 100644 --- a/core/lib/src/request/request.rs +++ b/core/lib/src/request/request.rs @@ -1112,10 +1112,14 @@ impl<'r> Request<'r> { // a security issue with Hyper, there isn't much we can do. #[cfg(debug_assertions)] if Origin::parse(uri.as_str()).is_err() { - warn!("Hyper/Rocket URI validity discord: {:?}", uri.as_str()); - info_!("Hyper believes the URI is valid while Rocket disagrees."); - info_!("This is likely a Hyper bug with potential security implications."); - warn_!("Please report this warning to Rocket's GitHub issue tracker."); + warn!( + name: "uri_discord", + %uri, + "Hyper/Rocket URI validity discord: {uri}\n\ + Hyper believes the URI is valid while Rocket disagrees.\n\ + This is likely a Hyper bug with potential security implications.\n\ + Please report this warning to Rocket's GitHub issue tracker." + ) } Origin::new(uri.path(), uri.query().map(Cow::Borrowed)) diff --git a/core/lib/src/rocket.rs b/core/lib/src/rocket.rs index 1840ff5a1b..b2278ab941 100644 --- a/core/lib/src/rocket.rs +++ b/core/lib/src/rocket.rs @@ -563,45 +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? let fairings = self.fairings.unique_set(); info_span!("config" [profile = %self.figment().profile()] => { - config.trace(); - self.figment().trace(); + config.trace_info(); + self.figment().trace_debug(); }); - info_span!("routes" [count = self.routes.len()] => self.routes().trace_all()); - info_span!("catchers" [count = self.catchers.len()] => self.catchers().trace_all()); - info_span!("fairings" [count = fairings.len()] => fairings.trace_all()); - - // trace::all("routes", self.routes()); - // tracing::info_span!("routes").in_scope(|| self.routes().for_each(|r| r.trace())); - // tracing::info_span!("catchers").in_scope(|| self.catchers().for_each(|c| c.trace())); - // for header in self.policies.values() { - // info!(name: "header", name = header.name().as_str(), value = header.value()); - // } - // - // warn!("Detected TLS-enabled liftoff without enabling HSTS."); - // warn!("Shield has enabled a default HSTS policy."); - // info!("To remove this warning, configure an HSTS policy."); - // }); - - // tracing::info_span!("routes") - // .in_scope(|| self.routes().for_each(|r| r.trace())); - // // self.polices.values().trace(); - // // for header in self.policies.values() { - // // info!(name: "header", name = header.name().as_str(), value = header.value()); - // // } - - // TODO: Store/print managed state type names? - // trace::collection_info!("routes" => self.routes()); - // trace::collection_info!("catchers" => self.catchers()); - // trace::collection_info!("fairings" => self.fairings.active_set()); - // trace::collection_info!("state" => self.active_set()); + info_span!("routes" [count = self.routes.len()] => self.routes().trace_all_info()); + info_span!("catchers" [count = self.catchers.len()] => self.catchers().trace_all_info()); + info_span!("fairings" [count = fairings.len()] => fairings.trace_all_info()); // Ignite the rocket. let rocket: Rocket = Rocket(Igniting { diff --git a/core/lib/src/server.rs b/core/lib/src/server.rs index f6796b38b9..c90d0234b6 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::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!("headers" => request.inner().headers().iter().trace_all_debug()); let mut response = request.into_response( stream, |rocket, request, data| Box::pin(rocket.preprocess(request, data)), diff --git a/core/lib/src/shield/shield.rs b/core/lib/src/shield/shield.rs index 0b92602093..803b5939e4 100644 --- a/core/lib/src/shield/shield.rs +++ b/core/lib/src/shield/shield.rs @@ -194,7 +194,7 @@ impl Fairing for Shield { && !self.is_enabled::(); info_span!("shield" [policies = self.policies.len()] => { - self.policies.values().trace_all(); + self.policies.values().trace_all_info(); if force_hsts { warn!("Detected TLS-enabled liftoff without enabling HSTS."); diff --git a/core/lib/src/trace/macros.rs b/core/lib/src/trace/macros.rs index b5dc28561b..a3ec72b990 100644 --- a/core/lib/src/trace/macros.rs +++ b/core/lib/src/trace/macros.rs @@ -21,7 +21,6 @@ macro_rules! declare_macro { ($d ($t:tt)*) => ({ #[allow(unused_imports)] use $crate::trace::macros::PaintExt as _; - $crate::tracing::$level!($d ($t)*); }) } @@ -46,10 +45,27 @@ macro_rules! declare_span_macro { #[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); + $crate::tracing::span!(tracing::Level::$level, $n $d (, $d ($f)* )?) + .in_scope(|| $in_scope); }) } ); } -declare_span_macro!(info_span INFO, trace_span TRACE); +declare_span_macro!(info_span INFO, trace_span TRACE, debug_span DEBUG); + +macro_rules! event { + ($level:expr, $($args:tt)*) => {{ + match $level { + $crate::tracing::Level::ERROR => event!(@$crate::tracing::Level::ERROR, $($args)*), + $crate::tracing::Level::WARN => event!(@$crate::tracing::Level::WARN, $($args)*), + $crate::tracing::Level::INFO => event!(@$crate::tracing::Level::INFO, $($args)*), + $crate::tracing::Level::DEBUG => event!(@$crate::tracing::Level::DEBUG, $($args)*), + $crate::tracing::Level::TRACE => event!(@$crate::tracing::Level::TRACE, $($args)*), + } + }}; + + (@$level:expr, $n:expr, $($args:tt)*) => {{ + $crate::tracing::event!(name: $n, target: concat!("rocket::", $n), $level, $($args)*); + }}; +} diff --git a/core/lib/src/trace/subscriber.rs b/core/lib/src/trace/subscriber.rs index 9699989e93..06ac304c5e 100644 --- a/core/lib/src/trace/subscriber.rs +++ b/core/lib/src/trace/subscriber.rs @@ -8,7 +8,7 @@ use std::fmt::{self, Debug, Display}; use tracing::{Event, Level, Metadata, Subscriber}; use tracing::level_filters::LevelFilter; use tracing::field::{Field, Visit}; -use tracing::span::{Attributes, Id}; +use tracing::span::{Attributes, Id, Record}; use tracing_subscriber::prelude::*; use tracing_subscriber::layer::Context; @@ -24,14 +24,14 @@ use crate::config::{Config, CliColors}; use crate::util::Formatter; pub trait PaintExt: Sized { - fn emoji(self) -> Painted; + fn emoji(self) -> Painted<&'static str>; } -impl PaintExt for &str { +impl PaintExt for Painted<&'static str> { /// Paint::masked(), but hidden on Windows due to broken output. See #1122. - fn emoji(self) -> Painted { + fn emoji(self) -> Painted<&'static str> { #[cfg(windows)] { Paint::new("").mask() } - #[cfg(not(windows))] { Paint::new(self).mask() } + #[cfg(not(windows))] { self.mask() } } } @@ -63,7 +63,7 @@ pub(crate) struct Data { } impl Data { - pub fn new(attrs: &T) -> Self { + pub fn new(attrs: T) -> Self { let mut data = Data { // start: Instant::now(), map: TinyVec::new(), @@ -106,51 +106,6 @@ struct RocketFmt { _subscriber: PhantomData S> } -// struct Printer { -// level: Level, -// } -// -// impl Printer { -// fn print(event: &Event) -// -// } - -macro_rules! log { - ($this:expr, $metadata:expr => $fmt:expr $(, $($t:tt)*)?) => { - let metadata = $metadata; - let (i, s, t) = ($this.indent(), $this.style(metadata), 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, $meta:expr => $fmt:literal $($t:tt)*) => { - log!($this, $meta => concat!($fmt, "\n") $($t)*); - }; -} - struct DisplayVisit(F); impl Visit for DisplayVisit { @@ -200,14 +155,27 @@ impl LookupSpan<'a>> RocketFmt { } fn indent(&self) -> &'static str { - match self.depth.load(Ordering::Acquire) { - 0 => "", - 1 => " >> ", - 2 => " >> ", - _ => " >> ", - } + static INDENT: &[&str] = &["", " ", " "]; + INDENT.get(self.depth()).copied().unwrap_or("--") + } + + fn marker(&self) -> &'static str { + static MARKER: &[&str] = &["", ">> ", ":: "]; + MARKER.get(self.depth()).copied().unwrap_or("-- ") + } + + fn depth(&self) -> usize { + 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(), @@ -218,38 +186,65 @@ impl LookupSpan<'a>> RocketFmt { } } - fn print(&self, event: &Event<'_>) { - let metadata = event.metadata(); + fn print_prefix(&self, meta: &Metadata<'_>) { + let (i, m, s) = (self.indent(), self.marker(), self.style(meta)); + match *meta.level() { + Level::WARN => print!("{i}{m}{} ", "warning:".paint(s).bold()), + Level::ERROR => print!("{i}{m}{} ", "error:".paint(s).bold()), + Level::DEBUG => print!("{i}{m}[{} {}] ", "debug".paint(s).bold(), meta.target()), + Level::TRACE => match (meta.file(), meta.line()) { + (Some(file), Some(line)) => print!( + "{i}{m}[{level} {target} {path}:{line}] ", + level = "trace".paint(s).bold(), + target = meta.target().paint(s).dim(), + path = RelPath(file.into()).underline(), + ), + _ => print!("{i}{m}[{} {}] ", "trace".paint(s).bold(), meta.target()) + } + _ => print!("{i}{m}"), + } + } + + fn print(&self, metadata: &Metadata<'_>, data: F) { let style = self.style(metadata); let fields = metadata.fields(); - if let Some(msg) = fields.field("message") { - event.record_display(|field: &Field, value: &dyn Display| { - if field == &msg { - log!(self, metadata => "{}", value.paint(style)); + if !fields.is_empty() { + self.print_prefix(metadata); + } + + let message = fields.field("message"); + if let Some(message_field) = &message { + data.record_display(|field: &Field, value: &dyn Display| { + if field == message_field { + for (i, line) in value.to_string().lines().enumerate() { + if i != 0 { + print!("{}{} ", self.indent(), "++".paint(style).dim()); + } + + println!("{}", line.paint(style)); + } } }); + } - self.print_fields_compact(false, metadata, event); - } else if !fields.is_empty() { - self.print_fields_compact(true, metadata, event); + if message.is_some() && fields.len() > 1 { + print!("{}{} ", self.indent(), "++".paint(style).dim()); + self.print_compact_fields(metadata, data) + } else if message.is_none() && !fields.is_empty() { + self.print_compact_fields(metadata, data); } } - fn print_fields_compact(&self, prefix: bool, metadata: &Metadata<'_>, fields: F) - where F: RecordFields - { + fn print_compact_fields(&self, metadata: &Metadata<'_>, data: F) { let key_style = self.style(metadata).bold(); let val_style = self.style(metadata).primary(); + let mut printed = false; - fields.record_display(|field: &Field, val: &dyn Display| { + data.record_display(|field: &Field, val: &dyn Display| { let key = field.name(); if key != "message" { - if !printed && prefix { - log!(self, metadata => "{}: {}", key.paint(key_style), val.paint(val_style)); - } else { - print!(" {}: {}", key.paint(key_style), val.paint(val_style)); - } - + if printed { print!(" "); } + print!("{}: {}", key.paint(key_style), val.paint(val_style)); printed = true; } }); @@ -257,11 +252,14 @@ impl LookupSpan<'a>> RocketFmt { println!(); } - fn print_fields(&self, metadata: &Metadata<'_>, fields: F) { + fn print_fields(&self, metadata: &Metadata<'_>, fields: F) + where F: RecordFields + { let style = self.style(metadata); fields.record_display(|key: &Field, value: &dyn Display| { if key.name() != "message" { - logln!(self, metadata => "{}: {}", key.paint(style), value.paint(style).primary()); + self.print_prefix(metadata); + println!("{}: {}", key.paint(style), value.paint(style).primary()); } }) } @@ -272,24 +270,18 @@ impl LookupSpan<'a>> Layer for RocketFmt { 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(), event.metadata().name()) { - ("config", "config") => self.print_fields(event.metadata(), event), - _ => self.print(event), - }; - } - - match event.metadata().name() { + 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 data = Data::new(event); - logln!(self, event.metadata() => "rocket has launched from {}", &data["endpoint"]); - + self.print_prefix(meta); + println!("{}{} {}", "🚀 ".paint(style).emoji(), + "Rocket has launched from".paint(style).primary().bold(), + &data["endpoint"].paint(style).primary().bold().underline()); } - _ => self.print(event), + _ => self.print(meta, event), } } @@ -299,26 +291,26 @@ impl LookupSpan<'a>> Layer for RocketFmt { match span.metadata().name() { "config" => println!("configured for {}", &data["profile"]), name => { - log!(self, span.metadata() => "{}", name); - self.print_fields_compact(false, span.metadata(), attrs); - // f.debug_map().entries(data.map.iter().map(|(k, v)| (k, v))).finish() + self.print_prefix(span.metadata()); + print!("{name} "); + self.print_compact_fields(span.metadata(), attrs); } } 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); + } + 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/traceable.rs b/core/lib/src/trace/traceable.rs index c5987190dd..605a4f36a8 100644 --- a/core/lib/src/trace/traceable.rs +++ b/core/lib/src/trace/traceable.rs @@ -1,35 +1,49 @@ use crate::fairing::Fairing; -use crate::{Catcher, Config, Route}; +use crate::{route, Catcher, Config, Route}; use crate::util::Formatter; use figment::Figment; use rocket::http::Header; +use tracing::Level; pub trait Traceable { - fn trace(&self); + 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 { - fn trace_all(self); +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) { - self.into_iter().for_each(|i| i.trace()) + fn trace_all(self, level: Level) { + self.into_iter().for_each(|i| i.trace(level)) } } impl Traceable for &T { - fn trace(&self) { - T::trace(self) + #[inline(always)] + fn trace(&self, level: Level) { + T::trace(self, level) } } impl Traceable for Figment { - fn trace(&self) { + fn trace(&self, level: Level) { for param in Config::PARAMETERS { if let Some(source) = self.find_metadata(param) { - tracing::trace! { + event! { level, "figment", param, %source.name, source.source = source.source.as_ref().map(|s| s.to_string()), @@ -40,8 +54,7 @@ impl Traceable for Figment { // Check for now deprecated config values. for (key, replacement) in Config::DEPRECATED_KEYS { if let Some(source) = self.find_metadata(key) { - warn! { - name: "deprecated", + event! { Level::WARN, "deprecated", key, replacement, %source.name, @@ -54,9 +67,8 @@ impl Traceable for Figment { } impl Traceable for Config { - fn trace(&self) { - info! { - name: "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, @@ -91,9 +103,9 @@ impl Traceable for Config { 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`; \ + "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", } } @@ -116,9 +128,8 @@ impl Traceable for Config { } impl Traceable for Route { - fn trace(&self) { - info! { - name: "route", + fn trace(&self, level: Level) { + event! { level, "route", name = self.name.as_ref().map(|n| &**n), method = %self.method, rank = self.rank, @@ -136,9 +147,8 @@ impl Traceable for Route { } impl Traceable for Catcher { - fn trace(&self) { - info! { - name: "catcher", + fn trace(&self, level: Level) { + event! { level, "catcher", name = self.name.as_ref().map(|n| &**n), code = self.code, rank = self.rank, @@ -148,13 +158,13 @@ impl Traceable for Catcher { } impl Traceable for &dyn Fairing { - fn trace(&self) { - info!(name: "fairing", name = self.info().name, kind = %self.info().kind) + 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) { + fn trace(&self, _: Level) { use figment::error::{OneOf as V, Kind::*}; match self { @@ -175,7 +185,7 @@ impl Traceable for figment::error::Kind { } impl Traceable for figment::Error { - fn trace(&self) { + fn trace(&self, _: Level) { for e in self.clone() { let span = tracing::error_span! { "config", @@ -184,16 +194,22 @@ impl Traceable for figment::Error { 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())), + source.source = e.metadata.as_ref().and_then(|m| m.source.as_ref()).map(display), }; - span.in_scope(|| e.kind.trace()); + span.in_scope(|| e.kind.trace_error()); } } } impl Traceable for Header<'_> { - fn trace(&self) { - info!(name: "header", name = self.name().as_str(), value = self.value()); + 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 = self.dbg_str(), status = self.status().code); } }