diff --git a/examples/Cargo.toml b/examples/Cargo.toml index 14d2ee34de..1f829940a0 100644 --- a/examples/Cargo.toml +++ b/examples/Cargo.toml @@ -32,7 +32,7 @@ futures = "0.3" tokio = { version = "1.1", features = ["full"] } # env-logger example -env_logger = "0.7" +env_logger = "0.9" # tower examples tower = { version = "0.4.4", features = ["full"] } diff --git a/examples/examples/hyper-echo.rs b/examples/examples/hyper-echo.rs index 3404a8d5e9..f0396d19cf 100644 --- a/examples/examples/hyper-echo.rs +++ b/examples/examples/hyper-echo.rs @@ -92,17 +92,9 @@ async fn echo(req: Request) -> Result, hyper::Error> { #[tokio::main] async fn main() -> Result<(), Box> { - use tracing_log::env_logger::BuilderExt; - let subscriber = tracing_subscriber::fmt() .with_max_level(Level::TRACE) .finish(); - let mut builder = env_logger::Builder::new(); - builder - .filter(Some("hyper_echo"), log::LevelFilter::Off) - .filter(Some("hyper"), log::LevelFilter::Trace) - .emit_traces() // from `tracing_log::env_logger::BuilderExt` - .try_init()?; tracing::subscriber::set_global_default(subscriber)?; let local_addr: std::net::SocketAddr = ([127, 0, 0, 1], 3000).into(); diff --git a/examples/examples/opentelemetry.rs b/examples/examples/opentelemetry.rs index 5c4b4c484a..fbc7469080 100644 --- a/examples/examples/opentelemetry.rs +++ b/examples/examples/opentelemetry.rs @@ -1,3 +1,4 @@ +use opentelemetry::global; use std::{error::Error, thread, time::Duration}; use tracing::{span, trace, warn}; use tracing_attributes::instrument; @@ -26,16 +27,20 @@ fn main() -> Result<(), Box> { .with(opentelemetry) .try_init()?; - let root = span!(tracing::Level::INFO, "app_start", work_units = 2); - let _enter = root.enter(); + { + let root = span!(tracing::Level::INFO, "app_start", work_units = 2); + let _enter = root.enter(); - let work_result = expensive_work(); + let work_result = expensive_work(); - span!(tracing::Level::INFO, "faster_work") - .in_scope(|| thread::sleep(Duration::from_millis(10))); + span!(tracing::Level::INFO, "faster_work") + .in_scope(|| thread::sleep(Duration::from_millis(10))); - warn!("About to exit!"); - trace!("status: {}", work_result); + warn!("About to exit!"); + trace!("status: {}", work_result); + } + + global::shutdown_tracer_provider(); Ok(()) } diff --git a/tracing-appender/Cargo.toml b/tracing-appender/Cargo.toml index c57932b503..2d02b38e95 100644 --- a/tracing-appender/Cargo.toml +++ b/tracing-appender/Cargo.toml @@ -32,6 +32,12 @@ default-features = false features = ["fmt", "std"] [dev-dependencies] + +criterion = { version = "0.3", default_features = false } tracing = { path = "../tracing", version = "0.1" } time = { version = "0.3", default-features = false, features = ["formatting", "parsing"] } tempfile = "3" + +[[bench]] +name = "bench" +harness = false \ No newline at end of file diff --git a/tracing-appender/benches/bench.rs b/tracing-appender/benches/bench.rs new file mode 100644 index 0000000000..e8ea4d75a6 --- /dev/null +++ b/tracing-appender/benches/bench.rs @@ -0,0 +1,134 @@ +use criterion::{criterion_group, criterion_main, Criterion}; +use std::{ + thread::{self, JoinHandle}, + time::Instant, +}; +use tracing::{event, Level}; +use tracing_appender::non_blocking; +use tracing_subscriber::fmt::MakeWriter; + +// a no-op writer is used in order to measure the overhead incurred by +// tracing-subscriber. +#[derive(Clone)] +struct NoOpWriter; + +impl NoOpWriter { + fn new() -> NoOpWriter { + NoOpWriter + } +} + +impl<'a> MakeWriter<'a> for NoOpWriter { + type Writer = NoOpWriter; + + fn make_writer(&self) -> Self::Writer { + self.clone() + } +} + +impl std::io::Write for NoOpWriter { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + Ok(buf.len()) + } + + fn flush(&mut self) -> std::io::Result<()> { + Ok(()) + } +} + +fn synchronous_benchmark(c: &mut Criterion) { + let mut group = c.benchmark_group("synchronous"); + group.bench_function("single_thread", |b| { + let subscriber = tracing_subscriber::fmt().with_writer(NoOpWriter::new()); + tracing::subscriber::with_default(subscriber.finish(), || { + b.iter(|| event!(Level::INFO, "event")) + }); + }); + + group.bench_function("multiple_writers", |b| { + b.iter_custom(|iters| { + let mut handles: Vec> = Vec::new(); + + let start = Instant::now(); + + let make_writer = NoOpWriter::new(); + let cloned_make_writer = make_writer.clone(); + + handles.push(thread::spawn(move || { + let subscriber = tracing_subscriber::fmt().with_writer(make_writer); + tracing::subscriber::with_default(subscriber.finish(), || { + for _ in 0..iters { + event!(Level::INFO, "event"); + } + }); + })); + + handles.push(thread::spawn(move || { + let subscriber = tracing_subscriber::fmt().with_writer(cloned_make_writer); + tracing::subscriber::with_default(subscriber.finish(), || { + for _ in 0..iters { + event!(Level::INFO, "event"); + } + }); + })); + + for handle in handles { + let _ = handle.join(); + } + + start.elapsed() + }); + }); +} + +fn non_blocking_benchmark(c: &mut Criterion) { + let mut group = c.benchmark_group("non_blocking"); + + group.bench_function("single_thread", |b| { + let (non_blocking, _guard) = non_blocking(NoOpWriter::new()); + let subscriber = tracing_subscriber::fmt().with_writer(non_blocking); + + tracing::subscriber::with_default(subscriber.finish(), || { + b.iter(|| event!(Level::INFO, "event")) + }); + }); + + group.bench_function("multiple_writers", |b| { + b.iter_custom(|iters| { + let (non_blocking, _guard) = non_blocking(NoOpWriter::new()); + + let mut handles: Vec> = Vec::new(); + + let start = Instant::now(); + + let cloned_make_writer = non_blocking.clone(); + + handles.push(thread::spawn(move || { + let subscriber = tracing_subscriber::fmt().with_writer(non_blocking); + tracing::subscriber::with_default(subscriber.finish(), || { + for _ in 0..iters { + event!(Level::INFO, "event"); + } + }); + })); + + handles.push(thread::spawn(move || { + let subscriber = tracing_subscriber::fmt().with_writer(cloned_make_writer); + tracing::subscriber::with_default(subscriber.finish(), || { + for _ in 0..iters { + event!(Level::INFO, "event"); + } + }); + })); + + for handle in handles { + let _ = handle.join(); + } + + start.elapsed() + }); + }); +} + +criterion_group!(benches, synchronous_benchmark, non_blocking_benchmark); +criterion_main!(benches); diff --git a/tracing-attributes/Cargo.toml b/tracing-attributes/Cargo.toml index 8bc4a96069..85e51f6ffe 100644 --- a/tracing-attributes/Cargo.toml +++ b/tracing-attributes/Cargo.toml @@ -46,7 +46,7 @@ quote = "1" [dev-dependencies] tracing = { path = "../tracing", version = "0.1" } tracing-mock = { path = "../tracing-mock", features = ["tokio-test"] } -tokio-test = { version = "0.2.0" } +tokio-test = { version = "0.3.0" } tracing-core = { path = "../tracing-core", version = "0.1"} async-trait = "0.1.44" diff --git a/tracing-core/Cargo.toml b/tracing-core/Cargo.toml index 77075846e7..cedffe7bfc 100644 --- a/tracing-core/Cargo.toml +++ b/tracing-core/Cargo.toml @@ -28,13 +28,13 @@ rust-version = "1.49.0" [features] default = ["std", "valuable/std"] -std = ["lazy_static"] +std = ["once_cell"] [badges] maintenance = { status = "actively-developed" } [dependencies] -lazy_static = { version = "1.0.2", optional = true } +once_cell = { version = "1.12", optional = true } [target.'cfg(tracing_unstable)'.dependencies] valuable = { version = "0.1.0", optional = true, default_features = false } diff --git a/tracing-core/src/callsite.rs b/tracing-core/src/callsite.rs index 573125a89a..87d084647b 100644 --- a/tracing-core/src/callsite.rs +++ b/tracing-core/src/callsite.rs @@ -253,6 +253,11 @@ static CALLSITES: Callsites = Callsites { static DISPATCHERS: Dispatchers = Dispatchers::new(); +#[cfg(feature = "std")] +static LOCKED_CALLSITES: once_cell::sync::Lazy>> = + once_cell::sync::Lazy::new(Default::default); + +#[cfg(not(feature = "std"))] crate::lazy_static! { static ref LOCKED_CALLSITES: Mutex> = Mutex::new(Vec::new()); } @@ -510,6 +515,7 @@ mod private { #[cfg(feature = "std")] mod dispatchers { use crate::dispatcher; + use once_cell::sync::Lazy; use std::sync::{ atomic::{AtomicBool, Ordering}, RwLock, RwLockReadGuard, RwLockWriteGuard, @@ -519,9 +525,8 @@ mod dispatchers { has_just_one: AtomicBool, } - crate::lazy_static! { - static ref LOCKED_DISPATCHERS: RwLock> = RwLock::new(Vec::new()); - } + static LOCKED_DISPATCHERS: Lazy>> = + Lazy::new(Default::default); pub(super) enum Rebuilder<'a> { JustOne, diff --git a/tracing-core/src/lib.rs b/tracing-core/src/lib.rs index 7424a6cb3f..eceef7be22 100644 --- a/tracing-core/src/lib.rs +++ b/tracing-core/src/lib.rs @@ -254,10 +254,6 @@ macro_rules! metadata { }; } -// when `std` is enabled, use the `lazy_static` crate from crates.io -#[cfg(feature = "std")] -pub(crate) use lazy_static::lazy_static; - // Facade module: `no_std` uses spinlocks, `std` uses the mutexes in the standard library #[cfg(not(feature = "std"))] #[macro_use] diff --git a/tracing-error/src/lib.rs b/tracing-error/src/lib.rs index 88f5ae228d..b94205ceeb 100644 --- a/tracing-error/src/lib.rs +++ b/tracing-error/src/lib.rs @@ -221,7 +221,7 @@ pub use self::layer::ErrorLayer; pub mod prelude { //! The `tracing-error` prelude. //! - //! This brings into scope the `InstrumentError, `InstrumentResult`, and `ExtractSpanTrace` + //! This brings into scope the `InstrumentError`, `InstrumentResult`, and `ExtractSpanTrace` //! extension traits. These traits allow attaching `SpanTrace`s to errors and //! subsequently retrieving them from `dyn Error` trait objects. diff --git a/tracing-flame/Cargo.toml b/tracing-flame/Cargo.toml index 5c6b9c0ba5..43ee62c922 100644 --- a/tracing-flame/Cargo.toml +++ b/tracing-flame/Cargo.toml @@ -28,7 +28,8 @@ smallvec = ["tracing-subscriber/smallvec"] [dependencies] tracing-subscriber = { path = "../tracing-subscriber", version = "0.3", default-features = false, features = ["registry", "fmt"] } tracing = { path = "../tracing", version = "0.1.12", default-features = false, features = ["std"] } -lazy_static = "1.3.0" +once_cell = "1.12" + [dev-dependencies] tempfile = "3" diff --git a/tracing-flame/src/lib.rs b/tracing-flame/src/lib.rs index b37bae74c1..f7d670aa61 100644 --- a/tracing-flame/src/lib.rs +++ b/tracing-flame/src/lib.rs @@ -137,7 +137,7 @@ pub use error::Error; use error::Kind; -use lazy_static::lazy_static; +use once_cell::sync::Lazy; use std::cell::Cell; use std::fmt; use std::fmt::Write as _; @@ -158,9 +158,7 @@ use tracing_subscriber::Layer; mod error; -lazy_static! { - static ref START: Instant = Instant::now(); -} +static START: Lazy = Lazy::new(Instant::now); thread_local! { static LAST_EVENT: Cell = Cell::new(*START); diff --git a/tracing-futures/Cargo.toml b/tracing-futures/Cargo.toml index 08afaa36bd..6347b97449 100644 --- a/tracing-futures/Cargo.toml +++ b/tracing-futures/Cargo.toml @@ -36,7 +36,7 @@ tokio = { version = "0.1", optional = true } [dev-dependencies] tokio = "0.1.22" -tokio-test = "0.2" +tokio-test = "0.3" tracing-core = { path = "../tracing-core", version = "0.1.2" } tracing-mock = { path = "../tracing-mock" } diff --git a/tracing-journald/Cargo.toml b/tracing-journald/Cargo.toml index c5cea152d5..e4f5eca8a1 100644 --- a/tracing-journald/Cargo.toml +++ b/tracing-journald/Cargo.toml @@ -18,9 +18,9 @@ rust-version = "1.49.0" [dependencies] libc = "0.2.107" tracing-core = { path = "../tracing-core", version = "0.1.10" } -tracing-subscriber = { path = "../tracing-subscriber", version = "0.3" } +tracing-subscriber = { path = "../tracing-subscriber", version = "0.3", default-features = false, features = ["registry"] } [dev-dependencies] serde_json = "1.0.68" serde = { version = "1.0.130", features = ["derive"] } -tracing = { path = "../tracing", version = "0.1" } \ No newline at end of file +tracing = { path = "../tracing", version = "0.1" } diff --git a/tracing-log/Cargo.toml b/tracing-log/Cargo.toml index b482341eab..a774357788 100644 --- a/tracing-log/Cargo.toml +++ b/tracing-log/Cargo.toml @@ -27,8 +27,8 @@ interest-cache = ["lru", "ahash"] [dependencies] tracing-core = { path = "../tracing-core", version = "0.1.17"} log = { version = "0.4" } -lazy_static = "1.3.0" -env_logger = { version = "0.7", optional = true } +once_cell = "1.12" +env_logger = { version = "0.8", optional = true } lru = { version = "0.7.0", optional = true } ahash = { version = "0.7.4", optional = true } diff --git a/tracing-log/src/interest_cache.rs b/tracing-log/src/interest_cache.rs index fb3da875eb..aabf9ebaf7 100644 --- a/tracing-log/src/interest_cache.rs +++ b/tracing-log/src/interest_cache.rs @@ -1,6 +1,7 @@ use ahash::AHasher; use log::{Level, Metadata}; use lru::LruCache; +use once_cell::sync::Lazy; use std::cell::RefCell; use std::hash::Hasher; use std::sync::atomic::{AtomicUsize, Ordering}; @@ -140,12 +141,10 @@ static SENTINEL_METADATA: tracing_core::Metadata<'static> = tracing_core::Metada tracing_core::metadata::Kind::EVENT, ); -lazy_static::lazy_static! { - static ref CONFIG: Mutex = { - tracing_core::callsite::register(&SENTINEL_CALLSITE); - Mutex::new(InterestCacheConfig::disabled()) - }; -} +static CONFIG: Lazy> = Lazy::new(|| { + tracing_core::callsite::register(&SENTINEL_CALLSITE); + Mutex::new(InterestCacheConfig::disabled()) +}); thread_local! { static STATE: RefCell = { @@ -236,10 +235,7 @@ mod tests { fn lock_for_test() -> impl Drop { // We need to make sure only one test runs at a time. - - lazy_static::lazy_static! { - static ref LOCK: Mutex<()> = Mutex::new(()); - } + static LOCK: Lazy> = Lazy::new(Mutex::new); match LOCK.lock() { Ok(guard) => guard, diff --git a/tracing-log/src/lib.rs b/tracing-log/src/lib.rs index 09e9114a4c..44b3f1d32d 100644 --- a/tracing-log/src/lib.rs +++ b/tracing-log/src/lib.rs @@ -128,7 +128,7 @@ unused_parens, while_true )] -use lazy_static::lazy_static; +use once_cell::sync::Lazy; use std::{fmt, io}; @@ -346,13 +346,11 @@ log_cs!( ErrorCallsite ); -lazy_static! { - static ref TRACE_FIELDS: Fields = Fields::new(&TRACE_CS); - static ref DEBUG_FIELDS: Fields = Fields::new(&DEBUG_CS); - static ref INFO_FIELDS: Fields = Fields::new(&INFO_CS); - static ref WARN_FIELDS: Fields = Fields::new(&WARN_CS); - static ref ERROR_FIELDS: Fields = Fields::new(&ERROR_CS); -} +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 { diff --git a/tracing-mock/Cargo.toml b/tracing-mock/Cargo.toml index c54adac51d..3b74dced26 100644 --- a/tracing-mock/Cargo.toml +++ b/tracing-mock/Cargo.toml @@ -20,7 +20,7 @@ publish = false [dependencies] tracing = { path = "../tracing", version = "0.1", default-features = false } tracing-core = { path = "../tracing-core", version = "0.1", default-features = false } -tokio-test = { version = "0.2.0", optional = true } +tokio-test = { version = "0.3.0", optional = true } [package.metadata.docs.rs] all-features = true diff --git a/tracing-opentelemetry/Cargo.toml b/tracing-opentelemetry/Cargo.toml index 788db1eb26..9e98b68f33 100644 --- a/tracing-opentelemetry/Cargo.toml +++ b/tracing-opentelemetry/Cargo.toml @@ -28,6 +28,7 @@ tracing = { path = "../tracing", version = "0.1", default-features = false, feat tracing-core = { path = "../tracing-core", version = "0.1" } tracing-subscriber = { path = "../tracing-subscriber", version = "0.3", default-features = false, features = ["registry", "std"] } tracing-log = { path = "../tracing-log", version = "0.1", default-features = false, optional = true } +once_cell = "1" [dev-dependencies] async-trait = "0.1" diff --git a/tracing-opentelemetry/src/layer.rs b/tracing-opentelemetry/src/layer.rs index bdaf1c32fa..2c4749a1c1 100644 --- a/tracing-opentelemetry/src/layer.rs +++ b/tracing-opentelemetry/src/layer.rs @@ -1,4 +1,5 @@ use crate::{OtelData, PreSampledTracer}; +use once_cell::unsync; use opentelemetry::{ trace::{self as otel, noop, TraceContextExt}, Context as OtelContext, Key, KeyValue, Value, @@ -7,6 +8,7 @@ use std::any::TypeId; use std::borrow::Cow; use std::fmt; use std::marker; +use std::thread; use std::time::{Instant, SystemTime}; use tracing_core::span::{self, Attributes, Id, Record}; use tracing_core::{field, Event, Subscriber}; @@ -28,8 +30,9 @@ const SPAN_STATUS_MESSAGE_FIELD: &str = "otel.status_message"; /// [tracing]: https://github.com/tokio-rs/tracing pub struct OpenTelemetryLayer { tracer: T, - event_location: bool, + location: bool, tracked_inactivity: bool, + with_threads: bool, get_context: WithContext, _registry: marker::PhantomData, } @@ -312,8 +315,9 @@ where pub fn new(tracer: T) -> Self { OpenTelemetryLayer { tracer, - event_location: true, + location: true, tracked_inactivity: true, + with_threads: true, get_context: WithContext(Self::get_context), _registry: marker::PhantomData, } @@ -351,20 +355,43 @@ where { OpenTelemetryLayer { tracer, - event_location: self.event_location, + location: self.location, tracked_inactivity: self.tracked_inactivity, + with_threads: self.with_threads, get_context: WithContext(OpenTelemetryLayer::::get_context), _registry: self._registry, } } - /// Sets whether or not event span's metadata should include detailed location - /// information, such as the file, module and line number. + /// Sets whether or not span and event metadata should include OpenTelemetry + /// attributes with location information, such as the file, module and line number. /// - /// By default, event locations are enabled. + /// These attributes follow the [OpenTelemetry semantic conventions for + /// source locations][conv]. + /// + /// By default, locations are enabled. + /// + /// [conv]: https://opentelemetry.io/docs/reference/specification/trace/semantic_conventions/span-general/#source-code-attributes + pub fn with_location(self, location: bool) -> Self { + Self { location, ..self } + } + + /// Sets whether or not span and event metadata should include OpenTelemetry + /// attributes with location information, such as the file, module and line number. + /// + /// These attributes follow the [OpenTelemetry semantic conventions for + /// source locations][conv]. + /// + /// By default, locations are enabled. + /// + /// [conv]: https://opentelemetry.io/docs/reference/specification/trace/semantic_conventions/span-general/#source-code-attributes + #[deprecated( + since = "0.17.3", + note = "renamed to `OpenTelemetrySubscriber::with_location`" + )] pub fn with_event_location(self, event_location: bool) -> Self { Self { - event_location, + location: event_location, ..self } } @@ -379,6 +406,20 @@ where } } + /// Sets whether or not spans record additional attributes for the thread + /// name and thread ID of the thread they were created on, following the + /// [OpenTelemetry semantic conventions for threads][conv]. + /// + /// By default, thread attributes are enabled. + /// + /// [conv]: https://opentelemetry.io/docs/reference/specification/trace/semantic_conventions/span-general/#general-thread-attributes + pub fn with_threads(self, threads: bool) -> Self { + Self { + with_threads: threads, + ..self + } + } + /// Retrieve the parent OpenTelemetry [`Context`] from the current tracing /// [`span`] through the [`Registry`]. This [`Context`] links spans to their /// parent for proper hierarchical visualization. @@ -431,6 +472,30 @@ where f(builder, &layer.tracer); } } + + fn extra_span_attrs(&self) -> usize { + let mut extra_attrs = 0; + if self.location { + extra_attrs += 3; + } + if self.with_threads { + extra_attrs += 2; + } + extra_attrs + } +} + +thread_local! { + static THREAD_ID: unsync::Lazy = unsync::Lazy::new(|| { + // OpenTelemetry's semantic conventions require the thread ID to be + // recorded as an integer, but `std::thread::ThreadId` does not expose + // the integer value on stable, so we have to convert it to a `usize` by + // parsing it. Since this requires allocating a `String`, store it in a + // thread local so we only have to do this once. + // TODO(eliza): once `std::thread::ThreadId::as_u64` is stabilized + // (https://github.com/rust-lang/rust/issues/67939), just use that. + thread_id_integer(thread::current().id()) + }); } impl Layer for OpenTelemetryLayer @@ -463,22 +528,35 @@ where builder.trace_id = Some(self.tracer.new_trace_id()); } - let builder_attrs = builder - .attributes - .get_or_insert(Vec::with_capacity(attrs.fields().len() + 3)); + let builder_attrs = builder.attributes.get_or_insert(Vec::with_capacity( + attrs.fields().len() + self.extra_span_attrs(), + )); - let meta = attrs.metadata(); + if self.location { + let meta = attrs.metadata(); - if let Some(filename) = meta.file() { - builder_attrs.push(KeyValue::new("code.filepath", filename)); - } + if let Some(filename) = meta.file() { + builder_attrs.push(KeyValue::new("code.filepath", filename)); + } - if let Some(module) = meta.module_path() { - builder_attrs.push(KeyValue::new("code.namespace", module)); + if let Some(module) = meta.module_path() { + builder_attrs.push(KeyValue::new("code.namespace", module)); + } + + if let Some(line) = meta.line() { + builder_attrs.push(KeyValue::new("code.lineno", line as i64)); + } } - if let Some(line) = meta.line() { - builder_attrs.push(KeyValue::new("code.lineno", line as i64)); + if self.with_threads { + THREAD_ID.with(|id| builder_attrs.push(KeyValue::new("thread.id", **id as i64))); + if let Some(name) = std::thread::current().name() { + // TODO(eliza): it's a bummer that we have to allocate here, but + // we can't easily get the string as a `static`. it would be + // nice if `opentelemetry` could also take `Arc`s as + // `String` values... + builder_attrs.push(KeyValue::new("thread.name", name.to_owned())); + } } attrs.record(&mut SpanAttributeVisitor(&mut builder)); @@ -601,9 +679,7 @@ where builder.status_code = Some(otel::StatusCode::Error); } - if self.event_location { - let builder_attrs = builder.attributes.get_or_insert(Vec::new()); - + if self.location { #[cfg(not(feature = "tracing-log"))] let normalized_meta: Option> = None; let (file, module) = match &normalized_meta { @@ -618,13 +694,19 @@ where }; if let Some(file) = file { - builder_attrs.push(KeyValue::new("code.filepath", file)); + otel_event + .attributes + .push(KeyValue::new("code.filepath", file)); } if let Some(module) = module { - builder_attrs.push(KeyValue::new("code.namespace", module)); + otel_event + .attributes + .push(KeyValue::new("code.namespace", module)); } if let Some(line) = meta.line() { - builder_attrs.push(KeyValue::new("code.lineno", line as i64)); + otel_event + .attributes + .push(KeyValue::new("code.lineno", line as i64)); } } @@ -700,15 +782,27 @@ impl Timings { } } +fn thread_id_integer(id: thread::ThreadId) -> u64 { + let thread_id = format!("{:?}", id); + thread_id + .trim_start_matches("ThreadId(") + .trim_end_matches(')') + .parse::() + .expect("thread ID should parse as an integer") +} + #[cfg(test)] mod tests { use super::*; use crate::OtelData; use opentelemetry::trace::{noop, SpanKind, TraceFlags}; - use std::borrow::Cow; - use std::collections::HashMap; - use std::sync::{Arc, Mutex}; - use std::time::SystemTime; + use std::{ + borrow::Cow, + collections::HashMap, + sync::{Arc, Mutex}, + thread, + time::SystemTime, + }; use tracing_subscriber::prelude::*; #[derive(Debug, Clone)] @@ -752,6 +846,14 @@ mod tests { } } + impl TestTracer { + fn with_data(&self, f: impl FnOnce(&OtelData) -> T) -> T { + let lock = self.0.lock().unwrap(); + let data = lock.as_ref().expect("no span data has been recorded yet"); + f(data) + } + } + #[derive(Debug, Clone)] struct TestSpan(otel::SpanContext); impl otel::Span for TestSpan { @@ -802,15 +904,7 @@ mod tests { tracing::debug_span!("request", otel.kind = %SpanKind::Server); }); - let recorded_kind = tracer - .0 - .lock() - .unwrap() - .as_ref() - .unwrap() - .builder - .span_kind - .clone(); + let recorded_kind = tracer.with_data(|data| data.builder.span_kind.clone()); assert_eq!(recorded_kind, Some(otel::SpanKind::Server)) } @@ -822,14 +916,8 @@ mod tests { tracing::subscriber::with_default(subscriber, || { tracing::debug_span!("request", otel.status_code = ?otel::StatusCode::Ok); }); - let recorded_status_code = tracer - .0 - .lock() - .unwrap() - .as_ref() - .unwrap() - .builder - .status_code; + + let recorded_status_code = tracer.with_data(|data| data.builder.status_code); assert_eq!(recorded_status_code, Some(otel::StatusCode::Ok)) } @@ -844,16 +932,7 @@ mod tests { tracing::debug_span!("request", otel.status_message = message); }); - let recorded_status_message = tracer - .0 - .lock() - .unwrap() - .as_ref() - .unwrap() - .builder - .status_message - .clone(); - + let recorded_status_message = tracer.with_data(|data| data.builder.status_message.clone()); assert_eq!(recorded_status_message, Some(message.into())) } @@ -875,16 +954,8 @@ mod tests { tracing::debug_span!("request", otel.kind = %SpanKind::Server); }); - let recorded_trace_id = tracer - .0 - .lock() - .unwrap() - .as_ref() - .unwrap() - .parent_cx - .span() - .span_context() - .trace_id(); + let recorded_trace_id = + tracer.with_data(|data| data.parent_cx.span().span_context().trace_id()); assert_eq!(recorded_trace_id, trace_id) } @@ -901,17 +972,7 @@ mod tests { tracing::debug_span!("request"); }); - let attributes = tracer - .0 - .lock() - .unwrap() - .as_ref() - .unwrap() - .builder - .attributes - .as_ref() - .unwrap() - .clone(); + let attributes = tracer.with_data(|data| data.builder.attributes.as_ref().unwrap().clone()); let keys = attributes .iter() .map(|attr| attr.key.as_str()) @@ -995,4 +1056,88 @@ mod tests { ) ); } + + #[test] + fn includes_span_location() { + let tracer = TestTracer(Arc::new(Mutex::new(None))); + let subscriber = tracing_subscriber::registry() + .with(layer().with_tracer(tracer.clone()).with_location(true)); + + tracing::subscriber::with_default(subscriber, || { + tracing::debug_span!("request"); + }); + + let attributes = tracer.with_data(|data| data.builder.attributes.as_ref().unwrap().clone()); + let keys = attributes + .iter() + .map(|attr| attr.key.as_str()) + .collect::>(); + assert!(keys.contains(&"code.filepath")); + assert!(keys.contains(&"code.namespace")); + assert!(keys.contains(&"code.lineno")); + } + + #[test] + fn excludes_span_location() { + let tracer = TestTracer(Arc::new(Mutex::new(None))); + let subscriber = tracing_subscriber::registry() + .with(layer().with_tracer(tracer.clone()).with_location(false)); + + tracing::subscriber::with_default(subscriber, || { + tracing::debug_span!("request"); + }); + + let attributes = tracer.with_data(|data| data.builder.attributes.as_ref().unwrap().clone()); + let keys = attributes + .iter() + .map(|attr| attr.key.as_str()) + .collect::>(); + assert!(!keys.contains(&"code.filepath")); + assert!(!keys.contains(&"code.namespace")); + assert!(!keys.contains(&"code.lineno")); + } + + #[test] + fn includes_thread() { + let thread = thread::current(); + let expected_name = thread + .name() + .map(|name| Value::String(Cow::Owned(name.to_owned()))); + let expected_id = Value::I64(thread_id_integer(thread.id()) as i64); + + let tracer = TestTracer(Arc::new(Mutex::new(None))); + let subscriber = tracing_subscriber::registry() + .with(layer().with_tracer(tracer.clone()).with_threads(true)); + + tracing::subscriber::with_default(subscriber, || { + tracing::debug_span!("request"); + }); + + let attributes = tracer + .with_data(|data| data.builder.attributes.as_ref().unwrap().clone()) + .drain(..) + .map(|keyval| (keyval.key.as_str().to_string(), keyval.value)) + .collect::>(); + assert_eq!(attributes.get("thread.name"), expected_name.as_ref()); + assert_eq!(attributes.get("thread.id"), Some(&expected_id)); + } + + #[test] + fn excludes_thread() { + let tracer = TestTracer(Arc::new(Mutex::new(None))); + let subscriber = tracing_subscriber::registry() + .with(layer().with_tracer(tracer.clone()).with_threads(false)); + + tracing::subscriber::with_default(subscriber, || { + tracing::debug_span!("request"); + }); + + let attributes = tracer.with_data(|data| data.builder.attributes.as_ref().unwrap().clone()); + let keys = attributes + .iter() + .map(|attr| attr.key.as_str()) + .collect::>(); + assert!(!keys.contains(&"thread.name")); + assert!(!keys.contains(&"thread.id")); + } } diff --git a/tracing-subscriber/Cargo.toml b/tracing-subscriber/Cargo.toml index b28f498615..3595318c46 100644 --- a/tracing-subscriber/Cargo.toml +++ b/tracing-subscriber/Cargo.toml @@ -27,7 +27,7 @@ rust-version = "1.49.0" default = ["smallvec", "fmt", "ansi", "tracing-log", "std"] alloc = [] std = ["alloc", "tracing-core/std"] -env-filter = ["matchers", "regex", "lazy_static", "tracing", "std", "thread_local"] +env-filter = ["matchers", "regex", "once_cell", "tracing", "std", "thread_local"] fmt = ["registry", "std"] ansi = ["fmt", "ansi_term"] registry = ["sharded-slab", "thread_local", "std"] @@ -38,14 +38,14 @@ valuable = ["tracing-core/valuable", "valuable_crate", "valuable-serde", "tracin local-time = ["time/local-offset"] [dependencies] -tracing-core = { path = "../tracing-core", version = "0.1.22" } +tracing-core = { path = "../tracing-core", version = "0.1.22", default-features = false } # only required by the filter feature tracing = { optional = true, path = "../tracing", version = "0.1", default-features = false } matchers = { optional = true, version = "0.1.0" } regex = { optional = true, version = "1", default-features = false, features = ["std"] } smallvec = { optional = true, version = "1.2.0" } -lazy_static = { optional = true, version = "1" } +once_cell = { optional = true, version = "1.12" } # fmt tracing-log = { path = "../tracing-log", version = "0.1.2", optional = true, default-features = false, features = ["log-tracer", "std"] } diff --git a/tracing-subscriber/src/filter/env/directive.rs b/tracing-subscriber/src/filter/env/directive.rs index 3e993f6c92..f062e6ef93 100644 --- a/tracing-subscriber/src/filter/env/directive.rs +++ b/tracing-subscriber/src/filter/env/directive.rs @@ -4,7 +4,7 @@ use crate::filter::{ env::{field, FieldMap}, level::LevelFilter, }; -use lazy_static::lazy_static; +use once_cell::sync::Lazy; use regex::Regex; use std::{cmp::Ordering, fmt, iter::FromIterator, str::FromStr}; use tracing_core::{span, Level, Metadata}; @@ -120,41 +120,39 @@ impl Directive { } pub(super) fn parse(from: &str, regex: bool) -> Result { - lazy_static! { - static ref DIRECTIVE_RE: Regex = Regex::new( - r"(?x) - ^(?P(?i:trace|debug|info|warn|error|off|[0-5]))$ | - # ^^^. - # `note: we match log level names case-insensitively - ^ - (?: # target name or span name - (?P[\w:-]+)|(?P\[[^\]]*\]) - ){1,2} - (?: # level or nothing - =(?P(?i:trace|debug|info|warn|error|off|[0-5]))? - # ^^^. - # `note: we match log level names case-insensitively - )? - $ - " - ) - .unwrap(); - static ref SPAN_PART_RE: Regex = - Regex::new(r#"(?P[^\]\{]+)?(?:\{(?P[^\}]*)\})?"#).unwrap(); - static ref FIELD_FILTER_RE: Regex = - // TODO(eliza): this doesn't _currently_ handle value matchers that include comma - // characters. We should fix that. - Regex::new(r#"(?x) - ( - # field name - [[:word:]][[[:word:]]\.]* - # value part (optional) - (?:=[^,]+)? - ) - # trailing comma or EOS - (?:,\s?|$) - "#).unwrap(); - } + static DIRECTIVE_RE: Lazy = Lazy::new(|| Regex::new( + r"(?x) + ^(?P(?i:trace|debug|info|warn|error|off|[0-5]))$ | + # ^^^. + # `note: we match log level names case-insensitively + ^ + (?: # target name or span name + (?P[\w:-]+)|(?P\[[^\]]*\]) + ){1,2} + (?: # level or nothing + =(?P(?i:trace|debug|info|warn|error|off|[0-5]))? + # ^^^. + # `note: we match log level names case-insensitively + )? + $ + " + ) + .unwrap()); + static SPAN_PART_RE: Lazy = + Lazy::new(|| Regex::new(r#"(?P[^\]\{]+)?(?:\{(?P[^\}]*)\})?"#).unwrap()); + static FIELD_FILTER_RE: Lazy = + // TODO(eliza): this doesn't _currently_ handle value matchers that include comma + // characters. We should fix that. + Lazy::new(|| Regex::new(r#"(?x) + ( + # field name + [[:word:]][[[:word:]]\.]* + # value part (optional) + (?:=[^,]+)? + ) + # trailing comma or EOS + (?:,\s?|$) + "#).unwrap()); let caps = DIRECTIVE_RE.captures(from).ok_or_else(ParseError::new)?; diff --git a/tracing-subscriber/src/filter/env/mod.rs b/tracing-subscriber/src/filter/env/mod.rs index dae20a6a2e..81a9ae2bde 100644 --- a/tracing-subscriber/src/filter/env/mod.rs +++ b/tracing-subscriber/src/filter/env/mod.rs @@ -449,6 +449,11 @@ impl EnvFilter { /// # Ok(()) /// # } /// ``` + /// In the above example, substitute `my_crate`, `module`, etc. with the + /// name your target crate/module is imported with. This might be + /// different from the package name in Cargo.toml (`-` is replaced by `_`). + /// Example, if the package name in your Cargo.toml is `MY-FANCY-LIB`, then + /// the corresponding Rust identifier would be `MY_FANCY_LIB`: pub fn add_directive(mut self, mut directive: Directive) -> Self { if !self.regex { directive.deregexify(); diff --git a/tracing/src/lib.rs b/tracing/src/lib.rs index fdd12bd3eb..65a4ebc951 100644 --- a/tracing/src/lib.rs +++ b/tracing/src/lib.rs @@ -119,8 +119,6 @@ //! tracing = "0.1" //! ``` //! -//! *Compiler support: [requires `rustc` 1.42+][msrv]* -//! //! ## Recording Spans and Events //! //! Spans and events are recorded using macros. diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index bca42933b3..b134af6e81 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -832,6 +832,8 @@ macro_rules! event { /// } /// ``` /// +/// [`enabled!`]: crate::enabled +/// [`span_enabled!`]: crate::span_enabled #[macro_export] macro_rules! event_enabled { ($($rest:tt)*)=> ( @@ -864,6 +866,8 @@ macro_rules! event_enabled { /// } /// ``` /// +/// [`enabled!`]: crate::enabled +/// [`span_enabled!`]: crate::span_enabled #[macro_export] macro_rules! span_enabled { ($($rest:tt)*)=> ( @@ -959,7 +963,8 @@ macro_rules! span_enabled { /// [`Metadata`]: crate::Metadata /// [`is_event`]: crate::Metadata::is_event /// [`is_span`]: crate::Metadata::is_span -/// +/// [`enabled!`]: crate::enabled +/// [`span_enabled!`]: crate::span_enabled #[macro_export] macro_rules! enabled { (kind: $kind:expr, target: $target:expr, $lvl:expr, { $($fields:tt)* } )=> ({