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. /// 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 diff --git a/tracing-opentelemetry/Cargo.toml b/tracing-opentelemetry/Cargo.toml index ee53821fc7..efe2de0ab9 100644 --- a/tracing-opentelemetry/Cargo.toml +++ b/tracing-opentelemetry/Cargo.toml @@ -20,7 +20,9 @@ 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 = ["trace"] } @@ -28,7 +30,7 @@ tracing = { path = "../tracing", version = "0.1.35", default-features = false, f 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 } @@ -38,6 +40,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 @@ -45,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 872afc8a44..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,7 +105,19 @@ 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::Subscriber trait; publishes OpenTelemetry metrics. +#[cfg(feature = "metrics")] +mod metrics; /// Implementation of the trace::Layer as a source of OpenTelemetry data. mod layer; @@ -107,6 +127,9 @@ mod span_ext; 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 new file mode 100644 index 0000000000..37df62c4b4 --- /dev/null +++ b/tracing-opentelemetry/src/metrics.rs @@ -0,0 +1,354 @@ +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. +/// +#[cfg_attr(docsrs, doc(cfg(feature = "metrics")))] +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..9db53fcb3f --- /dev/null +++ b/tracing-opentelemetry/tests/metrics_publishing.rs @@ -0,0 +1,284 @@ +#![cfg(feature = "metrics")] +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) +} 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 {} } 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/filter/layer_filters/combinator.rs b/tracing-subscriber/src/filter/layer_filters/combinator.rs index e79de20870..3934a13267 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, @@ -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,62 @@ 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 + /// 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 + /// [`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 +486,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..7c2ca4f640 100644 --- a/tracing-subscriber/src/filter/layer_filters/mod.rs +++ b/tracing-subscriber/src/filter/layer_filters/mod.rs @@ -298,6 +298,63 @@ 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 + /// 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 + /// [`event_enabled`]: crate::subscribe::Filter::event_enabled + /// [`callsite_enabled`]: crate::subscribe::Filter::callsite_enabled fn not(self) -> combinator::Not where Self: Sized, @@ -643,6 +700,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 +1087,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/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")] 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 diff --git a/tracing-subscriber/src/layer/mod.rs b/tracing-subscriber/src/layer/mod.rs index 24b8533234..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. /// @@ -1569,7 +1589,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>, 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(); +}