diff --git a/.github/workflows/check_msrv.yml b/.github/workflows/check_msrv.yml index be257bfd30..9c345bb5b0 100644 --- a/.github/workflows/check_msrv.yml +++ b/.github/workflows/check_msrv.yml @@ -27,37 +27,76 @@ env: RUSTUP_MAX_RETRIES: 10 # Don't emit giant backtraces in the CI logs. RUST_BACKTRACE: short + MSRV: 1.49.0 + # TODO: remove this once tracing's MSRV is bumped. + APPENDER_MSRV: 1.53.0 jobs: check-msrv: # Run `cargo check` on our minimum supported Rust version (1.49.0). runs-on: ubuntu-latest steps: - - uses: actions/checkout@main - - uses: actions-rs/toolchain@v1 + - uses: actions/checkout@master + - name: "install Rust ${{ env.MSRV }}" + uses: actions-rs/toolchain@v1 + with: + toolchain: ${{ env.MSRV }} + profile: minimal + - name: "install Rust nightly" + uses: actions-rs/toolchain@v1 with: - toolchain: 1.49.0 + toolchain: nightly profile: minimal - override: true + - name: Select minimal versions + uses: actions-rs/cargo@v1 + with: + command: update + args: -Z minimal-versions + toolchain: nightly - name: Check uses: actions-rs/cargo@v1 with: command: check - args: --all --exclude=tracing-appender + # skip the following crates: + # - tracing-appender, as it has its own MSRV. + # TODO(eliza): remove this when appender is on the same MSRV as + # everything else + # - the examples, as they are not published & we don't care about + # MSRV support for them. + # - tracing-futures, as it depends on ancient tokio versions. + # TODO(eliza): remove this when the ancient tokio deps are dropped + args: >- + --workspace --all-features --locked + --exclude=tracing-appender + --exclude=tracing-examples + --exclude=tracing-futures + toolchain: ${{ env.MSRV }} # TODO: remove this once tracing's MSRV is bumped. check-msrv-appender: # Run `cargo check` on our minimum supported Rust version (1.53.0). runs-on: ubuntu-latest steps: - - uses: actions/checkout@main - - uses: actions-rs/toolchain@v1 + - uses: actions/checkout@master + - name: "install Rust ${{ env.APPENDER_MSRV }}" + uses: actions-rs/toolchain@v1 with: - toolchain: 1.53.0 + toolchain: ${{ env.APPENDER_MSRV }} profile: minimal - override: true + - name: "install Rust nightly" + uses: actions-rs/toolchain@v1 + with: + toolchain: nightly + profile: minimal + - name: Select minimal versions + uses: actions-rs/cargo@v1 + with: + command: update + args: -Z minimal-versions + toolchain: nightly - name: Check uses: actions-rs/cargo@v1 with: command: check - args: --lib=tracing-appender \ No newline at end of file + args: --all-features --locked -p tracing-appender + toolchain: ${{ env.APPENDER_MSRV }} \ No newline at end of file diff --git a/README.md b/README.md index ab4886821e..0fc9bc0797 100644 --- a/README.md +++ b/README.md @@ -402,6 +402,7 @@ are not maintained by the `tokio` project. These include: - [`tracing-forest`] provides a subscriber that preserves contextual coherence by grouping together logs from the same spans during writing. - [`tracing-loki`] provides a layer for shipping logs to [Grafana Loki]. +- [`tracing-logfmt`] provides a layer that formats events and spans into the logfmt format. (if you're the maintainer of a `tracing` ecosystem crate not in this list, please let us know!) @@ -439,6 +440,7 @@ please let us know!) [`tracing-forest`]: https://crates.io/crates/tracing-forest [`tracing-loki`]: https://crates.io/crates/tracing-loki [Grafana Loki]: https://grafana.com/oss/loki/ +[`tracing-logfmt`]: https://crates.io/crates/tracing-logfmt **Note:** that some of the ecosystem crates are currently unreleased and undergoing active development. They may be less stable than `tracing` and diff --git a/bin/publish b/bin/publish index 2fba506222..ee2a3ec88a 100755 --- a/bin/publish +++ b/bin/publish @@ -1,5 +1,4 @@ #!/usr/bin/env bash -set -e USAGE="Publish a new release of a tokio crate USAGE: @@ -10,11 +9,15 @@ OPTIONS: -d, --dry-run Perform a dry run (do not publish or tag the release) -h, --help Show this help text and exit" +set -euo pipefail + +cd "$(dirname "$0")"/.. + DRY_RUN="" VERBOSE="" err() { - echo -e "\e[31m\e[1merror:\e[0m $@" 1>&2; + echo -e "\e[31m\e[1merror:\e[0m" "$@" 1>&2; } status() { @@ -31,20 +34,40 @@ verify() { exit 1 fi - if ! cargo list | grep -q "hack"; then - status "Installing" "cargo-hack" - cargo install cargo-hack + if ! cargo --list | grep -q "hack"; then + err "missing cargo-hack executable" + read -r -p "install it? [Y/n] " INPUT + + case "$INPUT" in + [yY][eE][sS]|[yY]) + status "Installing" "cargo-hack" + cargo install cargo-hack + ;; + [nN][oO]|[nN]) + echo "okay, exiting" + exit 1 + ;; + *) + err "invalid input $INPUT" + exit 1 + ;; + esac fi status "Checking" "if $CRATE builds across feature combinations" - CARGO_HACK=(cargo hack check $VERBOSE --feature-powerset --no-dev-deps) + CARGO_HACK=(cargo hack check --feature-powerset --no-dev-deps) + + if [[ "$VERBOSE" ]]; then + CARGO_HACK+=("$VERBOSE") + fi + case "$CRATE" in tracing-subscriber) # for tracing-subscriber, don't test a complete powerset because # there are lots of feature flags INCLUDE_FEATURES=(fmt ansi json registry env-filter) - ${CARGO_HACK[@]} --include-features "${INCLUDE_FEATURES[*]}" + "${CARGO_HACK[@]}" --include-features "${INCLUDE_FEATURES[*]}" CARGO_HACK_STATUS="$?" ;; tracing) @@ -58,17 +81,17 @@ verify() { release_max_level_info release_max_level_debug release_max_level_trace ) - ${CARGO_HACK[@]} --exclude-features "${EXCLUDE_FEATURES[*]}" + "${CARGO_HACK[@]}" --exclude-features "${EXCLUDE_FEATURES[*]}" CARGO_HACK_STATUS="$?" ;; *) - ${CARGO_HACK[@]} + "${CARGO_HACK[@]}" CARGO_HACK_STATUS="$?" ;; esac - if "$CARGO_HACK_STATUS" ; then - err "$CRATE did not build with all feature combinations!" + if [[ "$CARGO_HACK_STATUS" != "0" ]] ; then + err "$CRATE did not build with all feature combinations (cargo hack exited with $CARGO_HACK_STATUS)!" exit 1 fi @@ -81,11 +104,25 @@ verify() { release() { status "Releasing" "$CRATE v$VERSION" - cargo package $VERBOSE - cargo publish $VERBOSE $DRY_RUN + local CARGO_PACKAGE=(cargo package) + local CARGO_PUBLISH=(cargo publish) + + if [[ "$VERBOSE" ]]; then + CARGO_PACKAGE+=("$VERBOSE") + CARGO_PUBLISH+=("$VERBOSE") + fi + + if [[ "$DRY_RUN" ]]; then + CARGO_PUBLISH+=("$DRY_RUN") + fi + + "${CARGO_PACKAGE[@]}" + "${CARGO_PUBLISH[@]}" + + cargo publish "$VERBOSE" "$DRY_RUN" status "Tagging" "$TAG" - if [ -n "$DRY_RUN" ]; then + if [[ "$DRY_RUN" ]]; then echo "# git tag $TAG && git push --tags" else git tag "$TAG" && git push --tags @@ -111,9 +148,9 @@ case "$1" in exit 1 ;; *) # crate or version - if [ -z "$CRATE" ]; then + if [[ -z "${CRATE+crate}" ]]; then CRATE="$1" - elif [ -z "$VERSION" ]; then + elif [[ -z "${VERSION+version}" ]]; then VERSION="$1" else err "unknown positional argument \"$1\"" @@ -126,19 +163,19 @@ esac done # set -- "${POSITIONAL[@]}" -if [ -z "$VERSION" ]; then +if [[ -z "${VERSION+version}" ]]; then err "no version specified!" HELP=1 fi -if [ -n "$CRATE" ]; then +if [[ "${CRATE+crate}" ]]; then TAG="$CRATE-$VERSION" else err "no crate specified!" HELP=1 fi -if [ -n "$HELP" ]; then +if [[ "${HELP+help}" ]]; then echo "$USAGE" exit 1 fi diff --git a/examples/examples/opentelemetry.rs b/examples/examples/opentelemetry.rs index fbc7469080..b453c77cad 100644 --- a/examples/examples/opentelemetry.rs +++ b/examples/examples/opentelemetry.rs @@ -38,8 +38,11 @@ fn main() -> Result<(), Box> { warn!("About to exit!"); trace!("status: {}", work_result); - } + } // Once this scope is closed, all spans inside are closed as well + // Shut down the current tracer provider. This will invoke the shutdown + // method on all span processors. span processors should export remaining + // spans before return. global::shutdown_tracer_provider(); Ok(()) diff --git a/tracing-attributes/tests/fields.rs b/tracing-attributes/tests/fields.rs index a31c1c2a84..c178fbb3d3 100644 --- a/tracing-attributes/tests/fields.rs +++ b/tracing-attributes/tests/fields.rs @@ -31,6 +31,11 @@ fn fn_clashy_expr_field2(s: &str) { let _ = s; } +#[instrument(fields(s = &s))] +fn fn_string(s: String) { + let _ = s; +} + #[derive(Debug)] struct HasField { my_field: &'static str, @@ -134,6 +139,14 @@ fn empty_field() { }); } +#[test] +fn string_field() { + let span = span::mock().with_field(mock("s").with_value(&"hello world").only()); + run_test(span, || { + fn_string(String::from("hello world")); + }); +} + fn run_test T, T>(span: NewSpan, fun: F) { let (subscriber, handle) = subscriber::mock() .new_span(span) diff --git a/tracing-core/src/dispatcher.rs b/tracing-core/src/dispatcher.rs index 741744437c..041722c366 100644 --- a/tracing-core/src/dispatcher.rs +++ b/tracing-core/src/dispatcher.rs @@ -511,7 +511,9 @@ impl Dispatch { /// [`event`]: super::subscriber::Subscriber::event #[inline] pub fn event(&self, event: &Event<'_>) { - self.subscriber.event(event) + if self.subscriber.event_enabled(event) { + self.subscriber.event(event); + } } /// Records that a span has been can_enter. diff --git a/tracing-core/src/field.rs b/tracing-core/src/field.rs index ce8ebe58f4..c9869ce2ca 100644 --- a/tracing-core/src/field.rs +++ b/tracing-core/src/field.rs @@ -16,9 +16,9 @@ //! will contain any fields attached to each event. //! //! `tracing` represents values as either one of a set of Rust primitives -//! (`i64`, `u64`, `f64`, `bool`, and `&str`) or using a `fmt::Display` or -//! `fmt::Debug` implementation. `Subscriber`s are provided these primitive -//! value types as `dyn Value` trait objects. +//! (`i64`, `u64`, `f64`, `i128`, `u128`, `bool`, and `&str`) or using a +//! `fmt::Display` or `fmt::Debug` implementation. `Subscriber`s are provided +//! these primitive value types as `dyn Value` trait objects. //! //! These trait objects can be formatted using `fmt::Debug`, but may also be //! recorded as typed data by calling the [`Value::record`] method on these @@ -116,6 +116,7 @@ use crate::stdlib::{ hash::{Hash, Hasher}, num, ops::Range, + string::String, }; use self::private::ValidLen; @@ -277,6 +278,16 @@ pub trait Visit { self.record_debug(field, &value) } + /// Visit a signed 128-bit integer value. + fn record_i128(&mut self, field: &Field, value: i128) { + self.record_debug(field, &value) + } + + /// Visit an unsigned 128-bit integer value. + fn record_u128(&mut self, field: &Field, value: u128) { + self.record_debug(field, &value) + } + /// Visit a boolean value. fn record_bool(&mut self, field: &Field, value: bool) { self.record_debug(field, &value) @@ -489,6 +500,8 @@ impl_values! { record_u64(usize, u32, u16, u8 as u64), record_i64(i64), record_i64(isize, i32, i16, i8 as i64), + record_u128(u128), + record_i128(i128), record_bool(bool), record_f64(f64, f32 as f64) } @@ -596,6 +609,13 @@ where } } +impl crate::sealed::Sealed for String {} +impl Value for String { + fn record(&self, key: &Field, visitor: &mut dyn Visit) { + visitor.record_str(key, self.as_str()) + } +} + impl fmt::Debug for dyn Value { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { // We are only going to be recording the field value, so we don't diff --git a/tracing-core/src/subscriber.rs b/tracing-core/src/subscriber.rs index 501cce733d..a6f0834e2c 100644 --- a/tracing-core/src/subscriber.rs +++ b/tracing-core/src/subscriber.rs @@ -60,6 +60,9 @@ use crate::stdlib::{ /// See also the [documentation on the callsite registry][cs-reg] for details /// on [`register_callsite`]. /// +/// - [`event_enabled`] is called once before every call to the [`event`] +/// method. This can be used to implement filtering on events once their field +/// values are known, but before any processing is done in the `event` method. /// - [`clone_span`] is called every time a span ID is cloned, and [`try_close`] /// is called when a span ID is dropped. By default, these functions do /// nothing. However, they can be used to implement reference counting for @@ -75,6 +78,8 @@ use crate::stdlib::{ /// [`clone_span`]: Subscriber::clone_span /// [`try_close`]: Subscriber::try_close /// [cs-reg]: crate::callsite#registering-callsites +/// [`event`]: Subscriber::event +/// [`event_enabled`]: Subscriber::event_enabled pub trait Subscriber: 'static { // === Span registry methods ============================================== @@ -291,6 +296,17 @@ pub trait Subscriber: 'static { /// follow from _b_), it may silently do nothing. fn record_follows_from(&self, span: &span::Id, follows: &span::Id); + /// Determine if an [`Event`] should be recorded. + /// + /// By default, this returns `true` and `Subscriber`s can filter events in + /// [`event`][Self::event] without any penalty. However, when `event` is + /// more complicated, this can be used to determine if `event` should be + /// called at all, separating out the decision from the processing. + fn event_enabled(&self, event: &Event<'_>) -> bool { + let _ = event; + true + } + /// Records that an [`Event`] has occurred. /// /// This method will be invoked when an Event is constructed by @@ -484,6 +500,66 @@ impl dyn Subscriber { } } +impl dyn Subscriber + Send { + /// Returns `true` if this [`Subscriber`] is the same type as `T`. + pub fn is(&self) -> bool { + self.downcast_ref::().is_some() + } + + /// Returns some reference to this [`Subscriber`] value if it is of type `T`, + /// or `None` if it isn't. + pub fn downcast_ref(&self) -> Option<&T> { + unsafe { + let raw = self.downcast_raw(TypeId::of::())?; + if raw.is_null() { + None + } else { + Some(&*(raw as *const _)) + } + } + } +} + +impl dyn Subscriber + Sync { + /// Returns `true` if this [`Subscriber`] is the same type as `T`. + pub fn is(&self) -> bool { + self.downcast_ref::().is_some() + } + + /// Returns some reference to this `[`Subscriber`] value if it is of type `T`, + /// or `None` if it isn't. + pub fn downcast_ref(&self) -> Option<&T> { + unsafe { + let raw = self.downcast_raw(TypeId::of::())?; + if raw.is_null() { + None + } else { + Some(&*(raw as *const _)) + } + } + } +} + +impl dyn Subscriber + Send + Sync { + /// Returns `true` if this [`Subscriber`] is the same type as `T`. + pub fn is(&self) -> bool { + self.downcast_ref::().is_some() + } + + /// Returns some reference to this [`Subscriber`] value if it is of type `T`, + /// or `None` if it isn't. + pub fn downcast_ref(&self) -> Option<&T> { + unsafe { + let raw = self.downcast_raw(TypeId::of::())?; + if raw.is_null() { + None + } else { + Some(&*(raw as *const _)) + } + } + } +} + /// Indicates a [`Subscriber`]'s interest in a particular callsite. /// /// `Subscriber`s return an `Interest` from their [`register_callsite`] methods @@ -602,7 +678,10 @@ impl Subscriber for NoSubscriber { fn exit(&self, _span: &span::Id) {} } -impl Subscriber for Box { +impl Subscriber for Box +where + S: Subscriber + ?Sized, +{ #[inline] fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { self.as_ref().register_callsite(metadata) @@ -633,6 +712,11 @@ impl Subscriber for Box { self.as_ref().record_follows_from(span, follows) } + #[inline] + fn event_enabled(&self, event: &Event<'_>) -> bool { + self.as_ref().event_enabled(event) + } + #[inline] fn event(&self, event: &Event<'_>) { self.as_ref().event(event) @@ -679,7 +763,10 @@ impl Subscriber for Box { } } -impl Subscriber for Arc { +impl Subscriber for Arc +where + S: Subscriber + ?Sized, +{ #[inline] fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { self.as_ref().register_callsite(metadata) @@ -710,6 +797,11 @@ impl Subscriber for Arc { self.as_ref().record_follows_from(span, follows) } + #[inline] + fn event_enabled(&self, event: &Event<'_>) -> bool { + self.as_ref().event_enabled(event) + } + #[inline] fn event(&self, event: &Event<'_>) { self.as_ref().event(event) diff --git a/tracing-futures/Cargo.toml b/tracing-futures/Cargo.toml index 6347b97449..196094414e 100644 --- a/tracing-futures/Cargo.toml +++ b/tracing-futures/Cargo.toml @@ -35,8 +35,8 @@ tokio-executor = { version = "0.1", optional = true } tokio = { version = "0.1", optional = true } [dev-dependencies] -tokio = "0.1.22" -tokio-test = "0.3" +tokio = "1" +tokio-test = "0.4" tracing-core = { path = "../tracing-core", version = "0.1.2" } tracing-mock = { path = "../tracing-mock" } diff --git a/tracing-futures/src/lib.rs b/tracing-futures/src/lib.rs index addc624df8..2712c160ac 100644 --- a/tracing-futures/src/lib.rs +++ b/tracing-futures/src/lib.rs @@ -627,35 +627,35 @@ mod tests { handle.assert_finished(); } - #[test] - fn span_follows_future_onto_threadpool() { - let (subscriber, handle) = subscriber::mock() - .enter(span::mock().named("a")) - .enter(span::mock().named("b")) - .exit(span::mock().named("b")) - .enter(span::mock().named("b")) - .exit(span::mock().named("b")) - .drop_span(span::mock().named("b")) - .exit(span::mock().named("a")) - .drop_span(span::mock().named("a")) - .done() - .run_with_handle(); - let mut runtime = tokio::runtime::Runtime::new().unwrap(); - with_default(subscriber, || { - tracing::trace_span!("a").in_scope(|| { - let future = PollN::new_ok(2) - .instrument(tracing::trace_span!("b")) - .map(|_| { - tracing::trace_span!("c").in_scope(|| { - // "c" happens _outside_ of the instrumented future's - // span, so we don't expect it. - }) - }); - runtime.block_on(Box::new(future)).unwrap(); - }) - }); - handle.assert_finished(); - } + // #[test] + // fn span_follows_future_onto_threadpool() { + // let (subscriber, handle) = subscriber::mock() + // .enter(span::mock().named("a")) + // .enter(span::mock().named("b")) + // .exit(span::mock().named("b")) + // .enter(span::mock().named("b")) + // .exit(span::mock().named("b")) + // .drop_span(span::mock().named("b")) + // .exit(span::mock().named("a")) + // .drop_span(span::mock().named("a")) + // .done() + // .run_with_handle(); + // let mut runtime = tokio::runtime::Runtime::new().unwrap(); + // with_default(subscriber, || { + // tracing::trace_span!("a").in_scope(|| { + // let future = PollN::new_ok(2) + // .instrument(tracing::trace_span!("b")) + // .map(|_| { + // tracing::trace_span!("c").in_scope(|| { + // // "c" happens _outside_ of the instrumented future's + // // span, so we don't expect it. + // }) + // }); + // runtime.block_on(Box::new(future)).unwrap(); + // }) + // }); + // handle.assert_finished(); + // } } #[cfg(all(feature = "futures-03", feature = "std-future"))] diff --git a/tracing-subscriber/Cargo.toml b/tracing-subscriber/Cargo.toml index 3595318c46..9fe05df14f 100644 --- a/tracing-subscriber/Cargo.toml +++ b/tracing-subscriber/Cargo.toml @@ -76,7 +76,7 @@ tracing-log = { path = "../tracing-log", version = "0.1.2" } criterion = { version = "0.3", default_features = false } regex = { version = "1", default-features = false, features = ["std"] } tracing-futures = { path = "../tracing-futures", version = "0.2", default-features = false, features = ["std-future", "std"] } -tokio = { version = "0.2", features = ["rt-core", "macros"] } +tokio = { version = "1", features = ["rt", "macros"] } # Enable the `time` crate's `macros` feature, for examples. time = { version = "0.3", features = ["formatting", "macros"] } diff --git a/tracing-subscriber/src/fmt/mod.rs b/tracing-subscriber/src/fmt/mod.rs index 8470cc1c0f..3c6a6ac40e 100644 --- a/tracing-subscriber/src/fmt/mod.rs +++ b/tracing-subscriber/src/fmt/mod.rs @@ -397,6 +397,11 @@ where self.inner.record_follows_from(span, follows) } + #[inline] + fn event_enabled(&self, event: &Event<'_>) -> bool { + self.inner.event_enabled(event) + } + #[inline] fn event(&self, event: &Event<'_>) { self.inner.event(event); diff --git a/tracing-subscriber/src/layer/layered.rs b/tracing-subscriber/src/layer/layered.rs index 0c6658cb06..0160f99c1d 100644 --- a/tracing-subscriber/src/layer/layered.rs +++ b/tracing-subscriber/src/layer/layered.rs @@ -12,7 +12,11 @@ use crate::{ }; #[cfg(all(feature = "registry", feature = "std"))] use crate::{filter::FilterId, registry::Registry}; -use core::{any::TypeId, cmp, fmt, marker::PhantomData}; +use core::{ + any::{Any, TypeId}, + cmp, fmt, + marker::PhantomData, +}; /// A [`Subscriber`] composed of a `Subscriber` wrapped by one or more /// [`Layer`]s. @@ -63,6 +67,30 @@ pub struct Layered { // === impl Layered === +impl Layered +where + L: Layer, + S: Subscriber, +{ + /// Returns `true` if this [`Subscriber`] is the same type as `T`. + pub fn is(&self) -> bool { + self.downcast_ref::().is_some() + } + + /// Returns some reference to this [`Subscriber`] value if it is of type `T`, + /// or `None` if it isn't. + pub fn downcast_ref(&self) -> Option<&T> { + unsafe { + let raw = self.downcast_raw(TypeId::of::())?; + if raw.is_null() { + None + } else { + Some(&*(raw as *const T)) + } + } + } +} + impl Subscriber for Layered where L: Layer, @@ -111,6 +139,16 @@ where self.layer.on_follows_from(span, follows, self.ctx()); } + fn event_enabled(&self, event: &Event<'_>) -> bool { + if self.layer.event_enabled(event, self.ctx()) { + // if the outer layer enables the event, ask the inner subscriber. + self.inner.event_enabled(event) + } else { + // otherwise, the event is disabled by this layer + false + } + } + fn event(&self, event: &Event<'_>) { self.inner.event(event); self.layer.on_event(event, self.ctx()); @@ -250,6 +288,17 @@ where self.layer.on_follows_from(span, follows, ctx); } + #[inline] + fn event_enabled(&self, event: &Event<'_>, ctx: Context<'_, S>) -> bool { + if self.layer.event_enabled(event, ctx.clone()) { + // if the outer layer enables the event, ask the inner subscriber. + self.inner.event_enabled(event, ctx) + } else { + // otherwise, the event is disabled by this layer + false + } + } + #[inline] fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { self.inner.on_event(event, ctx.clone()); diff --git a/tracing-subscriber/src/layer/mod.rs b/tracing-subscriber/src/layer/mod.rs index d94742f0f2..a15870e691 100644 --- a/tracing-subscriber/src/layer/mod.rs +++ b/tracing-subscriber/src/layer/mod.rs @@ -415,6 +415,28 @@ //! [`Interest::never()`] from its [`register_callsite`] method, filter //! evaluation will short-circuit and the span or event will be disabled. //! +//! ### Enabling Interest +//! +//! Whenever an tracing event (or span) is emitted, it goes through a number of +//! steps to determine how and how much it should be processed. The earlier an +//! event is disabled, the less work has to be done to process the event, so +//! `Layer`s that implement filtering should attempt to disable unwanted +//! events as early as possible. In order, each event checks: +//! +//! - [`register_callsite`], once per callsite (roughly: once per time that +//! `event!` or `span!` is written in the source code; this is cached at the +//! callsite). See [`Subscriber::register_callsite`] and +//! [`tracing_core::callsite`] for a summary of how this behaves. +//! - [`enabled`], once per emitted event (roughly: once per time that `event!` +//! or `span!` is *executed*), and only if `register_callsite` regesters an +//! [`Interest::sometimes`]. This is the main customization point to globally +//! filter events based on their [`Metadata`]. If an event can be disabled +//! based only on [`Metadata`], it should be, as this allows the construction +//! of the actual `Event`/`Span` to be skipped. +//! - For events only (and not spans), [`event_enabled`] is called just before +//! processing the event. This gives layers one last chance to say that +//! an event should be filtered out, now that the event's fields are known. +//! //! ## Per-Layer Filtering //! //! **Note**: per-layer filtering APIs currently require the [`"registry"` crate @@ -634,6 +656,7 @@ //! [the current span]: Context::current_span //! [`register_callsite`]: Layer::register_callsite //! [`enabled`]: Layer::enabled +//! [`event_enabled`]: Layer::event_enabled //! [`on_enter`]: Layer::on_enter //! [`Layer::register_callsite`]: Layer::register_callsite //! [`Layer::enabled`]: Layer::enabled @@ -832,6 +855,31 @@ where // seems like a good future-proofing measure as it may grow other methods later... fn on_follows_from(&self, _span: &span::Id, _follows: &span::Id, _ctx: Context<'_, S>) {} + /// Called before [`on_event`], to determine if `on_event` should be called. + /// + ///
+ /// 
+    ///
+    /// **Note**: This method determines whether an event is globally enabled,
+    /// *not* whether the individual `Layer` will be notified about the
+    /// event. This is intended to be used by `Layer`s that implement
+    /// filtering for the entire stack. `Layer`s which do not wish to be
+    /// notified about certain events but do not wish to globally disable them
+    /// should ignore those events in their [on_event][Self::on_event].
+    ///
+    ///
+ /// + /// See [the trait-level documentation] for more information on filtering + /// with `Layer`s. + /// + /// [`on_event`]: Self::on_event + /// [`Interest`]: tracing_core::Interest + /// [the trait-level documentation]: #filtering-with-layers + #[inline] // collapse this to a constant please mrs optimizer + fn event_enabled(&self, _event: &Event<'_>, _ctx: Context<'_, S>) -> bool { + true + } + /// Notifies this layer that an event has occurred. fn on_event(&self, _event: &Event<'_>, _ctx: Context<'_, S>) {} @@ -1460,6 +1508,14 @@ where } } + #[inline] + fn event_enabled(&self, event: &Event<'_>, ctx: Context<'_, S>) -> bool { + match self { + Some(ref inner) => inner.event_enabled(event, ctx), + None => false, + } + } + #[inline] fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { if let Some(ref inner) = self { @@ -1548,6 +1604,11 @@ feature! { self.deref().on_follows_from(span, follows, ctx) } + #[inline] + fn event_enabled(&self, event: &Event<'_>, ctx: Context<'_, S>) -> bool { + self.deref().event_enabled(event, ctx) + } + #[inline] fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { self.deref().on_event(event, ctx) @@ -1629,6 +1690,10 @@ feature! { self.iter().all(|l| l.enabled(metadata, ctx.clone())) } + fn event_enabled(&self, event: &Event<'_>, ctx: Context<'_, S>) -> bool { + self.iter().all(|l| l.event_enabled(event, ctx.clone())) + } + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) { for l in self { l.on_new_span(attrs, id, ctx.clone()); diff --git a/tracing-subscriber/src/reload.rs b/tracing-subscriber/src/reload.rs index 422917a413..7e88956ec9 100644 --- a/tracing-subscriber/src/reload.rs +++ b/tracing-subscriber/src/reload.rs @@ -134,6 +134,11 @@ where try_lock!(self.inner.read()).on_follows_from(span, follows, ctx) } + #[inline] + fn event_enabled(&self, event: &Event<'_>, ctx: layer::Context<'_, S>) -> bool { + try_lock!(self.inner.read(), else return false).event_enabled(event, ctx) + } + #[inline] fn on_event(&self, event: &Event<'_>, ctx: layer::Context<'_, S>) { try_lock!(self.inner.read()).on_event(event, ctx) diff --git a/tracing-subscriber/tests/event_enabling.rs b/tracing-subscriber/tests/event_enabling.rs new file mode 100644 index 0000000000..8f67cfcbaf --- /dev/null +++ b/tracing-subscriber/tests/event_enabling.rs @@ -0,0 +1,81 @@ +#![cfg(feature = "registry")] + +use std::sync::{Arc, Mutex}; +use tracing::{subscriber::with_default, Event, Metadata, Subscriber}; +use tracing_subscriber::{layer::Context, prelude::*, registry, Layer}; + +struct TrackingLayer { + enabled: bool, + event_enabled_count: Arc>, + event_enabled: bool, + on_event_count: Arc>, +} + +impl Layer for TrackingLayer +where + C: Subscriber + Send + Sync + 'static, +{ + fn enabled(&self, _metadata: &Metadata<'_>, _ctx: Context<'_, C>) -> bool { + self.enabled + } + + fn event_enabled(&self, _event: &Event<'_>, _ctx: Context<'_, C>) -> bool { + *self.event_enabled_count.lock().unwrap() += 1; + self.event_enabled + } + + fn on_event(&self, _event: &Event<'_>, _ctx: Context<'_, C>) { + *self.on_event_count.lock().unwrap() += 1; + } +} + +#[test] +fn event_enabled_is_only_called_once() { + let event_enabled_count = Arc::new(Mutex::default()); + let count = event_enabled_count.clone(); + let subscriber = registry().with(TrackingLayer { + enabled: true, + event_enabled_count, + event_enabled: true, + on_event_count: Arc::new(Mutex::default()), + }); + with_default(subscriber, || { + tracing::error!("hiya!"); + }); + + assert_eq!(1, *count.lock().unwrap()); +} + +#[test] +fn event_enabled_not_called_when_not_enabled() { + let event_enabled_count = Arc::new(Mutex::default()); + let count = event_enabled_count.clone(); + let subscriber = registry().with(TrackingLayer { + enabled: false, + event_enabled_count, + event_enabled: true, + on_event_count: Arc::new(Mutex::default()), + }); + with_default(subscriber, || { + tracing::error!("hiya!"); + }); + + assert_eq!(0, *count.lock().unwrap()); +} + +#[test] +fn event_disabled_does_disable_event() { + let on_event_count = Arc::new(Mutex::default()); + let count = on_event_count.clone(); + let subscriber = registry().with(TrackingLayer { + enabled: true, + event_enabled_count: Arc::new(Mutex::default()), + event_enabled: false, + on_event_count, + }); + with_default(subscriber, || { + tracing::error!("hiya!"); + }); + + assert_eq!(0, *count.lock().unwrap()); +} diff --git a/tracing/README.md b/tracing/README.md index 5da141a3a5..1c7261c6ff 100644 --- a/tracing/README.md +++ b/tracing/README.md @@ -395,6 +395,7 @@ maintained by the `tokio` project. These include: framework for validating the behavior of `tracing` spans. - [`sentry-tracing`] provides a layer for reporting events and traces to [Sentry]. - [`tracing-loki`] provides a layer for shipping logs to [Grafana Loki]. +- [`tracing-logfmt`] provides a layer that formats events and spans into the logfmt format. If you're the maintainer of a `tracing` ecosystem crate not listed above, please let us know! We'd love to add your project to the list! @@ -424,6 +425,7 @@ please let us know! We'd love to add your project to the list! [Sentry]: https://sentry.io/welcome/ [`tracing-loki`]: https://crates.io/crates/tracing-loki [Grafana Loki]: https://grafana.com/oss/loki/ +[`tracing-logfmt`]: https://crates.io/crates/tracing-logfmt **Note:** that some of the ecosystem crates are currently unreleased and undergoing active development. They may be less stable than `tracing` and diff --git a/tracing/src/lib.rs b/tracing/src/lib.rs index 4743eba207..1ef96b54f8 100644 --- a/tracing/src/lib.rs +++ b/tracing/src/lib.rs @@ -743,6 +743,7 @@ //! - [`tracing-forest`] provides a subscriber that preserves contextual coherence by //! grouping together logs from the same spans during writing. //! - [`tracing-loki`] provides a layer for shipping logs to [Grafana Loki]. +//! - [`tracing-logfmt`] provides a layer that formats events and spans into the logfmt format. //! //! If you're the maintainer of a `tracing` ecosystem crate not listed above, //! please let us know! We'd love to add your project to the list! @@ -779,6 +780,7 @@ //! [`tracing-forest`]: https://crates.io/crates/tracing-forest //! [`tracing-loki`]: https://crates.io/crates/tracing-loki //! [Grafana Loki]: https://grafana.com/oss/loki/ +//! [`tracing-logfmt`]: https://crates.io/crates/tracing-logfmt //! //! 
 //!     Note: Some of these ecosystem crates are currently
diff --git a/tracing/tests/event.rs b/tracing/tests/event.rs
index ffb63c816b..61df19ad3c 100644
--- a/tracing/tests/event.rs
+++ b/tracing/tests/event.rs
@@ -474,3 +474,27 @@ fn option_ref_mut_values() {
 
     handle.assert_finished();
 }
+
+#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
+#[test]
+fn string_field() {
+    let (subscriber, handle) = subscriber::mock()
+        .event(event::mock().with_fields(field::mock("my_string").with_value(&"hello").only()))
+        .event(
+            event::mock().with_fields(field::mock("my_string").with_value(&"hello world!").only()),
+        )
+        .done()
+        .run_with_handle();
+    with_default(subscriber, || {
+        let mut my_string = String::from("hello");
+
+        tracing::event!(Level::INFO, my_string);
+
+        // the string is not moved by using it as a field!
+        my_string.push_str(" world!");
+
+        tracing::event!(Level::INFO, my_string);
+    });
+
+    handle.assert_finished();
+}