From 1361b58c99642eddb5b551a5bd42c4a7a3de97c3 Mon Sep 17 00:00:00 2001 From: Austin Gregg-Smith Date: Fri, 4 Sep 2026 13:07:45 +0100 Subject: [PATCH] feat: a cold launch says it is alive while devpod has stopped saying anything A cold launch spends minutes on one `postCreateCommand` step and said nothing while it did. Measured on one host, streaming devpod's output, two consecutive lines 5m01s apart with nothing in between to say the launch was alive, which step it was on, or how long that step had been running. The same launch warm was 21.6s in total with that step taking 5s, so the ratio between a warm and a cold launch of one branch is about 16x and a reader had no way to tell from the terminal which one they were in. 11:42:52 Pixi task (ui-install-locked): npm --prefix frontend ci Still working: devpod has printed nothing for 30s. Still working: devpod has printed nothing for 1m00s. ... 11:47:53 added 585 packages in 5m The measurement restarts at every line devpod writes, so it is the age of the step devpod is on and not the age of the launch, and its restarting is the whole of what tells a long step from a wedged one. Neither is something dl can diagnose; what it can do is stop them looking identical. A launch that is talking never produces one of these, because devpod's own steps are seconds apart, which keeps the line off a warm launch entirely and off most of a cold one. Whole lines rather than one refreshed in place, and that is a decision rather than a shortcut: dl echoes devpod's output but does not compose it, so a line rewritten with a carriage return could not be relied on to be the last thing written and would be overtyped by devpod's next; and a whole line is the only shape that also survives stderr being a file, which is what it is in CI and in the log aid's background boot replays from. Five minutes of it are the repository's own `postCreateCommand`. dl cannot make `npm ci` faster and does not try. # How Only something sitting on the read can time a silence: a line sink that is not being called says nothing. So `devpod up` runs as a watched session rather than a plain passthrough, and `Runner` grows one defaulted method that reports the gaps as well as the lines. Defaulted so it is not a second mechanism -- every fake and wrapper in the tree keeps implementing `session` alone and simply never ticks -- and `ProcessRunner` expresses `session` in terms of it, so there is one loop and `session` is the narrower view of it. The trade is that `devpod up`'s stderr is a pipe now and no longer a terminal to devpod. stdin and stdout are untouched, so the terminal devpod puts into raw mode is exactly as it was. The process group is untouched too, and that is the part that mattered: the build still leads a group of its own, so a Ctrl-C, a `kill -INT` or a closed terminal still takes it down with dl rather than orphaning it holding the launch lock. That is concurrency review F3 and `dl/tests/interrupt.rs` is its suite, run against the rebuilt binary. `session` used to hardcode "no group of its own" and would have dropped the contract silently, so the parent-side `setpgid` and the note the interrupt handler reads are now a helper both foreground methods take rather than one method's private business. Closes #576 --- CHANGELOG.md | 55 +++++ docs/performance.md | 47 +++++ rust/devlaunch-core/public-api.api.txt | 4 + rust/devlaunch-core/src/clients/devpod.rs | 46 +++- rust/devlaunch-core/src/flows/launch.rs | 35 ++- rust/devlaunch-runner/public-api.txt | 16 ++ rust/devlaunch-runner/src/lib.rs | 246 +++++++++++++++++----- rust/devlaunch-runner/src/tests.rs | 139 ++++++++++++ rust/dl/src/render.rs | 67 ++++++ 9 files changed, 600 insertions(+), 55 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 49c18d09..aadec13f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,61 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Added + +- **A `devpod up` that has gone quiet says so, every 30 seconds, with the number + going up.** A cold launch spends minutes on a single `postCreateCommand` step + and said nothing while it did. Measured on one host: two consecutive lines + **5m01s apart**, with nothing in between to say the launch was alive, which + step it was on, or how long that step had been running. The same launch warm + was 21.6s in total, so the ratio between the two is about 16x and a reader had + no way to tell from the terminal which one they were in. + + ``` + 11:42:52 Pixi task (ui-install-locked): npm --prefix frontend ci + Still working: devpod has printed nothing for 30s. + Still working: devpod has printed nothing for 1m00s. + ... + 11:47:53 added 585 packages in 5m + ``` + + **The measurement restarts at every line devpod writes**, so it is the age of + the step devpod is on and not the age of the launch, and its restarting is the + whole of what tells a long step from a wedged one. Neither is something `dl` can + diagnose; what it can do is stop them looking identical. A launch that is + talking never produces one of these, because devpod's own steps are seconds + apart, which keeps the line off a warm launch entirely and off most of a cold + one. + + Worth being clear about attribution: **the five minutes are the repository's own + `postCreateCommand`, not devlaunch's work.** `dl` cannot make `npm ci` faster and + does not try. + + Written as whole lines rather than one refreshed in place, deliberately. `dl` + echoes devpod's output but does not compose it, so a line rewritten with a + carriage return could not be relied on to be the last thing written and would + be overtyped by devpod's next; and a whole line is the only shape that also + survives stderr being a file, which is what it is in CI and in the log `aid`'s + background boot replays from. + +### Changed + +- **`devpod up` runs as a watched session rather than a plain passthrough**, which + is what makes the line above possible: only something sitting on the read can + time a silence, since a line sink that is not being called says nothing. The + trade is that `devpod up`'s stderr is a pipe now and no longer a terminal to + devpod. stdin and stdout are untouched, so the terminal devpod puts into raw + mode is exactly as it was. + + **The process group is untouched too, and that is the part that mattered.** The + build still leads a group of its own, so a Ctrl-C (or `kill -INT`, or a closed + terminal) still takes it down with `dl` rather than orphaning it holding the + launch lock, which is concurrency review F3 and has its own suite. The + parent-side `setpgid` and the note the interrupt handler reads were one method's + private business and are now a helper both foreground methods take, so there is + one copy of it rather than a second that could be subtly wrong in whichever + method nobody was thinking about. + ## [0.29.0] - 2026-09-02 ### Added diff --git a/docs/performance.md b/docs/performance.md index a19bcf73..e539ee2a 100644 --- a/docs/performance.md +++ b/docs/performance.md @@ -120,6 +120,53 @@ failing. A master that has gone away leaves a socket the next client unlinks, an resident `devpod ssh --stdio` process and a `docker exec` per key, and `dl` must not be the reason a container never goes idle. +## While the launch is still running + +`DEVLAUNCH_TIMING` answers after the fact, which is exactly when you no longer +need it. What a cold launch needed was something during, because a cold launch +spends minutes on one step and says nothing while it does. Measured on one host, +streaming devpod's output, two consecutive lines **5m01s apart**: + +``` +11:42:52 Pixi task (ui-install-locked): npm --prefix frontend ci +11:47:53 added 585 packages in 5m +``` + +Nothing in between said the launch was alive, which step it was on, or how long +that step had been running. The same launch warm was 21.6s in total with that +step taking 5s, so the ratio between a warm and a cold launch of one branch is +about 16x and a reader had no way to tell from the terminal which one they were +in. + +`dl` now times the gaps between devpod's own lines and says so every 30 seconds +while one lasts: + +``` +11:42:52 Pixi task (ui-install-locked): npm --prefix frontend ci +Still working: devpod has printed nothing for 30s. +Still working: devpod has printed nothing for 1m00s. +... +11:47:53 added 585 packages in 5m +``` + +Three things it does not claim. **It is not a diagnosis**: a step that is slow +and a step that is stuck both produce it, and the only thing separating them is +the number going up. **It is not devlaunch's time**: the five minutes above are +the repository's own `postCreateCommand`, `dl` cannot make `npm ci` faster and +does not try. And **it is not the age of the launch**: the measurement restarts +at every line devpod writes, so it is the age of the step devpod is on, and its +restarting is what tells a long step from a wedged one. + +A launch that is talking never produces one, because devpod's own steps are +seconds apart. That is what keeps the line off a warm launch entirely and off +most of a cold one. + +**What it costs.** `devpod up`'s stderr is a pipe now rather than the terminal, +so it is no longer a terminal to devpod and loses whatever devpod does with one. +stdin and stdout are untouched, and so is the process group the build leads: a +Ctrl-C still takes the build down with `dl` rather than orphaning it holding the +launch lock. + ## Measuring launch time Set `DEVLAUNCH_TIMING=1` and a `dl` command ends with one summary on stderr, diff --git a/rust/devlaunch-core/public-api.api.txt b/rust/devlaunch-core/public-api.api.txt index 123423d8..a7395bb2 100644 --- a/rust/devlaunch-core/public-api.api.txt +++ b/rust/devlaunch-core/public-api.api.txt @@ -78,6 +78,8 @@ pub devlaunch_core::api::LaunchNotice::StartingForDotfiles::workspace_id: alloc: pub devlaunch_core::api::LaunchNotice::TerminalTitle(devlaunch_core::flows::launch::TerminalTitle) pub devlaunch_core::api::LaunchNotice::TokenNotStaged pub devlaunch_core::api::LaunchNotice::TokenNotStaged::reason: alloc::string::String +pub devlaunch_core::api::LaunchNotice::UpHasGoneQuiet +pub devlaunch_core::api::LaunchNotice::UpHasGoneQuiet::quiet: core::time::Duration pub devlaunch_core::api::LaunchNotice::WaitingForSiblingLaunch pub devlaunch_core::api::LaunchNotice::WaitingForSiblingLaunch::workspace_id: alloc::string::String impl core::clone::Clone for devlaunch_core::flows::launch::LaunchNotice @@ -558,6 +560,8 @@ pub devlaunch_core::flows::launch::LaunchNotice::StartingForDotfiles::workspace_ pub devlaunch_core::flows::launch::LaunchNotice::TerminalTitle(devlaunch_core::flows::launch::TerminalTitle) pub devlaunch_core::flows::launch::LaunchNotice::TokenNotStaged pub devlaunch_core::flows::launch::LaunchNotice::TokenNotStaged::reason: alloc::string::String +pub devlaunch_core::flows::launch::LaunchNotice::UpHasGoneQuiet +pub devlaunch_core::flows::launch::LaunchNotice::UpHasGoneQuiet::quiet: core::time::Duration pub devlaunch_core::flows::launch::LaunchNotice::WaitingForSiblingLaunch pub devlaunch_core::flows::launch::LaunchNotice::WaitingForSiblingLaunch::workspace_id: alloc::string::String impl core::clone::Clone for devlaunch_core::flows::launch::LaunchNotice diff --git a/rust/devlaunch-core/src/clients/devpod.rs b/rust/devlaunch-core/src/clients/devpod.rs index 3963059b..6806bed2 100644 --- a/rust/devlaunch-core/src/clients/devpod.rs +++ b/rust/devlaunch-core/src/clients/devpod.rs @@ -58,7 +58,8 @@ use std::time::Duration; use crate::json::JsonKind; use crate::runner::{ - CapturedText, EnvSpec, Exit, Invocation, OsFailure, Outcome, Runner, SpawnSpec, StdinPlan, + CapturedText, EnvSpec, Exit, Invocation, OsFailure, Outcome, Runner, SessionOutput, SpawnSpec, + StdinPlan, }; use crate::timing; @@ -248,6 +249,49 @@ pub(crate) fn run_watching_stderr( ran(runner.session(&call.spec(), &mut forward)).map(|(exit, ())| exit) } +/// The same call, echoed as it arrives, with the silences between lines timed. +/// +/// For the one call that goes quiet for minutes at a stretch and gives a reader +/// no way to tell that from a hang (devlaunch#576). The lines are written back to +/// stderr exactly as [`run_watching_stderr`] writes them, so nothing about what +/// devpod's output looks like changes; what is added is a report on the gaps, +/// which is the thing no line sink can produce because a callback that is not +/// being called says nothing. +/// +/// `interval` is how often a continuing silence is reported and the measurement +/// restarts at every line, so what `on_quiet` is handed is the age of the step +/// devpod is on rather than the age of the call. +pub(crate) fn run_watching_silence( + runner: &dyn Runner, + call: &Call, + interval: Duration, + on_quiet: &mut dyn FnMut(Duration), +) -> Result { + let _span = timing::span(call.round_trip()); + let mut watcher = Echoing { interval, on_quiet }; + ran(runner.watched_session(&call.spec(), &mut watcher)).map(|(exit, ())| exit) +} + +/// [`run_watching_silence`]'s watcher: echo the lines, hand the gaps over. +struct Echoing<'a> { + interval: Duration, + on_quiet: &'a mut dyn FnMut(Duration), +} + +impl SessionOutput for Echoing<'_> { + fn line(&mut self, line: &str) { + eprintln!("{line}"); + } + + fn quiet_interval(&self) -> Option { + Some(self.interval) + } + + fn quiet(&mut self, quiet: Duration) { + (self.on_quiet)(quiet); + } +} + /// Whether this is devpod saying it is blocked on a workspace's lock. /// /// devpod's `initLock` is a *blocking* `flock` acquire with no deadline behind it, diff --git a/rust/devlaunch-core/src/flows/launch.rs b/rust/devlaunch-core/src/flows/launch.rs index 8a2fd7fb..9d4b6b65 100644 --- a/rust/devlaunch-core/src/flows/launch.rs +++ b/rust/devlaunch-core/src/flows/launch.rs @@ -157,6 +157,16 @@ pub(crate) const WORKSPACE_ID_VAR: &str = "DEVLAUNCH_WORKSPACE_ID"; /// the refresh is best-effort and the shell arrives either way. pub(crate) const DOTFILES_ATTACH_TIMEOUT: Duration = Duration::from_secs(60); +/// How often a `devpod up` that has printed nothing is reported as still running. +/// +/// Long enough that a launch which is talking never reaches it — devpod's own +/// steps are seconds apart, so most of a cold launch passes with nothing said +/// about the silence — and short enough that the five minutes devlaunch#576 +/// measured reads as ten lines rather than as two. Not a knob: what a knob would +/// tune is how often a line nobody needs is printed, and the answer to not +/// needing it is that it does not appear. +pub(crate) const UP_QUIET_REPORT: Duration = Duration::from_secs(30); + /// How long a cached copy of devpod's context options is believed. pub(crate) const CONTEXT_OPTIONS_TTL: Duration = Duration::from_secs(3600); @@ -394,6 +404,15 @@ pub enum LaunchNotice { /// wait. Handed over *before* the blocking acquisition, which is the only /// moment at which "this run is now waiting" can be reported at all. WaitingForSiblingLaunch { workspace_id: String }, + /// `devpod up` has printed nothing for this long and is still running. + /// + /// Said every [`UP_QUIET_REPORT`] while the silence lasts, and the duration is + /// measured from the last thing devpod said rather than from the start of the + /// call — so it is the age of the step devpod is on, and it restarts when + /// devpod moves to the next one. That restart is the whole of what tells a + /// long step from a wedged one, and neither is a thing dl can diagnose: what + /// it can do is stop them looking identical (devlaunch#576). + UpHasGoneQuiet { quiet: Duration }, /// The launch lock could not be taken, so this `up` is unserialized. Nothing /// worth failing a launch over: serialization guards a race that may not even /// be happening. @@ -1504,7 +1523,21 @@ fn up_under_stage( // The build runs for minutes in the foreground; it leads a process group of // its own so a Ctrl-C (or `kill -INT `) tears the whole build down with // `dl` rather than orphaning it holding the launch lock. - let exit = devpod::run(context.runner(), &Call::new(args).leading_its_own_group())?; + // + // Watched rather than a plain passthrough, and the trade is stated where it is + // paid: devpod's stderr becomes a pipe, so it is no longer a terminal to + // devpod and loses whatever devpod does with one. What it buys is the only + // thing that tells a long step from a wedged one -- a measurement of the gaps + // between devpod's lines. `postCreateCommand` steps go quiet for minutes at a + // time and nothing said the launch was alive while they did (devlaunch#576). + // stdin and stdout are still this process's, so the terminal devpod puts into + // raw mode is untouched. + let exit = devpod::run_watching_silence( + context.runner(), + &Call::new(args).leading_its_own_group(), + UP_QUIET_REPORT, + &mut |quiet| notices.say(LaunchNotice::UpHasGoneQuiet { quiet }), + )?; // `up` creates and starts workspaces, so any snapshot of `devpod list` taken // before it is now out of date. context.forget_workspaces(); diff --git a/rust/devlaunch-runner/public-api.txt b/rust/devlaunch-runner/public-api.txt index cacf11dc..51bdfd26 100644 --- a/rust/devlaunch-runner/public-api.txt +++ b/rust/devlaunch-runner/public-api.txt @@ -137,6 +137,11 @@ pub fn devlaunch_runner::Invocation::default() -> devlaunch_runner::Invocation impl core::fmt::Debug for devlaunch_runner::Invocation pub fn devlaunch_runner::Invocation::fmt(&self, &mut core::fmt::Formatter<'_>) -> core::fmt::Result impl core::marker::StructuralPartialEq for devlaunch_runner::Invocation +pub struct devlaunch_runner::Lines(pub F) +impl devlaunch_runner::SessionOutput for devlaunch_runner::Lines +pub fn devlaunch_runner::Lines::line(&mut self, &str) +pub fn devlaunch_runner::Lines::quiet(&mut self, core::time::Duration) +pub fn devlaunch_runner::Lines::quiet_interval(&self) -> core::option::Option pub struct devlaunch_runner::OsFailure pub devlaunch_runner::OsFailure::errno: core::option::Option pub devlaunch_runner::OsFailure::kind: core::io::error::ErrorKind @@ -166,6 +171,7 @@ pub fn devlaunch_runner::ProcessRunner::capture(&self, &devlaunch_runner::SpawnS pub fn devlaunch_runner::ProcessRunner::detach(&self, &devlaunch_runner::Invocation) -> devlaunch_runner::DetachOutcome pub fn devlaunch_runner::ProcessRunner::passthrough(&self, &devlaunch_runner::SpawnSpec) -> devlaunch_runner::Outcome pub fn devlaunch_runner::ProcessRunner::session(&self, &devlaunch_runner::SpawnSpec, &mut dyn core::ops::function::FnMut(&str)) -> devlaunch_runner::Outcome +pub fn devlaunch_runner::ProcessRunner::watched_session(&self, &devlaunch_runner::SpawnSpec, &mut dyn devlaunch_runner::SessionOutput) -> devlaunch_runner::Outcome pub struct devlaunch_runner::SpawnSpec pub devlaunch_runner::SpawnSpec::invocation: devlaunch_runner::Invocation pub devlaunch_runner::SpawnSpec::own_group: bool @@ -196,8 +202,18 @@ pub fn devlaunch_runner::Runner::capture(&self, &devlaunch_runner::SpawnSpec) -> pub fn devlaunch_runner::Runner::detach(&self, &devlaunch_runner::Invocation) -> devlaunch_runner::DetachOutcome pub fn devlaunch_runner::Runner::passthrough(&self, &devlaunch_runner::SpawnSpec) -> devlaunch_runner::Outcome pub fn devlaunch_runner::Runner::session(&self, &devlaunch_runner::SpawnSpec, &mut dyn core::ops::function::FnMut(&str)) -> devlaunch_runner::Outcome +pub fn devlaunch_runner::Runner::watched_session(&self, &devlaunch_runner::SpawnSpec, &mut dyn devlaunch_runner::SessionOutput) -> devlaunch_runner::Outcome impl devlaunch_runner::Runner for devlaunch_runner::ProcessRunner pub fn devlaunch_runner::ProcessRunner::capture(&self, &devlaunch_runner::SpawnSpec) -> devlaunch_runner::Outcome pub fn devlaunch_runner::ProcessRunner::detach(&self, &devlaunch_runner::Invocation) -> devlaunch_runner::DetachOutcome pub fn devlaunch_runner::ProcessRunner::passthrough(&self, &devlaunch_runner::SpawnSpec) -> devlaunch_runner::Outcome pub fn devlaunch_runner::ProcessRunner::session(&self, &devlaunch_runner::SpawnSpec, &mut dyn core::ops::function::FnMut(&str)) -> devlaunch_runner::Outcome +pub fn devlaunch_runner::ProcessRunner::watched_session(&self, &devlaunch_runner::SpawnSpec, &mut dyn devlaunch_runner::SessionOutput) -> devlaunch_runner::Outcome +pub trait devlaunch_runner::SessionOutput +pub fn devlaunch_runner::SessionOutput::line(&mut self, &str) +pub fn devlaunch_runner::SessionOutput::quiet(&mut self, core::time::Duration) +pub fn devlaunch_runner::SessionOutput::quiet_interval(&self) -> core::option::Option +impl devlaunch_runner::SessionOutput for devlaunch_runner::Lines +pub fn devlaunch_runner::Lines::line(&mut self, &str) +pub fn devlaunch_runner::Lines::quiet(&mut self, core::time::Duration) +pub fn devlaunch_runner::Lines::quiet_interval(&self) -> core::option::Option diff --git a/rust/devlaunch-runner/src/lib.rs b/rust/devlaunch-runner/src/lib.rs index ab507689..ceff5067 100644 --- a/rust/devlaunch-runner/src/lib.rs +++ b/rust/devlaunch-runner/src/lib.rs @@ -458,6 +458,23 @@ pub trait Runner: Sync { /// of a remote exit status) is held back rather than shown. fn session(&self, spec: &SpawnSpec, on_stderr_line: &mut dyn FnMut(&str)) -> Outcome; + /// [`Runner::session`], with the *silences* reported as well as the lines. + /// + /// The one thing a caller cannot work out for itself from a line sink: a + /// callback that is not being called says nothing, and "devpod has printed + /// nothing for five minutes" is exactly what a launch wants to be able to + /// say (devlaunch#576). Only something sitting on the read can time it. + /// + /// **Defaulted, so this is not a second mechanism.** A runner that has not + /// been taught to watch a clock still runs the call and still delivers every + /// line; the only thing lost is the tick. That is what the fakes and + /// wrappers in this tree take. [`ProcessRunner`] overrides it and expresses + /// [`Runner::session`] in terms of it, so there is one loop and `session` is + /// the narrower view of it rather than a copy. + fn watched_session(&self, spec: &SpawnSpec, output: &mut dyn SessionOutput) -> Outcome { + self.session(spec, &mut |line| output.line(line)) + } + /// Start a child in a session of its own with null stdio, and do not wait. /// /// Takes an [`Invocation`] rather than a [`SpawnSpec`]: a child nothing @@ -466,6 +483,53 @@ pub trait Runner: Sync { fn detach(&self, what: &Invocation) -> DetachOutcome; } +/// What a session tells its caller: the lines the child wrote, and the silences +/// between them. +/// +/// One trait and not two callbacks, because they are one observation of one +/// stream: a caller handed them separately could pass a line sink and a silence +/// sink that disagreed about which call they were watching. Both are `&mut self` +/// on one value, so there is one watcher per session by construction. +pub trait SessionOutput { + /// One line the child wrote to stderr, without its newline. + fn line(&mut self, line: &str); + + /// How often to report a silence, or `None` to never report one. + /// + /// `None` is the default and is what every caller that only wants the lines + /// gets: the read then blocks with no deadline of its own, exactly as it did + /// before silences were reported at all, so a session that runs for an hour + /// wakes for the hour's worth of output and nothing else. + fn quiet_interval(&self) -> Option { + None + } + + /// The child has written nothing for `quiet`. + /// + /// Called on [`SessionOutput::quiet_interval`] while the child is silent and + /// never while it is talking: the measurement restarts at zero after every + /// [`SessionOutput::line`], so what this reports is the gap since the last + /// thing the child said and not the age of the call. + fn quiet(&mut self, quiet: Duration); +} + +/// A watcher that only wants the lines: [`Runner::session`]'s sink, as a +/// [`SessionOutput`]. +/// +/// Named rather than written as a closure at each site, because the interesting +/// half of it is the half that is missing: it reports no silences and asks for +/// no interval, so wrapping a plain line sink in one cannot accidentally start a +/// clock. +pub struct Lines(pub F); + +impl SessionOutput for Lines { + fn line(&mut self, line: &str) { + (self.0)(line); + } + + fn quiet(&mut self, _quiet: Duration) {} +} + /// The production runner: [`std::process::Command`], and nothing else. #[derive(Clone, Copy, Debug, Default)] pub struct ProcessRunner; @@ -537,52 +601,13 @@ impl Runner for ProcessRunner { } fn passthrough(&self, spec: &SpawnSpec) -> Outcome { - // Whether this child leads a process group of its own is the caller's - // decision, carried on the spec (see [`SpawnSpec::own_group`]). - // - // `devpod up` sets it: it is the one long-running foreground child, and - // the one a Ctrl-C used to orphan — `dl`'s `_exit(130)` released the - // launch lock while the build carried on holding it (concurrency review - // F3). Leading its own group lets `dl`'s interrupt handler `killpg` the - // build before it exits, so the build comes down with `dl` rather than - // outliving it, even when the interrupt arrived as `kill -INT `. - // - // An interactive `ssh -t` (the other passthrough caller) must NOT: a - // child in a group of its own is no longer the controlling terminal's - // foreground group, so its first read of the PTY earns a SIGTTIN and the - // session hangs. It stays in this process's group, which is also what - // the Python original did — as do `session`'s and `capture`'s children, - // for the same reason. - let ending = if spec.own_group { - let mut child = match start(spec, Stdio::inherit(), Stdio::inherit(), OwnGroup::Yes) { - Ok(child) => child, - Err(outcome) => return outcome.retyped(), - }; - // The child led its own group from its `pre_exec`, so its pgid is its - // pid; set it from the parent too to close the fork-to-exec window. - let pgid = child.id() as i32; - // SAFETY: `setpgid` on our own just-spawned child; EACCES (already - // exec'd) or ESRCH (already gone) are both fine — the child's own - // `pre_exec` establishes the group regardless. - unsafe { - libc::setpgid(pgid, pgid); - } - interrupt::note_foreground_child(pgid); - let ending = wait(&mut child, spec.timeout); - // Reaped now, so the handler must not signal a possibly-recycled pgid. - interrupt::clear_foreground_child(); - ending - } else { - // The child stays in this process's group. Its "pgid" would be this - // process's own group, so it must NOT be noted for the interrupt - // handler — a `killpg` on it would fell `dl` and the whole foreground - // group. Just spawn, wait, and return. - let mut child = match start(spec, Stdio::inherit(), Stdio::inherit(), OwnGroup::No) { - Ok(child) => child, - Err(outcome) => return outcome.retyped(), - }; - wait(&mut child, spec.timeout) + let (mut child, note) = match start_foreground(spec, Stdio::inherit(), Stdio::inherit()) { + Ok(started) => started, + Err(outcome) => return outcome.retyped(), }; + let ending = wait(&mut child, spec.timeout); + // Reaped now, so the handler must not signal a possibly-recycled pgid. + drop(note); // The child had this process's stdout, so it had the terminal, so it may // have left modes switched on that only it was ever going to switch off — // and if it was killed rather than exited, it certainly did. Undone here, @@ -598,8 +623,14 @@ impl Runner for ProcessRunner { } fn session(&self, spec: &SpawnSpec, on_stderr_line: &mut dyn FnMut(&str)) -> Outcome { - let mut child = match start(spec, Stdio::inherit(), Stdio::piped(), OwnGroup::No) { - Ok(child) => child, + // The narrower view of the one loop, not a copy of it: `Lines` asks for no + // interval, so the read blocks exactly as it always did. + self.watched_session(spec, &mut Lines(on_stderr_line)) + } + + fn watched_session(&self, spec: &SpawnSpec, output: &mut dyn SessionOutput) -> Outcome { + let (mut child, note) = match start_foreground(spec, Stdio::inherit(), Stdio::piped()) { + Ok(started) => started, Err(outcome) => return outcome.retyped(), }; // The lines are read on a thread and handed over here as they arrive, @@ -634,13 +665,38 @@ impl Runner for ProcessRunner { }; let deadline = spec.timeout.map(|limit| Instant::now() + limit); + // Asked once. A watcher that changed its mind between reads would move the + // tick the loop is already waiting on, which is a silence reported at an + // interval nobody chose. + let tick = output.quiet_interval(); let mut timed_out = false; if let Some(lines) = lines { + // When the child last said something, which is what a silence is + // measured from -- not the start of the call. It restarts at every + // line, so a step that takes five minutes is reported as five minutes + // and a call that has been talking all along is never reported at all. + let mut last_spoke = Instant::now(); + // Tracked apart from `last_spoke`, and it has to be: a tick does not + // make the child speak, so an interval measured from `last_spoke` + // would be in the past the instant after it fired and every read would + // return immediately -- a spin that reports the same silence thousands + // of times a second. This one is pushed forward by each report. + let mut next_tick = tick.map(|tick| last_spoke + tick); loop { - let received = match deadline { + // The nearer of the two clocks. The deadline kills the child and + // the tick does not, so a read that could have been either has to + // wake for whichever comes first and work out afterwards which it + // was -- from the time, not from the wake. + let wake = match (deadline, next_tick) { + (None, None) => None, + (Some(deadline), None) => Some(deadline), + (None, Some(next_tick)) => Some(next_tick), + (Some(deadline), Some(next_tick)) => Some(deadline.min(next_tick)), + }; + let received = match wake { None => lines.recv().map_err(|_| Waited::Closed), - Some(deadline) => { - let left = deadline.saturating_duration_since(Instant::now()); + Some(wake) => { + let left = wake.saturating_duration_since(Instant::now()); lines.recv_timeout(left).map_err(|error| match error { mpsc::RecvTimeoutError::Timeout => Waited::Elapsed, mpsc::RecvTimeoutError::Disconnected => Waited::Closed, @@ -648,11 +704,26 @@ impl Runner for ProcessRunner { } }; match received { - Ok(line) => on_stderr_line(&line), + Ok(line) => { + last_spoke = Instant::now(); + next_tick = tick.map(|tick| last_spoke + tick); + output.line(&line); + } Err(Waited::Closed) => break, Err(Waited::Elapsed) => { - timed_out = true; - break; + // Whose deadline elapsed, asked of the clock rather than + // of which value went into the wake: a tick that fires in + // the same millisecond as the timeout must still kill the + // child, and a timeout that has not arrived must not. + if deadline.is_some_and(|deadline| Instant::now() >= deadline) { + timed_out = true; + break; + } + // From now rather than from the tick that just fired, so a + // slow watcher delays the next report instead of banking a + // backlog of them to deliver back to back. + next_tick = tick.map(|tick| Instant::now() + tick); + output.quiet(last_spoke.elapsed()); } } } @@ -667,6 +738,8 @@ impl Runner for ProcessRunner { deadline.map(|d| d.saturating_duration_since(Instant::now())), ) }; + // Reaped now, so the handler must not signal a possibly-recycled pgid. + drop(note); // The reader is joined only when the pipe closed of its own accord (the // loop broke on Closed, so the thread is already on its way out). On a // timeout it is abandoned: a descendant in a session of its own can hold @@ -803,6 +876,73 @@ enum OwnGroup { Yes, } +/// The interrupt handler's note about a foreground child's process group, +/// withdrawn when this is dropped. +/// +/// A guard and not a second call, because there are two methods that have to +/// remember to withdraw it and the moment they must do it in is the same: the +/// child has been reaped, so its pgid can be recycled, and a handler that +/// signalled it after that would be signalling somebody else. `false` is a child +/// in this process's own group, which is never noted at all. +struct ForegroundNote(bool); + +impl Drop for ForegroundNote { + fn drop(&mut self) { + if self.0 { + interrupt::clear_foreground_child(); + } + } +} + +/// Spawn a long-running foreground child in the process group the spec asks for. +/// +/// Whether the child leads a group of its own is the caller's decision, carried +/// on the spec (see [`SpawnSpec::own_group`]). One place for the dance rather +/// than one per method, because [`Runner::passthrough`] and [`Runner::session`] +/// both run a child that holds the terminal for minutes, and a second +/// hand-written copy of the parent-side `setpgid` is a copy that can be subtly +/// wrong in whichever method nobody was thinking about at the time. +/// +/// `devpod up` sets it: it is the one long-running foreground child, and the one +/// a Ctrl-C used to orphan — `dl`'s `_exit(130)` released the launch lock while +/// the build carried on holding it (concurrency review F3). Leading its own group +/// lets `dl`'s interrupt handler `killpg` the build before it exits, so the build +/// comes down with `dl` rather than outliving it, even when the interrupt arrived +/// as `kill -INT `. +/// +/// An interactive `ssh -t` must NOT: a child in a group of its own is no longer +/// the controlling terminal's foreground group, so its first read of the PTY +/// earns a SIGTTIN and the session hangs. It stays in this process's group, which +/// is also what the Python original did — as does `capture`'s child, for the same +/// reason. +fn start_foreground( + spec: &SpawnSpec, + stdout: Stdio, + stderr: Stdio, +) -> Result<(Child, ForegroundNote), NoChild> { + if !spec.own_group { + // The child stays in this process's group. Its "pgid" would be this + // process's own group, so it must NOT be noted for the interrupt handler + // — a `killpg` on it would fell `dl` and the whole foreground group. + return Ok(( + start(spec, stdout, stderr, OwnGroup::No)?, + ForegroundNote(false), + )); + } + let child = start(spec, stdout, stderr, OwnGroup::Yes)?; + // The child led its own group from its `pre_exec`, so its pgid is its pid; + // set it from the parent too to close the fork-to-exec window. + let pgid = child.id() as i32; + // SAFETY: `setpgid` on our own just-spawned child; EACCES (already exec'd) or + // ESRCH (already gone) are both fine — the child's own `pre_exec` establishes + // the group regardless. + unsafe { + libc::setpgid(pgid, pgid); + } + interrupt::note_foreground_child(pgid); + Ok((child, ForegroundNote(true))) +} + /// Spawn `spec`, or say why there is no child. fn start( spec: &SpawnSpec, diff --git a/rust/devlaunch-runner/src/tests.rs b/rust/devlaunch-runner/src/tests.rs index 4ef38788..0d09a625 100644 --- a/rust/devlaunch-runner/src/tests.rs +++ b/rust/devlaunch-runner/src/tests.rs @@ -525,6 +525,145 @@ fn a_session_hands_each_line_over_as_it_arrives() { assert_eq!(lines, ["one", "two"]); } +/// A watcher that records both halves of what a session tells it, in order. +/// +/// The order is the interesting part: a report of a silence that arrived after +/// the line ending it would be a report about a step that is already over. +#[derive(Default)] +struct Heard { + events: Vec, + interval: Option, +} + +impl SessionOutput for Heard { + fn line(&mut self, line: &str) { + self.events.push(format!("line {line}")); + } + + fn quiet_interval(&self) -> Option { + self.interval + } + + fn quiet(&mut self, _quiet: Duration) { + self.events.push("quiet".to_owned()); + } +} + +#[test] +fn a_watched_session_reports_the_silence_between_two_lines() { + // devlaunch#576's shape in miniature: two lines with a gap between them, and + // a caller that could not tell a live gap from a hung one because a line sink + // that is not being called says nothing at all. + let mut heard = Heard { + interval: Some(Duration::from_millis(60)), + ..Heard::default() + }; + + let outcome = ProcessRunner.watched_session( + &sh("echo one >&2; sleep 0.4; echo two >&2").into(), + &mut heard, + ); + + assert_eq!(exit_of(outcome), Exit::Code(0)); + assert_eq!(heard.events.first().map(String::as_str), Some("line one")); + assert_eq!(heard.events.last().map(String::as_str), Some("line two")); + // Bounded rather than counted exactly: the number of ticks in 0.4s is the + // scheduler's business. That there were some, and that they landed between + // the two lines rather than after both, is this test's. + let quiets = heard.events.iter().filter(|it| *it == "quiet").count(); + assert!(quiets >= 1, "no silence was reported: {:?}", heard.events); + assert_eq!( + heard.events.iter().position(|it| it == "line two"), + Some(heard.events.len() - 1), + "a silence was reported after the line that ended it: {:?}", + heard.events + ); +} + +#[test] +fn a_silence_is_measured_from_the_last_line_and_not_from_the_call() { + // What makes a tick worth printing: the number restarts at every line, so it + // is the age of *this step* and not the age of the launch. A gap of 0.3s + // after 0.6s of chatter must report about 0.3s. + let mut reported = Vec::new(); + let mut watcher = Reporting { + interval: Duration::from_millis(100), + quiets: &mut reported, + }; + + let outcome = ProcessRunner.watched_session( + &sh("for i in 1 2 3 4 5 6; do echo tick >&2; sleep 0.1; done; sleep 0.3").into(), + &mut watcher, + ); + + assert_eq!(exit_of(outcome), Exit::Code(0)); + let longest = reported.iter().copied().max().unwrap_or_default(); + assert!( + longest < Duration::from_secs(1), + "a silence was measured from the start of the call, not the last line: {reported:?}" + ); +} + +/// A watcher that keeps the durations it was told, for the measurement above. +struct Reporting<'a> { + interval: Duration, + quiets: &'a mut Vec, +} + +impl SessionOutput for Reporting<'_> { + fn line(&mut self, _line: &str) {} + + fn quiet_interval(&self) -> Option { + Some(self.interval) + } + + fn quiet(&mut self, quiet: Duration) { + self.quiets.push(quiet); + } +} + +#[test] +fn a_watcher_that_asks_for_no_interval_is_never_told_about_a_silence() { + // The default, and what every caller that only wants the lines keeps: the + // read blocks with no deadline of its own, so a session that runs for an hour + // wakes for its output and nothing else. + let mut heard = Heard::default(); + + let outcome = ProcessRunner.watched_session( + &sh("echo one >&2; sleep 0.3; echo two >&2").into(), + &mut heard, + ); + + assert_eq!(exit_of(outcome), Exit::Code(0)); + assert_eq!(heard.events, ["line one", "line two"]); +} + +#[test] +fn a_timeout_still_kills_a_child_that_is_being_watched_for_silence() { + // The two clocks against each other. The tick fires several times over + // before the deadline does, and each one must leave the child running -- and + // then the deadline must still kill it, rather than being reset by them. + let mut heard = Heard { + interval: Some(Duration::from_millis(40)), + ..Heard::default() + }; + let mut spec: SpawnSpec = sh("sleep 30").into(); + spec.timeout = Some(Duration::from_millis(300)); + let started = Instant::now(); + + let outcome = ProcessRunner.watched_session(&spec, &mut heard); + + assert_eq!(outcome, Outcome::TimedOut); + assert!( + started.elapsed() < Duration::from_secs(5), + "the ticks pushed the deadline back" + ); + assert!( + heard.events.iter().any(|it| it == "quiet"), + "the ticks fired while the deadline was pending" + ); +} + #[test] fn a_session_leaves_stdin_and_stdout_alone() { // devpod puts the real terminal into raw mode through them and asks for a diff --git a/rust/dl/src/render.rs b/rust/dl/src/render.rs index 2396721b..5ab653b7 100644 --- a/rust/dl/src/render.rs +++ b/rust/dl/src/render.rs @@ -1968,6 +1968,22 @@ pub(crate) fn report_refusals<'a>( lines } +/// A short wall-clock span, for a reader watching one go by. +/// +/// Minutes and seconds, because that is the range this is asked about: a launch +/// step that has been quiet for four seconds is not reported at all and one that +/// has been quiet for two hours has the same advice as one that has been quiet +/// for ten minutes. Zero-padded seconds past the minute so a column of these +/// lines reads as a clock going forwards rather than as numbers that get +/// shorter. +fn elapsed(span: std::time::Duration) -> String { + let seconds = span.as_secs(); + match seconds / 60 { + 0 => format!("{seconds}s"), + minutes => format!("{minutes}m{:02}s", seconds % 60), + } +} + fn refusal_reason(reason: &RefusalReason) -> String { match reason { RefusalReason::System(words) => words.clone(), @@ -2527,6 +2543,20 @@ pub(crate) fn launch_notice(notice: &LaunchNotice) -> Option { // debug: a lock that could not be taken costs this `up` its serialization // and nothing a user acts on. LaunchNotice::LaunchLockUnavailable { .. } => return None, + + // --- a build that has stopped saying anything (info; devlaunch#576) + // + // A whole line rather than one refreshed in place, and that is a decision + // rather than a shortcut. devpod owns the stream this is interleaved with: + // dl echoes devpod's lines but does not compose them, so a line rewritten + // with a carriage return could not be relied on to be the last thing + // written and would be overtyped by devpod's next. A whole line is also the + // only shape that survives stderr being a file, which is what it is in CI + // and in the log `aid`'s background boot replays from. + LaunchNotice::UpHasGoneQuiet { quiet } => format!( + "Still working: devpod has printed nothing for {}.", + elapsed(*quiet) + ), // info LaunchNotice::BroughtUpBySibling { workspace_id } => { format!("Workspace {workspace_id} was brought up by another dl run.") @@ -3258,6 +3288,8 @@ pub(crate) fn provision_event(event: &ProvisionEvent) -> Option { mod tests { use std::path::PathBuf; + use std::time::Duration; + use devlaunch_core::flows::kill::{HostProcess, Signalled}; use devlaunch_core::flows::launch::{HerdrTabRename, TerminalTitle}; use devlaunch_core::flows::listing::{SourceDescription, SourceKind}; @@ -4892,4 +4924,39 @@ mod tests { "Could not kill this workspace's containers: could not run docker (TimedOut)" ); } + + #[test] + fn a_build_that_has_gone_quiet_says_how_long_for() { + // The line devlaunch#576 is about, and the whole of what it claims: not + // that anything is wrong, only that the launch is alive and this is how + // long the step has been running. + assert_eq!( + launch_notice(&LaunchNotice::UpHasGoneQuiet { + quiet: Duration::from_secs(30) + }), + Some("Still working: devpod has printed nothing for 30s.".to_owned()) + ); + assert_eq!( + launch_notice(&LaunchNotice::UpHasGoneQuiet { + quiet: Duration::from_secs(301) + }), + Some("Still working: devpod has printed nothing for 5m01s.".to_owned()) + ); + } + + #[test] + fn a_span_reads_as_a_clock_going_forwards() { + // Zero-padded past the minute, because these arrive one under another and + // a column of them is read as a clock. `5m1s` beside `5m31s` reads as the + // number getting shorter. + assert_eq!(elapsed(Duration::from_secs(0)), "0s"); + assert_eq!(elapsed(Duration::from_secs(59)), "59s"); + assert_eq!(elapsed(Duration::from_secs(60)), "1m00s"); + assert_eq!(elapsed(Duration::from_secs(61)), "1m01s"); + assert_eq!(elapsed(Duration::from_secs(3600)), "60m00s"); + // Sub-second remainders are dropped rather than rounded up: the number is + // the age of a step, and a step reported as a second older than it is + // would be a report that ran ahead of the clock it is quoting. + assert_eq!(elapsed(Duration::from_millis(1900)), "1s"); + } }