Add lint for holding a tracing Span Guard Across an .await

CHANGELOG.md

@@ -3051,6 +3051,7 @@ Released 2018-09-13
 [`async_yields_async`]: https://rust-lang.github.io/rust-clippy/master/index.html#async_yields_async
 [`await_holding_lock`]: https://rust-lang.github.io/rust-clippy/master/index.html#await_holding_lock
 [`await_holding_refcell_ref`]: https://rust-lang.github.io/rust-clippy/master/index.html#await_holding_refcell_ref
+[`await_holding_span_guard`]: https://rust-lang.github.io/rust-clippy/master/index.html#await_holding_span_guard
 [`bad_bit_mask`]: https://rust-lang.github.io/rust-clippy/master/index.html#bad_bit_mask
 [`bind_instead_of_map`]: https://rust-lang.github.io/rust-clippy/master/index.html#bind_instead_of_map
 [`blacklisted_name`]: https://rust-lang.github.io/rust-clippy/master/index.html#blacklisted_name

Cargo.toml

@@ -50,6 +50,7 @@ syn = { version = "1.0", features = ["full"] }
 futures = "0.3"
 parking_lot = "0.11.2"
 tokio = { version = "1", features = ["io-util"] }
+tracing = "0.1"
 
 [build-dependencies]
 rustc_tools_util = { version = "0.2", path = "rustc_tools_util" }

clippy_lints/src/await_holding_invalid.rs

@@ -95,7 +95,74 @@ declare_clippy_lint! {
     "Inside an async function, holding a RefCell ref while calling await"
 }
 
-declare_lint_pass!(AwaitHolding => [AWAIT_HOLDING_LOCK, AWAIT_HOLDING_REFCELL_REF]);
+declare_clippy_lint! {
+    /// ### What it does
+    /// Checks for calls to await while holding a
+    /// `tracing` span's `Entered` or `EnteredSpan` guards.
+    ///
+    /// ### Why is this bad?
+    /// The guards created by `tracing::Span::enter()` or `tracing::Span::entered()`
+    /// across `.await` points will result in incorrect traces. This occurs when
+    /// an async function or async block yields at an .await point, the current
+    /// scope is exited, but values in that scope are not dropped (because
+    /// the async block will eventually resume execution from that await point).
+    /// This means that another task will begin executing while remaining in the entered span.
+    ///
+    /// ### Known problems
+    /// Will report false positive for explicitly dropped refs ([#6353](https://github.com/rust-lang/rust-clippy/issues/6353)).
+    ///
+    /// ### Example
+    /// ```rust,ignore
+    /// use tracing::{span, Level};
+    ///
+    /// async fn foo() {
+    ///     let span = span!(Level::INFO, "foo");
+    ///
+    ///     THIS WILL RESULT IN INCORRECT TRACES
+    ///     let _enter = span.enter();
+    ///     bar().await;
+    /// }
+    /// ```
+    ///
+    /// Use instead:
+    /// ```rust,ignore
+    /// use tracing::{span, Level}
+    ///
+    /// async fn foo() {
+    ///     let span = span!(Level::INFO, "foo");
+    ///
+    ///     let some_value = span.in_scope(|| {
+    ///         // run some synchronous code inside the span...
+    ///     });
+    ///
+    ///     // This is okay! The span has already been exited before we reach
+    ///     // the await point.
+    ///     bar(some_value).await;
+    /// }
+    /// ```
+    ///
+    /// Or use:
+    ///
+    /// ```rust,ignore
+    /// use tracing::{span, Level, Instrument};
+    ///
+    /// async fn foo() {
+    ///     let span = span!(Level::INFO, "foo");
+    ///     async move {
+    ///         // This is correct! If we yield here, the span will be exited,
+    ///         // and re-entered when we resume.
+    ///         bar().await;
+    ///     }.instrument(span) // instrument the async block with the span...
+    ///     .await // ...and await it.
+    /// }
+    /// ```
+    #[clippy::version = "1.60.0"]
+    pub AWAIT_HOLDING_SPAN_GUARD,
+    pedantic,
+    "Inside an async function, holding a Span guard while calling await"
+}
+
+declare_lint_pass!(AwaitHolding => [AWAIT_HOLDING_LOCK, AWAIT_HOLDING_REFCELL_REF, AWAIT_HOLDING_SPAN_GUARD]);
 
 impl LateLintPass<'_> for AwaitHolding {
     fn check_body(&mut self, cx: &LateContext<'_>, body: &'_ Body<'_>) {
@@ -137,6 +204,16 @@ fn check_interior_types(cx: &LateContext<'_>, ty_causes: &[GeneratorInteriorType
                     "these are all the await points this ref is held through",
                 );
             }
+            if is_tracing_span_guard(cx, adt.did) {
+                span_lint_and_note(
+                    cx,
+                    AWAIT_HOLDING_SPAN_GUARD,
+                    ty_cause.span,
+                    "this Span guard is held across an 'await' point. Consider using the `.instrument()` combinator or the `.in_scope()` method instead",
+                    ty_cause.scope_span.or(Some(span)),
+                    "these are all the await points this ref is held through",
+                );
+            }
         }
     }
 }
@@ -153,3 +230,8 @@ fn is_mutex_guard(cx: &LateContext<'_>, def_id: DefId) -> bool {
 fn is_refcell_ref(cx: &LateContext<'_>, def_id: DefId) -> bool {
     match_def_path(cx, def_id, &paths::REFCELL_REF) || match_def_path(cx, def_id, &paths::REFCELL_REFMUT)
 }
+
+fn is_tracing_span_guard(cx: &LateContext<'_>, def_id: DefId) -> bool {
+    match_def_path(cx, def_id, &paths::TRACING_SPAN_ENTER_GUARD)
+        || match_def_path(cx, def_id, &paths::TRACING_SPAN_ENTERED_GUARD)
+}

clippy_lints/src/lib.register_lints.rs

@@ -51,6 +51,7 @@ store.register_lints(&[
     attrs::USELESS_ATTRIBUTE,
     await_holding_invalid::AWAIT_HOLDING_LOCK,
     await_holding_invalid::AWAIT_HOLDING_REFCELL_REF,
+    await_holding_invalid::AWAIT_HOLDING_SPAN_GUARD,
     bit_mask::BAD_BIT_MASK,
     bit_mask::INEFFECTIVE_BIT_MASK,
     bit_mask::VERBOSE_BIT_MASK,

clippy_lints/src/lib.register_pedantic.rs

@@ -6,6 +6,7 @@ store.register_group(true, "clippy::pedantic", Some("clippy_pedantic"), vec![
     LintId::of(attrs::INLINE_ALWAYS),
     LintId::of(await_holding_invalid::AWAIT_HOLDING_LOCK),
     LintId::of(await_holding_invalid::AWAIT_HOLDING_REFCELL_REF),
+    LintId::of(await_holding_invalid::AWAIT_HOLDING_SPAN_GUARD),
     LintId::of(bit_mask::VERBOSE_BIT_MASK),
     LintId::of(borrow_as_ptr::BORROW_AS_PTR),
     LintId::of(bytecount::NAIVE_BYTECOUNT),

clippy_utils/src/paths.rs

@@ -198,6 +198,10 @@ pub const TO_STRING_METHOD: [&str; 4] = ["alloc", "string", "ToString", "to_stri
 pub const TOKIO_IO_ASYNCREADEXT: [&str; 5] = ["tokio", "io", "util", "async_read_ext", "AsyncReadExt"];
 #[allow(clippy::invalid_paths)] // internal lints do not know about all external crates
 pub const TOKIO_IO_ASYNCWRITEEXT: [&str; 5] = ["tokio", "io", "util", "async_write_ext", "AsyncWriteExt"];
+#[allow(clippy::invalid_paths)] // internal lints do not know about all external crates
+pub const TRACING_SPAN_ENTER_GUARD: [&str; 3] = ["tracing", "span", "Entered"];
+#[allow(clippy::invalid_paths)] // internal lints do not know about all external crates
+pub const TRACING_SPAN_ENTERED_GUARD: [&str; 3] = ["tracing", "span", "EnteredSpan"];
 pub const TRY_FROM: [&str; 4] = ["core", "convert", "TryFrom", "try_from"];
 pub const VEC_AS_MUT_SLICE: [&str; 4] = ["alloc", "vec", "Vec", "as_mut_slice"];
 pub const VEC_AS_SLICE: [&str; 4] = ["alloc", "vec", "Vec", "as_slice"];

tests/compile-test.rs

@@ -33,6 +33,7 @@ static TEST_DEPENDENCIES: &[&str] = &[
     "serde_derive",
     "syn",
     "tokio",
+    "tracing",
     "parking_lot",
 ];
 
@@ -56,6 +57,8 @@ extern crate quote;
 extern crate syn;
 #[allow(unused_extern_crates)]
 extern crate tokio;
+#[allow(unused_extern_crates)]
+extern crate tracing;
 
 /// Produces a string with an `--extern` flag for all UI test crate
 /// dependencies.

tests/ui/await_holding_tracing_span_guard.rs

@@ -0,0 +1,54 @@
+#![warn(clippy::await_holding_span_guard)]
+
+use tracing::{span, Instrument, Level, Span};
+
+async fn good_in_scope() {
+    let span = span!(Level::INFO, "good");
+
+    let some_value = span.in_scope(|| 32);
+
+    baz(some_value).await;
+}
+
+async fn good_instrument() {
+    let span = span!(Level::INFO, "good");
+
+    baz(32).instrument(span).await;
+}
+
+async fn bad_borrowed() {
+    let span = span!(Level::INFO, "bad_borrowed");
+
+    let _guard = span.enter();
+    bar().await;
+}
+
+async fn bad_owned() {
+    let span = span!(Level::INFO, "bad_owned");
+
+    let _guard = span.entered();
+    bar().await;
+}
+
+#[allow(clippy::manual_async_fn)]
+fn bad_async_block_borrowed() -> impl std::future::Future<Output = ()> + 'static {
+    async move {
+        let span = span!(Level::INFO, "async_block_borrowed");
+        let _guard = span.enter();
+        bar().await
+    }
+}
+
+async fn bar() {}
+
+async fn baz(value: usize) {
+    let _ = value;
+}
+
+fn main() {
+    good_in_scope();
+    good_instrument();
+    bad_borrowed();
+    bad_owned();
+    bad_async_block_borrowed();
+}

tests/ui/await_holding_tracing_span_guard.stderr

@@ -0,0 +1,45 @@
+error: this Span guard is held across an 'await' point. Consider using the `.instrument()` combinator or the `.in_scope()` method instead
+  --> $DIR/await_holding_tracing_span_guard.rs:22:9
+   |
+LL |     let _guard = span.enter();
+   |         ^^^^^^
+   |
+   = note: `-D clippy::await-holding-span-guard` implied by `-D warnings`
+note: these are all the await points this ref is held through
+  --> $DIR/await_holding_tracing_span_guard.rs:22:5
+   |
+LL | /     let _guard = span.enter();
+LL | |     bar().await;
+LL | | }
+   | |_^
+
+error: this Span guard is held across an 'await' point. Consider using the `.instrument()` combinator or the `.in_scope()` method instead
+  --> $DIR/await_holding_tracing_span_guard.rs:29:9
+   |
+LL |     let _guard = span.entered();
+   |         ^^^^^^
+   |
+note: these are all the await points this ref is held through
+  --> $DIR/await_holding_tracing_span_guard.rs:29:5
+   |
+LL | /     let _guard = span.entered();
+LL | |     bar().await;
+LL | | }
+   | |_^
+
+error: this Span guard is held across an 'await' point. Consider using the `.instrument()` combinator or the `.in_scope()` method instead
+  --> $DIR/await_holding_tracing_span_guard.rs:37:13
+   |
+LL |         let _guard = span.enter();
+   |             ^^^^^^
+   |
+note: these are all the await points this ref is held through
+  --> $DIR/await_holding_tracing_span_guard.rs:37:9
+   |
+LL | /         let _guard = span.enter();
+LL | |         bar().await
+LL | |     }
+   | |_____^
+
+error: aborting due to 3 previous errors
+