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

@@ -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

.github/workflows/check_features.yml

@@ -0,0 +1,143 @@
+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.
+    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 static max level (release)"
+      run: cargo test --release
+      working-directory: "tracing/test_static_max_level_features"
+    - name: "Test tracing-core no-std support"
+      run: cargo test --no-default-features
+      working-directory: tracing
+    - name: "Test tracing no-std support"
+      run: cargo test --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 with all features disabled"
+      run: cargo test --lib --tests --no-default-features
+      working-directory: tracing-subscriber

tracing/test_static_max_level_features/Cargo.toml

@@ -13,3 +13,6 @@ edition = "2018"
 [dependencies.tracing]
 path = ".."
 features = ["max_level_debug", "release_max_level_info"]
+
+[dev-dependencies]
+tokio-test = "0.2.0"

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<Option<Level>>,
 }
 
-struct TestSubscriber(Arc<State>);
+struct TestCollector(Arc<State>);
+const EXPECTED_DEBUG: Option<Level> = 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<Level>) {
+    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<Level>) {
-    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<Output = ()> {
+    async move {}
+}
+
+#[instrument(level = "debug")]
+fn instrumented_manual_box_pin() -> Pin<Box<dyn Future<Output = ()>>> {
+    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);
+        })
+    });
 }