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.

Sign up for GitHub

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

Jump to bottom

assertion failed: next.is_notified() during task dump #6185

Closed
scottlamb opened this issue Dec 1, 2023 · 3 comments
Closed

assertion failed: next.is_notified() during task dump #6185

scottlamb opened this issue Dec 1, 2023 · 3 comments
Assignees
@jswrenn
Labels
A-tokio Area: The main tokio crate C-bug Category: This is a bug. M-taskdump --cfg tokio_taskdump

Comments

@scottlamb
Copy link

Version

$ cargo tree | grep tokio
│   │   │   │   ├── tokio v1.34.0
│   │   │   │   │   ├── tokio-macros v2.2.0 (proc-macro)
│   │   │   │   ├── tokio-util v0.6.7
│   │   │   │   │   └── tokio v1.34.0 (*)
│   │   │   │   ├── tokio v1.34.0 (*)
│   │   │   │   ├── tokio v1.34.0 (*)
│   │   │   │   └── tokio-native-tls v0.3.0
│   │   │   │       └── tokio v1.34.0 (*)
│   │   │   ├── tokio v1.34.0 (*)
│   │   │   ├── tokio-native-tls v0.3.0 (*)
│   │   │   ├── tokio-util v0.6.7 (*)
│   │   │   │   ├── tokio v1.34.0 (*)
│   │   │   │   └── tokio v1.34.0 (*)
│   │   │   ├── tokio v1.34.0 (*)
│   │   ├── tokio v1.34.0 (*)
│   │   │   └── tokio v1.34.0 (*)
│   │   ├── tokio v1.34.0 (*)
│   │   └── tokio v1.34.0 (*)
│   │       ├── tokio v1.34.0 (*)
│   │       └── tokio-stream v0.1.14
│   │           └── tokio v1.34.0 (*)
│   │   └── tokio v1.34.0 (*)
│   │   │   │   │   └── tokio v1.34.0 (*)
│   │   │   │   ├── tokio v1.34.0 (*)
│   │   │   │   ├── tokio-util v0.6.7 (*)
│   │   └── tokio v1.34.0 (*)
│   ├── tokio v1.34.0 (*)
│   ├── tokio-metrics v0.3.1
│   │   ├── tokio v1.34.0 (*)
│   │   └── tokio-stream v0.1.14 (*)
│   ├── tokio-stream v0.1.14 (*)
│   └── tokio v1.34.0 (*)
│   └── tokio v1.34.0 (*)
│   └── tokio v1.34.0 (*)
│   ├── tokio v1.34.0 (*)
│       ├── tokio v1.34.0 (*)
│       ├── tokio-stream v0.1.14 (*)
│       ├── tokio-tungstenite v0.13.0
│       │   ├── tokio v1.34.0 (*)
│       ├── tokio-util v0.6.7 (*)
├── tokio v1.34.0 (*)
├── tokio-metrics v0.3.1 (*)
├── tokio-stream v0.1.14 (*)
├── tokio-util v0.6.7 (*)
├── tokio v1.34.0 (*)
│   ├── tokio v1.34.0 (*)
│   ├── tokio-stream v0.1.14 (*)
│   │   ├── tokio v1.34.0 (*)
│   ├── tokio v1.34.0 (*)
├── tokio v1.34.0 (*)
├── tokio-util v0.6.7 (*)
├── tokio v1.34.0 (*)
├── tokio v1.34.0 (*)
├── tokio-stream v0.1.14 (*)

Platform

Linux ip-10-0-205-57 4.14.225-121.362.amzn1.x86_64 #1 SMP Tue Mar 23 00:29:14 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

Description

While trying to debug some stuckness in my server, I added code to use the experimental Handle::dump stuff on SIGTERM via this function:

#[cfg(target_os = "linux")]
async fn taskdump(logger: &slog::Logger) {
    let handle = tokio::runtime::Handle::current();
    let dump = handle.dump().await;
    let tasks: Vec<_> = dump.tasks().iter().collect();
    info!(logger, "dump completed with {} active tasks", tasks.len());
    for (i, task) in tasks.iter().enumerate() {
        info!(logger, "active task at SIGTERM"; "task_num" => i, "trace" => %task.trace());
    }
}

I expected to see this happen: it dumps all the tasks successfully.

Instead, this happened: it dumped several, and I got a panic. Log snippet below. It's from an awkward export that drops tracing attributes from my active task at SIGTERM log lines, but the panic stack trace is there.

thread 'tokio-runtime-worker' panicked at 'assertion failed: next.is_notified()', /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/task/state.rs:118:13
stack backtrace:
dump completed with 10 active tasks
0: rust_begin_unwind
at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library/std/src/panicking.rs:578:5
1: core::panicking::panic_fmt
at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library/core/src/panicking.rs:67:14
2: core::panicking::panic
at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library/core/src/panicking.rs:117:5
3: tokio::runtime::task::state::State::transition_to_running::{{closure}}
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/task/state.rs:118:13
4: tokio::runtime::task::state::State::fetch_update_action
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/task/state.rs:474:34
5: tokio::runtime::task::state::State::transition_to_running
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/task/state.rs:116:9
6: tokio::runtime::task::harness::Harness<T,S>::poll_inner
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/task/harness.rs:194:15
7: tokio::runtime::task::harness::Harness<T,S>::poll
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/task/harness.rs:153:15
8: tokio::runtime::task::raw::RawTask::poll
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/task/raw.rs:201:18
9: tokio::runtime::task::LocalNotified<S>::run
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/task/mod.rs:408:9
10: tokio::runtime::scheduler::multi_thread::worker::Context::run_task::{{closure}}
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/scheduler/multi_thread/worker.rs:577:13
11: tokio::runtime::coop::with_budget
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/coop.rs:107:5
12: tokio::runtime::coop::budget
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/coop.rs:73:5
13: tokio::runtime::scheduler::multi_thread::worker::Context::run_task
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/scheduler/multi_thread/worker.rs:576:9
14: tokio::runtime::scheduler::multi_thread::worker::Context::run
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/scheduler/multi_thread/worker.rs:526:24
15: tokio::runtime::scheduler::multi_thread::worker::run::{{closure}}::{{closure}}
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/scheduler/multi_thread/worker.rs:491:21
16: tokio::runtime::context::scoped::Scoped<T>::set
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/context/scoped.rs:40:9
17: tokio::runtime::context::set_scheduler::{{closure}}
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/context.rs:176:26
18: std::thread::local::LocalKey<T>::try_with
at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library/std/src/thread/local.rs:252:16
19: std::thread::local::LocalKey<T>::with
at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library/std/src/thread/local.rs:228:9
20: tokio::runtime::context::set_scheduler
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/context.rs:176:9
21: tokio::runtime::scheduler::multi_thread::worker::run::{{closure}}
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/scheduler/multi_thread/worker.rs:486:9
22: tokio::runtime::context::runtime::enter_runtime
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/context/runtime.rs:65:16
23: tokio::runtime::scheduler::multi_thread::worker::run
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/scheduler/multi_thread/worker.rs:478:5
24: tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}}
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/scheduler/multi_thread/worker.rs:447:45
25: <tokio::runtime::blocking::task::BlockingTask<T> as core::future::future::Future>::poll
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/blocking/task.rs:42:21
26: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.37/src/instrument.rs:272:9
27: tokio::runtime::task::core::Core<T,S>::poll::{{closure}}
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/task/core.rs:328:17
28: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/loom/std/unsafe_cell.rs:16:9
29: tokio::runtime::task::core::Core<T,S>::poll
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/task/core.rs:317:30
30: tokio::runtime::task::harness::poll_future::{{closure}}
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/task/harness.rs:485:19
31: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library/core/src/panic/unwind_safe.rs:271:9
32: std::panicking::try::do_call
at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library/std/src/panicking.rs:485:40
33: std::panicking::try
at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library/std/src/panicking.rs:449:19
34: std::panic::catch_unwind
at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library/std/src/panic.rs:140:14
35: tokio::runtime::task::harness::poll_future
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/task/harness.rs:473:18
36: tokio::runtime::task::harness::Harness<T,S>::poll_inner
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/task/harness.rs:208:27
37: tokio::runtime::task::harness::Harness<T,S>::poll
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/task/harness.rs:153:15
38: tokio::runtime::task::raw::RawTask::poll
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/task/raw.rs:201:18
39: tokio::runtime::task::UnownedTask<S>::run
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/task/mod.rs:445:9
40: tokio::runtime::blocking::pool::Task::run
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/blocking/pool.rs:159:9
41: tokio::runtime::blocking::pool::Inner::run
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/blocking/pool.rs:513:17
42: tokio::runtime::blocking::pool::Spawner::spawn_thread::{{closure}}
at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/blocking/pool.rs:471:13
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
active task at SIGTERM
active task at SIGTERM
active task at SIGTERM
active task at SIGTERM
active task at SIGTERM
active task at SIGTERM
active task at SIGTERM
active task at SIGTERM
active task at SIGTERM
active task at SIGTERM

I encountered a similar error with tokio 1.31.0. I saw there have been recent fixes to the task dump stuff (at least #6036) and thought updating to 1.34.0 might help. Apparently not.

This happens maybe 25% of the time (guess).
@scottlamb scottlamb added A-tokio Area: The main tokio crate C-bug Category: This is a bug. labels Dec 1, 2023
@scottlamb scottlamb mentioned this issue Dec 4, 2023
Open
18 tasks
@jswrenn jswrenn self-assigned this Dec 4, 2023
@jswrenn
Copy link
Contributor

jswrenn commented Dec 4, 2023

This is strange. There isn't anything directly relating to task dumping in that backtrace. Are the traces non-empty?

My current best-guess is that we're perhaps failing to restore the notified bit after tracing a task.

@Darksonn Darksonn added the M-taskdump --cfg tokio_taskdump label Dec 4, 2023
@Darksonn
Copy link
Contributor

Darksonn commented Dec 4, 2023

This is a duplicate of #6051.

@Darksonn Darksonn closed this as not planned Won't fix, can't repro, duplicate, stale Dec 4, 2023
@jswrenn
Copy link
Contributor

jswrenn commented Dec 7, 2023

We should have a fix merged soon, but if you'd like to test it out in the meantime, check out #6194!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@jswrenn jswrenn

Labels
A-tokio Area: The main tokio crate C-bug Category: This is a bug. M-taskdump --cfg tokio_taskdump
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@Darksonn @jswrenn @scottlamb