use std::process::{ExitStatus, Output};
use std::time::{Duration, Instant};
use tokio::io::{AsyncRead, AsyncReadExt};
use tokio::process::Child;
use tokio::sync::mpsc;
use super::compile_output::RawOutputChunk;
const DEFAULT_POST_EXIT_GRACE: Duration = Duration::from_secs(2);
const POST_EXIT_GRACE_ENV: &str = "ZCCACHE_POST_EXIT_DRAIN_MS";
fn post_exit_grace() -> Duration {
match std::env::var(POST_EXIT_GRACE_ENV) {
Ok(v) => match v.trim().parse::<u64>() {
Ok(ms) => Duration::from_millis(ms),
Err(_) => DEFAULT_POST_EXIT_GRACE,
},
Err(_) => DEFAULT_POST_EXIT_GRACE,
}
}
const DEFAULT_STALL_WINDOW: Duration = Duration::from_secs(300);
const STALL_TICK: Duration = Duration::from_secs(5);
const STALL_WINDOW_ENV: &str = "ZCCACHE_STALL_WINDOW_MS";
fn stall_window() -> Duration {
match std::env::var(STALL_WINDOW_ENV) {
Ok(v) => match v.trim().parse::<u64>() {
Ok(ms) => Duration::from_millis(ms),
Err(_) => DEFAULT_STALL_WINDOW,
},
Err(_) => DEFAULT_STALL_WINDOW,
}
}
fn should_kill_stalled(
since_progress: Duration,
stall_window: Duration,
cpu_advanced: bool,
) -> bool {
since_progress >= stall_window && !cpu_advanced
}
#[cfg(windows)]
fn child_cpu_ticks(child: &Child) -> Option<u64> {
use windows_sys::Win32::Foundation::FILETIME;
use windows_sys::Win32::System::Threading::GetProcessTimes;
let handle = child.raw_handle()?;
let mut creation = FILETIME {
dwLowDateTime: 0,
dwHighDateTime: 0,
};
let mut exit = creation;
let mut kernel = creation;
let mut user = creation;
let ok = unsafe {
GetProcessTimes(
handle.cast::<std::ffi::c_void>(),
&mut creation,
&mut exit,
&mut kernel,
&mut user,
)
};
if ok == 0 {
return None;
}
let filetime_to_u64 =
|ft: FILETIME| ((ft.dwHighDateTime as u64) << 32) | ft.dwLowDateTime as u64;
Some(filetime_to_u64(kernel).wrapping_add(filetime_to_u64(user)))
}
#[cfg(target_os = "linux")]
fn child_cpu_ticks(child: &Child) -> Option<u64> {
let pid = child.id()?;
let stat = std::fs::read_to_string(format!("/proc/{pid}/stat")).ok()?;
let after_comm = stat.rsplit_once(')')?.1;
let fields: Vec<&str> = after_comm.split_whitespace().collect();
let utime: u64 = fields.get(11)?.parse().ok()?;
let stime: u64 = fields.get(12)?.parse().ok()?;
Some(utime.wrapping_add(stime))
}
#[cfg(target_os = "macos")]
fn child_cpu_ticks(child: &Child) -> Option<u64> {
let pid = child.id()? as libc::c_int;
let mut info: libc::rusage_info_v2 = unsafe { std::mem::zeroed() };
let rc = unsafe {
libc::proc_pid_rusage(
pid,
libc::RUSAGE_INFO_V2,
&mut info as *mut libc::rusage_info_v2 as *mut _,
)
};
if rc != 0 {
return None;
}
Some(info.ri_user_time.wrapping_add(info.ri_system_time))
}
#[cfg(not(any(windows, target_os = "linux", target_os = "macos")))]
fn child_cpu_ticks(_child: &Child) -> Option<u64> {
None
}
pub(crate) async fn wait_with_output_watchdog(
child: Child,
cmd_desc: &str,
) -> std::io::Result<Output> {
watchdog_inner(
child,
cmd_desc,
post_exit_grace(),
stall_window(),
STALL_TICK,
)
.await
}
pub(crate) async fn wait_with_output_watchdog_streaming(
child: Child,
cmd_desc: &str,
sender: mpsc::Sender<RawOutputChunk>,
) -> std::io::Result<Output> {
watchdog_inner_impl(
child,
cmd_desc,
post_exit_grace(),
stall_window(),
STALL_TICK,
Some(sender),
)
.await
}
#[cfg(test)]
async fn wait_with_output_watchdog_with_grace(
child: Child,
cmd_desc: &str,
grace: Duration,
) -> std::io::Result<Output> {
watchdog_inner(child, cmd_desc, grace, Duration::ZERO, STALL_TICK).await
}
async fn watchdog_inner(
child: Child,
cmd_desc: &str,
grace: Duration,
stall_window: Duration,
stall_tick: Duration,
) -> std::io::Result<Output> {
watchdog_inner_impl(child, cmd_desc, grace, stall_window, stall_tick, None).await
}
async fn watchdog_inner_impl(
mut child: Child,
cmd_desc: &str,
grace: Duration,
stall_window: Duration,
stall_tick: Duration,
stream: Option<mpsc::Sender<RawOutputChunk>>,
) -> std::io::Result<Output> {
if grace.is_zero() && stall_window.is_zero() && stream.is_none() {
return child.wait_with_output().await;
}
let child_pid = child.id();
let mut stdout = child.stdout.take();
let mut stderr = child.stderr.take();
let mut out: Vec<u8> = Vec::new();
let mut err: Vec<u8> = Vec::new();
let mut stdout_bytes = 0usize;
let mut stderr_bytes = 0usize;
let mut sbuf = vec![0u8; 64 * 1024];
let mut ebuf = vec![0u8; 64 * 1024];
let mut stdout_done = stdout.is_none();
let mut stderr_done = stderr.is_none();
let mut exited: Option<(ExitStatus, Instant)> = None;
let mode_b = !stall_window.is_zero();
let mut last_progress = Instant::now();
let mut last_cpu = if mode_b {
child_cpu_ticks(&child)
} else {
None
};
loop {
if let (Some((status, _)), true, true) = (exited, stdout_done, stderr_done) {
return Ok(Output {
status,
stdout: out,
stderr: err,
});
}
let grace_remaining: Option<Duration> =
exited.map(|(_, at)| grace.saturating_sub(at.elapsed()));
let grace_deadline = async move {
match grace_remaining {
Some(remaining) => tokio::time::sleep(remaining).await,
None => std::future::pending::<()>().await,
}
};
let stall_armed = mode_b && exited.is_none();
let stall_tick_fut = async move {
if stall_armed {
tokio::time::sleep(stall_tick).await;
} else {
std::future::pending::<()>().await;
}
};
tokio::select! {
status = child.wait(), if exited.is_none() => {
let status = status?;
exited = Some((status, Instant::now()));
}
r = read_opt(stdout.as_mut(), &mut sbuf), if !stdout_done => match r {
Ok(0) => stdout_done = true,
Ok(n) => {
stdout_bytes += n;
if let Some(sender) = stream.as_ref() {
sender
.send(RawOutputChunk::Stdout(sbuf[..n].to_vec()))
.await
.map_err(|_| std::io::Error::new(
std::io::ErrorKind::BrokenPipe,
"compiler output consumer disconnected",
))?;
} else {
out.extend_from_slice(&sbuf[..n]);
}
last_progress = Instant::now();
}
Err(_) => stdout_done = true,
},
r = read_opt(stderr.as_mut(), &mut ebuf), if !stderr_done => match r {
Ok(0) => stderr_done = true,
Ok(n) => {
stderr_bytes += n;
if let Some(sender) = stream.as_ref() {
sender
.send(RawOutputChunk::Stderr(ebuf[..n].to_vec()))
.await
.map_err(|_| std::io::Error::new(
std::io::ErrorKind::BrokenPipe,
"compiler output consumer disconnected",
))?;
} else {
err.extend_from_slice(&ebuf[..n]);
}
last_progress = Instant::now();
}
Err(_) => stderr_done = true,
},
() = grace_deadline, if exited.is_some() => {
if let Some((status, at)) = exited {
emit_orphan_pipe_diagnostics(
cmd_desc,
child_pid,
grace,
at.elapsed(),
stdout_bytes,
stderr_bytes,
stdout_done,
stderr_done,
);
return Ok(Output {
status,
stdout: out,
stderr: err,
});
}
}
() = stall_tick_fut, if stall_armed => {
let now_cpu = child_cpu_ticks(&child);
let cpu_advanced = match (last_cpu, now_cpu) {
(Some(prev), Some(cur)) => cur > prev,
_ => true,
};
last_cpu = now_cpu;
if should_kill_stalled(last_progress.elapsed(), stall_window, cpu_advanced) {
emit_stall_diagnostics(
cmd_desc,
child_pid,
stall_window,
last_progress.elapsed(),
stdout_bytes,
stderr_bytes,
);
let _ = child.start_kill();
return match child.wait().await {
Ok(status) => Ok(Output {
status,
stdout: out,
stderr: err,
}),
Err(e) => Err(e),
};
}
}
}
}
}
async fn read_opt<R: AsyncRead + Unpin>(
reader: Option<&mut R>,
buf: &mut [u8],
) -> std::io::Result<usize> {
match reader {
Some(reader) => reader.read(buf).await,
None => std::future::pending().await,
}
}
#[allow(clippy::too_many_arguments)]
fn emit_orphan_pipe_diagnostics(
cmd_desc: &str,
pid: Option<u32>,
grace: Duration,
elapsed_since_exit: Duration,
stdout_bytes: usize,
stderr_bytes: usize,
stdout_done: bool,
stderr_done: bool,
) {
tracing::warn!(
event = "child_wait_watchdog_fired",
stage = "post_exit_pipe_drain",
cmd = %cmd_desc,
pid = pid.unwrap_or(0),
grace_ms = grace.as_millis() as u64,
elapsed_since_exit_ms = elapsed_since_exit.as_millis() as u64,
stdout_bytes,
stderr_bytes,
stdout_eof = stdout_done,
stderr_eof = stderr_done,
"child exited but a stdout/stderr pipe did not reach EOF within the drain grace — \
an orphaned grandchild inherited the pipe write handle; abandoning the drain and \
returning captured output so the daemon does not park forever and leak a \
compile-concurrency permit (issue #962)"
);
crate::daemon_core::core::lifecycle::write_event(
"child_wait_watchdog_fired",
serde_json::json!({
"stage": "post_exit_pipe_drain",
"cmd": cmd_desc,
"pid": pid,
"grace_ms": grace.as_millis() as u64,
"elapsed_since_exit_ms": elapsed_since_exit.as_millis() as u64,
"stdout_bytes": stdout_bytes,
"stderr_bytes": stderr_bytes,
"stdout_eof": stdout_done,
"stderr_eof": stderr_done,
"reason": "orphaned grandchild inherited the pipe write handle; drain abandoned to free the compile-concurrency permit",
}),
);
}
fn emit_stall_diagnostics(
cmd_desc: &str,
pid: Option<u32>,
stall_window: Duration,
since_progress: Duration,
stdout_bytes: usize,
stderr_bytes: usize,
) {
tracing::warn!(
event = "child_wait_watchdog_fired",
stage = "alive_hung_no_progress",
cmd = %cmd_desc,
pid = pid.unwrap_or(0),
stall_window_ms = stall_window.as_millis() as u64,
since_progress_ms = since_progress.as_millis() as u64,
stdout_bytes,
stderr_bytes,
"child is still running but produced no output AND burned no CPU for the \
stall window — treating it as wedged; killing it so the daemon does not \
park forever and leak a compile-concurrency permit (issue #891). This is \
progress-based, not a wall-clock cap: a compile emitting output or burning \
CPU is never affected."
);
crate::daemon_core::core::lifecycle::write_event(
"child_wait_watchdog_fired",
serde_json::json!({
"stage": "alive_hung_no_progress",
"cmd": cmd_desc,
"pid": pid,
"stall_window_ms": stall_window.as_millis() as u64,
"since_progress_ms": since_progress.as_millis() as u64,
"stdout_bytes": stdout_bytes,
"stderr_bytes": stderr_bytes,
"reason": "no output and no CPU progress for the stall window; killed as wedged",
}),
);
}
#[cfg(test)]
mod tests {
use super::*;
use std::process::Stdio;
fn piped(mut cmd: tokio::process::Command) -> tokio::process::Command {
cmd.stdout(Stdio::piped())
.stderr(Stdio::piped())
.stdin(Stdio::null())
.kill_on_drop(true);
cmd
}
#[tokio::test]
async fn well_behaved_child_returns_full_output() {
crate::daemon_core::test_support::test_timeout(async {
#[cfg(windows)]
let mut cmd = tokio::process::Command::new("cmd");
#[cfg(windows)]
cmd.args(["/c", "echo hello"]);
#[cfg(unix)]
let mut cmd = tokio::process::Command::new("sh");
#[cfg(unix)]
cmd.args(["-c", "echo hello"]);
let child = piped(cmd).spawn().expect("spawn");
let out = wait_with_output_watchdog_with_grace(child, "echo", Duration::from_secs(2))
.await
.expect("watchdog wait");
assert!(out.status.success(), "status: {:?}", out.status);
assert!(
String::from_utf8_lossy(&out.stdout).contains("hello"),
"stdout was: {:?}",
String::from_utf8_lossy(&out.stdout)
);
})
.await;
}
#[cfg(unix)]
#[tokio::test]
async fn streaming_sink_preserves_output_and_orphan_watchdog() {
crate::daemon_core::test_support::test_timeout(async {
let mut cmd = tokio::process::Command::new("sh");
cmd.args(["-c", "sleep 30 & printf 'live\\n'"]);
let child = piped(cmd).spawn().expect("spawn");
let (sender, mut receiver) = mpsc::channel(8);
let wait = watchdog_inner_impl(
child,
"stream-orphan",
Duration::from_millis(300),
Duration::ZERO,
STALL_TICK,
Some(sender),
);
let collect = async {
let mut stdout = Vec::new();
while let Some(chunk) = receiver.recv().await {
if let RawOutputChunk::Stdout(bytes) = chunk {
stdout.extend(bytes);
}
}
stdout
};
let started = Instant::now();
let (output, stdout) = tokio::join!(wait, collect);
let output = output.expect("watchdog wait");
assert!(started.elapsed() < Duration::from_secs(10));
assert!(output.status.success());
assert!(
output.stdout.is_empty(),
"streaming sink owns captured bytes"
);
assert_eq!(stdout, b"live\n");
})
.await;
}
#[tokio::test]
async fn nonzero_exit_is_reported() {
crate::daemon_core::test_support::test_timeout(async {
#[cfg(windows)]
let mut cmd = tokio::process::Command::new("cmd");
#[cfg(windows)]
cmd.args(["/c", "exit 3"]);
#[cfg(unix)]
let mut cmd = tokio::process::Command::new("sh");
#[cfg(unix)]
cmd.args(["-c", "exit 3"]);
let child = piped(cmd).spawn().expect("spawn");
let out = wait_with_output_watchdog_with_grace(child, "exit3", Duration::from_secs(2))
.await
.expect("watchdog wait");
assert_eq!(out.status.code(), Some(3));
})
.await;
}
#[cfg(unix)]
#[tokio::test]
async fn orphan_holding_pipe_does_not_wedge() {
use std::time::Instant;
crate::daemon_core::test_support::test_timeout(async {
let mut cmd = tokio::process::Command::new("sh");
cmd.args(["-c", "sleep 30 & echo hi"]);
let child = piped(cmd).spawn().expect("spawn");
let start = Instant::now();
let out =
wait_with_output_watchdog_with_grace(child, "orphan", Duration::from_millis(300))
.await
.expect("watchdog wait");
assert!(
start.elapsed() < Duration::from_secs(10),
"watchdog did not fire; wait took {:?} (orphan wedge not bounded)",
start.elapsed()
);
assert!(
String::from_utf8_lossy(&out.stdout).contains("hi"),
"captured output before firing should include the child's stdout"
);
})
.await;
}
#[tokio::test]
async fn zero_grace_disables_watchdog() {
crate::daemon_core::test_support::test_timeout(async {
#[cfg(windows)]
let mut cmd = tokio::process::Command::new("cmd");
#[cfg(windows)]
cmd.args(["/c", "echo ok"]);
#[cfg(unix)]
let mut cmd = tokio::process::Command::new("sh");
#[cfg(unix)]
cmd.args(["-c", "echo ok"]);
let child = piped(cmd).spawn().expect("spawn");
let out = wait_with_output_watchdog_with_grace(child, "echo", Duration::ZERO)
.await
.expect("watchdog wait");
assert!(out.status.success());
assert!(String::from_utf8_lossy(&out.stdout).contains("ok"));
})
.await;
}
fn sleeper_cmd() -> tokio::process::Command {
#[cfg(windows)]
{
let mut c = tokio::process::Command::new("cmd");
c.args(["/c", "ping -n 31 127.0.0.1 >nul"]);
c
}
#[cfg(unix)]
{
let mut c = tokio::process::Command::new("sh");
c.args(["-c", "sleep 30"]);
c
}
}
#[test]
fn should_kill_stalled_only_when_silent_and_cpu_flat() {
let w = Duration::from_secs(300);
assert!(
should_kill_stalled(Duration::from_secs(301), w, false),
"no output past the window AND cpu flat → wedged"
);
assert!(
!should_kill_stalled(Duration::from_secs(301), w, true),
"cpu still advancing → never killed, even past the window"
);
assert!(
!should_kill_stalled(Duration::from_secs(10), w, false),
"within the window → never killed"
);
assert!(
!should_kill_stalled(Duration::from_secs(10), w, true),
"recent progress + cpu → never killed"
);
}
#[cfg(any(windows, target_os = "linux", target_os = "macos"))]
#[tokio::test]
async fn child_cpu_ticks_reports_for_live_process() {
crate::daemon_core::test_support::test_timeout(async {
let mut child = piped(sleeper_cmd()).spawn().expect("spawn");
let ticks = super::child_cpu_ticks(&child);
let _ = child.start_kill();
let _ = child.wait().await;
assert!(
ticks.is_some(),
"per-process CPU sampling must be wired up on this platform (#891)"
);
})
.await;
}
#[tokio::test]
async fn alive_hung_no_progress_child_is_killed() {
crate::daemon_core::test_support::test_timeout(async {
let child = piped(sleeper_cmd()).spawn().expect("spawn");
let start = Instant::now();
let out = watchdog_inner(
child,
"sleeper",
Duration::ZERO,
Duration::from_millis(150),
Duration::from_millis(50),
)
.await
.expect("watchdog wait");
assert!(
start.elapsed() < Duration::from_secs(15),
"Mode B must kill the wedged child promptly (took {:?})",
start.elapsed()
);
assert!(
!out.status.success(),
"a killed wedged child must not report success"
);
})
.await;
}
#[tokio::test]
async fn streaming_sink_preserves_alive_hung_watchdog() {
crate::daemon_core::test_support::test_timeout(async {
let child = piped(sleeper_cmd()).spawn().expect("spawn");
let (sender, mut receiver) = mpsc::channel(8);
let wait = watchdog_inner_impl(
child,
"stream-sleeper",
Duration::ZERO,
Duration::from_millis(150),
Duration::from_millis(50),
Some(sender),
);
let drain = async { while receiver.recv().await.is_some() {} };
let (output, ()) = tokio::join!(wait, drain);
assert!(!output.expect("watchdog wait").status.success());
})
.await;
}
#[tokio::test]
async fn concurrent_drain_survives_pipe_saturation() {
crate::daemon_core::test_support::test_timeout(async {
const FLOOD: usize = 256 * 1024; #[cfg(windows)]
let cmd = {
let mut c = tokio::process::Command::new("powershell");
c.args([
"-NoProfile",
"-Command",
&format!("[Console]::Error.Write('b' * {FLOOD}); [Console]::Out.Write('done')"),
]);
c
};
#[cfg(unix)]
let cmd = {
let mut c = tokio::process::Command::new("sh");
c.args([
"-c",
&format!("yes b | tr -d '\\n' | head -c {FLOOD} 1>&2; printf done"),
]);
c
};
let child = piped(cmd).spawn().expect("spawn");
let start = Instant::now();
let out = wait_with_output_watchdog(child, "saturate")
.await
.expect("watchdog wait");
assert!(
start.elapsed() < Duration::from_secs(20),
"concurrent drain deadlocked on a saturated pipe (took {:?})",
start.elapsed()
);
assert!(
out.stderr.len() >= FLOOD,
"full stderr flood must be captured: got {} of {FLOOD} bytes",
out.stderr.len()
);
assert!(
String::from_utf8_lossy(&out.stdout).contains("done"),
"the post-flood stdout marker must be captured"
);
})
.await;
}
fn short_sleep_cmd() -> tokio::process::Command {
#[cfg(windows)]
{
let mut c = tokio::process::Command::new("cmd");
c.args(["/c", "ping -n 2 127.0.0.1 >nul"]);
c
}
#[cfg(unix)]
{
let mut c = tokio::process::Command::new("sh");
c.args(["-c", "sleep 1"]);
c
}
}
#[tokio::test]
async fn concurrent_waits_are_not_serialized() {
crate::daemon_core::test_support::test_timeout(async {
const N: usize = 4;
let start = Instant::now();
let handles: Vec<_> = (0..N)
.map(|_| {
let child = piped(short_sleep_cmd()).spawn().expect("spawn");
tokio::spawn(async move { wait_with_output_watchdog(child, "sleep1").await })
})
.collect();
for h in handles {
h.await.expect("join").expect("watchdog wait");
}
let elapsed = start.elapsed();
assert!(
elapsed < Duration::from_secs(3),
"watchdog serialized {N} concurrent ~1s waits (took {elapsed:?}); \
concurrency was reduced (#894)"
);
})
.await;
}
}