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 73b2deac76c..6c915ecd3e4 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 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..7391cd8b735 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 fb215ca7ce0..5466ad960f0 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 4d5701598df..a227cde7a73 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)