Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Spans unexpectedly remain open within spawned tasks #412

Closed
joshua-cooper opened this issue Apr 20, 2023 · 2 comments
Closed

Spans unexpectedly remain open within spawned tasks #412

joshua-cooper opened this issue Apr 20, 2023 · 2 comments
Labels
S-bug Severity: bug

Comments

@joshua-cooper
Copy link

What crate(s) in this repo are involved in the problem?

console-subscriber

What is the issue?

When using console-subscriber, spans are kept around across spawned tasks when they wouldn't be without it.

How can the bug be reproduced?

[package]
name = "tc-bug"
version = "0.1.0"
edition = "2021"

[dependencies]
console-subscriber = "0.1.8"
tokio = { version = "1.27.0", features = ["full"] }
tracing = "0.1.37"
tracing-subscriber = "0.3.16"
use std::time::Duration;
use tokio::time::sleep;
use tracing::{info, instrument, metadata::LevelFilter};
use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt, Layer};

#[tokio::main]
async fn main() {
    tracing_subscriber::registry()
        .with(
            tracing_subscriber::fmt::layer()
                .pretty()
                .with_filter(LevelFilter::INFO),
        )
        .with(console_subscriber::spawn()) // comment out this line to see the difference in behavior
        .init();

    fn_a().await;

    sleep(Duration::from_secs(1)).await;
}

#[instrument]
async fn fn_a() {
    info!("hi from a");
    tokio::spawn(fn_b());
}

#[instrument]
async fn fn_b() {
    info!("hi from b");
}

Logs, error output, etc

Without console-subscriber:

  2023-04-20T12:52:30.707451Z  INFO tc_bug: hi from b
    at src/main.rs:30
    in tc_bug::fn_b

With console-subscriber:

  2023-04-20T12:53:33.980546Z  INFO tc_bug: hi from b
    at src/main.rs:30
    in tc_bug::fn_b
    in tc_bug::fn_a

Versions

├── console-subscriber v0.1.8
│   ├── console-api v0.4.0

Possible solution

No response

Additional context

No response

Would you like to work on fixing this bug?

maybe

@joshua-cooper joshua-cooper added the S-bug Severity: bug label Apr 20, 2023
@hawkw
Copy link
Member

hawkw commented Apr 20, 2023

This is similar to #345 (comment) --- we should probably change the Tokio instrumentation so that task spans have parent: None, and don't inadvertantly capture the spawning span as their parent...

hds added a commit that referenced this issue Nov 17, 2023
In the Tokio instrumentation, a tracing span is created for each task
which is spawned. Since the new span is created within the context of
where `tokio::spawn()` (or similar) is called from, it gets a contextual
parent attached.

In tracing, when a span has a child span (either because the child was
created in the context of the parent, or because the parent was set
explicitly) then that span will not be closed until the child has
closed.

The result in the console subscriber is that a task which spawns another
task won't have a `dropped_at` time set until the spawned task exits,
even if the parent task exits much earlier. This causes Tokio Console to
show an incorrect lost waker warning (#345). It also affects other spans
that are entered when a task is spawned (#412).

The solution is to modify the instrumentation in Tokio so that task
spans are explicit roots (`parent: None`). This will be done as part of
enriching the Tokio instrumentation (tokio-rs/tokio#5792).

This change adds functionality to the test framework within
`console-subscriber` so that the state of a task can be set as an
expectation. The state is calculated based on 4 values:
* `console_api::tasks::Stats::dropped_at`
* `console_api::tasks::Stats::last_wake`
* `console_api::PollStats::last_poll_started`
* `console_api::PollStats::last_poll_ended`

It can then be tested that a task that spawns another task and then ends
actually goes to the `Completed` state, even if the spawned task is
still running. As of Tokio 1.33.0, this test fails, but the PR FIXME:TBD
fixes this and the test should pass from Tokio 1.34 onwards.
hds added a commit that referenced this issue Nov 18, 2023
In the Tokio instrumentation, a tracing span is created for each task
which is spawned. Since the new span is created within the context of
where `tokio::spawn()` (or similar) is called from, it gets a contextual
parent attached.

In tracing, when a span has a child span (either because the child was
created in the context of the parent, or because the parent was set
explicitly) then that span will not be closed until the child has
closed.

The result in the console subscriber is that a task which spawns another
task won't have a `dropped_at` time set until the spawned task exits,
even if the parent task exits much earlier. This causes Tokio Console to
show an incorrect lost waker warning (#345). It also affects other spans
that are entered when a task is spawned (#412).

The solution is to modify the instrumentation in Tokio so that task
spans are explicit roots (`parent: None`). This will be done as part of
enriching the Tokio instrumentation (tokio-rs/tokio#5792).

This change adds functionality to the test framework within
`console-subscriber` so that the state of a task can be set as an
expectation. The state is calculated based on 4 values:
* `console_api::tasks::Stats::dropped_at`
* `console_api::tasks::Stats::last_wake`
* `console_api::PollStats::last_poll_started`
* `console_api::PollStats::last_poll_ended`

It can then be tested that a task that spawns another task and then ends
actually goes to the `Completed` state, even if the spawned task is
still running. As of Tokio 1.34.0, this test fails, but the PR
tokio-rs/tokio#XXXX fixes this and the test should pass from Tokio 1.35
onwards.
hds added a commit that referenced this issue Nov 18, 2023
In the Tokio instrumentation, a tracing span is created for each task
which is spawned. Since the new span is created within the context of
where `tokio::spawn()` (or similar) is called from, it gets a contextual
parent attached.

In tracing, when a span has a child span (either because the child was
created in the context of the parent, or because the parent was set
explicitly) then that span will not be closed until the child has
closed.

The result in the console subscriber is that a task which spawns another
task won't have a `dropped_at` time set until the spawned task exits,
even if the parent task exits much earlier. This causes Tokio Console to
show an incorrect lost waker warning (#345). It also affects other spans
that are entered when a task is spawned (#412).

The solution is to modify the instrumentation in Tokio so that task
spans are explicit roots (`parent: None`). This will be done as part of
enriching the Tokio instrumentation (tokio-rs/tokio#5792).

This change adds functionality to the test framework within
`console-subscriber` so that the state of a task can be set as an
expectation. The state is calculated based on 4 values:
* `console_api::tasks::Stats::dropped_at`
* `console_api::tasks::Stats::last_wake`
* `console_api::PollStats::last_poll_started`
* `console_api::PollStats::last_poll_ended`

It can then be tested that a task that spawns another task and then ends
actually goes to the `Completed` state, even if the spawned task is
still running. As of Tokio 1.34.0, this test fails, but the PR
tokio-rs/tokio#6158 fixes this and the test should pass from Tokio 1.35
onwards.
@hds
Copy link
Collaborator

hds commented Nov 19, 2023

This issue has been fixed in Tokio on master. Since this ticket is a duplicate, I'll close it now. Please refer to #345 to track when the fix has been included in the next Tokio release.

@hds hds closed this as completed Nov 19, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
S-bug Severity: bug
Projects
None yet
Development

No branches or pull requests

3 participants