From 4a044d41347e9a8736c82970fb67b439beadedad Mon Sep 17 00:00:00 2001 From: Arpad Borsos Date: Sat, 29 Jan 2022 20:31:57 +0100 Subject: [PATCH] tracing: add static level tests for spans and instrumented fns (#1872) The current tests for the compile-time maximum level were not being run in `--release` mode, and did not previously assert anything about `Span`s. This also adds some test cases for various `#[instrument]`-ed functions. --- .github/workflows/CI.yml | 89 ----------- .github/workflows/check_features.yml | 147 ++++++++++++++++++ .../test_static_max_level_features/Cargo.toml | 6 + .../tests/test.rs | 95 +++++++++-- 4 files changed, 236 insertions(+), 101 deletions(-) create mode 100644 .github/workflows/check_features.yml diff --git a/.github/workflows/CI.yml b/.github/workflows/CI.yml index 1ca6969d42..95dd8e7a41 100644 --- a/.github/workflows/CI.yml +++ b/.github/workflows/CI.yml @@ -127,56 +127,6 @@ jobs: working-directory: ${{ matrix.subcrate }} run: cargo hack check --feature-powerset --no-dev-deps - cargo-check-tracing: - runs-on: ubuntu-latest - strategy: - matrix: - featureset: - - "" - - async-await - - async-await std - - async-await log-always - - async-await std log-always - - log-always - - std log-always - - std - fail-fast: false - steps: - - uses: actions/checkout@main - - uses: actions-rs/toolchain@v1 - with: - toolchain: stable - profile: minimal - override: true - - name: cargo check - working-directory: tracing - run: cargo check --no-default-features --features "${{ matrix.featureset }}" - - cargo-check-subscriber: - runs-on: ubuntu-latest - strategy: - matrix: - featureset: - - "" - - fmt - - fmt ansi - - fmt json - - fmt json ansi - - fmt registry - - fmt env-filter - - registry - - env-filter - steps: - - uses: actions/checkout@main - - uses: actions-rs/toolchain@v1 - with: - toolchain: stable - profile: minimal - override: true - - name: cargo check - working-directory: tracing-subscriber - run: cargo check --no-default-features --features "${{ matrix.featureset }}" - test-versions: # Test against the stable, beta, and nightly Rust toolchains on ubuntu-latest. needs: check @@ -289,45 +239,6 @@ jobs: command: test args: --all --features "valuable" - - features-stable: - # Feature flag tests that run on stable Rust. - # TODO(david): once tracing's MSRV goes up to Rust 1.51, we should be able to switch to - # using cargo's V2 feature resolver (https://doc.rust-lang.org/cargo/reference/resolver.html#resolver-versions) - # and avoid cd'ing into each crate's directory. - needs: check - runs-on: ubuntu-latest - steps: - - uses: actions/checkout@main - - uses: actions-rs/toolchain@v1 - with: - toolchain: stable - profile: minimal - override: true - - name: "Test log support" - run: cargo test - working-directory: "tracing/test-log-support" - - name: "Test static max level" - run: cargo test - working-directory: "tracing/test_static_max_level_features" - - name: "Test tracing-core no-std support" - run: cargo test --no-default-features - working-directory: tracing-core - - name: "Test tracing no-std support" - run: cargo test --lib --tests --no-default-features - working-directory: tracing - # this skips running doctests under the `--no-default-features` flag, - # as rustdoc isn't aware of cargo's feature flags. - - name: "Test tracing-subscriber no-std support" - run: cargo test --lib --tests --no-default-features - working-directory: tracing-subscriber - - name: "Test tracing-subscriber with liballoc only" - run: cargo test --lib --tests --no-default-features --features "alloc" - working-directory: tracing-subscriber - - name: "Test tracing-subscriber with no default features" - run: cargo test --lib --tests --no-default-features --features "std" - working-directory: tracing-subscriber - style: # Check style. needs: check diff --git a/.github/workflows/check_features.yml b/.github/workflows/check_features.yml new file mode 100644 index 0000000000..c14e3a45fe --- /dev/null +++ b/.github/workflows/check_features.yml @@ -0,0 +1,147 @@ +name: Check Features + +on: + push: + branches: + - master + - "v0.1.x" + pull_request: {} + +env: + # Disable incremental compilation. + # + # Incremental compilation is useful as part of an edit-build-test-edit cycle, + # as it lets the compiler avoid recompiling code that hasn't changed. However, + # on CI, we're not making small edits; we're almost always building the entire + # project from scratch. Thus, incremental compilation on CI actually + # introduces *additional* overhead to support making future builds + # faster...but no future builds will ever occur in any given CI environment. + # + # See https://matklad.github.io/2021/09/04/fast-rust-builds.html#ci-workflow + # for details. + CARGO_INCREMENTAL: 0 + # Allow more retries for network requests in cargo (downloading crates) and + # rustup (installing toolchains). This should help to reduce flaky CI failures + # from transient network timeouts or other issues. + CARGO_NET_RETRY: 10 + RUSTUP_MAX_RETRIES: 10 + # Don't emit giant backtraces in the CI logs. + RUST_BACKTRACE: short + +jobs: + cargo-hack: + runs-on: ubuntu-latest + strategy: + matrix: + # cargo hack --feature-powerset will have a significant permutation + # number, we can't just use --all as it increases the runtime + # further than what we would like to + subcrate: + - tracing-attributes + - tracing-core + - tracing-futures + - tracing-log + - tracing-macros + - tracing-serde + - tracing-tower + # tracing and tracing-subscriber have too many features to be checked by + # cargo-hack --feature-powerset, combinatorics there is exploding. + #- tracing + #- tracing-subscriber + steps: + - uses: actions/checkout@main + - uses: actions-rs/toolchain@v1 + with: + toolchain: stable + profile: minimal + override: true + - name: Install cargo-hack + run: | + curl -LsSf https://github.com/taiki-e/cargo-hack/releases/latest/download/cargo-hack-x86_64-unknown-linux-gnu.tar.gz | tar xzf - -C ~/.cargo/bin + - name: cargo hack check + working-directory: ${{ matrix.subcrate }} + run: cargo hack check --feature-powerset --no-dev-deps + + cargo-check-tracing: + runs-on: ubuntu-latest + strategy: + matrix: + featureset: + - "" + - log-always + - std log-always + - std + fail-fast: false + steps: + - uses: actions/checkout@main + - uses: actions-rs/toolchain@v1 + with: + toolchain: stable + profile: minimal + override: true + - name: cargo check + working-directory: tracing + run: cargo check --no-default-features --features "${{ matrix.featureset }}" + + cargo-check-subscriber: + runs-on: ubuntu-latest + strategy: + matrix: + featureset: + - "" + - fmt + - fmt ansi + - fmt json + - fmt json ansi + - fmt registry + - fmt env-filter + - registry + - env-filter + steps: + - uses: actions/checkout@main + - uses: actions-rs/toolchain@v1 + with: + toolchain: stable + profile: minimal + override: true + - name: cargo check + working-directory: tracing-subscriber + run: cargo check --no-default-features --features "${{ matrix.featureset }}" + + features-stable: + # Feature flag tests that run on stable Rust. + # TODO(david): once tracing's MSRV goes up to Rust 1.51, we should be able to switch to + # using cargo's V2 feature resolver (https://doc.rust-lang.org/cargo/reference/resolver.html#resolver-versions) + # and avoid cd'ing into each crate's directory. + needs: check + runs-on: ubuntu-latest + steps: + - uses: actions/checkout@main + - uses: actions-rs/toolchain@v1 + with: + toolchain: stable + profile: minimal + override: true + - name: "Test log support" + run: cargo test + working-directory: "tracing/test-log-support" + - name: "Test static max level" + run: cargo test + working-directory: "tracing/test_static_max_level_features" + - name: "Test tracing-core no-std support" + run: cargo test --no-default-features + working-directory: tracing-core + - name: "Test tracing no-std support" + run: cargo test --lib --tests --no-default-features + working-directory: tracing + # this skips running doctests under the `--no-default-features` flag, + # as rustdoc isn't aware of cargo's feature flags. + - name: "Test tracing-subscriber no-std support" + run: cargo test --lib --tests --no-default-features + working-directory: tracing-subscriber + - name: "Test tracing-subscriber with liballoc only" + run: cargo test --lib --tests --no-default-features --features "alloc" + working-directory: tracing-subscriber + - name: "Test tracing-subscriber with no default features" + run: cargo test --lib --tests --no-default-features --features "std" + working-directory: tracing-subscriber diff --git a/tracing/test_static_max_level_features/Cargo.toml b/tracing/test_static_max_level_features/Cargo.toml index 5d3d0ea72f..3770240b2a 100644 --- a/tracing/test_static_max_level_features/Cargo.toml +++ b/tracing/test_static_max_level_features/Cargo.toml @@ -10,6 +10,12 @@ version = "0.1.0" publish = false edition = "2018" +[dependencies] +tracing-core = { path = "../../tracing-core" } + [dependencies.tracing] path = ".." features = ["max_level_debug", "release_max_level_info"] + +[dev-dependencies] +tokio-test = "0.2.0" diff --git a/tracing/test_static_max_level_features/tests/test.rs b/tracing/test_static_max_level_features/tests/test.rs index d8be44c97e..f0d50c84dd 100644 --- a/tracing/test_static_max_level_features/tests/test.rs +++ b/tracing/test_static_max_level_features/tests/test.rs @@ -1,19 +1,36 @@ +#[path = "../../../tracing-futures/tests/support.rs"] +// this is only needed for `block_on_future` +#[allow(dead_code)] +mod support; +use support::*; + +use std::future::Future; +use std::pin::Pin; use std::sync::{Arc, Mutex}; use tracing::span::{Attributes, Record}; -use tracing::{debug, error, info, span, trace, warn, Event, Id, Level, Metadata, Subscriber}; +use tracing::{ + debug, error, info, instrument, span, trace, warn, Subscriber, Event, Id, Level, Metadata, +}; + struct State { last_level: Mutex>, } struct TestSubscriber(Arc); +const EXPECTED_DEBUG: Option = if cfg!(debug_assertions) { + Some(Level::DEBUG) +} else { + None +}; impl Subscriber for TestSubscriber { fn enabled(&self, _: &Metadata) -> bool { true } - fn new_span(&self, _span: &Attributes) -> Id { + fn new_span(&self, span: &Attributes) -> Id { + *self.0.last_level.lock().unwrap() = Some(span.metadata().level().clone()); span::Id::from_u64(42) } @@ -30,9 +47,15 @@ impl Subscriber for TestSubscriber { fn exit(&self, _span: &Id) {} } +#[track_caller] +fn last(state: &State, expected: Option) { + let lvl = state.last_level.lock().unwrap().take(); + assert_eq!(lvl, expected); +} + #[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)] #[test] -fn test_static_max_level_features() { +fn test_static_max_level_events() { let me = Arc::new(State { last_level: Mutex::new(None), }); @@ -45,25 +68,73 @@ fn test_static_max_level_features() { info!(""); last(&a, Some(Level::INFO)); debug!(""); - last(&a, Some(Level::DEBUG)); + last(&a, EXPECTED_DEBUG); trace!(""); last(&a, None); + }); +} +#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)] +#[test] +fn test_static_max_level_spans() { + let me = Arc::new(State { + last_level: Mutex::new(None), + }); + let a = me.clone(); + + tracing::subscriber::with_default(TestSubscriber(me), || { span!(Level::ERROR, ""); - last(&a, None); + last(&a, Some(Level::ERROR)); span!(Level::WARN, ""); - last(&a, None); + last(&a, Some(Level::WARN)); span!(Level::INFO, ""); - last(&a, None); + last(&a, Some(Level::INFO)); span!(Level::DEBUG, ""); - last(&a, None); + last(&a, EXPECTED_DEBUG); span!(Level::TRACE, ""); last(&a, None); }); } -fn last(state: &State, expected: Option) { - let mut lvl = state.last_level.lock().unwrap(); - assert_eq!(*lvl, expected); - *lvl = None; +#[instrument(level = "debug")] +#[inline(never)] // this makes it a bit easier to look at the asm output +fn instrumented_fn() {} + +#[instrument(level = "debug")] +async fn instrumented_async_fn() {} + +#[allow(clippy::manual_async_fn)] +#[instrument(level = "debug")] +fn instrumented_manual_async() -> impl Future { + async move {} +} + +#[instrument(level = "debug")] +fn instrumented_manual_box_pin() -> Pin>> { + Box::pin(async move {}) +} + +#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)] +#[test] +fn test_static_max_level_instrument() { + let me = Arc::new(State { + last_level: Mutex::new(None), + }); + let a = me.clone(); + + tracing::subscriber::with_default(TestSubscriber(me), || { + block_on_future(async { + instrumented_fn(); + last(&a, EXPECTED_DEBUG); + + instrumented_async_fn().await; + last(&a, EXPECTED_DEBUG); + + instrumented_manual_async().await; + last(&a, EXPECTED_DEBUG); + + instrumented_manual_box_pin().await; + last(&a, EXPECTED_DEBUG); + }) + }); }