Panic: pidfd is ready to read, the process should have exited

[jeromegn]

Version

TL;DR: 1.42.0

cargo tree

❯ cargo tree | grep tokio
└── tokio v1.42.0
    └── tokio-macros v2.4.0 (proc-macro)
│   │   │   └── tokio v1.42.0 (*)
│   │   └── tokio v1.42.0 (*)
│   │   ├── tokio v1.42.0 (*)
│   │   │   │   ├── tokio v1.42.0 (*)
│   │   │   │   ├── tokio-util v0.7.11
│   │   │   │   │   └── tokio v1.42.0 (*)
│   │   │   ├── tokio v1.42.0 (*)
│   │   ├── tokio v1.42.0 (*)
│   │   ├── tokio v1.42.0 (*)
│   │   │   ├── tokio v1.42.0 (*)
│   │   │   ├── tokio-util v0.7.11 (*)
│   │   ├── tokio v1.42.0 (*)
│   │   │   └── tokio v1.42.0 (*)
│   │   └── tokio v1.42.0 (*)
│   ├── tokio v1.42.0 (*)
│   ├── tokio-stream v0.1.15
│   │   ├── tokio v1.42.0 (*)
│   │   └── tokio-util v0.7.11 (*)
│   ├── tokio-util v0.7.11 (*)
│   ├── tokio-vsock v0.5.0
│   │   ├── tokio v1.42.0 (*)
│       ├── tokio v1.42.0 (*)
│       ├── tokio-tungstenite v0.21.0
│       │   ├── tokio v1.42.0 (*)
│       ├── tokio-util v0.7.11 (*)
├── tokio v1.42.0 (*)
├── tokio-vsock v0.5.0 (*)
│   ├── tokio v1.42.0 (*)
│   └── tokio v1.42.0 (*)
│   │   ├── tokio v1.42.0 (*)
│   │   ├── tokio-rustls v0.25.0
│   │   │   └── tokio v1.42.0 (*)
│   ├── tokio v1.42.0 (*)
│   ├── tokio-stream v0.1.15 (*)
│   ├── tokio-util v0.7.11 (*)
│   ├── tokio-vsock v0.5.0 (*)
├── tokio v1.42.0 (*)
├── tokio-stream v0.1.15 (*)
├── tokio-util v0.7.11 (*)
├── tokio-vsock v0.5.0 (*)
│   ├── tokio v1.42.0 (*)
│   ├── tokio v1.42.0 (*)
│   ├── tokio-util v0.7.11 (*)
│   │   │       │   ├── tokio v1.42.0 (*)
│   │   │       │   └── tokio-io-timeout v1.2.0
│   │   │       │       └── tokio v1.42.0 (*)
│   │   │       ├── tokio v1.42.0 (*)
│   │   │       ├── tokio-stream v0.1.15 (*)
│   │   │   ├── tokio v1.42.0 (*)
│   │   ├── tokio v1.42.0 (*)
│   │   ├── tokio-util v0.7.11 (*)
│   │   │   └── tokio v1.42.0 (*)
│   │   ├── tokio v1.42.0 (*)
│   │   ├── tokio-stream v0.1.15 (*)
│   ├── tokio v1.42.0 (*)
│   ├── tokio-fd v0.3.0
│   │   └── tokio v1.42.0 (*)
│   ├── tokio-stream v0.1.15 (*)
│   ├── tokio-tar v0.3.1
│   │   ├── tokio v1.42.0 (*)
│   │   ├── tokio-stream v0.1.15 (*)
│   ├── tokio-util v0.7.11 (*)
│   ├── tokio-vsock v0.5.0 (*)
│   │   ├── tokio v1.42.0 (*)
│   │   └── tokio-util v0.7.11 (*)
├── tokio v1.42.0 (*)
├── tokio-util v0.7.11 (*)

Platform

Linux version 5.15.98

Description

I'm launching crun run ... commands with tokio::process::Command and using Child::wait.

stack backtrace:
   0: rust_begin_unwind
             at ./rustc/f6e511eec7342f59a25f7c0534f1dbea00d01b14/library/std/src/panicking.rs:662:5
   1: core::panicking::panic_fmt
             at ./rustc/f6e511eec7342f59a25f7c0534f1dbea00d01b14/library/core/src/panicking.rs:74:14
   2: core::panicking::panic_display
             at ./rustc/f6e511eec7342f59a25f7c0534f1dbea00d01b14/library/core/src/panicking.rs:264:5
   3: core::option::expect_failed
             at ./rustc/f6e511eec7342f59a25f7c0534f1dbea00d01b14/library/core/src/option.rs:2025:5
   4: core::option::Option<T>::expect
             at ./rustc/f6e511eec7342f59a25f7c0534f1dbea00d01b14/library/core/src/option.rs:928:21
   5: <tokio::process::imp::pidfd_reaper::PidfdReaperInner<W> as core::future::future::Future>::poll
             at ./usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.42.0/src/process/unix/pidfd_reaper.rs:127:24
   6: <tokio::process::imp::pidfd_reaper::PidfdReaper<W,Q> as core::future::future::Future>::poll
             at ./usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.42.0/src/process/unix/pidfd_reaper.rs:188:9
   7: <tokio::process::imp::Child as core::future::future::Future>::poll
             at ./usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.42.0/src/process/unix/mod.rs:183:48
   8: <tokio::process::ChildDropGuard<F> as core::future::future::Future>::poll
             at ./usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.42.0/src/process/mod.rs:1023:19
   9: <&mut F as core::future::future::Future>::poll
             at ./rustc/f6e511eec7342f59a25f7c0534f1dbea00d01b14/library/core/src/future/future.rs:111:9
  10: tokio::process::Child::wait::{{closure}}
             at ./usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.42.0/src/process/mod.rs:1223:33

# ...

I am using a FutureMap (implementation) and spawning children on it like:

self.reaper.insert(name.clone(), Box::pin(async move { child.wait().await }));

Then I'm polling it in tokio::select!.

Is it because my FutureMap is not cancel safe?

[jeromegn]

I just noticed that it only seems to happen while I am strace-ing the program after the fact (strace -fp <pid>). Very weird.

[Darksonn]

I'm not sure, but can we eliminate your map from the equation? E.g., could you instead do

let send = send.clone();
tokio::spawn(async move { send.send((key, child.wait().await)) });

with send being a sender for an unbounded mpsc channel. The receiver can go in your select!.

[jeromegn]

@Darksonn best I could do was to use a StreamMap<String, Once<ChildWait>> since I needed to be able to remove a ChildWait in some circumstances and changing that would mean changing a lot more code.

I was still able to trigger the issue with a StreamMap (which I believe should be cancel safe?)

Only when strace-ing the process AND it doesn't happen consistently, but usually 50% of the time if not a bit more.

[jeromegn]

strace significantly slows down syscalls in a process. I wonder if there's a timing issue.

[Darksonn]

cc @ipetkov

Ideas? I guess the pidfd sometimes becomes ready when stracing?

[jeromegn]

To clarify, this happens while stracing and the child exits during that time.

[sdebruyn]

Also seeing this with astral-sh/uv#14589

[Darksonn]

@sdebruyn It's unclear whether you are seeing it due to use of strace. Can you please confirm?

[sdebruyn]

@sdebruyn It's unclear whether you are seeing it due to use of strace. Can you please confirm?

That I don't know personally. I don't use this directly. I use uv as a user and they seem to use tokio-rs underneath which is causing the panics. astral-sh/uv#14589 has all the details I have for now. Is there anything I can test to help you?

[zanieb]

👋 I maintain uv. We have a bit of a bespoke entry point where the panic is occurring: https://github.com/astral-sh/uv/blob/088a436efe34ec517d5762545a753ab9424278d8/crates/uv/src/lib.rs#L2254-L2278

I don't see how strace would be involved unless @sdebruyn is invoking it unknowingly?

[geofft]

I haven't yet figured out how to reproduce this without strace, but here's a relatively self-contained reproducer:

#!/usr/bin/env -S cargo -Zscript
//! ```cargo
//! [package]
//! edition = "2021"
//! [dependencies]
//! tokio = { version = "1.47.0", features = ["full"] }
//! nix = { version = "0.30.1", features = ["signal"] }
//! ```

use std::time::Duration;
use nix::{sys::signal::{kill, Signal::*}, unistd::Pid};
use tokio::{time::sleep, process::Command};

#[tokio::main]
async fn main() {
    loop {
        let mut t = Command::new("strace")
            .args("-o /dev/null -D sleep 5".split(" "))
            .spawn()
            .unwrap();
        sleep(Duration::from_millis(100)).await;
        kill(Pid::from_raw(t.id().unwrap() as _), SIGINT).unwrap();
        t.wait().await.unwrap();
        println!("Ok!")
    }
}

(strace -D means that strace double-forks itself and execs the target process as the original PID, so the signal goes to sleep alone and not to strace.)

On my machine running Linux kernel 6.8, this will panic after about a dozen loops.

FWIW, my suspicion is this is a kernel bug - the implementation of ptrace is that the "parent" process is temporarily set to the ptracer, so that notifications of important events (like the process exiting) go to it. I think with wait() this broadly works fine because the real parent won't get notified until the tracer exits (see __ptrace_detach() in kernel/ptrace.c, both the comment "our attachedness prevented normal parent notification" and the fact that it calls do_notify_parent()). But one of the specific cool things about pidfds is that you can pass them around and still wait on them regardless of parent/child relationship - which means that in our case, the real parent will get notified prematurely because the pidfd wakeup doesn't care that it's (temporarily) not the parent.

(I think, in particular, that the call to do_notify_pidfd() in exit_notify() in kernel/exit.c is redundant in the ptrace case because __ptrace_detach() will take care of it later, but I am not super closely following the code, and torvalds/linux@0fb4827 looks worth understanding but it's probably not actually fixing our bug.)

I do wonder if that means we will get a second pidfd notification when the process is actually ready to exit, and so we can safely dismiss this as a spurious wakeup and go back to waiting on the pidfd.

I can't really figure out how this would happen in the absence of a ptracer. I tried some theories around subreapers, around processes where the main thread exits, etc. and couldn't manage to reproduce it nor theorize a plausible mechanism from reading kernel code.

[Darksonn]

I guess we should probably just treat the notification as spurious in this scenario and go back to waiting.

Any input @ipetkov ?