From 161f9383bd60b2055ba6fc29fc7677b6949246d2 Mon Sep 17 00:00:00 2001 From: CAD97 Date: Mon, 4 Apr 2022 11:04:47 -0500 Subject: [PATCH] Implement tracing-log on core dynamic metadata And now we reach the point of this commit series. tracing-log is now capable of implementing its dynamic metadata resolution on solely publicly available APIs*, and thus so can anyone else do the same. *Dispatch still uses #[doc(hidden)] APIs to create the value set. Figuring out how to best expose is still an open question. --- tracing-log/src/lib.rs | 308 ++++++-------------- tracing-log/tests/log_tracer.rs | 62 ++-- tracing-opentelemetry/src/subscriber.rs | 22 -- tracing-subscriber/src/fmt/format/json.rs | 11 - tracing-subscriber/src/fmt/format/mod.rs | 16 - tracing-subscriber/src/fmt/format/pretty.rs | 11 - 6 files changed, 131 insertions(+), 299 deletions(-) diff --git a/tracing-log/src/lib.rs b/tracing-log/src/lib.rs index 9fe16d7efd..50b26befc1 100644 --- a/tracing-log/src/lib.rs +++ b/tracing-log/src/lib.rs @@ -125,18 +125,10 @@ unused_parens, while_true )] -use once_cell::sync::Lazy; -use std::{fmt, io}; +use std::io; -use tracing_core::{ - callsite::{self, Callsite}, - collect, dispatch, - field::{self, Field, Visit}, - identify_callsite, - metadata::{Kind, Level}, - Event, Metadata, -}; +use tracing_core::{dispatch, dynamic_metadata, field, Event, Metadata}; #[cfg(feature = "log-tracer")] #[cfg_attr(docsrs, doc(cfg(feature = "log-tracer")))] @@ -169,7 +161,7 @@ pub(crate) fn dispatch_record(record: &log::Record<'_>) { return; } - let (_, keys, meta) = loglevel_to_cs(record.level()); + let (keys, meta) = level_to_meta(record.level()); let log_module = record.module_path(); let log_file = record.file(); @@ -181,12 +173,15 @@ pub(crate) fn dispatch_record(record: &log::Record<'_>) { dispatch.event(&Event::new( meta, + // The use of the normalized field set here is critical; it's what + // allows the Event to know to skip over them unless asked for. &meta.fields().value_set(&[ - (&keys.message, Some(record.args() as &dyn field::Value)), + (&keys.name, Some(&"log event" as &dyn field::Value)), (&keys.target, Some(&record.target())), - (&keys.module, module), (&keys.file, file), (&keys.line, line), + (&keys.module, module), + (&keys.message, Some(record.args())), ]), )); }); @@ -226,128 +221,113 @@ impl<'a> crate::sealed::Sealed for log::Metadata<'a> {} impl<'a> AsTrace for log::Metadata<'a> { type Trace = Metadata<'a>; fn as_trace(&self) -> Self::Trace { - let cs_id = identify_callsite!(loglevel_to_cs(self.level()).0); + let dynamic = level_to_meta(self.level()).1; Metadata::new( - "log record", + "log event", self.target(), self.level().as_trace(), None, None, None, - field::FieldSet::new(FIELD_NAMES, cs_id), - Kind::EVENT, + dynamic.fields(), + dynamic.kind().clone(), ) } } struct Fields { - message: field::Field, + name: field::Field, target: field::Field, - module: field::Field, file: field::Field, line: field::Field, + module: field::Field, + message: field::Field, } -static FIELD_NAMES: &[&str] = &[ - "message", - "log.target", - "log.module_path", - "log.file", - "log.line", -]; - impl Fields { - fn new(cs: &'static dyn Callsite) -> Self { - let fieldset = cs.metadata().fields(); - let message = fieldset.field("message").unwrap(); - let target = fieldset.field("log.target").unwrap(); - let module = fieldset.field("log.module_path").unwrap(); - let file = fieldset.field("log.file").unwrap(); - let line = fieldset.field("log.line").unwrap(); + fn new(meta: &Metadata<'_>) -> Self { + let mut fields = meta.fields_prenormal().iter(); + let name = fields.next().unwrap(); + let target = fields.next().unwrap(); + let _level = fields.next().unwrap(); + let file = fields.next().unwrap(); + let line = fields.next().unwrap(); + let module = fields.next().unwrap(); + let message = fields.next().unwrap(); + assert!(fields.next().is_none()); Fields { - message, + name, target, - module, file, line, + module, + message, } } } -macro_rules! log_cs { - ($level:expr, $cs:ident, $meta:ident, $ty:ident) => { - struct $ty; - static $cs: $ty = $ty; - static $meta: Metadata<'static> = Metadata::new( - "log event", - "log", - $level, - None, - None, - None, - field::FieldSet::new(FIELD_NAMES, identify_callsite!(&$cs)), - Kind::EVENT, - ); - - impl callsite::Callsite for $ty { - fn set_interest(&self, _: collect::Interest) {} - fn metadata(&self) -> &'static Metadata<'static> { - &$meta - } - } - }; -} - -log_cs!( - tracing_core::Level::TRACE, - TRACE_CS, - TRACE_META, - TraceCallsite -); -log_cs!( - tracing_core::Level::DEBUG, - DEBUG_CS, - DEBUG_META, - DebugCallsite -); -log_cs!(tracing_core::Level::INFO, INFO_CS, INFO_META, InfoCallsite); -log_cs!(tracing_core::Level::WARN, WARN_CS, WARN_META, WarnCallsite); -log_cs!( - tracing_core::Level::ERROR, - ERROR_CS, - ERROR_META, - ErrorCallsite -); - -static TRACE_FIELDS: Lazy = Lazy::new(|| Fields::new(&TRACE_CS)); -static DEBUG_FIELDS: Lazy = Lazy::new(|| Fields::new(&DEBUG_CS)); -static INFO_FIELDS: Lazy = Lazy::new(|| Fields::new(&INFO_CS)); -static WARN_FIELDS: Lazy = Lazy::new(|| Fields::new(&WARN_CS)); -static ERROR_FIELDS: Lazy = Lazy::new(|| Fields::new(&ERROR_CS)); - -fn level_to_cs(level: Level) -> (&'static dyn Callsite, &'static Fields) { - match level { - Level::TRACE => (&TRACE_CS, &*TRACE_FIELDS), - Level::DEBUG => (&DEBUG_CS, &*DEBUG_FIELDS), - Level::INFO => (&INFO_CS, &*INFO_FIELDS), - Level::WARN => (&WARN_CS, &*WARN_FIELDS), - Level::ERROR => (&ERROR_CS, &*ERROR_FIELDS), - } -} - -fn loglevel_to_cs( - level: log::Level, -) -> ( - &'static dyn Callsite, - &'static Fields, - &'static Metadata<'static>, -) { +fn level_to_meta(level: log::Level) -> (Fields, &'static Metadata<'static>) { match level { - log::Level::Trace => (&TRACE_CS, &*TRACE_FIELDS, &TRACE_META), - log::Level::Debug => (&DEBUG_CS, &*DEBUG_FIELDS, &DEBUG_META), - log::Level::Info => (&INFO_CS, &*INFO_FIELDS, &INFO_META), - log::Level::Warn => (&WARN_CS, &*WARN_FIELDS, &WARN_META), - log::Level::Error => (&ERROR_CS, &*ERROR_FIELDS, &ERROR_META), + log::Level::Trace => { + let meta = dynamic_metadata! { + name, + target: "log", + level: tracing_core::Level::TRACE, + file, + line, + module, + message, + }; + (Fields::new(meta), meta) + } + log::Level::Debug => { + let meta = dynamic_metadata! { + name, + target: "log", + level: tracing_core::Level::DEBUG, + file, + line, + module, + message, + }; + (Fields::new(meta), meta) + } + log::Level::Info => { + let meta = dynamic_metadata! { + name, + target: "log", + level: tracing_core::Level::INFO, + file, + line, + module, + message, + }; + (Fields::new(meta), meta) + } + log::Level::Warn => { + let meta = dynamic_metadata! { + name, + target: "log", + level: tracing_core::Level::WARN, + file, + line, + module, + message, + }; + (Fields::new(meta), meta) + } + log::Level::Error => { + let meta = dynamic_metadata! { + name, + target: "log", + level: tracing_core::Level::ERROR, + file, + line, + module, + message, + }; + (Fields::new(meta), meta) + } } } @@ -356,16 +336,16 @@ impl<'a> crate::sealed::Sealed for log::Record<'a> {} impl<'a> AsTrace for log::Record<'a> { type Trace = Metadata<'a>; fn as_trace(&self) -> Self::Trace { - let cs_id = identify_callsite!(loglevel_to_cs(self.level()).0); + let dynamic = level_to_meta(self.level()).1; Metadata::new( - "log record", + "log event", self.target(), self.level().as_trace(), self.file(), self.line(), self.module_path(), - field::FieldSet::new(FIELD_NAMES, cs_id), - Kind::EVENT, + dynamic.fields(), + dynamic.kind().clone(), ) } } @@ -434,105 +414,6 @@ impl AsLog for tracing_core::LevelFilter { } } } -/// Extends log `Event`s to provide complete `Metadata`. -/// -/// In `tracing-log`, an `Event` produced by a log (through [`AsTrace`]) has an hard coded -/// "log" target and no `file`, `line`, or `module_path` attributes. This happens because `Event` -/// requires its `Metadata` to be `'static`, while [`log::Record`]s provide them with a generic -/// lifetime. -/// -/// However, these values are stored in the `Event`'s fields and -/// the [`normalized_metadata`] method allows to build a new `Metadata` -/// that only lives as long as its source `Event`, but provides complete -/// data. -/// -/// It can typically be used by collectors when processing an `Event`, -/// to allow accessing its complete metadata in a consistent way, -/// regardless of the source of its source. -/// -/// [`normalized_metadata`]: NormalizeEvent#normalized_metadata -pub trait NormalizeEvent<'a>: crate::sealed::Sealed { - /// If this `Event` comes from a `log`, this method provides a new - /// normalized `Metadata` which has all available attributes - /// from the original log, including `file`, `line`, `module_path` - /// and `target`. - /// Returns `None` is the `Event` is not issued from a `log`. - fn normalized_metadata(&'a self) -> Option>; - /// Returns whether this `Event` represents a log (from the `log` crate) - fn is_log(&self) -> bool; -} - -impl<'a> crate::sealed::Sealed for Event<'a> {} - -impl<'a> NormalizeEvent<'a> for Event<'a> { - fn normalized_metadata(&'a self) -> Option> { - let original = self.metadata(); - if self.is_log() { - let mut fields = LogVisitor::new(level_to_cs(*original.level()).1); - self.record(&mut fields); - - Some(Metadata::new( - "log event", - fields.target.unwrap_or("log"), - *original.level(), - fields.file, - fields.line.map(|l| l as u32), - fields.module_path, - field::FieldSet::new(&["message"], original.callsite()), - Kind::EVENT, - )) - } else { - None - } - } - - fn is_log(&self) -> bool { - self.metadata().callsite() == identify_callsite!(level_to_cs(*self.metadata().level()).0) - } -} - -struct LogVisitor<'a> { - target: Option<&'a str>, - module_path: Option<&'a str>, - file: Option<&'a str>, - line: Option, - fields: &'static Fields, -} - -impl<'a> LogVisitor<'a> { - // We don't actually _use_ the provided event argument; it is simply to - // ensure that the `LogVisitor` does not outlive the event whose fields it - // is visiting, so that the reference casts in `record_str` are safe. - fn new(fields: &'static Fields) -> Self { - Self { - target: None, - module_path: None, - file: None, - line: None, - fields, - } - } -} - -impl<'a> Visit<'a> for LogVisitor<'a> { - fn record_debug(&mut self, _field: &Field, _value: &dyn fmt::Debug) {} - - fn record_u64(&mut self, field: &Field, value: u64) { - if field == &self.fields.line { - self.line = Some(value); - } - } - - fn record_str(&mut self, field: &Field, value: &'a str) { - if field == &self.fields.file { - self.file = Some(value); - } else if field == &self.fields.target { - self.target = Some(value); - } else if field == &self.fields.module { - self.module_path = Some(value); - } - } -} mod sealed { pub trait Sealed {} @@ -553,8 +434,7 @@ mod test { .build(); let meta = record.as_trace(); - let (cs, _keys, _) = loglevel_to_cs(record.level()); - let cs_meta = cs.metadata(); + let (_keys, cs_meta) = level_to_meta(record.level()); assert_eq!( meta.callsite(), cs_meta.callsite(), diff --git a/tracing-log/tests/log_tracer.rs b/tracing-log/tests/log_tracer.rs index 79d3f45cac..7ea9ffc716 100644 --- a/tracing-log/tests/log_tracer.rs +++ b/tracing-log/tests/log_tracer.rs @@ -2,10 +2,10 @@ use std::sync::{Arc, Mutex}; use tracing::collect::with_default; use tracing_core::span::{Attributes, Record}; use tracing_core::{span, Collect, Event, Level, LevelFilter, Metadata}; -use tracing_log::{LogTracer, NormalizeEvent}; +use tracing_log::LogTracer; struct State { - last_normalized_metadata: Mutex<(bool, Option)>, + last_normalized_metadata: Mutex>, } #[derive(PartialEq, Debug)] @@ -18,6 +18,19 @@ struct OwnedMetadata { line: Option, } +impl From> for OwnedMetadata { + fn from(meta: Metadata<'_>) -> Self { + Self { + name: meta.name().to_string(), + target: meta.target().to_string(), + level: *meta.level(), + module_path: meta.module_path().map(String::from), + file: meta.file().map(String::from), + line: meta.line(), + } + } +} + struct TestSubscriber(Arc); impl Collect for TestSubscriber { @@ -40,17 +53,7 @@ impl Collect for TestSubscriber { fn event(&self, event: &Event<'_>) { dbg!(event); - *self.0.last_normalized_metadata.lock().unwrap() = ( - event.is_log(), - event.normalized_metadata().map(|normalized| OwnedMetadata { - name: normalized.name().to_string(), - target: normalized.target().to_string(), - level: *normalized.level(), - module_path: normalized.module_path().map(String::from), - file: normalized.file().map(String::from), - line: normalized.line(), - }), - ) + *self.0.last_normalized_metadata.lock().unwrap() = Some(event.metadata().into()); } fn enter(&self, _span: &span::Id) {} @@ -66,7 +69,7 @@ impl Collect for TestSubscriber { fn normalized_metadata() { LogTracer::init().unwrap(); let me = Arc::new(State { - last_normalized_metadata: Mutex::new((false, None)), + last_normalized_metadata: Mutex::new(None), }); let state = me.clone(); @@ -80,15 +83,14 @@ fn normalized_metadata() { log::logger().log(&log); last( &state, - true, - Some(OwnedMetadata { + &OwnedMetadata { name: "log event".to_string(), target: "".to_string(), level: Level::INFO, module_path: None, file: None, line: None, - }), + }, ); let log = log::Record::builder() @@ -102,26 +104,36 @@ fn normalized_metadata() { log::logger().log(&log); last( &state, - true, - Some(OwnedMetadata { + &OwnedMetadata { name: "log event".to_string(), target: "log_tracer_target".to_string(), level: Level::INFO, module_path: Some("log_tracer".to_string()), file: Some("server.rs".to_string()), line: Some(144), - }), + }, ); tracing::info!("test with a tracing info"); - last(&state, false, None); + let line = line!() - 1; + let file = file!(); + last( + &state, + &OwnedMetadata { + name: format!("event {file}:{line}"), + target: module_path!().to_string(), + level: Level::INFO, + module_path: Some(module_path!().to_string()), + file: Some(file.to_string()), + line: Some(line), + }, + ); }) } -fn last(state: &State, should_be_log: bool, expected: Option) { +fn last(state: &State, expected: &OwnedMetadata) { let lock = state.last_normalized_metadata.lock().unwrap(); - let (is_log, metadata) = &*lock; + let metadata = &*lock; dbg!(&metadata); - assert_eq!(dbg!(*is_log), should_be_log); - assert_eq!(metadata.as_ref(), expected.as_ref()); + assert_eq!(metadata.as_ref(), Some(expected)); } diff --git a/tracing-opentelemetry/src/subscriber.rs b/tracing-opentelemetry/src/subscriber.rs index a305ec5de2..4401140650 100644 --- a/tracing-opentelemetry/src/subscriber.rs +++ b/tracing-opentelemetry/src/subscriber.rs @@ -11,8 +11,6 @@ use std::time::{Instant, SystemTime}; use std::{any::TypeId, ptr::NonNull}; use tracing_core::span::{self, Attributes, Id, Record}; use tracing_core::{field, Collect, Event}; -#[cfg(feature = "tracing-log")] -use tracing_log::NormalizeEvent; use tracing_subscriber::registry::LookupSpan; use tracing_subscriber::subscribe::Context; use tracing_subscriber::Subscribe; @@ -118,9 +116,6 @@ impl<'a> field::Visit<'_> for SpanEventVisitor<'a> { fn record_bool(&mut self, field: &field::Field, value: bool) { match field.name() { "message" => self.0.name = value.to_string().into(), - // Skip fields that are actually log metadata that have already been handled - #[cfg(feature = "tracing-log")] - name if name.starts_with("log.") => (), name => { self.0.attributes.push(KeyValue::new(name, value)); } @@ -133,9 +128,6 @@ impl<'a> field::Visit<'_> for SpanEventVisitor<'a> { fn record_f64(&mut self, field: &field::Field, value: f64) { match field.name() { "message" => self.0.name = value.to_string().into(), - // Skip fields that are actually log metadata that have already been handled - #[cfg(feature = "tracing-log")] - name if name.starts_with("log.") => (), name => { self.0.attributes.push(KeyValue::new(name, value)); } @@ -148,9 +140,6 @@ impl<'a> field::Visit<'_> for SpanEventVisitor<'a> { fn record_i64(&mut self, field: &field::Field, value: i64) { match field.name() { "message" => self.0.name = value.to_string().into(), - // Skip fields that are actually log metadata that have already been handled - #[cfg(feature = "tracing-log")] - name if name.starts_with("log.") => (), name => { self.0.attributes.push(KeyValue::new(name, value)); } @@ -163,9 +152,6 @@ impl<'a> field::Visit<'_> for SpanEventVisitor<'a> { fn record_str(&mut self, field: &field::Field, value: &str) { match field.name() { "message" => self.0.name = value.to_string().into(), - // Skip fields that are actually log metadata that have already been handled - #[cfg(feature = "tracing-log")] - name if name.starts_with("log.") => (), name => { self.0 .attributes @@ -181,9 +167,6 @@ impl<'a> field::Visit<'_> for SpanEventVisitor<'a> { fn record_debug(&mut self, field: &field::Field, value: &dyn fmt::Debug) { match field.name() { "message" => self.0.name = format!("{:?}", value).into(), - // Skip fields that are actually log metadata that have already been handled - #[cfg(feature = "tracing-log")] - name if name.starts_with("log.") => (), name => { self.0 .attributes @@ -624,11 +607,6 @@ where if let Some(span) = ctx.lookup_current() { // Performing read operations before getting a write lock to avoid a deadlock // See https://github.com/tokio-rs/tracing/issues/763 - #[cfg(feature = "tracing-log")] - let normalized_meta = event.normalized_metadata(); - #[cfg(feature = "tracing-log")] - let meta = normalized_meta.unwrap_or_else(|| event.metadata()); - #[cfg(not(feature = "tracing-log"))] let meta = event.metadata(); let target = Key::new("target").string(meta.target().to_owned()); diff --git a/tracing-subscriber/src/fmt/format/json.rs b/tracing-subscriber/src/fmt/format/json.rs index 9a5572d389..cee593d6cc 100644 --- a/tracing-subscriber/src/fmt/format/json.rs +++ b/tracing-subscriber/src/fmt/format/json.rs @@ -20,9 +20,6 @@ use tracing_core::{ }; use tracing_serde::AsSerde; -#[cfg(feature = "tracing-log")] -use tracing_log::NormalizeEvent; - /// Marker for [`Format`] that indicates that the newline-delimited JSON log /// format should be used. /// @@ -211,11 +208,6 @@ where let mut timestamp = String::new(); self.timer.format_time(&mut Writer::new(&mut timestamp))?; - #[cfg(feature = "tracing-log")] - let normalized_meta = event.normalized_metadata(); - #[cfg(feature = "tracing-log")] - let meta = normalized_meta.unwrap_or_else(|| event.metadata()); - #[cfg(not(feature = "tracing-log"))] let meta = event.metadata(); let mut visit = || { @@ -494,9 +486,6 @@ impl<'a> field::Visit<'_> for JsonVisitor<'a> { fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { match field.name() { - // Skip fields that are actually log metadata that have already been handled - #[cfg(feature = "tracing-log")] - name if name.starts_with("log.") => (), name if name.starts_with("r#") => { self.values .insert(&name[2..], serde_json::Value::from(format!("{:?}", value))); diff --git a/tracing-subscriber/src/fmt/format/mod.rs b/tracing-subscriber/src/fmt/format/mod.rs index df8e44a632..0fb286271f 100644 --- a/tracing-subscriber/src/fmt/format/mod.rs +++ b/tracing-subscriber/src/fmt/format/mod.rs @@ -42,9 +42,6 @@ use tracing_core::{ span, Collect, Event, Level, }; -#[cfg(feature = "tracing-log")] -use tracing_log::NormalizeEvent; - #[cfg(feature = "ansi")] use ansi_term::{Colour, Style}; @@ -926,11 +923,6 @@ where mut writer: Writer<'_>, event: &Event<'_>, ) -> fmt::Result { - #[cfg(feature = "tracing-log")] - let normalized_meta = event.normalized_metadata(); - #[cfg(feature = "tracing-log")] - let meta = normalized_meta.unwrap_or_else(|| event.metadata()); - #[cfg(not(feature = "tracing-log"))] let meta = event.metadata(); // if the `Format` struct *also* has an ANSI color configuration, @@ -1041,11 +1033,6 @@ where mut writer: Writer<'_>, event: &Event<'_>, ) -> fmt::Result { - #[cfg(feature = "tracing-log")] - let normalized_meta = event.normalized_metadata(); - #[cfg(feature = "tracing-log")] - let meta = normalized_meta.unwrap_or_else(|| event.metadata()); - #[cfg(not(feature = "tracing-log"))] let meta = event.metadata(); self.format_timestamp(&mut writer)?; @@ -1235,9 +1222,6 @@ impl<'a> field::Visit<'_> for DefaultVisitor<'a> { self.maybe_pad(); self.result = match field.name() { "message" => write!(self.writer, "{:?}", value), - // Skip fields that are actually log metadata that have already been handled - #[cfg(feature = "tracing-log")] - name if name.starts_with("log.") => Ok(()), name if name.starts_with("r#") => write!( self.writer, "{}{}{:?}", diff --git a/tracing-subscriber/src/fmt/format/pretty.rs b/tracing-subscriber/src/fmt/format/pretty.rs index 9347a3a0c4..494a4b0d8f 100644 --- a/tracing-subscriber/src/fmt/format/pretty.rs +++ b/tracing-subscriber/src/fmt/format/pretty.rs @@ -11,9 +11,6 @@ use tracing_core::{ Collect, Event, Level, }; -#[cfg(feature = "tracing-log")] -use tracing_log::NormalizeEvent; - use ansi_term::{Colour, Style}; /// An excessively pretty, human-readable event formatter. @@ -178,11 +175,6 @@ where mut writer: Writer<'_>, event: &Event<'_>, ) -> fmt::Result { - #[cfg(feature = "tracing-log")] - let normalized_meta = event.normalized_metadata(); - #[cfg(feature = "tracing-log")] - let meta = normalized_meta.unwrap_or_else(|| event.metadata()); - #[cfg(not(feature = "tracing-log"))] let meta = event.metadata(); write!(&mut writer, " ")?; @@ -468,9 +460,6 @@ impl<'a> field::Visit<'_> for PrettyVisitor<'a> { let bold = self.bold(); match field.name() { "message" => self.write_padded(&format_args!("{}{:?}", self.style.prefix(), value,)), - // Skip fields that are actually log metadata that have already been handled - #[cfg(feature = "tracing-log")] - name if name.starts_with("log.") => self.result = Ok(()), name if name.starts_with("r#") => self.write_padded(&format_args!( "{}{}{}: {:?}", bold.prefix(),