Skip to content

A launch blocked on devpod's workspace lock waits forever and says nothing, though rm says exactly the right thing #600

Description

@blooop

Handover ticket: everything below is diagnosed, nothing is built. Cited line numbers are against e34d420 (main at the time of writing).

What happened

Reported on 0.39.0. Three launches in a row, the first two interrupted:

$ dl kinisi-robotics/kinisi_ros@nb2
Fetching nb2 for kinisi-robotics/kinisi_ros
Fetching main for kinisi-robotics/kinisi_ros
^C
$ dl kinisi-robotics/kinisi_ros@nb2
Fetching nb2 for kinisi-robotics/kinisi_ros
Fetching main for kinisi-robotics/kinisi_ros
Created local branch nb2
Creating workspace clone at /home/kinisi-ci/.cache/devlaunch/repos/kinisi-robotics/kinisi_ros/kinisi-ros-nb2-jf78
Fetching git-lfs objects into the cache
Fetching reference refs/heads/nb2
dotfiles: https://github.com/blooop/dotfiles (devpod context options), passed to devpod up; devpod installs them when it creates the container.
22:01:17 info creating devcontainer up.go:581
^C
$ aid kinisi-robotics/kinisi_ros@nb2
...
dotfiles: https://github.com/blooop/dotfiles (devpod context options), passed to devpod up; devpod installs them when it creates the container.
22:01:29 info Trying to lock workspace, seems like another process is running that blocks this workspace machine_client.go:311
22:01:34 info Trying to lock workspace, seems like another process is running that blocks this workspace machine_client.go:311

The third launch sits there. Every line on the terminal after the dotfiles: one is devpod's, with a Go source location on it; dl contributes nothing at all, including nothing about the way out.

Reading the trace

Run 3 prints no Fetching and no Creating workspace clone, so it resolved warm: devpod status answered, because run 2's devpod up had already registered the workspace before it was interrupted. It then got as far as building the devpod up argv (that is where the dotfiles: line comes from, flows/launch.rs:663) and blocked in devpod's initLock.

devpod's acquire is blocking with no deadline. It logs every five seconds and waits for as long as the holder lives. So this is not slow, it is stuck: the same wedge as #484, which is closed by dl <ws> kill and which clears it here too.

This is not the window #598 closed. That change covers a launch killed between a completed devpod up and the end of dl's setup pass. Run 2 never got that far, so no in-flight record was ever opened. Worth stating because the two failures share a symptom and the fix for one does nothing for the other.

Three separate gaps

1. The launch does not watch devpod up's stderr, so it cannot see the block

This is the one to build, and dl already solves it one verb over.

devpod::says_it_is_blocked (clients/devpod.rs:258) matches the stable half of devpod's line. It has exactly one caller: flows/lifecycle/delete.rs:261, reached through devpod::run_watching_stderr at delete.rs:257. dl <ws> rm therefore prints render::delete_blocked (dl/src/render.rs:535):

dl: devpod is waiting for another process to let go of <ws>, and it will wait for as long as that takes. In another terminal, dl <ws> kill clears whatever is holding it and deletes it. (This rm is still waiting.)

docs/cleanup.md:241 publishes that behaviour: "An rm that devpod cannot get the workspace's lock for now says so while it waits, and names the kill that clears it."

A launch spawns its up through devpod::run — a plain passthrough, flows/launch.rs:1642, inside up_under_stage (flows/launch.rs:1544, called from workspace_up at :1519). Nothing reads that stream, so dl cannot notice and cannot advise. Every launch verb is affected: attach, up, restart, recreate, reset, code, dotfiles.

2. ContainerState::Busy is dead data

Declared at clients/devpod.rs:484, parsed at :496, rendered at :508, and read by nothing. The only consumer of the enum is is_running() (:516), so "another process is holding this workspace right now" and "it is stopped" reach the launch as the same answer, and it walks into an up that can only block.

Whether run 3's devpod status actually returned Busy is not recoverable from the trace. If it did, dl had the answer one round trip before it hung and threw it away.

3. Why the orphan exists at all

Out of scope here, and already stated as open in flows/kill.rs's header:

Why the orphan exists at all. Something killed a dl and left its child running, which is either a path outside #304's SIGTERM drain or a signal that drain cannot catch. That is a different question with a different fix, and a verb that treats the symptom does not stop being worth having while it is open.

An untested hypothesis, offered only so nobody re-derives it: devpod up leads a process group of its own (flows/launch.rs:1642, and runner's passthrough explains why an interactive ssh -t must not), so a terminal Ctrl-C never reaches it and only dl's killpg(..., SIGTERM) does. #484's evidence was devpod up ... PPID 1, sleeping, no children, which is the shape of a Go program that traps SIGTERM and then blocks in shutdown, not one that dies on it. Confirming that needs a real reproduction and the process still on a host; do not fold it into this ticket.

What to build

Thread the mechanism delete already has into the launch's up:

  • up_under_stage calls devpod::run_watching_stderr instead of devpod::run, keeping leading_its_own_group(). The docstring on run_watching_stderr already argues that a caller stays a passthrough from the outside, so nothing about the build's output changes.
  • A new LaunchNotice arm, said once, on the first matching line. LaunchNotice::CreateNeverFinished (flows/launch.rs:561, rendered dl/src/render.rs:2807) is the nearest model for the plumbing.
  • Wording modelled on delete_blocked, and it has to keep that line's two judgements: it names another terminal, because this one is busy holding the command the advice is about, and it says the wait has no deadline. It should also say kill deletes the workspace, which for one that never finished creating is what the user wants but is still worth saying out loud.
  • Say it once per launch, not every five seconds. devpod is already repeating itself.

Optional second half, cheaper and independent: act on ContainerState::Busy before the up is even attempted, so a launch that already knows says so a round trip earlier. Reasonable to split into its own PR.

Not in scope

  • Do not unlink devpod's flock. flows/kill.rs's header and domain::locks both argue this at length: a process holding the old inode excludes nobody while new arrivals lock a fresh file. The kernel drops it when the holder dies, which is why kill kills the holder. The busy marker under agent/contexts/... is the one that goes stale and the one kill sweeps.
  • Gap 3 above.
  • Any change to what dl <ws> kill does. It works; it is only undiscoverable from a wedged launch.

Seams and tests

  • Unit, at the flows::launch seam: a fake runner whose up writes devpod's line to stderr, asserting the notice is said exactly once and the launch still ends the way the up ended. flows/lifecycle/delete.rs's own tests are the model.
  • Binary level: dl/tests/lock_wait.rs is the existing shape for "a blocked command says it is waiting", though it holds dl's own repo lock rather than devpod's. A devpod shim that emits the line and then blocks is the cheaper route here, in the shape dl/tests/interrupt.rs and dl/tests/resumed_setup.rs use.
  • Red before green: the notice must be proven absent on today's code first, or the test is pinning nothing.

Reproducing it

dl <owner>/<repo>@<branch>       # Ctrl-C while `creating devcontainer` is on screen
dl <owner>/<repo>@<branch>       # blocks, silently

If the orphan does not appear, ps -ef | grep '[d]evpod up' after the first Ctrl-C says whether one survived. Holding the flock by hand from a sibling process is the deterministic substitute and is what a test should do.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions