diff --git a/core/lib/Cargo.toml b/core/lib/Cargo.toml index b37254b14a..a29047041f 100644 --- a/core/lib/Cargo.toml +++ b/core/lib/Cargo.toml @@ -20,6 +20,7 @@ rust-version = "1.75" all-features = true [lints.rust] +unexpected_cfgs = "allow" rust_2018_idioms = "warn" # missing_docs = "warn" async_fn_in_trait = "allow" @@ -42,7 +43,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. @@ -87,6 +88,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/trace/mod.rs b/core/lib/src/trace/mod.rs index 4a160a4aaf..1f0bb2344f 100644 --- a/core/lib/src/trace/mod.rs +++ b/core/lib/src/trace/mod.rs @@ -1,5 +1,3 @@ -use rocket::Config; - #[macro_use] pub mod macros; #[cfg(feature = "trace")] @@ -7,7 +5,10 @@ pub mod subscriber; pub mod level; pub mod traceable; -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 df201e4e4b..0000000000 --- a/core/lib/src/trace/subscriber.rs +++ /dev/null @@ -1,425 +0,0 @@ -use std::cell::Cell; -use std::ops::Index; -use std::sync::OnceLock; -use std::sync::atomic::{AtomicU8, Ordering}; -use std::fmt::{self, Debug, Display}; -use std::thread::ThreadId; -use std::hash::{Hash, Hasher}; - -use tracing::{Event, Level, Metadata, Subscriber}; -use tracing::level_filters::LevelFilter; -use tracing::field::{Field, Visit}; -use tracing::span::{Attributes, Id, Record}; - -use tracing_subscriber::prelude::*; -use tracing_subscriber::layer::{Context, Layered}; -use tracing_subscriber::registry::{LookupSpan, SpanRef}; -use tracing_subscriber::{reload, filter, Layer, Registry}; -use tracing_subscriber::field::RecordFields; - -use tinyvec::TinyVec; -use yansi::{Condition, Paint, Painted, Style}; - -use crate::config::{Config, CliColors}; -use crate::util::Formatter; - -pub trait PaintExt: Sized { - fn emoji(self) -> Painted<&'static str>; -} - -impl PaintExt for Painted<&'static str> { - /// Paint::masked(), but hidden on Windows due to broken output. See #1122. - fn emoji(self) -> Painted<&'static str> { - #[cfg(windows)] { Paint::new("").mask() } - #[cfg(not(windows))] { self.mask() } - } -} - -#[derive(Default)] -pub struct IdentHasher(u128); - -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) { - self.0 = (self.0 << 64) | (i as u128); - } - - fn write_u128(&mut self, i: u128) { - self.0 = i; - } -} - -#[derive(Debug, Clone, Hash, PartialEq, Eq)] -pub struct RequestId { - thread: ThreadId, - span: Id, -} - -thread_local! { - pub static CURRENT_REQUEST_ID: Cell> = Cell::new(None); -} - -impl RequestId { - fn new(span: &Id) -> Self { - thread_local! { - pub static THREAD_ID: Cell> = Cell::new(None); - } - - RequestId { - span: span.clone(), - thread: THREAD_ID.get().unwrap_or_else(|| { - let id = std::thread::current().id(); - THREAD_ID.set(Some(id)); - id - }), - } - } - - fn of LookupSpan<'a>>(span: &SpanRef<'_, R>) -> Option { - span.extensions().get::().map(|id| id.as_u128()) - } - - fn current() -> Option { - CURRENT_REQUEST_ID.get() - } - - fn layer() -> RequestIdLayer { - RequestIdLayer - } - - fn as_u128(&self) -> u128 { - let mut hasher = IdentHasher::default(); - self.hash(&mut hasher); - hasher.0 - } -} - -struct RequestIdLayer; - -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(id)); - } - } - - fn on_enter(&self, id: &Id, ctxt: Context<'_, S>) { - let span = ctxt.span(id).expect("enter: span does not exist"); - if span.name() == "request" { - 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" { - CURRENT_REQUEST_ID.set(None); - } - } -} - -pub(crate) fn init(config: Option<&Config>) { - type RocketSubscriber = Layered; - - static HANDLE: OnceLock> = 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(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.set(cli_colors, log_level)).is_ok()); - } -} - -pub(crate) 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 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, -} - -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 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 { - 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 style(&self, metadata: &Metadata<'_>) -> Style { - match *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_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::INFO => print!("{i}{m}"), - level => print!("{i}{m}[{} {}] ", level.paint(s).bold(), meta.target()), - } - - if let Some(id) = RequestId::current() { - print!("[{id:x}] "); - } - } - - fn print(&self, metadata: &Metadata<'_>, data: F) { - let style = self.style(metadata); - let fields = metadata.fields(); - 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)); - } - } - }); - } - - if message.is_some() && fields.len() > 1 { - print!("{}{} ", self.indent(), "++".paint(style).dim()); - self.println_compact_fields(metadata, data) - } else if message.is_none() && !fields.is_empty() { - self.println_compact_fields(metadata, data); - } - } - - fn println_compact_fields(&self, metadata: &Metadata<'_>, data: F) { - self.print_compact_fields(metadata, data); - println!(); - } - - fn print_compact_fields(&self, metadata: &Metadata<'_>, data: F) { - let key_style = self.style(metadata).bold(); - let val_style = self.style(metadata).primary(); - - let mut printed = false; - data.record_display(|field: &Field, val: &dyn Display| { - let key = field.name(); - if key != "message" { - if printed { print!(" "); } - print!("{}: {}", key.paint(key_style), val.paint(val_style)); - printed = true; - } - }); - } - - 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" { - self.print_prefix(metadata); - println!("{}: {}", 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" => { - 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(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"); - let style = self.style(span.metadata()); - if &data["count"] != "0" { - let name = span.name(); - let emoji = match name { - "config" => "🔧 ", - "routes" => "📬 ", - "catchers" => "🚧 ", - "fairings" => "📦 ", - "shield" => "🛡️ ", - "request" => "● ", - _ => "", - }; - - self.print_prefix(span.metadata()); - print!("{}{}", emoji.paint(style).emoji(), name.paint(style).bold()); - if let Some(id) = RequestId::of(&span) { - print!(" [{id:x}]"); - } - - if !attrs.fields().is_empty() { - print!(" {}", "(".paint(style)); - self.print_compact_fields(span.metadata(), attrs); - print!("{}", ")".paint(style)); - } - - println!(); - } - - span.extensions_mut().replace(data); - } - - fn on_record(&self, id: &Id, values: &Record<'_>, ctxt: Context<'_, S>) { - let span = ctxt.span(id).expect("new_span: span does not exist"); - match span.extensions_mut().get_mut::() { - Some(data) => values.record(data), - None => span.extensions_mut().insert(Data::new(values)), - } - - self.print_prefix(span.metadata()); - self.println_compact_fields(span.metadata(), values); - } - - fn on_enter(&self, _: &Id, _: Context<'_, S>) { - self.depth.fetch_add(1, Ordering::AcqRel); - } - - fn on_exit(&self, _: &Id, _: Context<'_, S>) { - self.depth.fetch_sub(1, Ordering::AcqRel); - } -} diff --git a/core/lib/src/trace/subscriber/common.rs b/core/lib/src/trace/subscriber/common.rs new file mode 100644 index 0000000000..a35be827dd --- /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 0000000000..5dee0b03d4 --- /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 0000000000..d7a2e66d83 --- /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 0000000000..d0f4affa06 --- /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 pretty_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.pretty_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.pretty_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.pretty_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.pretty_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.pretty_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 0000000000..b40924d11d --- /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 0000000000..eeafc312fd --- /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 index 74ab1593c2..a698ccf8a6 100644 --- a/core/lib/src/trace/traceable.rs +++ b/core/lib/src/trace/traceable.rs @@ -137,6 +137,10 @@ impl Traceable for Route { 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)) diff --git a/examples/hello/Cargo.toml b/examples/hello/Cargo.toml index 747887f79b..03a01b1bbb 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 3efa6e75d8..10dbc09e05 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])