From b5c227d51feff804fe7ce73721fb32f4227fad73 Mon Sep 17 00:00:00 2001 From: Hayden Stainsby Date: Wed, 4 Dec 2024 07:47:48 +0100 Subject: [PATCH] tracing: move tracing instrumentation tests into tokio tests (#7007) 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} | 109 ++++++++++++------ .../tests/task.rs => tracing_task.rs} | 23 ++-- .../tests/time.rs => tracing_time.rs} | 21 +++- 6 files changed, 104 insertions(+), 98 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} (62%) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 50746e792..6740f7052 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 73b2deac7..6c915ecd3 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(all(tokio_unstable, target_has_atomic = "64"))'.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 94c88dc28..000000000 --- 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 110928dda..7391cd8b7 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", target_has_atomic = "64"))] 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()) 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 fb215ca7c..5466ad960 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", target_has_atomic = "64"))] 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 62% rename from tokio/tests/tracing-instrumentation/tests/time.rs rename to tokio/tests/tracing_time.rs index 4d5701598..a227cde7a 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", target_has_atomic = "64"))] + 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"); @@ -16,11 +22,16 @@ async fn test_sleep_creates_span() { .with_target("runtime::resource::state_update") .with_fields( expect::field("duration") - .with_value(&(7_u64 + 1)) + // FIXME(hds): This value isn't stable and doesn't seem to make sense. We're not + // going to test on it until the resource instrumentation has been + // refactored and we know that we're getting a stable value here. + //.with_value(&(7_u64 + 1)) .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 +40,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)