From b02c7f5f4a52e5e452ba3c25fae99895a1eac976 Mon Sep 17 00:00:00 2001 From: Hayden Stainsby Date: Tue, 3 Dec 2024 14:16:10 +0100 Subject: [PATCH] tracing: move tracing instrumentation tests into tokio tests In #6112, tests for the tracing instrumentation were introduced. They had to live in their own test crate under `tokio/tests` because the `tracing-mock` crate that the tests use had not yet been published to crates.io. Now `tracing-mock` has been published to crates.io and so the separate test crate and separate job to run it are no longer necessary. The tracing instrumentation tests can be placed in with the other integration tests in the `tokio` crate. The tests themselves have also been updated to match the changes in the `tracing-mock` API since the version which was being used. --- .github/workflows/ci.yml | 29 ----- tokio/Cargo.toml | 3 + .../tests/tracing-instrumentation/Cargo.toml | 17 --- .../tests/sync.rs => tracing_sync.rs} | 115 ++++++++++++------ .../tests/task.rs => tracing_task.rs} | 23 ++-- .../tests/time.rs => tracing_time.rs} | 16 ++- 6 files changed, 106 insertions(+), 97 deletions(-) delete mode 100644 tokio/tests/tracing-instrumentation/Cargo.toml rename tokio/tests/{tracing-instrumentation/tests/sync.rs => tracing_sync.rs} (75%) rename tokio/tests/{tracing-instrumentation/tests/task.rs => tracing_task.rs} (90%) rename tokio/tests/{tracing-instrumentation/tests/time.rs => tracing_time.rs} (72%) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 50746e79222..6740f7052e1 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -47,7 +47,6 @@ jobs: - test-workspace-all-features - test-integration-tests-per-feature - test-parking_lot - - test-tracing-instrumentation - valgrind - test-unstable - miri @@ -246,34 +245,6 @@ jobs: - name: Check tests with all features enabled run: cargo check --workspace --all-features --tests - test-tracing-instrumentation: - # These tests use the as-yet unpublished `tracing-mock` crate to test the - # tracing instrumentation present in Tokio. As such they are placed in - # their own test crate outside of the workspace. - needs: basics - name: test tokio instrumentation - runs-on: ubuntu-latest - steps: - - uses: actions/checkout@v4 - - name: Install Rust ${{ env.rust_stable }} - uses: dtolnay/rust-toolchain@stable - with: - toolchain: ${{ env.rust_stable }} - - name: Install cargo-nextest - uses: taiki-e/install-action@v2 - with: - tool: cargo-nextest - - - uses: Swatinem/rust-cache@v2 - - - name: test tracing-instrumentation - run: | - set -euxo pipefail - cargo nextest run - working-directory: tokio/tests/tracing-instrumentation - env: - RUSTFLAGS: --cfg tokio_unstable -Dwarnings - valgrind: name: valgrind needs: basics diff --git a/tokio/Cargo.toml b/tokio/Cargo.toml index ac789e242f9..4001f2eeb0c 100644 --- a/tokio/Cargo.toml +++ b/tokio/Cargo.toml @@ -151,6 +151,9 @@ mio-aio = { version = "0.9.0", features = ["tokio"] } [target.'cfg(loom)'.dev-dependencies] loom = { version = "0.7", features = ["futures", "checkpoint"] } +[target.'cfg(tokio_unstable)'.dev-dependencies] +tracing-mock = "= 0.1.0-beta.1" + [package.metadata.docs.rs] all-features = true # enable unstable features in the documentation diff --git a/tokio/tests/tracing-instrumentation/Cargo.toml b/tokio/tests/tracing-instrumentation/Cargo.toml deleted file mode 100644 index 94c88dc2810..00000000000 --- a/tokio/tests/tracing-instrumentation/Cargo.toml +++ /dev/null @@ -1,17 +0,0 @@ -[package] -name = "tracing-instrumentation" -version = "0.1.0" -edition = "2021" - -[dependencies] - -[dev-dependencies] -futures = { version = "0.3.0", features = ["async-await"] } -tokio = { version = "1.33.0", path = "../..", features = ["full", "tracing"] } -tracing = { version = "0.1.40", git = "https://github.com/tokio-rs/tracing.git", tag = "tracing-0.1.40" } -tracing-mock = { version = "0.1.0", git = "https://github.com/tokio-rs/tracing.git", tag = "tracing-0.1.40" } - -[patch.crates-io] -tracing = { git = "https://github.com/tokio-rs/tracing.git", tag = "tracing-0.1.40" } - -[workspace] diff --git a/tokio/tests/tracing-instrumentation/tests/sync.rs b/tokio/tests/tracing_sync.rs similarity index 75% rename from tokio/tests/tracing-instrumentation/tests/sync.rs rename to tokio/tests/tracing_sync.rs index 110928dda78..067a3a67037 100644 --- a/tokio/tests/tracing-instrumentation/tests/sync.rs +++ b/tokio/tests/tracing_sync.rs @@ -2,6 +2,9 @@ //! //! These tests ensure that the instrumentation for tokio //! synchronization primitives is correct. +#![allow(unknown_lints, unexpected_cfgs)] +#![warn(rust_2018_idioms)] +#![cfg(all(tokio_unstable, feature = "tracing"))] use tokio::sync; use tracing_mock::{expect, subscriber}; @@ -14,19 +17,23 @@ async fn test_barrier_creates_span() { let size_event = expect::event() .with_target("runtime::resource::state_update") - .with_fields(expect::field("size").with_value(&1u64)); + .with_fields(expect::field("size").with_value(&1_u64)); let arrived_event = expect::event() .with_target("runtime::resource::state_update") - .with_fields(expect::field("arrived").with_value(&0)); + .with_fields(expect::field("arrived").with_value(&0_i64)); let (subscriber, handle) = subscriber::mock() - .new_span(barrier_span.clone().with_explicit_parent(None)) - .enter(barrier_span.clone()) + .new_span( + barrier_span + .clone() + .with_ancestry(expect::is_explicit_root()), + ) + .enter(&barrier_span) .event(size_event) .event(arrived_event) - .exit(barrier_span.clone()) - .drop_span(barrier_span) + .exit(&barrier_span) + .drop_span(&barrier_span) .run_with_handle(); { @@ -57,16 +64,20 @@ async fn test_mutex_creates_span() { .with_fields(expect::field("permits.op").with_value(&"override")); let (subscriber, handle) = subscriber::mock() - .new_span(mutex_span.clone().with_explicit_parent(None)) - .enter(mutex_span.clone()) + .new_span(mutex_span.clone().with_ancestry(expect::is_explicit_root())) + .enter(&mutex_span) .event(locked_event) - .new_span(batch_semaphore_span.clone().with_explicit_parent(None)) - .enter(batch_semaphore_span.clone()) + .new_span( + batch_semaphore_span + .clone() + .with_ancestry(expect::is_explicit_root()), + ) + .enter(&batch_semaphore_span) .event(batch_semaphore_permits_event) - .exit(batch_semaphore_span.clone()) - .exit(mutex_span.clone()) - .drop_span(mutex_span) - .drop_span(batch_semaphore_span) + .exit(&batch_semaphore_span) + .exit(&mutex_span) + .drop_span(&mutex_span) + .drop_span(&batch_semaphore_span) .run_with_handle(); { @@ -79,7 +90,9 @@ async fn test_mutex_creates_span() { #[tokio::test] async fn test_oneshot_creates_span() { + let oneshot_span_id = expect::id(); let oneshot_span = expect::span() + .with_id(oneshot_span_id.clone()) .named("runtime.resource") .with_target("tokio::sync::oneshot"); @@ -113,7 +126,9 @@ async fn test_oneshot_creates_span() { .with_fields(expect::field("value_received").with_value(&false)) .with_fields(expect::field("value_received.op").with_value(&"override")); + let async_op_span_id = expect::id(); let async_op_span = expect::span() + .with_id(async_op_span_id.clone()) .named("runtime.resource.async_op") .with_target("tokio::sync::oneshot"); @@ -122,34 +137,46 @@ async fn test_oneshot_creates_span() { .with_target("tokio::sync::oneshot"); let (subscriber, handle) = subscriber::mock() - .new_span(oneshot_span.clone().with_explicit_parent(None)) - .enter(oneshot_span.clone()) + .new_span( + oneshot_span + .clone() + .with_ancestry(expect::is_explicit_root()), + ) + .enter(&oneshot_span) .event(initial_tx_dropped_event) - .exit(oneshot_span.clone()) - .enter(oneshot_span.clone()) + .exit(&oneshot_span) + .enter(&oneshot_span) .event(initial_rx_dropped_event) - .exit(oneshot_span.clone()) - .enter(oneshot_span.clone()) + .exit(&oneshot_span) + .enter(&oneshot_span) .event(value_sent_event) - .exit(oneshot_span.clone()) - .enter(oneshot_span.clone()) + .exit(&oneshot_span) + .enter(&oneshot_span) .event(value_received_event) - .exit(oneshot_span.clone()) - .enter(oneshot_span.clone()) - .new_span(async_op_span.clone()) - .exit(oneshot_span.clone()) - .enter(async_op_span.clone()) - .new_span(async_op_poll_span.clone()) - .exit(async_op_span.clone()) - .enter(oneshot_span.clone()) + .exit(&oneshot_span) + .enter(&oneshot_span) + .new_span( + async_op_span + .clone() + .with_ancestry(expect::has_contextual_parent(&oneshot_span_id)), + ) + .exit(&oneshot_span) + .enter(&async_op_span) + .new_span( + async_op_poll_span + .clone() + .with_ancestry(expect::has_contextual_parent(&async_op_span_id)), + ) + .exit(&async_op_span) + .enter(&oneshot_span) .event(final_tx_dropped_event) - .exit(oneshot_span.clone()) - .enter(oneshot_span.clone()) + .exit(&oneshot_span) + .enter(&oneshot_span) .event(final_rx_dropped_event) - .exit(oneshot_span.clone()) + .exit(&oneshot_span) .drop_span(oneshot_span) .drop_span(async_op_span) - .drop_span(async_op_poll_span) + .drop_span(&async_op_poll_span) .run_with_handle(); { @@ -176,7 +203,7 @@ async fn test_rwlock_creates_span() { let current_readers_event = expect::event() .with_target("runtime::resource::state_update") - .with_fields(expect::field("current_readers").with_value(&0)); + .with_fields(expect::field("current_readers").with_value(&0_i64)); let batch_semaphore_span = expect::span() .named("runtime.resource") @@ -188,7 +215,11 @@ async fn test_rwlock_creates_span() { .with_fields(expect::field("permits.op").with_value(&"override")); let (subscriber, handle) = subscriber::mock() - .new_span(rwlock_span.clone().with_explicit_parent(None)) + .new_span( + rwlock_span + .clone() + .with_ancestry(expect::is_explicit_root()), + ) .enter(rwlock_span.clone()) .event(max_readers_event) .event(write_locked_event) @@ -228,7 +259,11 @@ async fn test_semaphore_creates_span() { .with_fields(expect::field("permits.op").with_value(&"override")); let (subscriber, handle) = subscriber::mock() - .new_span(semaphore_span.clone().with_explicit_parent(None)) + .new_span( + semaphore_span + .clone() + .with_ancestry(expect::is_explicit_root()), + ) .enter(semaphore_span.clone()) .new_span(batch_semaphore_span.clone()) .enter(batch_semaphore_span.clone()) @@ -246,3 +281,9 @@ async fn test_semaphore_creates_span() { handle.assert_finished(); } + +#[test] +fn this_test_must_fail() { + let value = false; + assert!(value, "I must fail"); +} diff --git a/tokio/tests/tracing-instrumentation/tests/task.rs b/tokio/tests/tracing_task.rs similarity index 90% rename from tokio/tests/tracing-instrumentation/tests/task.rs rename to tokio/tests/tracing_task.rs index fb215ca7ce0..27fdd5bf7de 100644 --- a/tokio/tests/tracing-instrumentation/tests/task.rs +++ b/tokio/tests/tracing_task.rs @@ -2,6 +2,9 @@ //! //! These tests ensure that the instrumentation for task spawning and task //! lifecycles is correct. +#![allow(unknown_lints, unexpected_cfgs)] +#![warn(rust_2018_idioms)] +#![cfg(all(tokio_unstable, feature = "tracing"))] use std::{mem, time::Duration}; @@ -15,12 +18,12 @@ async fn task_spawn_creates_span() { .with_target("tokio::task"); let (subscriber, handle) = subscriber::mock() - .new_span(task_span.clone()) - .enter(task_span.clone()) - .exit(task_span.clone()) + .new_span(&task_span) + .enter(&task_span) + .exit(&task_span) // The task span is entered once more when it gets dropped - .enter(task_span.clone()) - .exit(task_span.clone()) + .enter(&task_span) + .exit(&task_span) .drop_span(task_span) .run_with_handle(); @@ -39,7 +42,7 @@ async fn task_spawn_loc_file_recorded() { let task_span = expect::span() .named("runtime.spawn") .with_target("tokio::task") - .with_field(expect::field("loc.file").with_value(&file!())); + .with_fields(expect::field("loc.file").with_value(&file!())); let (subscriber, handle) = subscriber::mock().new_span(task_span).run_with_handle(); @@ -78,7 +81,7 @@ async fn task_builder_loc_file_recorded() { let task_span = expect::span() .named("runtime.spawn") .with_target("tokio::task") - .with_field(expect::field("loc.file").with_value(&file!())); + .with_fields(expect::field("loc.file").with_value(&file!())); let (subscriber, handle) = subscriber::mock().new_span(task_span).run_with_handle(); @@ -105,7 +108,7 @@ async fn task_spawn_sizes_recorded() { .with_target("tokio::task") // TODO(hds): check that original_size.bytes is NOT recorded when this can be done in // tracing-mock without listing every other field. - .with_field(expect::field("size.bytes").with_value(&size)); + .with_fields(expect::field("size.bytes").with_value(&size)); let (subscriber, handle) = subscriber::mock().new_span(task_span).run_with_handle(); @@ -149,7 +152,7 @@ async fn task_big_spawn_sizes_recorded() { let task_span = expect::span() .named("runtime.spawn") .with_target("tokio::task") - .with_field( + .with_fields( expect::field("size.bytes") .with_value(&boxed_size) .and(expect::field("original_size.bytes").with_value(&size)), @@ -178,7 +181,7 @@ fn expect_task_named(name: &str) -> NewSpan { expect::span() .named("runtime.spawn") .with_target("tokio::task") - .with_field( + .with_fields( expect::field("task.name").with_value(&tracing::field::debug(format_args!("{}", name))), ) } diff --git a/tokio/tests/tracing-instrumentation/tests/time.rs b/tokio/tests/tracing_time.rs similarity index 72% rename from tokio/tests/tracing-instrumentation/tests/time.rs rename to tokio/tests/tracing_time.rs index 4d5701598df..a18b29e70b9 100644 --- a/tokio/tests/tracing-instrumentation/tests/time.rs +++ b/tokio/tests/tracing_time.rs @@ -2,13 +2,19 @@ //! //! These tests ensure that the instrumentation for tokio //! synchronization primitives is correct. +#![allow(unknown_lints, unexpected_cfgs)] +#![warn(rust_2018_idioms)] +#![cfg(all(tokio_unstable, feature = "tracing"))] + use std::time::Duration; use tracing_mock::{expect, subscriber}; #[tokio::test] async fn test_sleep_creates_span() { + let sleep_span_id = expect::id(); let sleep_span = expect::span() + .with_id(sleep_span_id.clone()) .named("runtime.resource") .with_target("tokio::time::sleep"); @@ -20,7 +26,9 @@ async fn test_sleep_creates_span() { .and(expect::field("duration.op").with_value(&"override")), ); + let async_op_span_id = expect::id(); let async_op_span = expect::span() + .with_id(async_op_span_id.clone()) .named("runtime.resource.async_op") .with_target("tokio::time::sleep"); @@ -29,21 +37,21 @@ async fn test_sleep_creates_span() { .with_target("tokio::time::sleep"); let (subscriber, handle) = subscriber::mock() - .new_span(sleep_span.clone().with_explicit_parent(None)) + .new_span(sleep_span.clone().with_ancestry(expect::is_explicit_root())) .enter(sleep_span.clone()) .event(state_update) .new_span( async_op_span .clone() - .with_contextual_parent(Some("runtime.resource")) - .with_field(expect::field("source").with_value(&"Sleep::new_timeout")), + .with_ancestry(expect::has_contextual_parent(&sleep_span_id)) + .with_fields(expect::field("source").with_value(&"Sleep::new_timeout")), ) .exit(sleep_span.clone()) .enter(async_op_span.clone()) .new_span( async_op_poll_span .clone() - .with_contextual_parent(Some("runtime.resource.async_op")), + .with_ancestry(expect::has_contextual_parent(&async_op_span_id)), ) .exit(async_op_span.clone()) .drop_span(async_op_span)