From 1f9dad1bd25c8c7df8c4a60e0cf5f34fe6d6938c Mon Sep 17 00:00:00 2001 From: Charles Date: Thu, 21 Jul 2022 14:18:23 -0400 Subject: [PATCH 01/11] appender: add `Builder::filename_suffix` parameter (#2225) ## Motivation The `RollingFileAppender` currently only supports a filename suffix. A lot of editors have support for log files using the `.log` extension. It would be nice to be able to configure what gets added after the date. ## Solution - Add a `Builder::filename_suffix` method, taking a string. - If the string is non-empty, this gets appended to the filename after the date. - This isn't an `AsRef` because it's not supposed to be a `Path` - Update the date appending logic to handle cases when the suffix or prefix is empty - Split each part with a `.` so the final output would be `prefix.date.suffix` - Make sure to remove unnecessary `.` when a prefix or suffix is empty - Add tests related to those changes ## Notes It would probably be nicer to simply have a completely configurable file name format, but I went with the easiest approach that achieved what I needed. Closes #1477 --- tracing-appender/src/rolling.rs | 130 +++++++++++++++--------- tracing-appender/src/rolling/builder.rs | 54 ++++++++++ 2 files changed, 138 insertions(+), 46 deletions(-) diff --git a/tracing-appender/src/rolling.rs b/tracing-appender/src/rolling.rs index d4b2ee6fcf..8e9597c29a 100644 --- a/tracing-appender/src/rolling.rs +++ b/tracing-appender/src/rolling.rs @@ -103,6 +103,7 @@ pub struct RollingWriter<'a>(RwLockReadGuard<'a, File>); struct Inner { log_directory: PathBuf, log_filename_prefix: Option, + log_filename_suffix: Option, rotation: Rotation, next_date: AtomicUsize, } @@ -170,6 +171,7 @@ impl RollingFileAppender { /// let file_appender = RollingFileAppender::builder() /// .rotation(Rotation::HOURLY) // rotate log files once every hour /// .filename_prefix("myapp") // log file names will be prefixed with `myapp.` + /// .filename_suffix("log") // log file names will be suffixed with `.log` /// .build("/var/log") // try to build an appender that stores log files in `/var/log` /// .expect("initializing rolling file appender failed"); /// # drop(file_appender); @@ -184,11 +186,17 @@ impl RollingFileAppender { let Builder { ref rotation, ref prefix, + ref suffix, } = builder; - let filename_prefix = prefix.clone(); let directory = directory.as_ref().to_path_buf(); let now = OffsetDateTime::now_utc(); - let (state, writer) = Inner::new(now, rotation.clone(), directory, filename_prefix)?; + let (state, writer) = Inner::new( + now, + rotation.clone(), + directory, + prefix.clone(), + suffix.clone(), + )?; Ok(Self { state, writer, @@ -480,42 +488,31 @@ impl Rotation { } } - pub(crate) fn join_date(&self, filename: Option<&str>, date: &OffsetDateTime) -> String { - let date = match *self { - Rotation::MINUTELY => { - let format = format_description::parse("[year]-[month]-[day]-[hour]-[minute]") - .expect("Unable to create a formatter; this is a bug in tracing-appender"); - date.format(&format) - .expect("Unable to format OffsetDateTime; this is a bug in tracing-appender") - } - Rotation::HOURLY => { - let format = format_description::parse("[year]-[month]-[day]-[hour]") - .expect("Unable to create a formatter; this is a bug in tracing-appender"); - date.format(&format) - .expect("Unable to format OffsetDateTime; this is a bug in tracing-appender") - } - Rotation::DAILY => { - let format = format_description::parse("[year]-[month]-[day]") - .expect("Unable to create a formatter; this is a bug in tracing-appender"); - date.format(&format) - .expect("Unable to format OffsetDateTime; this is a bug in tracing-appender") - } - Rotation::NEVER => { - // If there's a name prefix, use that. - if let Some(filename) = filename { - return filename.to_owned(); - } - - // Otherwise, just use the date. - let format = format_description::parse("[year]-[month]-[day]") - .expect("Unable to create a formatter; this is a bug in tracing-appender"); - date.format(&format) - .expect("Unable to format OffsetDateTime; this is a bug in tracing-appender") - } - }; - match filename { - Some(filename) => format!("{}.{}", filename, date), - None => date, + pub(crate) fn join_date( + &self, + filename: Option<&str>, + date: &OffsetDateTime, + suffix: Option<&str>, + ) -> String { + let format = match *self { + Rotation::MINUTELY => format_description::parse("[year]-[month]-[day]-[hour]-[minute]"), + Rotation::HOURLY => format_description::parse("[year]-[month]-[day]-[hour]"), + Rotation::DAILY => format_description::parse("[year]-[month]-[day]"), + Rotation::NEVER => format_description::parse("[year]-[month]-[day]"), + } + .expect("Unable to create a formatter; this is a bug in tracing-appender"); + let date = date + .format(&format) + .expect("Unable to format OffsetDateTime; this is a bug in tracing-appender"); + + match (self, filename, suffix) { + (&Rotation::NEVER, Some(filename), None) => filename.to_string(), + (&Rotation::NEVER, Some(filename), Some(suffix)) => format!("{}.{}", filename, suffix), + (&Rotation::NEVER, None, Some(suffix)) => suffix.to_string(), + (_, Some(filename), Some(suffix)) => format!("{}.{}.{}", filename, date, suffix), + (_, Some(filename), None) => format!("{}.{}", filename, date), + (_, None, Some(suffix)) => format!("{}.{}", date, suffix), + (_, None, None) => date, } } } @@ -540,15 +537,21 @@ impl Inner { rotation: Rotation, directory: impl AsRef, log_filename_prefix: Option, + log_filename_suffix: Option, ) -> Result<(Self, RwLock), builder::InitError> { let log_directory = directory.as_ref().to_path_buf(); - let filename = rotation.join_date(log_filename_prefix.as_deref(), &now); + let filename = rotation.join_date( + log_filename_prefix.as_deref(), + &now, + log_filename_suffix.as_deref(), + ); let next_date = rotation.next_date(&now); let writer = RwLock::new(create_writer(log_directory.as_ref(), &filename)?); let inner = Inner { log_directory, log_filename_prefix, + log_filename_suffix, next_date: AtomicUsize::new( next_date .map(|date| date.unix_timestamp() as usize) @@ -560,9 +563,11 @@ impl Inner { } fn refresh_writer(&self, now: OffsetDateTime, file: &mut File) { - let filename = self - .rotation - .join_date(self.log_filename_prefix.as_deref(), &now); + let filename = self.rotation.join_date( + self.log_filename_prefix.as_deref(), + &now, + self.log_filename_suffix.as_deref(), + ); match create_writer(&self.log_directory, &filename) { Ok(new_file) => { @@ -732,19 +737,51 @@ mod test { let now = OffsetDateTime::parse("2020-02-01 10:01:00 +00:00:00", &format).unwrap(); // per-minute - let path = Rotation::MINUTELY.join_date(Some("app.log"), &now); + let path = Rotation::MINUTELY.join_date(Some("app.log"), &now, None); assert_eq!("app.log.2020-02-01-10-01", path); // per-hour - let path = Rotation::HOURLY.join_date(Some("app.log"), &now); + let path = Rotation::HOURLY.join_date(Some("app.log"), &now, None); assert_eq!("app.log.2020-02-01-10", path); // per-day - let path = Rotation::DAILY.join_date(Some("app.log"), &now); + let path = Rotation::DAILY.join_date(Some("app.log"), &now, None); assert_eq!("app.log.2020-02-01", path); // never - let path = Rotation::NEVER.join_date(Some("app.log"), &now); + let path = Rotation::NEVER.join_date(Some("app.log"), &now, None); + assert_eq!("app.log", path); + + // per-minute with suffix + let path = Rotation::MINUTELY.join_date(Some("app"), &now, Some("log")); + assert_eq!("app.2020-02-01-10-01.log", path); + + // per-hour with suffix + let path = Rotation::HOURLY.join_date(Some("app"), &now, Some("log")); + assert_eq!("app.2020-02-01-10.log", path); + + // per-day with suffix + let path = Rotation::DAILY.join_date(Some("app"), &now, Some("log")); + assert_eq!("app.2020-02-01.log", path); + + // never with suffix + let path = Rotation::NEVER.join_date(Some("app"), &now, Some("log")); + assert_eq!("app.log", path); + + // per-minute without prefix + let path = Rotation::MINUTELY.join_date(None, &now, Some("app.log")); + assert_eq!("2020-02-01-10-01.app.log", path); + + // per-hour without prefix + let path = Rotation::HOURLY.join_date(None, &now, Some("app.log")); + assert_eq!("2020-02-01-10.app.log", path); + + // per-day without prefix + let path = Rotation::DAILY.join_date(None, &now, Some("app.log")); + assert_eq!("2020-02-01.app.log", path); + + // never without prefix + let path = Rotation::NEVER.join_date(None, &now, Some("app.log")); assert_eq!("app.log", path); } @@ -766,6 +803,7 @@ mod test { Rotation::HOURLY, directory.path(), Some("test_make_writer".to_string()), + None, ) .unwrap(); diff --git a/tracing-appender/src/rolling/builder.rs b/tracing-appender/src/rolling/builder.rs index 82161f0cc6..ea5d39cd5f 100644 --- a/tracing-appender/src/rolling/builder.rs +++ b/tracing-appender/src/rolling/builder.rs @@ -9,6 +9,7 @@ use thiserror::Error; pub struct Builder { pub(super) rotation: Rotation, pub(super) prefix: Option, + pub(super) suffix: Option, } /// Errors returned by [`Builder::build`]. @@ -46,6 +47,7 @@ impl Builder { Self { rotation: Rotation::NEVER, prefix: None, + suffix: None, } } @@ -127,6 +129,58 @@ impl Builder { Self { prefix, ..self } } + /// Sets the suffix for log filenames. The suffix is output after the + /// timestamp in the file name, and if it is non-empty, it is preceded by a + /// dot (`.`). + /// + /// By default, log files do not have a suffix. + /// + /// # Examples + /// + /// Setting a suffix: + /// + /// ``` + /// use tracing_appender::rolling::RollingFileAppender; + /// + /// # fn docs() { + /// let appender = RollingFileAppender::builder() + /// .filename_suffix("myapp.log") // log files will have names like "2019-01-01.myapp.log" + /// // ... + /// .build("/var/log") + /// .expect("failed to initialize rolling file appender"); + /// # drop(appender) + /// # } + /// ``` + /// + /// No suffix: + /// + /// ``` + /// use tracing_appender::rolling::RollingFileAppender; + /// + /// # fn docs() { + /// let appender = RollingFileAppender::builder() + /// .filename_suffix("") // log files will have names like "2019-01-01" + /// // ... + /// .build("/var/log") + /// .expect("failed to initialize rolling file appender"); + /// # drop(appender) + /// # } + /// ``` + /// + /// [rotation strategy]: Rotation + #[must_use] + pub fn filename_suffix(self, suffix: impl Into) -> Self { + let suffix = suffix.into(); + // If the configured suffix is the empty string, then don't include a + // separator character. + let suffix = if suffix.is_empty() { + None + } else { + Some(suffix) + }; + Self { suffix, ..self } + } + /// Builds a new [`RollingFileAppender`] with the configured parameters, /// emitting log files to the provided directory. /// From af5a800a8ea8d36e9a745ea8ffcd5704e488af83 Mon Sep 17 00:00:00 2001 From: Kartavya Vashishtha Date: Fri, 22 Jul 2022 00:08:11 +0530 Subject: [PATCH 02/11] subscriber: mark builders as must_use (#2239) ## Motivation Builders not marked `#[must_use]` can not be initialized sometimes, causing silent failures. Eg. ```rust fn main() { tracing_subscriber::fmt(); tracing::info!("hello"); } ``` won't print anything. ## Solution Added `#[must_use]` to builder types in the tracing-subscriber crate. --- tracing-subscriber/src/filter/env/builder.rs | 1 + tracing-subscriber/src/fmt/mod.rs | 13 +++++++++---- 2 files changed, 10 insertions(+), 4 deletions(-) diff --git a/tracing-subscriber/src/filter/env/builder.rs b/tracing-subscriber/src/filter/env/builder.rs index 36b5205431..7bc65484ea 100644 --- a/tracing-subscriber/src/filter/env/builder.rs +++ b/tracing-subscriber/src/filter/env/builder.rs @@ -11,6 +11,7 @@ use tracing::level_filters::STATIC_MAX_LEVEL; /// /// [builder]: https://rust-unofficial.github.io/patterns/patterns/creational/builder.html #[derive(Debug, Clone)] +#[must_use] pub struct Builder { regex: bool, env: Option, diff --git a/tracing-subscriber/src/fmt/mod.rs b/tracing-subscriber/src/fmt/mod.rs index 9103ce8f16..025e17504d 100644 --- a/tracing-subscriber/src/fmt/mod.rs +++ b/tracing-subscriber/src/fmt/mod.rs @@ -243,6 +243,7 @@ pub type Formatter< /// Configures and constructs `Subscriber`s. #[cfg_attr(docsrs, doc(cfg(all(feature = "fmt", feature = "std"))))] #[derive(Debug)] +#[must_use] pub struct SubscriberBuilder< N = format::DefaultFields, E = format::Format, @@ -465,7 +466,8 @@ impl Default for SubscriberBuilder { SubscriberBuilder { filter: Subscriber::DEFAULT_MAX_LEVEL, inner: Default::default(), - }.log_internal_errors(true) + } + .log_internal_errors(true) } } @@ -626,12 +628,15 @@ where /// By default, `fmt::Layer` will write any `FormatEvent`-internal errors to /// the writer. These errors are unlikely and will only occur if there is a /// bug in the `FormatEvent` implementation or its dependencies. - /// + /// /// If writing to the writer fails, the error message is printed to stderr /// as a fallback. - /// + /// /// [`FormatEvent`]: crate::fmt::FormatEvent - pub fn log_internal_errors(self, log_internal_errors: bool) -> SubscriberBuilder, F, W> { + pub fn log_internal_errors( + self, + log_internal_errors: bool, + ) -> SubscriberBuilder, F, W> { SubscriberBuilder { inner: self.inner.log_internal_errors(log_internal_errors), ..self From 9099a6964692dc2ec9b3a354f07a4d852cafbb81 Mon Sep 17 00:00:00 2001 From: Bryan Garza <1396101+bryangarza@users.noreply.github.com> Date: Mon, 11 Jul 2022 18:09:21 -0700 Subject: [PATCH 03/11] opentelemetry: support publishing metrics (#2185) Motivation: Currently, there is no way to publish metrics via tracing. Solution: Update the tracing-opentelemetry crate to publish metrics for event fields that contain specific prefixes in the name. Right now, we lazily instantiate and store one metrics object per-callsite, but a future improvement that we should add to tracing itself is the ability to store data per-callsite, so that we don't have to do a HashMap lookup each time we want to publish a metric. Co-authored-by: Eliza Weisman Co-authored-by: David Barsky --- tracing-opentelemetry/Cargo.toml | 5 +- tracing-opentelemetry/src/lib.rs | 5 + tracing-opentelemetry/src/metrics.rs | 352 ++++++++++++++++++ .../tests/metrics_publishing.rs | 283 ++++++++++++++ 4 files changed, 644 insertions(+), 1 deletion(-) create mode 100644 tracing-opentelemetry/src/metrics.rs create mode 100644 tracing-opentelemetry/tests/metrics_publishing.rs diff --git a/tracing-opentelemetry/Cargo.toml b/tracing-opentelemetry/Cargo.toml index ee53821fc7..0a7d05cd3e 100644 --- a/tracing-opentelemetry/Cargo.toml +++ b/tracing-opentelemetry/Cargo.toml @@ -23,7 +23,7 @@ rust-version = "1.46.0" default = ["tracing-log"] [dependencies] -opentelemetry = { version = "0.17.0", default-features = false, features = ["trace"] } +opentelemetry = { version = "0.17.0", default-features = false, features = ["metrics", "trace"] } tracing = { path = "../tracing", version = "0.1.35", default-features = false, features = ["std"] } tracing-core = { path = "../tracing-core", version = "0.1.28" } tracing-subscriber = { path = "../tracing-subscriber", version = "0.3.0", default-features = false, features = ["registry", "std"] } @@ -38,6 +38,9 @@ thiserror = { version = "1.0.31", optional = true } async-trait = "0.1.56" criterion = { version = "0.3.6", default-features = false } opentelemetry-jaeger = "0.16.0" +futures-util = { version = "0.3", default-features = false } +tokio = { version = "1", features = ["full"] } +tokio-stream = "0.1" [lib] bench = false diff --git a/tracing-opentelemetry/src/lib.rs b/tracing-opentelemetry/src/lib.rs index 872afc8a44..c3a3992587 100644 --- a/tracing-opentelemetry/src/lib.rs +++ b/tracing-opentelemetry/src/lib.rs @@ -99,6 +99,9 @@ )] #![cfg_attr(docsrs, deny(rustdoc::broken_intra_doc_links))] +/// Implementation of the trace::Layer trait; publishes OpenTelemetry metrics. +mod metrics; + /// Implementation of the trace::Layer as a source of OpenTelemetry data. mod layer; /// Span extension which enables OpenTelemetry context management. @@ -107,6 +110,8 @@ mod span_ext; mod tracer; pub use layer::{layer, OpenTelemetryLayer}; + +pub use metrics::MetricsLayer; pub use span_ext::OpenTelemetrySpanExt; pub use tracer::PreSampledTracer; diff --git a/tracing-opentelemetry/src/metrics.rs b/tracing-opentelemetry/src/metrics.rs new file mode 100644 index 0000000000..50a98cc1e9 --- /dev/null +++ b/tracing-opentelemetry/src/metrics.rs @@ -0,0 +1,352 @@ +use std::{collections::HashMap, fmt, sync::RwLock}; +use tracing::{field::Visit, Subscriber}; +use tracing_core::Field; + +use opentelemetry::{ + metrics::{Counter, Meter, MeterProvider, UpDownCounter, ValueRecorder}, + sdk::metrics::PushController, +}; +use tracing_subscriber::{layer::Context, registry::LookupSpan, Layer}; + +const CARGO_PKG_VERSION: &str = env!("CARGO_PKG_VERSION"); +const INSTRUMENTATION_LIBRARY_NAME: &str = "tracing/tracing-opentelemetry"; + +const METRIC_PREFIX_MONOTONIC_COUNTER: &str = "monotonic_counter."; +const METRIC_PREFIX_COUNTER: &str = "counter."; +const METRIC_PREFIX_VALUE: &str = "value."; +const I64_MAX: u64 = i64::MAX as u64; + +#[derive(Default)] +pub(crate) struct Instruments { + u64_counter: MetricsMap>, + f64_counter: MetricsMap>, + i64_up_down_counter: MetricsMap>, + f64_up_down_counter: MetricsMap>, + u64_value_recorder: MetricsMap>, + i64_value_recorder: MetricsMap>, + f64_value_recorder: MetricsMap>, +} + +type MetricsMap = RwLock>; + +#[derive(Copy, Clone, Debug)] +pub(crate) enum InstrumentType { + CounterU64(u64), + CounterF64(f64), + UpDownCounterI64(i64), + UpDownCounterF64(f64), + ValueRecorderU64(u64), + ValueRecorderI64(i64), + ValueRecorderF64(f64), +} + +impl Instruments { + pub(crate) fn update_metric( + &self, + meter: &Meter, + instrument_type: InstrumentType, + metric_name: &'static str, + ) { + fn update_or_insert( + map: &MetricsMap, + name: &'static str, + insert: impl FnOnce() -> T, + update: impl FnOnce(&T), + ) { + { + let lock = map.read().unwrap(); + if let Some(metric) = lock.get(name) { + update(metric); + return; + } + } + + // that metric did not already exist, so we have to acquire a write lock to + // create it. + let mut lock = map.write().unwrap(); + // handle the case where the entry was created while we were waiting to + // acquire the write lock + let metric = lock.entry(name).or_insert_with(insert); + update(metric) + } + + match instrument_type { + InstrumentType::CounterU64(value) => { + update_or_insert( + &self.u64_counter, + metric_name, + || meter.u64_counter(metric_name).init(), + |ctr| ctr.add(value, &[]), + ); + } + InstrumentType::CounterF64(value) => { + update_or_insert( + &self.f64_counter, + metric_name, + || meter.f64_counter(metric_name).init(), + |ctr| ctr.add(value, &[]), + ); + } + InstrumentType::UpDownCounterI64(value) => { + update_or_insert( + &self.i64_up_down_counter, + metric_name, + || meter.i64_up_down_counter(metric_name).init(), + |ctr| ctr.add(value, &[]), + ); + } + InstrumentType::UpDownCounterF64(value) => { + update_or_insert( + &self.f64_up_down_counter, + metric_name, + || meter.f64_up_down_counter(metric_name).init(), + |ctr| ctr.add(value, &[]), + ); + } + InstrumentType::ValueRecorderU64(value) => { + update_or_insert( + &self.u64_value_recorder, + metric_name, + || meter.u64_value_recorder(metric_name).init(), + |rec| rec.record(value, &[]), + ); + } + InstrumentType::ValueRecorderI64(value) => { + update_or_insert( + &self.i64_value_recorder, + metric_name, + || meter.i64_value_recorder(metric_name).init(), + |rec| rec.record(value, &[]), + ); + } + InstrumentType::ValueRecorderF64(value) => { + update_or_insert( + &self.f64_value_recorder, + metric_name, + || meter.f64_value_recorder(metric_name).init(), + |rec| rec.record(value, &[]), + ); + } + }; + } +} + +pub(crate) struct MetricVisitor<'a> { + pub(crate) instruments: &'a Instruments, + pub(crate) meter: &'a Meter, +} + +impl<'a> Visit for MetricVisitor<'a> { + fn record_debug(&mut self, _field: &Field, _value: &dyn fmt::Debug) { + // Do nothing + } + + fn record_u64(&mut self, field: &Field, value: u64) { + if let Some(metric_name) = field.name().strip_prefix(METRIC_PREFIX_MONOTONIC_COUNTER) { + self.instruments.update_metric( + self.meter, + InstrumentType::CounterU64(value), + metric_name, + ); + } else if let Some(metric_name) = field.name().strip_prefix(METRIC_PREFIX_COUNTER) { + if value <= I64_MAX { + self.instruments.update_metric( + self.meter, + InstrumentType::UpDownCounterI64(value as i64), + metric_name, + ); + } else { + eprintln!( + "[tracing-opentelemetry]: Received Counter metric, but \ + provided u64: {} is greater than i64::MAX. Ignoring \ + this metric.", + value + ); + } + } else if let Some(metric_name) = field.name().strip_prefix(METRIC_PREFIX_VALUE) { + self.instruments.update_metric( + self.meter, + InstrumentType::ValueRecorderU64(value), + metric_name, + ); + } + } + + fn record_f64(&mut self, field: &Field, value: f64) { + if let Some(metric_name) = field.name().strip_prefix(METRIC_PREFIX_MONOTONIC_COUNTER) { + self.instruments.update_metric( + self.meter, + InstrumentType::CounterF64(value), + metric_name, + ); + } else if let Some(metric_name) = field.name().strip_prefix(METRIC_PREFIX_COUNTER) { + self.instruments.update_metric( + self.meter, + InstrumentType::UpDownCounterF64(value), + metric_name, + ); + } else if let Some(metric_name) = field.name().strip_prefix(METRIC_PREFIX_VALUE) { + self.instruments.update_metric( + self.meter, + InstrumentType::ValueRecorderF64(value), + metric_name, + ); + } + } + + fn record_i64(&mut self, field: &Field, value: i64) { + if let Some(metric_name) = field.name().strip_prefix(METRIC_PREFIX_MONOTONIC_COUNTER) { + self.instruments.update_metric( + self.meter, + InstrumentType::CounterU64(value as u64), + metric_name, + ); + } else if let Some(metric_name) = field.name().strip_prefix(METRIC_PREFIX_COUNTER) { + self.instruments.update_metric( + self.meter, + InstrumentType::UpDownCounterI64(value), + metric_name, + ); + } else if let Some(metric_name) = field.name().strip_prefix(METRIC_PREFIX_VALUE) { + self.instruments.update_metric( + self.meter, + InstrumentType::ValueRecorderI64(value), + metric_name, + ); + } + } +} + +/// A layer that publishes metrics via the OpenTelemetry SDK. +/// +/// # Usage +/// +/// No configuration is needed for this Layer, as it's only responsible for +/// pushing data out to the `opentelemetry` family of crates. For example, when +/// using `opentelemetry-otlp`, that crate will provide its own set of +/// configuration options for setting up the duration metrics will be collected +/// before exporting to the OpenTelemetry Collector, aggregation of data points, +/// etc. +/// +/// ```no_run +/// use tracing_opentelemetry::MetricsLayer; +/// use tracing_subscriber::layer::SubscriberExt; +/// use tracing_subscriber::Registry; +/// # use opentelemetry::sdk::metrics::PushController; +/// +/// // Constructing a PushController is out-of-scope for the docs here, but there +/// // are examples in the opentelemetry repository. See: +/// // https://github.com/open-telemetry/opentelemetry-rust/blob/c13a11e62a68eacd8c41a0742a0d097808e28fbd/examples/basic-otlp/src/main.rs#L39-L53 +/// # let push_controller: PushController = unimplemented!(); +/// +/// let opentelemetry_metrics = MetricsLayer::new(push_controller); +/// let subscriber = Registry::default().with(opentelemetry_metrics); +/// tracing::subscriber::set_global_default(subscriber).unwrap(); +/// ``` +/// +/// To publish a new metric, add a key-value pair to your `tracing::Event` that +/// contains following prefixes: +/// - `monotonic_counter.` (non-negative numbers): Used when the counter should +/// only ever increase +/// - `counter.`: Used when the counter can go up or down +/// - `value.`: Used for discrete data points (i.e., summing them does not make +/// semantic sense) +/// +/// Examples: +/// ``` +/// # use tracing::info; +/// info!(monotonic_counter.foo = 1); +/// info!(monotonic_counter.bar = 1.1); +/// +/// info!(counter.baz = 1); +/// info!(counter.baz = -1); +/// info!(counter.xyz = 1.1); +/// +/// info!(value.qux = 1); +/// info!(value.abc = -1); +/// info!(value.def = 1.1); +/// ``` +/// +/// # Mixing data types +/// +/// ## Floating-point numbers +/// +/// Do not mix floating point and non-floating point numbers for the same +/// metric. If a floating point number will be used for a given metric, be sure +/// to cast any other usages of that metric to a floating point number. +/// +/// Do this: +/// ``` +/// # use tracing::info; +/// info!(monotonic_counter.foo = 1_f64); +/// info!(monotonic_counter.foo = 1.1); +/// ``` +/// +/// This is because all data published for a given metric name must be the same +/// numeric type. +/// +/// ## Integers +/// +/// Positive and negative integers can be mixed freely. The instrumentation +/// provided by `tracing` assumes that all integers are `i64` unless explicitly +/// cast to something else. In the case that an integer *is* cast to `u64`, this +/// subscriber will handle the conversion internally. +/// +/// For example: +/// ``` +/// # use tracing::info; +/// // The subscriber receives an i64 +/// info!(counter.baz = 1); +/// +/// // The subscriber receives an i64 +/// info!(counter.baz = -1); +/// +/// // The subscriber receives a u64, but casts it to i64 internally +/// info!(counter.baz = 1_u64); +/// +/// // The subscriber receives a u64, but cannot cast it to i64 because of +/// // overflow. An error is printed to stderr, and the metric is dropped. +/// info!(counter.baz = (i64::MAX as u64) + 1) +/// ``` +/// +/// # Implementation Details +/// +/// `MetricsLayer` holds a set of maps, with each map corresponding to a +/// type of metric supported by OpenTelemetry. These maps are populated lazily. +/// The first time that a metric is emitted by the instrumentation, a `Metric` +/// instance will be created and added to the corresponding map. This means that +/// any time a metric is emitted by the instrumentation, one map lookup has to +/// be performed. +/// +/// In the future, this can be improved by associating each `Metric` instance to +/// its callsite, eliminating the need for any maps. +pub struct MetricsLayer { + meter: Meter, + instruments: Instruments, +} + +impl MetricsLayer { + /// Create a new instance of MetricsLayer. + pub fn new(push_controller: PushController) -> Self { + let meter = push_controller + .provider() + .meter(INSTRUMENTATION_LIBRARY_NAME, Some(CARGO_PKG_VERSION)); + MetricsLayer { + meter, + instruments: Default::default(), + } + } +} + +impl Layer for MetricsLayer +where + S: Subscriber + for<'span> LookupSpan<'span>, +{ + fn on_event(&self, event: &tracing::Event<'_>, _ctx: Context<'_, S>) { + let mut metric_visitor = MetricVisitor { + instruments: &self.instruments, + meter: &self.meter, + }; + event.record(&mut metric_visitor); + } +} diff --git a/tracing-opentelemetry/tests/metrics_publishing.rs b/tracing-opentelemetry/tests/metrics_publishing.rs new file mode 100644 index 0000000000..419558363f --- /dev/null +++ b/tracing-opentelemetry/tests/metrics_publishing.rs @@ -0,0 +1,283 @@ +use async_trait::async_trait; +use futures_util::{Stream, StreamExt as _}; +use opentelemetry::{ + metrics::{Descriptor, InstrumentKind}, + metrics::{Number, NumberKind}, + sdk::{ + export::{ + metrics::{ + CheckpointSet, ExportKind, ExportKindFor, ExportKindSelector, + Exporter as MetricsExporter, Points, Sum, + }, + trace::{SpanData, SpanExporter}, + }, + metrics::{ + aggregators::{ArrayAggregator, SumAggregator}, + selectors::simple::Selector, + }, + }, + Key, Value, +}; +use std::cmp::Ordering; +use std::time::Duration; +use tracing::Subscriber; +use tracing_opentelemetry::MetricsLayer; +use tracing_subscriber::prelude::*; + +const CARGO_PKG_VERSION: &str = env!("CARGO_PKG_VERSION"); +const INSTRUMENTATION_LIBRARY_NAME: &str = "tracing/tracing-opentelemetry"; + +#[tokio::test] +async fn u64_counter_is_exported() { + let subscriber = init_subscriber( + "hello_world".to_string(), + InstrumentKind::Counter, + NumberKind::U64, + Number::from(1_u64), + ); + + tracing::subscriber::with_default(subscriber, || { + tracing::info!(monotonic_counter.hello_world = 1_u64); + }); +} + +#[tokio::test] +async fn u64_counter_is_exported_i64_at_instrumentation_point() { + let subscriber = init_subscriber( + "hello_world2".to_string(), + InstrumentKind::Counter, + NumberKind::U64, + Number::from(1_u64), + ); + + tracing::subscriber::with_default(subscriber, || { + tracing::info!(monotonic_counter.hello_world2 = 1_i64); + }); +} + +#[tokio::test] +async fn f64_counter_is_exported() { + let subscriber = init_subscriber( + "float_hello_world".to_string(), + InstrumentKind::Counter, + NumberKind::F64, + Number::from(1.000000123_f64), + ); + + tracing::subscriber::with_default(subscriber, || { + tracing::info!(monotonic_counter.float_hello_world = 1.000000123_f64); + }); +} + +#[tokio::test] +async fn i64_up_down_counter_is_exported() { + let subscriber = init_subscriber( + "pebcak".to_string(), + InstrumentKind::UpDownCounter, + NumberKind::I64, + Number::from(-5_i64), + ); + + tracing::subscriber::with_default(subscriber, || { + tracing::info!(counter.pebcak = -5_i64); + }); +} + +#[tokio::test] +async fn i64_up_down_counter_is_exported_u64_at_instrumentation_point() { + let subscriber = init_subscriber( + "pebcak2".to_string(), + InstrumentKind::UpDownCounter, + NumberKind::I64, + Number::from(5_i64), + ); + + tracing::subscriber::with_default(subscriber, || { + tracing::info!(counter.pebcak2 = 5_u64); + }); +} + +#[tokio::test] +async fn f64_up_down_counter_is_exported() { + let subscriber = init_subscriber( + "pebcak_blah".to_string(), + InstrumentKind::UpDownCounter, + NumberKind::F64, + Number::from(99.123_f64), + ); + + tracing::subscriber::with_default(subscriber, || { + tracing::info!(counter.pebcak_blah = 99.123_f64); + }); +} + +#[tokio::test] +async fn u64_value_is_exported() { + let subscriber = init_subscriber( + "abcdefg".to_string(), + InstrumentKind::ValueRecorder, + NumberKind::U64, + Number::from(9_u64), + ); + + tracing::subscriber::with_default(subscriber, || { + tracing::info!(value.abcdefg = 9_u64); + }); +} + +#[tokio::test] +async fn i64_value_is_exported() { + let subscriber = init_subscriber( + "abcdefg_auenatsou".to_string(), + InstrumentKind::ValueRecorder, + NumberKind::I64, + Number::from(-19_i64), + ); + + tracing::subscriber::with_default(subscriber, || { + tracing::info!(value.abcdefg_auenatsou = -19_i64); + }); +} + +#[tokio::test] +async fn f64_value_is_exported() { + let subscriber = init_subscriber( + "abcdefg_racecar".to_string(), + InstrumentKind::ValueRecorder, + NumberKind::F64, + Number::from(777.0012_f64), + ); + + tracing::subscriber::with_default(subscriber, || { + tracing::info!(value.abcdefg_racecar = 777.0012_f64); + }); +} + +fn init_subscriber( + expected_metric_name: String, + expected_instrument_kind: InstrumentKind, + expected_number_kind: NumberKind, + expected_value: Number, +) -> impl Subscriber + 'static { + let exporter = TestExporter { + expected_metric_name, + expected_instrument_kind, + expected_number_kind, + expected_value, + }; + + let push_controller = opentelemetry::sdk::metrics::controllers::push( + Selector::Exact, + ExportKindSelector::Stateless, + exporter, + tokio::spawn, + delayed_interval, + ) + .build(); + + tracing_subscriber::registry().with(MetricsLayer::new(push_controller)) +} + +#[derive(Clone, Debug)] +struct TestExporter { + expected_metric_name: String, + expected_instrument_kind: InstrumentKind, + expected_number_kind: NumberKind, + expected_value: Number, +} + +#[async_trait] +impl SpanExporter for TestExporter { + async fn export( + &mut self, + mut _batch: Vec, + ) -> opentelemetry::sdk::export::trace::ExportResult { + Ok(()) + } +} + +impl MetricsExporter for TestExporter { + fn export(&self, checkpoint_set: &mut dyn CheckpointSet) -> opentelemetry::metrics::Result<()> { + checkpoint_set.try_for_each(self, &mut |record| { + assert_eq!(self.expected_metric_name, record.descriptor().name()); + assert_eq!( + self.expected_instrument_kind, + *record.descriptor().instrument_kind() + ); + assert_eq!( + self.expected_number_kind, + *record.descriptor().number_kind() + ); + let number = match self.expected_instrument_kind { + InstrumentKind::Counter | InstrumentKind::UpDownCounter => record + .aggregator() + .unwrap() + .as_any() + .downcast_ref::() + .unwrap() + .sum() + .unwrap(), + InstrumentKind::ValueRecorder => record + .aggregator() + .unwrap() + .as_any() + .downcast_ref::() + .unwrap() + .points() + .unwrap()[0] + .clone(), + _ => panic!( + "InstrumentKind {:?} not currently supported!", + self.expected_instrument_kind + ), + }; + assert_eq!( + Ordering::Equal, + number + .partial_cmp(&NumberKind::U64, &self.expected_value) + .unwrap() + ); + + // The following are the same regardless of the individual metric. + assert_eq!( + INSTRUMENTATION_LIBRARY_NAME, + record.descriptor().instrumentation_library().name + ); + assert_eq!( + CARGO_PKG_VERSION, + record.descriptor().instrumentation_version().unwrap() + ); + assert_eq!( + Value::String("unknown_service".into()), + record + .resource() + .get(Key::new("service.name".to_string())) + .unwrap() + ); + + opentelemetry::metrics::Result::Ok(()) + }) + } +} + +impl ExportKindFor for TestExporter { + fn export_kind_for(&self, _descriptor: &Descriptor) -> ExportKind { + // I don't think the value here makes a difference since + // we are just testing a single metric. + ExportKind::Cumulative + } +} + +// From opentelemetry::sdk::util:: +// For some reason I can't pull it in from the other crate, it gives +// could not find `util` in `sdk` +/// Helper which wraps `tokio::time::interval` and makes it return a stream +fn tokio_interval_stream(period: std::time::Duration) -> tokio_stream::wrappers::IntervalStream { + tokio_stream::wrappers::IntervalStream::new(tokio::time::interval(period)) +} + +// https://github.com/open-telemetry/opentelemetry-rust/blob/2585d109bf90d53d57c91e19c758dca8c36f5512/examples/basic-otlp/src/main.rs#L34-L37 +// Skip first immediate tick from tokio, not needed for async_std. +fn delayed_interval(duration: Duration) -> impl Stream { + tokio_interval_stream(duration).skip(0) +} From 63914b6e29a82f285abf2d342f8d20a51deba715 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 21 Jul 2022 15:46:12 -0700 Subject: [PATCH 04/11] opentelemetry: feature-flag `MetricsLayer` (#2234) In the upstream `opentelemetry` crate, the `trace` and `metrics` features are gated by separate feature flags. This allows users who are only using OpenTelemetry for tracing, or who are only using it for metrics, to pick and choose what they depend on. Currently, the release version of `tracing-opentelemetry` only provides tracing functionality, and therefore, it only depends on `opentelemetry` with the `trace` feature enabled. However, the metrics support added in #2185 adds a dependency on the `opentelemetry/metrics` feature. This is currently always enabled. We should probably follow the same approach as upstream `opentelemetry`, and allow enabling/disabling metrics and tracing separately. This branch adds a `metrics` feature to `tracing-opentelemetry`, and makes the `MetricsLayer` from #2185 gated on the `metrics` feature. This feature flag is on by default, like the upstream `opentelemetry/metrics` feature, but it can be disabled using `default-features = false`. We should probably do something similar for the tracing components of the crate, and make them gated on a `trace` feature flag, but adding a feature flag to released APIs is not semver-compatible, so we should save that until the next breaking release. --- tracing-opentelemetry/Cargo.toml | 12 +++++++--- tracing-opentelemetry/README.md | 6 +++++ tracing-opentelemetry/src/lib.rs | 22 +++++++++++++++++-- tracing-opentelemetry/src/metrics.rs | 2 ++ .../tests/metrics_publishing.rs | 1 + 5 files changed, 38 insertions(+), 5 deletions(-) diff --git a/tracing-opentelemetry/Cargo.toml b/tracing-opentelemetry/Cargo.toml index 0a7d05cd3e..efe2de0ab9 100644 --- a/tracing-opentelemetry/Cargo.toml +++ b/tracing-opentelemetry/Cargo.toml @@ -20,15 +20,17 @@ edition = "2018" rust-version = "1.46.0" [features] -default = ["tracing-log"] +default = ["tracing-log", "metrics"] +# Enables support for exporting OpenTelemetry metrics +metrics = ["opentelemetry/metrics"] [dependencies] -opentelemetry = { version = "0.17.0", default-features = false, features = ["metrics", "trace"] } +opentelemetry = { version = "0.17.0", default-features = false, features = ["trace"] } tracing = { path = "../tracing", version = "0.1.35", default-features = false, features = ["std"] } tracing-core = { path = "../tracing-core", version = "0.1.28" } tracing-subscriber = { path = "../tracing-subscriber", version = "0.3.0", default-features = false, features = ["registry", "std"] } tracing-log = { path = "../tracing-log", version = "0.1.3", default-features = false, optional = true } -once_cell = "1" +once_cell = "1.13.0" # Fix minimal-versions async-trait = { version = "0.1.56", optional = true } @@ -48,3 +50,7 @@ bench = false [[bench]] name = "trace" harness = false + +[package.metadata.docs.rs] +all-features = true +rustdoc-args = ["--cfg", "docsrs"] \ No newline at end of file diff --git a/tracing-opentelemetry/README.md b/tracing-opentelemetry/README.md index 6640754483..4fcb658cfa 100644 --- a/tracing-opentelemetry/README.md +++ b/tracing-opentelemetry/README.md @@ -101,6 +101,12 @@ $ firefox http://localhost:16686/ ![Jaeger UI](trace.png) +## Feature Flags + + - `metrics`: Enables the [`MetricsSubscriber`] type, a [subscriber] that + exports OpenTelemetry metrics from specifically-named events. This enables + the `metrics` feature flag on the `opentelemetry` crate. + ## Supported Rust Versions Tracing Opentelemetry is built against the latest stable release. The minimum diff --git a/tracing-opentelemetry/src/lib.rs b/tracing-opentelemetry/src/lib.rs index c3a3992587..5cd725d5a3 100644 --- a/tracing-opentelemetry/src/lib.rs +++ b/tracing-opentelemetry/src/lib.rs @@ -76,6 +76,13 @@ //! }); //! ``` //! +//! ## Feature Flags +//! +//! - `metrics`: Enables the [`MetricsSubscriber`] type, a [subscriber] that +//! exports OpenTelemetry metrics from specifically-named events. This enables +//! the `metrics` feature flag on the `opentelemetry` crate. *Enabled by +//! default*. +//! //! ## Supported Rust Versions //! //! Tracing is built against the latest stable release. The minimum supported @@ -90,6 +97,7 @@ //! supported compiler version is not considered a semver breaking change as //! long as doing so complies with this policy. //! +//! [subscriber]: tracing_subscriber::subscribe #![deny(unreachable_pub)] #![cfg_attr(test, deny(warnings))] #![doc(html_root_url = "https://docs.rs/tracing-opentelemetry/0.17.4")] @@ -97,9 +105,18 @@ html_logo_url = "https://raw.githubusercontent.com/tokio-rs/tracing/master/assets/logo-type.png", issue_tracker_base_url = "https://github.com/tokio-rs/tracing/issues/" )] -#![cfg_attr(docsrs, deny(rustdoc::broken_intra_doc_links))] +#![cfg_attr( + docsrs, + // Allows displaying cfgs/feature flags in the documentation. + feature(doc_cfg, doc_auto_cfg), + // Allows adding traits to RustDoc's list of "notable traits" + feature(doc_notable_trait), + // Fail the docs build if any intra-docs links are broken + deny(rustdoc::broken_intra_doc_links), +)] -/// Implementation of the trace::Layer trait; publishes OpenTelemetry metrics. +/// Implementation of the trace::Subscriber trait; publishes OpenTelemetry metrics. +#[cfg(feature = "metrics")] mod metrics; /// Implementation of the trace::Layer as a source of OpenTelemetry data. @@ -111,6 +128,7 @@ mod tracer; pub use layer::{layer, OpenTelemetryLayer}; +#[cfg(feature = "metrics")] pub use metrics::MetricsLayer; pub use span_ext::OpenTelemetrySpanExt; pub use tracer::PreSampledTracer; diff --git a/tracing-opentelemetry/src/metrics.rs b/tracing-opentelemetry/src/metrics.rs index 50a98cc1e9..37df62c4b4 100644 --- a/tracing-opentelemetry/src/metrics.rs +++ b/tracing-opentelemetry/src/metrics.rs @@ -320,6 +320,8 @@ impl<'a> Visit for MetricVisitor<'a> { /// /// In the future, this can be improved by associating each `Metric` instance to /// its callsite, eliminating the need for any maps. +/// +#[cfg_attr(docsrs, doc(cfg(feature = "metrics")))] pub struct MetricsLayer { meter: Meter, instruments: Instruments, diff --git a/tracing-opentelemetry/tests/metrics_publishing.rs b/tracing-opentelemetry/tests/metrics_publishing.rs index 419558363f..9db53fcb3f 100644 --- a/tracing-opentelemetry/tests/metrics_publishing.rs +++ b/tracing-opentelemetry/tests/metrics_publishing.rs @@ -1,3 +1,4 @@ +#![cfg(feature = "metrics")] use async_trait::async_trait; use futures_util::{Stream, StreamExt as _}; use opentelemetry::{ From dc6c1813be5a1de8ac01daad32fd60d4d79cfa40 Mon Sep 17 00:00:00 2001 From: Chris Connelly Date: Mon, 25 Jul 2022 18:08:05 +0100 Subject: [PATCH 05/11] subscriber: add `Targets::default_level` method (#2242) ## Motivation This makes it possible to fully "override" some base `Targets` filter with another (e.g. user-supplied) filter. Without some way to obtain the default, only explicit targets can be overridden (via `IntoIter` and friends). See also https://github.com/tokio-rs/tracing/issues/1790#issuecomment-999739222 ## Solution We can add a method to `Targets` that filters the underlying `DirectiveSet` for the default directive. This works because `DirectiveSet::add` will replace directives with the same `target`/`field_names`, which is always `None`/`vec![]` for the directive added by `with_default` (and in fact we are only concerned with `target`, since no other `Targets` API allows adding directives with a `None` target). Ideally the method would be named `default`, corresponding to `with_default`, however this conflicts with `Default::default` and so would be a breaking change (and harm ergonomics). `default_level` seemed a better name than `get_default`, since "getters" of this style are generally considered unidiomatic[citation needed]. Example usage: ```rust let mut filter = Targets::new().with_target("some_module", LevelFilter::INFO); // imagine this came from `RUST_LOG` or similar let override: Targets = "trace".parse().unwrap(); // merge the override if let Some(default) = override.default_level() { filter = filter.with_default(default); } for (target, level) in override.iter() { filter = filter.with_target(target, level); } ``` Closes #1790 --- tracing-subscriber/src/filter/targets.rs | 71 ++++++++++++++++++++++++ 1 file changed, 71 insertions(+) diff --git a/tracing-subscriber/src/filter/targets.rs b/tracing-subscriber/src/filter/targets.rs index 2a30d2db60..e1407114b5 100644 --- a/tracing-subscriber/src/filter/targets.rs +++ b/tracing-subscriber/src/filter/targets.rs @@ -277,6 +277,62 @@ impl Targets { self } + /// Returns the default level for this filter, if one is set. + /// + /// The default level is used to filter any spans or events with targets + /// that do not match any of the configured set of prefixes. + /// + /// The default level can be set for a filter either by using + /// [`with_default`](Self::with_default) or when parsing from a filter string that includes a + /// level without a target (e.g. `"trace"`). + /// + /// # Examples + /// + /// ``` + /// use tracing_subscriber::filter::{LevelFilter, Targets}; + /// + /// let filter = Targets::new().with_default(LevelFilter::INFO); + /// assert_eq!(filter.default_level(), Some(LevelFilter::INFO)); + /// + /// let filter: Targets = "info".parse().unwrap(); + /// assert_eq!(filter.default_level(), Some(LevelFilter::INFO)); + /// ``` + /// + /// The default level is `None` if no default is set: + /// + /// ``` + /// use tracing_subscriber::filter::Targets; + /// + /// let filter = Targets::new(); + /// assert_eq!(filter.default_level(), None); + /// + /// let filter: Targets = "my_crate=info".parse().unwrap(); + /// assert_eq!(filter.default_level(), None); + /// ``` + /// + /// Note that an unset default level (`None`) behaves like [`LevelFilter::OFF`] when the filter is + /// used, but it could also be set explicitly which may be useful to distinguish (such as when + /// merging multiple `Targets`). + /// + /// ``` + /// use tracing_subscriber::filter::{LevelFilter, Targets}; + /// + /// let filter = Targets::new().with_default(LevelFilter::OFF); + /// assert_eq!(filter.default_level(), Some(LevelFilter::OFF)); + /// + /// let filter: Targets = "off".parse().unwrap(); + /// assert_eq!(filter.default_level(), Some(LevelFilter::OFF)); + /// ``` + pub fn default_level(&self) -> Option { + self.0.directives().into_iter().find_map(|d| { + if d.target.is_none() { + Some(d.level) + } else { + None + } + }) + } + /// Returns an iterator over the [target]-[`LevelFilter`] pairs in this filter. /// /// The order of iteration is undefined. @@ -685,6 +741,21 @@ mod tests { ); } + #[test] + fn targets_default_level() { + let filter = expect_parse("crate1::mod1=error,crate1::mod2,crate2=debug,crate3=off"); + assert_eq!(filter.default_level(), None); + + let filter = expect_parse("crate1::mod1=error,crate1::mod2,crate2=debug,crate3=off") + .with_default(LevelFilter::OFF); + assert_eq!(filter.default_level(), Some(LevelFilter::OFF)); + + let filter = expect_parse("crate1::mod1=error,crate1::mod2,crate2=debug,crate3=off") + .with_default(LevelFilter::OFF) + .with_default(LevelFilter::INFO); + assert_eq!(filter.default_level(), Some(LevelFilter::INFO)); + } + #[test] // `println!` is only available with `libstd`. #[cfg(feature = "std")] From 64f20f97501a1521e6a01dfc5add3e37774700c6 Mon Sep 17 00:00:00 2001 From: Jack Wrenn Date: Tue, 26 Jul 2022 18:24:01 -0400 Subject: [PATCH 06/11] subscriber: impl `LookupSpan` for `Box` and `Arc` (#2247) These implementations mirror those provided by tracing-core for `Collect` on `Box` and `Arc`. --- tracing-subscriber/src/layer/mod.rs | 2 +- tracing-subscriber/src/registry/mod.rs | 65 ++++++++++++++++++++++++++ 2 files changed, 66 insertions(+), 1 deletion(-) diff --git a/tracing-subscriber/src/layer/mod.rs b/tracing-subscriber/src/layer/mod.rs index 24b8533234..d4bccfcf1a 100644 --- a/tracing-subscriber/src/layer/mod.rs +++ b/tracing-subscriber/src/layer/mod.rs @@ -1569,7 +1569,7 @@ where feature! { #![any(feature = "std", feature = "alloc")] #[cfg(not(feature = "std"))] - use alloc::vec::Vec; + use alloc::{vec::Vec, boxed::Box}; macro_rules! layer_impl_body { () => { diff --git a/tracing-subscriber/src/registry/mod.rs b/tracing-subscriber/src/registry/mod.rs index 38af53e8ad..0f9fe76a1a 100644 --- a/tracing-subscriber/src/registry/mod.rs +++ b/tracing-subscriber/src/registry/mod.rs @@ -230,6 +230,11 @@ pub struct Scope<'a, R> { feature! { #![any(feature = "alloc", feature = "std")] + use alloc::{ + boxed::Box, + sync::Arc + }; + #[cfg(not(feature = "smallvec"))] use alloc::vec::{self, Vec}; @@ -251,6 +256,66 @@ feature! { #[cfg(feature = "smallvec")] type SpanRefVecArray<'span, L> = [SpanRef<'span, L>; 16]; + impl<'a, S> LookupSpan<'a> for Arc + where + S: LookupSpan<'a>, + { + type Data = >::Data; + + fn span_data(&'a self, id: &Id) -> Option { + self.as_ref().span_data(id) + } + + fn span(&'a self, id: &Id) -> Option> + where + Self: Sized, + { + self.as_ref().span(id).map( + |SpanRef { + registry: _, + data, + #[cfg(feature = "registry")] + filter, + }| SpanRef { + registry: self, + data, + #[cfg(feature = "registry")] + filter, + }, + ) + } + } + + impl<'a, S> LookupSpan<'a> for Box + where + S: LookupSpan<'a>, + { + type Data = >::Data; + + fn span_data(&'a self, id: &Id) -> Option { + self.as_ref().span_data(id) + } + + fn span(&'a self, id: &Id) -> Option> + where + Self: Sized, + { + self.as_ref().span(id).map( + |SpanRef { + registry: _, + data, + #[cfg(feature = "registry")] + filter, + }| SpanRef { + registry: self, + data, + #[cfg(feature = "registry")] + filter, + }, + ) + } + } + impl<'a, R> Scope<'a, R> where R: LookupSpan<'a>, From 1dbd6689017efab66b8c530a194da70840839112 Mon Sep 17 00:00:00 2001 From: Ilia Konnov Date: Wed, 27 Jul 2022 02:02:44 +0300 Subject: [PATCH 07/11] serde: implement `AsSerde` for `FieldSet` (#2241) ## Motivation I've wanted to serialize fieldset of current span. ## Solution Expose already existing `SerializeFieldSet` for users by implementing `AsSerde` for `FieldSet`. --- tracing-serde/src/lib.rs | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/tracing-serde/src/lib.rs b/tracing-serde/src/lib.rs index 3df9114f0a..f099853ec0 100644 --- a/tracing-serde/src/lib.rs +++ b/tracing-serde/src/lib.rs @@ -565,6 +565,14 @@ impl<'a> AsSerde<'a> for Level { } } +impl<'a> AsSerde<'a> for FieldSet { + type Serializable = SerializeFieldSet<'a>; + + fn as_serde(&'a self) -> Self::Serializable { + SerializeFieldSet(self) + } +} + impl<'a> self::sealed::Sealed for Event<'a> {} impl<'a> self::sealed::Sealed for Attributes<'a> {} @@ -577,6 +585,8 @@ impl<'a> self::sealed::Sealed for Record<'a> {} impl<'a> self::sealed::Sealed for Metadata<'a> {} +impl self::sealed::Sealed for FieldSet {} + mod sealed { pub trait Sealed {} } From f0663e817fff436452185860bcd8d51679c89d8b Mon Sep 17 00:00:00 2001 From: Christopher Durham Date: Wed, 27 Jul 2022 15:17:44 -0400 Subject: [PATCH 08/11] subscriber: add `Filter::event_enabled` (#2245) ## Motivation Like for `Subscriber` and `Layer`, allow per-layer `Filter`s to filter based on event fields. ## Solution Add `Filter::event_enabled`, plumb it through the combinator implementations, and call it from `Filtered`. The bit I'm the least confident about is the check in `Registry`'s implementation, but I *think* it matches what `event` is doing and everything seems to function correctly. --- .../src/filter/layer_filters/combinator.rs | 27 ++++++++ .../src/filter/layer_filters/mod.rs | 35 +++++++++++ tracing-subscriber/src/layer/mod.rs | 20 ++++++ tracing-subscriber/src/registry/sharded.rs | 7 +++ .../tests/layer_filters/main.rs | 1 + .../tests/layer_filters/per_event.rs | 61 +++++++++++++++++++ 6 files changed, 151 insertions(+) create mode 100644 tracing-subscriber/tests/layer_filters/per_event.rs diff --git a/tracing-subscriber/src/filter/layer_filters/combinator.rs b/tracing-subscriber/src/filter/layer_filters/combinator.rs index e79de20870..669ddf63a7 100644 --- a/tracing-subscriber/src/filter/layer_filters/combinator.rs +++ b/tracing-subscriber/src/filter/layer_filters/combinator.rs @@ -137,6 +137,11 @@ where cmp::min(self.a.max_level_hint(), self.b.max_level_hint()) } + #[inline] + fn event_enabled(&self, event: &tracing_core::Event<'_>, cx: &Context<'_, S>) -> bool { + self.a.event_enabled(event, cx) && self.b.event_enabled(event, cx) + } + #[inline] fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) { self.a.on_new_span(attrs, id, ctx.clone()); @@ -324,6 +329,11 @@ where Some(cmp::max(self.a.max_level_hint()?, self.b.max_level_hint()?)) } + #[inline] + fn event_enabled(&self, event: &tracing_core::Event<'_>, cx: &Context<'_, S>) -> bool { + self.a.event_enabled(event, cx) || self.b.event_enabled(event, cx) + } + #[inline] fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) { self.a.on_new_span(attrs, id, ctx.clone()); @@ -393,7 +403,16 @@ where /// If the wrapped filter would enable a span or event, it will be disabled. If /// it would disable a span or event, that span or event will be enabled. /// + /// This inverts the values returned by the [`enabled`] and [`callsite_enabled`] + /// methods on the wrapped filter; it does *not* invert [`event_enabled`], as + /// implementing that method is optional, and filters which do not implement + /// filtering on event field values will return `true` even for events that their + /// [`enabled`] method would disable. + /// /// [`Filter`]: crate::layer::Filter + /// [`enabled`]: crate::layer::Filter::enabled + /// [`event_enabled`]: crate::layer::Filter::event_enabled + /// [`callsite_enabled`]: crate::layer::Filter::callsite_enabled pub(crate) fn new(a: A) -> Self { Self { a, _s: PhantomData } } @@ -421,6 +440,14 @@ where None } + #[inline] + fn event_enabled(&self, event: &tracing_core::Event<'_>, cx: &Context<'_, S>) -> bool { + // Never disable based on event_enabled; we "disabled" it in `enabled`, + // so the `not` has already been applied and filtered this not out. + let _ = (event, cx); + true + } + #[inline] fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) { self.a.on_new_span(attrs, id, ctx); diff --git a/tracing-subscriber/src/filter/layer_filters/mod.rs b/tracing-subscriber/src/filter/layer_filters/mod.rs index 8949cfb5a8..fbfa55a443 100644 --- a/tracing-subscriber/src/filter/layer_filters/mod.rs +++ b/tracing-subscriber/src/filter/layer_filters/mod.rs @@ -298,6 +298,17 @@ pub trait FilterExt: layer::Filter { /// Inverts `self`, returning a filter that enables spans and events only if /// `self` would *not* enable them. + /// + /// This inverts the values returned by the [`enabled`] and [`callsite_enabled`] + /// methods on the wrapped filter; it does *not* invert [`event_enabled`], as + /// implementing that method is optional, and filters which do not implement + /// filtering on event field values will return `true` even for events that their + /// [`enabled`] method would disable. + /// + /// [`Filter`]: crate::subscribe::Filter + /// [`enabled`]: crate::subscribe::Filter::enabled + /// [`event_enabled`]: crate::subscribe::Filter::event_enabled + /// [`callsite_enabled`]: crate::subscribe::Filter::callsite_enabled fn not(self) -> combinator::Not where Self: Sized, @@ -643,6 +654,22 @@ where } } + fn event_enabled(&self, event: &Event<'_>, cx: Context<'_, S>) -> bool { + let cx = cx.with_filter(self.id()); + let enabled = FILTERING + .with(|filtering| filtering.and(self.id(), || self.filter.event_enabled(event, &cx))); + + if enabled { + // If the filter enabled this event, ask the wrapped subscriber if + // _it_ wants it --- it might have a global filter. + self.layer.event_enabled(event, cx) + } else { + // Otherwise, return `true`. See the comment in `enabled` for why this + // is necessary. + true + } + } + fn on_event(&self, event: &Event<'_>, cx: Context<'_, S>) { self.did_enable(|| { self.layer.on_event(event, cx.with_filter(self.id())); @@ -1014,6 +1041,14 @@ impl FilterState { } } + /// Run a second filtering pass, e.g. for Subscribe::event_enabled. + fn and(&self, filter: FilterId, f: impl FnOnce() -> bool) -> bool { + let map = self.enabled.get(); + let enabled = map.is_enabled(filter) && f(); + self.enabled.set(map.set(filter, enabled)); + enabled + } + /// Clears the current in-progress filter state. /// /// This resets the [`FilterMap`] and current [`Interest`] as well as diff --git a/tracing-subscriber/src/layer/mod.rs b/tracing-subscriber/src/layer/mod.rs index d4bccfcf1a..c5ce1f2e88 100644 --- a/tracing-subscriber/src/layer/mod.rs +++ b/tracing-subscriber/src/layer/mod.rs @@ -1352,6 +1352,26 @@ feature! { Interest::sometimes() } + /// Called before the filtered [`Layer]'s [`on_event`], to determine if + /// `on_event` should be called. + /// + /// This gives a chance to filter events based on their fields. Note, + /// however, that this *does not* override [`enabled`], and is not even + /// called if [`enabled`] returns `false`. + /// + /// ## Default Implementation + /// + /// By default, this method returns `true`, indicating that no events are + /// filtered out based on their fields. + /// + /// [`enabled`]: crate::layer::Filter::enabled + /// [`on_event`]: crate::layer::Layer::on_event + #[inline] // collapse this to a constant please mrs optimizer + fn event_enabled(&self, event: &Event<'_>, cx: &Context<'_, S>) -> bool { + let _ = (event, cx); + true + } + /// Returns an optional hint of the highest [verbosity level][level] that /// this `Filter` will enable. /// diff --git a/tracing-subscriber/src/registry/sharded.rs b/tracing-subscriber/src/registry/sharded.rs index b81d5fef83..7978997678 100644 --- a/tracing-subscriber/src/registry/sharded.rs +++ b/tracing-subscriber/src/registry/sharded.rs @@ -275,6 +275,13 @@ impl Subscriber for Registry { fn record_follows_from(&self, _span: &span::Id, _follows: &span::Id) {} + fn event_enabled(&self, _event: &Event<'_>) -> bool { + if self.has_per_layer_filters() { + return FilterState::event_enabled(); + } + true + } + /// This is intentionally not implemented, as recording events /// is the responsibility of layers atop of this registry. fn event(&self, _: &Event<'_>) {} diff --git a/tracing-subscriber/tests/layer_filters/main.rs b/tracing-subscriber/tests/layer_filters/main.rs index 0233f063b9..10f06c24c6 100644 --- a/tracing-subscriber/tests/layer_filters/main.rs +++ b/tracing-subscriber/tests/layer_filters/main.rs @@ -5,6 +5,7 @@ use self::support::*; mod boxed; mod downcast_raw; mod filter_scopes; +mod per_event; mod targets; mod trees; mod vec; diff --git a/tracing-subscriber/tests/layer_filters/per_event.rs b/tracing-subscriber/tests/layer_filters/per_event.rs new file mode 100644 index 0000000000..9c785f9a23 --- /dev/null +++ b/tracing-subscriber/tests/layer_filters/per_event.rs @@ -0,0 +1,61 @@ +use crate::support::*; +use tracing::Level; +use tracing_subscriber::{field::Visit, layer::Filter, prelude::*}; + +struct FilterEvent; + +impl Filter for FilterEvent { + fn enabled( + &self, + _meta: &tracing::Metadata<'_>, + _cx: &tracing_subscriber::layer::Context<'_, S>, + ) -> bool { + true + } + + fn event_enabled( + &self, + event: &tracing::Event<'_>, + _cx: &tracing_subscriber::layer::Context<'_, S>, + ) -> bool { + struct ShouldEnable(bool); + impl Visit for ShouldEnable { + fn record_bool(&mut self, field: &tracing_core::Field, value: bool) { + if field.name() == "enable" { + self.0 = value; + } + } + + fn record_debug( + &mut self, + _field: &tracing_core::Field, + _value: &dyn core::fmt::Debug, + ) { + } + } + let mut should_enable = ShouldEnable(false); + event.record(&mut should_enable); + should_enable.0 + } +} + +#[test] +fn per_subscriber_event_field_filtering() { + let (expect, handle) = layer::mock() + .event(event::mock().at_level(Level::TRACE)) + .event(event::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + + let _subscriber = tracing_subscriber::registry() + .with(expect.with_filter(FilterEvent)) + .set_default(); + + tracing::trace!(enable = true, "hello trace"); + tracing::debug!("hello debug"); + tracing::info!(enable = true, "hello info"); + tracing::warn!(enable = false, "hello warn"); + tracing::error!("hello error"); + + handle.assert_finished(); +} From 403d506cfe02a381cc8ee54c78f7cf71f9b321ed Mon Sep 17 00:00:00 2001 From: Christopher Durham Date: Wed, 27 Jul 2022 16:46:11 -0400 Subject: [PATCH 09/11] subscriber: `Not` is `not`, not `or` (#2249) ## Motivation Doc typo. ## Solution Fix. --- tracing-subscriber/src/filter/layer_filters/combinator.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tracing-subscriber/src/filter/layer_filters/combinator.rs b/tracing-subscriber/src/filter/layer_filters/combinator.rs index 669ddf63a7..745531de69 100644 --- a/tracing-subscriber/src/filter/layer_filters/combinator.rs +++ b/tracing-subscriber/src/filter/layer_filters/combinator.rs @@ -40,11 +40,11 @@ pub struct Or { /// If the wrapped filter would enable a span or event, it will be disabled. If /// it would disable a span or event, that span or event will be enabled. /// -/// This type is typically returned by the [`FilterExt::or`] method. See that +/// This type is typically returned by the [`FilterExt::not`] method. See that /// method's documentation for details. /// /// [`Filter`]: crate::layer::Filter -/// [`FilterExt::or`]: crate::filter::FilterExt::or +/// [`FilterExt::not`]: crate::filter::FilterExt::not pub struct Not { a: A, _s: PhantomData, From 5dd00487e67039feb3c9c281f592f36a38a1f9ab Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 27 Jul 2022 14:52:52 -0700 Subject: [PATCH 10/11] core: give `SetGlobalDefaultError` a useful `Debug` impl (#2250) ## Motivation When a global default dispatcher has already been set, the `dispatch::set_global_default` function fails with a `SetGlobalDefaultError`. The `fmt::Display` impl for this type includes a message explaining that the error indicates that a global default has already been set, but the `fmt::Debug` impl is derived, and just looks like this: ``` SetGlobalDefaultError { _no_construct: () } ``` which isn't particularly helpful. Unfortunately, when `unwrap()`ping or `expect()`ing a `Result`, the `fmt::Debug` implementation for the error type is used, rather than `fmt::Display`. This means that the error message will not explain to the user why setting the global default dispatcher failed, which is a bummer. ## Solution This branch replaces the derived `Debug` impl with a manually implemented one that prints the same message as the `Display` impl, but formatted like a tuple struct with a single string field. This avoids emitting `Debug` output that's *just* a textual human-readable message, rather than looking like Rust code, but ensures the message is visible to the user when writing code like ```rust tracing::dispatch::set_global_default(foo).unwrap(); ``` The mesasge now looks like: ``` SetGlobalDefaultError("a global default trace dispatcher has already been set") ``` which should be a bit easier to debug. --- tracing-core/src/dispatcher.rs | 15 +++++++++++++-- 1 file changed, 13 insertions(+), 2 deletions(-) diff --git a/tracing-core/src/dispatcher.rs b/tracing-core/src/dispatcher.rs index 041722c366..a3661817c0 100644 --- a/tracing-core/src/dispatcher.rs +++ b/tracing-core/src/dispatcher.rs @@ -293,14 +293,21 @@ pub fn has_been_set() -> bool { } /// Returned if setting the global dispatcher fails. -#[derive(Debug)] pub struct SetGlobalDefaultError { _no_construct: (), } +impl fmt::Debug for SetGlobalDefaultError { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.debug_tuple("SetGlobalDefaultError") + .field(&Self::MESSAGE) + .finish() + } +} + impl fmt::Display for SetGlobalDefaultError { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - f.pad("a global default trace dispatcher has already been set") + f.pad(Self::MESSAGE) } } @@ -308,6 +315,10 @@ impl fmt::Display for SetGlobalDefaultError { #[cfg_attr(docsrs, doc(cfg(feature = "std")))] impl error::Error for SetGlobalDefaultError {} +impl SetGlobalDefaultError { + const MESSAGE: &'static str = "a global default trace dispatcher has already been set"; +} + /// Executes a closure with a reference to this thread's current [dispatcher]. /// /// Note that calls to `get_default` should not be nested; if this function is From 9f8c020f208bb78f701e17f1e71180e1400fbbd3 Mon Sep 17 00:00:00 2001 From: Christopher Durham Date: Thu, 28 Jul 2022 17:50:41 -0400 Subject: [PATCH 11/11] subscriber: clarify `filter.not()` docs w.r.t. event_enabled (#2251) * Explain filter.not() w.r.t. event_enabled Co-authored-by: David Barsky Co-authored-by: Eliza Weisman --- .../src/filter/layer_filters/combinator.rs | 52 +++++++++++++++++-- .../src/filter/layer_filters/mod.rs | 52 +++++++++++++++++-- 2 files changed, 98 insertions(+), 6 deletions(-) diff --git a/tracing-subscriber/src/filter/layer_filters/combinator.rs b/tracing-subscriber/src/filter/layer_filters/combinator.rs index 745531de69..3934a13267 100644 --- a/tracing-subscriber/src/filter/layer_filters/combinator.rs +++ b/tracing-subscriber/src/filter/layer_filters/combinator.rs @@ -405,9 +405,55 @@ where /// /// This inverts the values returned by the [`enabled`] and [`callsite_enabled`] /// methods on the wrapped filter; it does *not* invert [`event_enabled`], as - /// implementing that method is optional, and filters which do not implement - /// filtering on event field values will return `true` even for events that their - /// [`enabled`] method would disable. + /// filters which do not implement filtering on event field values will return + /// the default `true` even for events that their [`enabled`] method disables. + /// + /// Consider a normal filter defined as: + /// + /// ```ignore (pseudo-code) + /// // for spans + /// match callsite_enabled() { + /// ALWAYS => on_span(), + /// SOMETIMES => if enabled() { on_span() }, + /// NEVER => (), + /// } + /// // for events + /// match callsite_enabled() { + /// ALWAYS => on_event(), + /// SOMETIMES => if enabled() && event_enabled() { on_event() }, + /// NEVER => (), + /// } + /// ``` + /// + /// and an inverted filter defined as: + /// + /// ```ignore (pseudo-code) + /// // for spans + /// match callsite_enabled() { + /// ALWAYS => (), + /// SOMETIMES => if !enabled() { on_span() }, + /// NEVER => on_span(), + /// } + /// // for events + /// match callsite_enabled() { + /// ALWAYS => (), + /// SOMETIMES => if !enabled() { on_event() }, + /// NEVER => on_event(), + /// } + /// ``` + /// + /// A proper inversion would do `!(enabled() && event_enabled())` (or + /// `!enabled() || !event_enabled()`), but because of the implicit `&&` + /// relation between `enabled` and `event_enabled`, it is difficult to + /// short circuit and not call the wrapped `event_enabled`. + /// + /// A combinator which remembers the result of `enabled` in order to call + /// `event_enabled` only when `enabled() == true` is possible, but requires + /// additional thread-local mutable state to support a very niche use case. + // + // Also, it'd mean the wrapped layer's `enabled()` always gets called and + // globally applied to events where it doesn't today, since we can't know + // what `event_enabled` will say until we have the event to call it with. /// /// [`Filter`]: crate::layer::Filter /// [`enabled`]: crate::layer::Filter::enabled diff --git a/tracing-subscriber/src/filter/layer_filters/mod.rs b/tracing-subscriber/src/filter/layer_filters/mod.rs index fbfa55a443..7c2ca4f640 100644 --- a/tracing-subscriber/src/filter/layer_filters/mod.rs +++ b/tracing-subscriber/src/filter/layer_filters/mod.rs @@ -301,9 +301,55 @@ pub trait FilterExt: layer::Filter { /// /// This inverts the values returned by the [`enabled`] and [`callsite_enabled`] /// methods on the wrapped filter; it does *not* invert [`event_enabled`], as - /// implementing that method is optional, and filters which do not implement - /// filtering on event field values will return `true` even for events that their - /// [`enabled`] method would disable. + /// filters which do not implement filtering on event field values will return + /// the default `true` even for events that their [`enabled`] method disables. + /// + /// Consider a normal filter defined as: + /// + /// ```ignore (pseudo-code) + /// // for spans + /// match callsite_enabled() { + /// ALWAYS => on_span(), + /// SOMETIMES => if enabled() { on_span() }, + /// NEVER => (), + /// } + /// // for events + /// match callsite_enabled() { + /// ALWAYS => on_event(), + /// SOMETIMES => if enabled() && event_enabled() { on_event() }, + /// NEVER => (), + /// } + /// ``` + /// + /// and an inverted filter defined as: + /// + /// ```ignore (pseudo-code) + /// // for spans + /// match callsite_enabled() { + /// ALWAYS => (), + /// SOMETIMES => if !enabled() { on_span() }, + /// NEVER => on_span(), + /// } + /// // for events + /// match callsite_enabled() { + /// ALWAYS => (), + /// SOMETIMES => if !enabled() { on_event() }, + /// NEVER => on_event(), + /// } + /// ``` + /// + /// A proper inversion would do `!(enabled() && event_enabled())` (or + /// `!enabled() || !event_enabled()`), but because of the implicit `&&` + /// relation between `enabled` and `event_enabled`, it is difficult to + /// short circuit and not call the wrapped `event_enabled`. + /// + /// A combinator which remembers the result of `enabled` in order to call + /// `event_enabled` only when `enabled() == true` is possible, but requires + /// additional thread-local mutable state to support a very niche use case. + // + // Also, it'd mean the wrapped layer's `enabled()` always gets called and + // globally applied to events where it doesn't today, since we can't know + // what `event_enabled` will say until we have the event to call it with. /// /// [`Filter`]: crate::subscribe::Filter /// [`enabled`]: crate::subscribe::Filter::enabled