feat: a cold launch says it is alive while devpod has stopped saying anything - #579
feat: a cold launch says it is alive while devpod has stopped saying anything#579blooop wants to merge 2 commits into
Conversation
…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
![sourcery-ai[bot]](https://avatars.githubusercontent.com/in/48477?s=60&v=4){kind=small}
Reviewer's GuideThis PR makes Sequence diagram for reporting silent devpod up stepssequenceDiagram
participant DL as dl
participant Runner
participant Devpod
participant Notice as LaunchNotice
DL->>Runner: watched_session(spec, SessionOutput)
Runner->>Devpod: start devpod up with stderr pipe
Devpod-->>Runner: line
Runner->>DL: SessionOutput.line(line)
Note over Runner: Reset silence measurement
loop Every 30 seconds while silent
Runner->>DL: SessionOutput.quiet(quiet)
DL->>Notice: UpHasGoneQuiet { quiet }
end
Devpod-->>Runner: next line
Runner->>DL: SessionOutput.line(line)
Note over Runner: Reset silence measurement
File-Level Changes
Assessment against linked issues
Tips and commandsInteracting with Sourcery
Customizing Your ExperienceAccess your dashboard to:
Getting Help
|
…progress # Conflicts: # CHANGELOG.md
Codecov Report❌ Patch coverage is Additional details and impacted files
Flags with carried forward coverage won't be shown. Click here to find out more.
🚀 New features to boost your workflow:
|
The watched stream is the wrong one
Measured against the devpod this repo pins, devpod's stream logger routes What that does to the notice
with devpod's own lines scrolling past directly above them. The number is the age That is the PR's central claim inverted -- "the measurement restarts at every Why the tests are greenAll four new runner tests drive Also worth a look, separatelyThe cost paragraph buys nothing as written: "devpod's stderr becomes a pipe, so it And the precedent this leans on may never have fired either. The shape of the fixWatch stdout, or both. Small in lines, but it changes what stdout means for |
1 participant
Closes #576.
The line
The ticket's measurement was 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 measurement restarts at every line devpod writes. That is the part that answers the ticket's title rather than only its first half: the number is the age of the step devpod is on, 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
dlcan diagnose. What it can do is stop them looking identical.A launch that is talking never produces one, because devpod's own steps are seconds apart. A warm launch never sees one at all, and most of a cold one does not either.
Attribution, as the ticket asks: the five minutes are the repository's own
postCreateCommand.dlcannot makenpm cifaster and does not try.The two decisions the ticket left open
Whole lines, not a line refreshed in place. The ticket suggested
postCreate · npm ci · 2m10srefreshed in place, and I did not build that.dlechoes devpod's output but does not compose it, so a line rewritten with\rcould not be relied on to still 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 logaid's background boot replays from. Since the tick only fires while devpod is silent, consecutive ticks are adjacent lines and the step they are about is directly above them.No phase name in the text, for the same reason: the last devpod line is the line above it. Naming it again would be quoting the screen back at itself.
How
Only something sitting on the read can time a silence: a line sink that is not being called says nothing. So
devpod upruns as a watched session rather than a plain passthrough, andRunnergrows 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
sessionalone and simply never ticks, andProcessRunnerexpressessessionin terms of the new one, so there is one loop andsessionis the narrower view of it. The snapshot diff is purely additive, with no signature changed and nothing removed.What it costs, stated where it is paid
devpod up's stderr is a pipe now and no longer a terminal to devpod, so it loses whatever devpod does with one. stdin and stdout are untouched, so the terminal devpod puts into raw mode is exactly as it was.devpod sshanddevpod deletealready ran this way, so this is the established trade rather than a new one.The part that mattered: the interrupt contract
sessionhardcodedOwnGroup::No, anddevpod upis spawned leading a group of its own on purpose (concurrency review F3): a Ctrl-C has tokillpgthe build so it comes down withdlinstead of outliving it holding the launch lock. Movingupontosessionnaively would have dropped that silently.So the parent-side
setpgidand the note the interrupt handler reads are no longer one method's private business:start_foregroundis a helper both foreground methods take, andForegroundNotewithdraws the note when the child is reaped. One copy of the dance rather than a second that could be subtly wrong in whichever method nobody was thinking about.rust/dl/tests/interrupt.rsis the suite for that contract and it is unchanged and green against a rebuilt release binary (it spawnstarget/release/dl, so a stale build would have proved nothing):Verification
1m00s/5m01sformatting.launch_scenario.pyworld with a devpod whoseupprints, sleeps and prints again. One tick landed in a 40s gap, devpod's own lines passed through verbatim and in order around it.cargo test --workspace: 32 suites green.cargo clippy --locked --all-targets -- -D warningsandcargo fmt --check: clean.pytest test: 700 passed, 6 skipped.public-api.api.txtgains the one notice variant.Two things in the ticket I did not build, and one correction
The
--remote-controlhalf. A blockingAskUserQuestionrendering somewhere other than the terminalaidwas invoked in is a different mechanism with a different fix, and a line aboutdevpod upcannot say "waiting for you, elsewhere" about something that is notdevpod up.A correction to the reported-rather-than-measured half. The ticket relays that in
aid's interactive flow the terminal shows nothing after the prompt is accepted, flagged as inferred from the binary's strings. Reading the code, that is not so:interactive::BootChild::finishrelays the boot log to stderr as it lands, byte for byte, andaid'smaincalls it beforedlruns. What is genuinely silent is the editor window itself, which is the user's own typing time and is silent by design. The ticks land in that log and are relayed with the rest, soaidgets this for free.Summary by Sourcery
Make quiet
devpod upsteps visibly report ongoing progress without changing their output or interrupt behavior.New Features:
devpod uphas stopped producing output, including the elapsed silence since its last line.Bug Fixes:
devpod upprocesses in their own process group so interrupts and termination continue to cleanly stop the entire build.Enhancements:
Documentation:
Tests:
Chores: