diff --git a/CHANGELOG.md b/CHANGELOG.md index 6426fb52..d2f1849e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -153,6 +153,59 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 passing its own token further down, and `DEVLAUNCH_NO_CLAUDE_TOKEN` still beats everything. +- **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 2093ad53..aefaed7c 100644 --- a/rust/devlaunch-core/public-api.api.txt +++ b/rust/devlaunch-core/public-api.api.txt @@ -80,6 +80,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 @@ -563,6 +565,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 ec9a315f..62992fc2 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); @@ -419,6 +429,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. @@ -1540,7 +1559,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 4a8cf24a..ce795d9d 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.") @@ -3296,6 +3326,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}; @@ -5008,4 +5040,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"); + } }