From 25ea92a1821438313e4a777fc1325ddae8b23653 Mon Sep 17 00:00:00 2001 From: David Barsky Date: Mon, 14 Feb 2022 10:55:03 -0500 Subject: [PATCH] add lint for holding a tracing span across an await --- CHANGELOG.md | 1 + Cargo.toml | 1 + clippy_lints/src/await_holding_invalid.rs | 84 ++++++++++++++++++- clippy_lints/src/lib.register_lints.rs | 1 + clippy_lints/src/lib.register_pedantic.rs | 1 + clippy_utils/src/paths.rs | 4 + tests/compile-test.rs | 3 + tests/ui/await_holding_tracing_span_guard.rs | 54 ++++++++++++ .../await_holding_tracing_span_guard.stderr | 45 ++++++++++ 9 files changed, 193 insertions(+), 1 deletion(-) create mode 100644 tests/ui/await_holding_tracing_span_guard.rs create mode 100644 tests/ui/await_holding_tracing_span_guard.stderr diff --git a/CHANGELOG.md b/CHANGELOG.md index c9adf77c0d63..130f028bacf9 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/Cargo.toml b/Cargo.toml index e445889a58f7..9e1dca5232d2 100644 --- a/Cargo.toml +++ b/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" } diff --git a/clippy_lints/src/await_holding_invalid.rs b/clippy_lints/src/await_holding_invalid.rs index 1cc3418d4748..80f65cba4b4d 100644 --- a/clippy_lints/src/await_holding_invalid.rs +++ b/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) +} diff --git a/clippy_lints/src/lib.register_lints.rs b/clippy_lints/src/lib.register_lints.rs index a80320a578f0..eb6efd20602e 100644 --- a/clippy_lints/src/lib.register_lints.rs +++ b/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, diff --git a/clippy_lints/src/lib.register_pedantic.rs b/clippy_lints/src/lib.register_pedantic.rs index 1292675f4a96..ee96f4dd6d9a 100644 --- a/clippy_lints/src/lib.register_pedantic.rs +++ b/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), diff --git a/clippy_utils/src/paths.rs b/clippy_utils/src/paths.rs index 288c56e9fd73..805872a91f23 100644 --- a/clippy_utils/src/paths.rs +++ b/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"]; diff --git a/tests/compile-test.rs b/tests/compile-test.rs index a82ff1828393..a81329439440 100644 --- a/tests/compile-test.rs +++ b/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. diff --git a/tests/ui/await_holding_tracing_span_guard.rs b/tests/ui/await_holding_tracing_span_guard.rs new file mode 100644 index 000000000000..1c4901b5af52 --- /dev/null +++ b/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 + '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(); +} diff --git a/tests/ui/await_holding_tracing_span_guard.stderr b/tests/ui/await_holding_tracing_span_guard.stderr new file mode 100644 index 000000000000..48fa3e61fcf6 --- /dev/null +++ b/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 +