diff --git a/Cargo.toml b/Cargo.toml index 79b600dbfb..c545a36106 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -17,3 +17,8 @@ members = [ "tracing-journald", "examples" ] + +[workspace.metadata.dylint] +libraries = [ + { path = "lints/await_holding_span_guard" }, +] diff --git a/lints/await_holding_span_guard/.cargo/config.toml b/lints/await_holding_span_guard/.cargo/config.toml new file mode 100644 index 0000000000..d624ca4c74 --- /dev/null +++ b/lints/await_holding_span_guard/.cargo/config.toml @@ -0,0 +1,8 @@ +[target.x86_64-apple-darwin] +linker = "dylint-link" + +[target.x86_64-unknown-linux-gnu] +linker = "dylint-link" + +[target.x86_64-pc-windows-msvc] +linker = "dylint-link" diff --git a/lints/await_holding_span_guard/.gitignore b/lints/await_holding_span_guard/.gitignore new file mode 100644 index 0000000000..4fffb2f89c --- /dev/null +++ b/lints/await_holding_span_guard/.gitignore @@ -0,0 +1,2 @@ +/target +/Cargo.lock diff --git a/lints/await_holding_span_guard/Cargo.toml b/lints/await_holding_span_guard/Cargo.toml new file mode 100644 index 0000000000..b635af2eb2 --- /dev/null +++ b/lints/await_holding_span_guard/Cargo.toml @@ -0,0 +1,28 @@ +[package] +name = "await_holding_span_guard" +version = "0.1.0" +authors = ["authors go here"] +description = "decription goes here" +edition = "2021" +publish = false + +[lib] +crate-type = ["cdylib"] + +[[example]] +name = "ui" +path = "ui/main.rs" + +[dependencies] +clippy_utils = { git = "https://github.com/rust-lang/rust-clippy", rev = "5707491b185f9c9fc913f25efbd09d2649136683" } +dylint_linting = "1.0.13" +if_chain = "1.0.2" + +[dev-dependencies] +dylint_testing = "1.0.13" +tracing = { path = "../../tracing" } + +[package.metadata.rust-analyzer] +rustc_private = true + +[workspace] diff --git a/lints/await_holding_span_guard/rust-toolchain b/lints/await_holding_span_guard/rust-toolchain new file mode 100644 index 0000000000..f16a2f1f54 --- /dev/null +++ b/lints/await_holding_span_guard/rust-toolchain @@ -0,0 +1,3 @@ +[toolchain] +channel = "nightly-2022-02-10" +components = ["llvm-tools-preview", "rustc-dev"] diff --git a/lints/await_holding_span_guard/src/await_holding_span_guard.rs b/lints/await_holding_span_guard/src/await_holding_span_guard.rs new file mode 100644 index 0000000000..f7ddf8eaf3 --- /dev/null +++ b/lints/await_holding_span_guard/src/await_holding_span_guard.rs @@ -0,0 +1,125 @@ +use clippy_utils::diagnostics::span_lint_and_note; +use clippy_utils::match_def_path; +use rustc_hir::def_id::DefId; +use rustc_hir::{AsyncGeneratorKind, Body, BodyId, GeneratorKind}; +use rustc_lint::{LateContext, LateLintPass}; +use rustc_middle::ty::GeneratorInteriorTypeCause; +use rustc_session::{declare_lint, declare_lint_pass}; +use rustc_span::Span; + +declare_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. + /// } + /// ``` + pub AWAIT_HOLDING_SPAN_GUARD, + Warn, + "Inside an async function, holding a Span guard while calling await" +} + +declare_lint_pass!(AwaitHoldingSpanGuard => [AWAIT_HOLDING_SPAN_GUARD]); + +pub const TRACING_SPAN_ENTER_GUARD: [&str; 3] = ["tracing", "span", "Entered"]; +pub const TRACING_SPAN_ENTERED_GUARD: [&str; 3] = ["tracing", "span", "EnteredSpan"]; + +impl LateLintPass<'_> for AwaitHoldingSpanGuard { + fn check_body(&mut self, cx: &LateContext<'_>, body: &'_ Body<'_>) { + use AsyncGeneratorKind::{Block, Closure, Fn}; + if let Some(GeneratorKind::Async(Block | Closure | Fn)) = body.generator_kind { + let body_id = BodyId { + hir_id: body.value.hir_id, + }; + let typeck_results = cx.tcx.typeck_body(body_id); + check_interior_types( + cx, + typeck_results + .generator_interior_types + .as_ref() + .skip_binder(), + body.value.span, + ); + } + } +} + +fn check_interior_types( + cx: &LateContext<'_>, + ty_causes: &[GeneratorInteriorTypeCause<'_>], + span: Span, +) { + for ty_cause in ty_causes { + if let rustc_middle::ty::Adt(adt, _) = ty_cause.ty.kind() { + 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", + ); + } + } + } +} + +fn is_tracing_span_guard(cx: &LateContext<'_>, def_id: DefId) -> bool { + match_def_path(cx, def_id, &TRACING_SPAN_ENTER_GUARD) + || match_def_path(cx, def_id, &TRACING_SPAN_ENTERED_GUARD) +} diff --git a/lints/await_holding_span_guard/src/lib.rs b/lints/await_holding_span_guard/src/lib.rs new file mode 100644 index 0000000000..2bbd3e45b1 --- /dev/null +++ b/lints/await_holding_span_guard/src/lib.rs @@ -0,0 +1,24 @@ +#![feature(rustc_private)] +#![warn(unused_extern_crates)] + +dylint_linting::dylint_library!(); + +extern crate rustc_hir; +extern crate rustc_lint; +extern crate rustc_middle; +extern crate rustc_session; +extern crate rustc_span; + +mod await_holding_span_guard; + +#[doc(hidden)] +#[no_mangle] +pub fn register_lints(_sess: &rustc_session::Session, lint_store: &mut rustc_lint::LintStore) { + lint_store.register_lints(&[await_holding_span_guard::AWAIT_HOLDING_SPAN_GUARD]); + lint_store.register_late_pass(|| Box::new(await_holding_span_guard::AwaitHoldingSpanGuard)); +} + +#[test] +fn ui() { + dylint_testing::ui_test_example(env!("CARGO_PKG_NAME"), "ui"); +} diff --git a/lints/await_holding_span_guard/ui/main.rs b/lints/await_holding_span_guard/ui/main.rs new file mode 100644 index 0000000000..9809ecdcea --- /dev/null +++ b/lints/await_holding_span_guard/ui/main.rs @@ -0,0 +1,54 @@ +#![warn(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/lints/await_holding_span_guard/ui/main.stderr b/lints/await_holding_span_guard/ui/main.stderr new file mode 100644 index 0000000000..300e1eadae --- /dev/null +++ b/lints/await_holding_span_guard/ui/main.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/main.rs:22:9 + | +LL | let _guard = span.enter(); + | ^^^^^^ + | + = note: `-D await-holding-span-guard` implied by `-D warnings` +note: these are all the await points this ref is held through + --> $DIR/main.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/main.rs:29:9 + | +LL | let _guard = span.entered(); + | ^^^^^^ + | +note: these are all the await points this ref is held through + --> $DIR/main.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/main.rs:37:13 + | +LL | let _guard = span.enter(); + | ^^^^^^ + | +note: these are all the await points this ref is held through + --> $DIR/main.rs:37:9 + | +LL | / let _guard = span.enter(); +LL | | bar().await +LL | | } + | |_____^ + +error: aborting due to 3 previous errors +