From 09df7ba8ef532a7f08914f3ddf969f30927ce161 Mon Sep 17 00:00:00 2001 From: Bryan Garza <1396101+bryangarza@users.noreply.github.com> Date: Mon, 6 Jun 2022 11:53:01 -0700 Subject: [PATCH 1/9] opentelemetry: add more comments to example (#2140) This patch adds a bit more context around why we are creating a smaller scope for the spans, and also what happens when we call `global::shutdown_tracer_provider()` (that comment was copied from the`rust-opentelemetry` repo). Co-authored-by: Eliza Weisman --- examples/examples/opentelemetry.rs | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) 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(()) From 7302a88437cf33f7d892d321b4ad4dc56a58c10f Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Sat, 11 Jun 2022 12:34:09 -0700 Subject: [PATCH 2/9] chore: `bin/publish` shell script fixes (#2162) * fix use of `cargo --list` in bin/publish * fix shellcheck lints in bin/publish * set -euo pipefail * fix cargo hack exit status check * fix wrong emptystring args * prompt before installing cargo-hack Signed-off-by: Eliza Weisman --- bin/publish | 75 +++++++++++++++++++++++++++++++++++++++-------------- 1 file changed, 56 insertions(+), 19 deletions(-) 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 From 240cd500dab75ae8279e0e802fb8ccd5f9702dbb Mon Sep 17 00:00:00 2001 From: Jack Wrenn Date: Mon, 13 Jun 2022 18:50:52 -0400 Subject: [PATCH 3/9] core, subscriber: more `downcast_ref` & `is` methods (#2160) Adds inherent `downcast_ref` and `is` inherent methods to: - `dyn Subscriber + Send` - `dyn Subscriber + Sync` - `dyn Subscriber + Send + Sync` - `Layered` These additional implementations reduce the circumstances in which one must cast to `dyn Subscriber` (which, previously, was the only type for which `downcast_ref` and `is` were available). --- tracing-core/src/subscriber.rs | 60 +++++++++++++++++++++++++ tracing-subscriber/src/layer/layered.rs | 30 ++++++++++++- 2 files changed, 89 insertions(+), 1 deletion(-) diff --git a/tracing-core/src/subscriber.rs b/tracing-core/src/subscriber.rs index 501cce733d..3d6aaa3441 100644 --- a/tracing-core/src/subscriber.rs +++ b/tracing-core/src/subscriber.rs @@ -484,6 +484,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 diff --git a/tracing-subscriber/src/layer/layered.rs b/tracing-subscriber/src/layer/layered.rs index 0c6658cb06..5c9b934e35 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, From 5a90095092b7c34937ea1b55ded632c8fd84e50a Mon Sep 17 00:00:00 2001 From: Fredrik Enestad Date: Thu, 16 Jun 2022 20:57:04 +0200 Subject: [PATCH 4/9] docs: add tracing-logfmt to related crates (#2163) Adds tracing-logfmt crate to the related crates section --- README.md | 2 ++ tracing/README.md | 2 ++ tracing/src/lib.rs | 2 ++ 3 files changed, 6 insertions(+) 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/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

From f90b4553d11f0f033bb417ad6516586f8a012ea9 Mon Sep 17 00:00:00 2001
From: Eliza Weisman 
Date: Thu, 16 Jun 2022 13:13:57 -0700
Subject: [PATCH 5/9] core: `impl field::Value for String` (#2164)

## Motivation

Currently, it is rather difficult to record `String`s as field values,
even though `&str` is a primitive `Value` type. For example, this code
does not currently compile:

```rust
let my_string = String::from("hello world!");
tracing::debug!(my_string);
```

Instead, it is necessary to explicitly call `String::as_str` or a
similar conversion method:

```rust
let my_string = String::from("hello world!");
tracing::debug!(my_string = my_string.as_str());
```

This is unfortunate, as it makes a fairly straightforward, commomplace
task (recording a `String` as a field) unnecessarily verbose.

## Solution

This branch adds an `impl Value for String` in `tracing-core`. The impl
simply calls `String::as_str` and then calls `record_str`. Because
`Value` takes an `&self`, and there are preexisting `impl
Value` for `&T` and `&mut T`, the string is not consumed, and `&String`
or `&mut String`s can also be used as `Value`s.

I've also added tests validating that this actually works.
---
 tracing-attributes/tests/fields.rs | 13 +++++++++++++
 tracing-core/src/field.rs          |  8 ++++++++
 tracing/tests/event.rs             | 24 ++++++++++++++++++++++++
 3 files changed, 45 insertions(+)

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/field.rs b/tracing-core/src/field.rs
index ce8ebe58f4..df67566cda 100644
--- a/tracing-core/src/field.rs
+++ b/tracing-core/src/field.rs
@@ -116,6 +116,7 @@ use crate::stdlib::{
     hash::{Hash, Hasher},
     num,
     ops::Range,
+    string::String,
 };
 
 use self::private::ValidLen;
@@ -596,6 +597,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/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();
+}

From a6cb13e5523a9407ac563cfaef2de4e4032d846e Mon Sep 17 00:00:00 2001
From: Jack Wrenn 
Date: Thu, 16 Jun 2022 16:27:35 -0400
Subject: [PATCH 6/9] core: `impl Subscriber` for
 `Box`, `Arc` (#2161)

These broader impls supersede the previous impls where the inner type was a
`dyn Subscriber`. With these generic impls, you no longer must (but
still can, if you wish) cast the inner type of a boxed or arc'd
subscriber to `dyn Subscriber` to use it as a `Subscriber`.
---
 tracing-core/src/subscriber.rs | 10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)

diff --git a/tracing-core/src/subscriber.rs b/tracing-core/src/subscriber.rs
index 3d6aaa3441..9c7e210b06 100644
--- a/tracing-core/src/subscriber.rs
+++ b/tracing-core/src/subscriber.rs
@@ -662,7 +662,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)
@@ -739,7 +742,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)

From cc9531986f69551bb32a45730fbf35567206e644 Mon Sep 17 00:00:00 2001
From: David Barsky 
Date: Fri, 17 Jun 2022 18:21:32 -0400
Subject: [PATCH 7/9] core: add support for recording 128-bit integers (#2166)

## Motivation

I've received a request at work to record 128-bit integers and realized
that we should probably support recording them.

## Solution

Added two methods to the `Visit` trait, `record_i128` and `record_u128`.
However, I didn't add the size conversions present for 64-bit integers,
as 128-bit integers are, at this time, more specialized.
---
 tracing-core/src/field.rs | 18 +++++++++++++++---
 1 file changed, 15 insertions(+), 3 deletions(-)

diff --git a/tracing-core/src/field.rs b/tracing-core/src/field.rs
index df67566cda..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
@@ -278,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)
@@ -490,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)
 }

From 907604cdabc38800b6eb6e57880ad530dbacc2aa Mon Sep 17 00:00:00 2001
From: Christopher Durham 
Date: Tue, 21 Jun 2022 14:02:21 -0400
Subject: [PATCH 8/9] core, subscriber: add `event_enabled` to filter events on
 fields (#2008)

## Motivation

Allow filter layers to filter on the contents of events (see #2007).

## Solution

This branch adds a new `Subscriber::event_enabled` method, taking an
`Event` and returning `bool`. This is called before the
`Subscriber::event` method, and if it returns `false`,
`Subscriber::event` is not called.

For simple subscriber (e.g. not using `Layer`s), the `event_enabled`
method is not particulary necessary, as the subscriber can just skip the
`event` call. However, this branch also adds a new
`Layer::event_enabled` method, with the signature:
```rust
fn event_enabled(&self, event: &Event<'_>, ctx: Context<'_, S>) -> bool;
```

This is called before `Layer::on_event`, and if `event_enabled`
returns `false`, `on_event` is not called (nor is `Subscriber::event`).
This allows filter `Layer`s to filter out an `Event` based on its
fields.

Closes #2007
---
 tracing-core/src/dispatcher.rs             |  4 +-
 tracing-core/src/subscriber.rs             | 26 +++++++
 tracing-subscriber/src/fmt/mod.rs          |  5 ++
 tracing-subscriber/src/layer/layered.rs    | 21 ++++++
 tracing-subscriber/src/layer/mod.rs        | 65 +++++++++++++++++
 tracing-subscriber/src/reload.rs           |  5 ++
 tracing-subscriber/tests/event_enabling.rs | 81 ++++++++++++++++++++++
 7 files changed, 206 insertions(+), 1 deletion(-)
 create mode 100644 tracing-subscriber/tests/event_enabling.rs

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/subscriber.rs b/tracing-core/src/subscriber.rs
index 9c7e210b06..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
@@ -696,6 +712,11 @@ where
         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)
@@ -776,6 +797,11 @@ where
         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-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 5c9b934e35..0160f99c1d 100644
--- a/tracing-subscriber/src/layer/layered.rs
+++ b/tracing-subscriber/src/layer/layered.rs
@@ -139,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());
@@ -278,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()); +} From 0231ad60d4dd96299207ebb73b6b81d30c54dfcd Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 21 Jun 2022 15:57:03 -0700 Subject: [PATCH 9/9] chore(ci): run MSRV checks with minimal versions (#2171) In many cases, new releases of a dependency can break compatibility with `tracing`'s minimum supported Rust version (MSRV). It shouldn't be necessary for a `tracing` crate to bump its MSRV when a dependency does, as users on older Rust versions should be able to depend on older versions of that crate explicitly and avoid bumping. Instead, we should probably just run our MSRV checks with minimal dependency versions. This way, we don't need to bump our MSRV when the latest version of a dependency does, unless we actually *need* to pick up that new version. This branch changes the `check_msrv` CI jobs to do that. I also did some minor dependency editing to actually make tracing build with `-Zminimal-versions`. Note that `tracing-futures` is currently excluded from the MSRV build because it depends on a really ancient version of Tokio that pulls in broken deps. We should probably drop support for Tokio 0.1 and release a new version of that crate, but for now, we have to skip it from the CI job temporarily. Signed-off-by: Eliza Weisman --- .github/workflows/check_msrv.yml | 59 ++++++++++++++++++++++++++------ tracing-futures/Cargo.toml | 4 +-- tracing-futures/src/lib.rs | 58 +++++++++++++++---------------- tracing-subscriber/Cargo.toml | 2 +- 4 files changed, 81 insertions(+), 42 deletions(-) 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/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"] }