[TaylorMutch]

Summary

Prevent reconciliation from failing a sandbox restart with the previous runtime's ContainerExited observation. Release Dev's Docker SSH identity test exposed this race when a sweep observed the stopped container after the gateway had already committed Starting.

Related Issue

Closes #4981

Changes

• Acquire the existing per-sandbox lifecycle gate without waiting before refreshing and applying a reconciliation observation. Busy sandboxes are deferred to a later sweep.
• Skip durably pending driver operations, including operations owned by another gateway replica.
• Add deterministic coverage for local and separate-replica observers, unrelated sandbox progress, successful start completion, and genuine later exits.
• Document reconciliation behavior in the server README.

Release Notes

Testing

• Checks appropriate to the affected code and behavior pass: server Clippy with warnings denied, Rust formatting, license headers, Markdown lint, and diff whitespace checks.
• Unit tests added/updated: regression fails before the fix; all 275 compute tests pass with the fix.
• E2E tests added/updated: existing Docker SSH host identity test passes against the fixed gateway and published runtime images from 2c31ac7e606c4e175288cee3656b23192a1a36b0, using a freshly built workload fixture. A temporary wrapper routes containers through host.docker.internal for Docker Desktop; repository test code is unchanged.

Checklist

• Follows Conventional Commits
• Commits are signed off (DCO)
• Architecture docs updated: server README

[github-actions]

Label test:e2e applied for 06561f9. Open the existing run and click Re-run all jobs to execute with the label set. The run will execute the standard E2E suite after building the required gateway, sandbox, and supervisor images once. The matching required CI gate status on this PR will flip green automatically once the run finishes.

[mpereira]

Hey @TaylorMutch,

I reproduced this on main at 9f1cdb4ef with the Docker driver, then ran the same steps with #4983 applied.

This comment just puts the two cases side by side: the race without #4983, and the fixed outcome with #4983.

The loop used to reproduce it is below. The full experiment definition is in sandbox-stop-start.yaml.

start 8 sandboxes, each running:
    once a second, 1500 times: append "<tick> <unix time>" to a journal
    (after a restart, resume from the saved tick)

wait until all 8 are running

repeat for 20 minutes:
    wait for the gateway's next reconcile.sandboxes span (the sweep ending)
    
    sleep 57.5 s
    
    for each of the 8 sandboxes, in parallel:
        sleep a random 0 to 4 s
        openshell sandbox stop
        openshell sandbox start

The 57.5 s delay aims each start at the next sweep. The gateway starts a reconcile.sandboxes sweep 60 s after the previous one ended and exports a span when it ends, so a start 57.5 s after the span, plus up to 4 s of jitter, lands within about 2 s either side of the next sweep. The race needs the sweep to fall between the start committing Starting and the driver starting the container, and the closer the two, the more often that happens.

Two runs of that loop made 248 sandbox starts, and 7 failed with ContainerExited, about 1 in 35. Every failed start has the sweep's old_phase=Starting new_phase=Error in the gateway log, and the sandbox then stays in Error for the rest of the run even though its containers come up. Two more runs with #4983 applied made 320 starts and hit it 0 times.

The loop is an experiment on the chaos harness I was playing with, and proposed in mpereira#1. The mechanism matches the issue's Investigation, and nothing below is a problem with #4983. What this comment adds is how often the race hits when the starts are aimed at the sweep, the timing of one hit, and the (correct) runs against #4983.

How to reproduce

The experiments are against local Docker only for now. A run takes about 26 minutes, or 41 when it hits the race, because a failed sandbox then waits out the experiment's 40-minute instance timeout. The first run also builds the gateway.

git clone -b feat/chaos-experiment-harness/mpereira https://github.com/mpereira/OpenShell
cd OpenShell
mise run e2e:chaos e2e/chaos/experiments/sandbox-stop-start.yaml

mise run e2e:chaos builds the gateway, runs the experiment and prints the run directory, which holds report.html, the gateway and sandbox logs, docker events and the journals. The experiment file lists this issue as an expected flaky failure, so a run that hits the race reads XFAIL and one that misses it reads PASS.

To run it against #4983, cherry-pick the PR on top first. The branch is main 9f1cdb4ef plus the harness, with nothing under crates/ changed, so it applies cleanly:

git fetch https://github.com/NVIDIA/OpenShell pull/4983/head && git cherry-pick FETCH_HEAD

Result

gateway	starts	failed with ContainerExited
openshell @ 9f1cdb4ef, run b144	114	5
openshell @ 9f1cdb4ef, run db22	134	2
openshell @ 9f1cdb4ef + #4983, run c592	160	0
openshell @ 9f1cdb4ef + #4983, run a6f6	160	0

Two notes on the table. The #4983 rows use the PR's head 06561f990 cherry-picked onto 9f1cdb4ef. Main has fewer than 160 starts per run because a round skips a sandbox that is already in Error.

In the gateway log, each failed start leaves two lines at the moment of the hit: old_phase=Starting new_phase=Error and the Sandbox failed to become ready warning beside it. Nothing else.

The gateway's Prometheus metrics, captured by the chaos tool every 2 s, show nothing wrong. openshell_server_grpc_requests_total counts all 7 failed StartSandbox calls as code 0. openshell_server_supervisor_sessions, the number of supervisors connected to the gateway, is back at 8 within 3 s of each hit: the new supervisor connects fine while its sandbox's record sits in Error.

There is one later trace. When the counter in a failed sandbox finishes its 1500 ticks, 20 minutes on, the gateway drops the new supervisor's exit report as stale, because the record still names the old instance. So the sandbox never reaches Completed either. That warning appears once per hit in the main runs and never in the #4983 runs.

The 1 in 35 rate comes from aiming the starts at the sweep. Without that aim, an earlier version of the loop (the same stop and start per sandbox, but no wait for the sweep) hit the race once in about 1,300 starts, on main 2ff59bf33 of 2026-10-26. The #4983 runs were timed the same way, with the sweep landing 2.3 to 2.9 s into each round, as on main. At 1 in 35, their 320 starts should have hit it about nine times.

One hit in detail, from run db22 on main (the second row above): sandbox cdb22-2133161399, counter-4 to the harness, in round 4. Times are seconds from that run's start on the harness clock; the round began at 294.27; the sweep's span ran from 296.61 to 296.66, and the harness received it at 296.77.

event in run db22	seconds from run start
Supervisor container gets SIGTERM (sandbox stop)	296.44
Sandbox container exits with code 1; StopSandbox completes	296.55
StartSandbox commits Starting (no log line; bracketed by its neighbours)	296.55 to 296.59
Gateway calls the Docker driver, which inspects the container and stages the bundle before asking Docker to start it	296.59
Sweep begins; its GetSandbox still sees the exited container	296.61
Sweep: Starting -> Error, reason ContainerExited	296.66
Docker driver starts the retained sandbox container (same container id)	296.72
New supervisor container started	296.87
Replacement supervisor session accepted, auth_epoch=5	297.10
Start settlement write hits a resource version conflict from a concurrent write; retried a second later	297.19
StartSandbox RPC completes; openshell sandbox start reports ContainerExited: Container exited while waiting for Ready	298.19
Round 20 skips the sandbox because it is still Error (16 min later)	1258.69
Counter finishes its 1500 ticks; the gateway ignores the new supervisor's exit report as stale (active_instance_id is the old one)	1515.63
Harness gives up on it at its instance timeout, never having read it as Running again	2402.05

The journal in that sandbox has all 1500 lines and the script exited 0, so the workload itself restarted fine.

Timeline on main: run db22, openshell @ 9f1cdb4ef

The two affected sandboxes of run db22. Green is Running; amber Pending is the harness's state while a sandbox restarts; red Unknown is a status it cannot read as a known state, here Error (and, at 03:58, a stop caught mid-way). The two red bars that run to the end are the hits.

%%{init: {"themeVariables": {"taskBkgColor": "#64748b", "taskBorderColor": "#334155", "activeTaskBkgColor": "#34d399", "activeTaskBorderColor": "#047857", "doneTaskBkgColor": "#fbbf24", "doneTaskBorderColor": "#b45309", "critBkgColor": "#dc2626", "critBorderColor": "#7f1d1d", "taskTextColor": "#ffffff", "taskTextDarkColor": "#111827", "taskTextOutsideColor": "#111827", "sectionBkgColor": "#94a3b8", "sectionBkgColor2": "#94a3b8", "altSectionBkgColor": "#ffffff"}}}%%
gantt
  title sandbox-stop-start · 20261029T123535Z-db22 · XFAIL
  dateFormat mm:ss
  axisFormat %M:%S
  todayMarker off
  section flow
    counter :00:01, 40:03
    wait counter started :00:01, 00:04
    restart ×20 :01:54, 21:01
  section counter-4
    Created :milestone, 00:03, 00:03
    Running :active, 00:04, 02:58
    Pending :done, 02:58, 03:00
    Running :active, 03:00, 03:58
    Unknown :crit, 03:58, 04:00
    Running :active, 04:00, 04:58
    Unknown :crit, 04:58, 40:03
  section counter-6
    Created :milestone, 00:03, 00:03
    Running :active, 00:04, 01:56
    Pending :done, 01:56, 01:58
    Running :active, 01:58, 02:56
    Pending :done, 02:56, 02:58
    Running :active, 02:58, 03:58
    Pending :done, 03:58, 04:00
    Running :active, 04:00, 04:58
    Pending :done, 04:58, 05:00
    Running :active, 05:00, 07:56
    Pending :done, 07:56, 07:58
    Running :active, 07:58, 09:58
    Pending :done, 09:58, 10:00
    Running :active, 10:00, 10:58
    Unknown :crit, 10:58, 40:03

Loading

Timeline with the fix: run a6f6, openshell @ 9f1cdb4ef + #4983

Two of the eight sandboxes from run a6f6 (the other six look the same): every restart comes back to Running, the short red marks are 2-second reads of a stop in progress, and both reach Succeeded at 25 min, where db22 ran to 40 min waiting on its two stuck sandboxes.

%%{init: {"themeVariables": {"taskBkgColor": "#64748b", "taskBorderColor": "#334155", "activeTaskBkgColor": "#34d399", "activeTaskBorderColor": "#047857", "doneTaskBkgColor": "#fbbf24", "doneTaskBorderColor": "#b45309", "critBkgColor": "#dc2626", "critBorderColor": "#7f1d1d", "taskTextColor": "#ffffff", "taskTextDarkColor": "#111827", "taskTextOutsideColor": "#111827", "sectionBkgColor": "#94a3b8", "sectionBkgColor2": "#94a3b8", "altSectionBkgColor": "#ffffff"}}}%%
gantt
  title sandbox-stop-start · 20261029T225454Z-a6f6 · PASS
  dateFormat mm:ss
  axisFormat %M:%S
  todayMarker off
  section flow
    counter :00:01, 25:27
    wait counter started :00:01, 00:04
    restart ×20 :01:54, 20:59
  section counter-2
    Created :milestone, 00:04, 00:04
    Running :active, 00:04, 02:59
    Pending :done, 02:59, 03:01
    Running :active, 03:01, 03:59
    Pending :done, 03:59, 04:01
    Running :active, 04:01, 06:57
    Unknown :crit, 06:57, 06:59
    Running :active, 06:59, 09:57
    Pending :done, 09:57, 09:59
    Running :active, 09:59, 10:59
    Pending :done, 10:59, 11:01
    Running :active, 11:01, 14:59
    Unknown :crit, 14:59, 15:02
    Running :active, 15:02, 20:57
    Pending :done, 20:57, 20:59
    Running :active, 20:59, 25:23
    Succeeded :milestone, active, 25:23, 25:23
  section counter-3
    Created :milestone, 00:04, 00:04
    Running :active, 00:04, 01:56
    Pending :done, 01:56, 01:59
    Running :active, 01:59, 03:59
    Pending :done, 03:59, 04:01
    Running :active, 04:01, 15:57
    Pending :done, 15:57, 15:59
    Running :active, 15:59, 17:59
    Unknown :crit, 17:59, 18:01
    Running :active, 18:01, 19:57
    Unknown :crit, 19:57, 19:59
    Running :active, 19:59, 25:27
    Succeeded :milestone, active, 25:27, 25:27

Loading

Gateway log for the db22 start, spans abbreviated:

2026-10-29T12:40:32.164922Z  INFO request{StopSandbox}: openshell_server::grpc::sandbox: StopSandbox request completed successfully sandbox_name=cdb22-2133161399
2026-10-29T12:40:32.274840Z  INFO reconcile{otel.name="reconcile.sandboxes" driver.name=docker backend_count=8}: openshell_server::compute: Sandbox phase changed sandbox_id=fa1e623d-aaa3-4167-8ce4-234328ff13d3 sandbox_name=cdb22-2133161399 old_phase=Starting new_phase=Error
2026-10-29T12:40:32.274891Z  WARN reconcile{otel.name="reconcile.sandboxes" driver.name=docker backend_count=8}: openshell_server::compute: Sandbox failed to become ready sandbox_id=fa1e623d-aaa3-4167-8ce4-234328ff13d3 sandbox_name=cdb22-2133161399 reason=ContainerExited Container exited
2026-10-29T12:40:32.327353Z  INFO request{StartSandbox}:docker.start_sandbox{sandbox.name=cdb22-2133161399}: openshell_driver_docker: Selected Docker supervisor networking sandbox_id=fa1e623d-aaa3-4167-8ce4-234328ff13d3 network_mode=Host endpoint=https://127.0.0.1:51808
2026-10-29T12:40:32.706944Z  INFO openshell_server::supervisor_session: supervisor session: accepted sandbox_id=fa1e623d-aaa3-4167-8ce4-234328ff13d3 session_id=5a8361be-2d8f-4c7b-a55a-2a37dfd06c30 instance_id=d3683524-9a19-4370-b94f-f4ce1152e408 connection_epoch=1 auth_epoch=5 replica_id=8d544ff7-f0e0-4b72-8b0b-f263d64827a1 config_push=false
2026-10-29T12:40:32.797247Z  WARN request{StartSandbox}: openshell_server::compute::provisioning_operation: Retaining driver response until operation ownership can be persisted sandbox_id="fa1e623d-aaa3-4167-8ce4-234328ff13d3" error=code: 'Internal error', message: "resource version conflict: expected version does not match current"
2026-10-29T12:40:33.800100Z  INFO request{StartSandbox}: openshell_server::grpc::sandbox: StartSandbox request completed successfully sandbox_name=cdb22-2133161399

The sandbox container's own log around the stop:

2026-10-29T12:40:32.134Z Error:   × sandbox boundary received SIGTERM before supervisor confirmation
2026-10-29T12:40:32.328Z INFO openshell_sandbox::boundary_server::linux: Boundary control dialer ready
2026-10-29T12:40:32.699Z OCSF PROC:LAUNCH [INFO] sh(66)

Selected docker events for the same sandbox (time, action, openshell.ai/isolation-role label, container id, attributes):

12:40:32.109 destroy  supervisor 438914b56e7a
12:40:32.127 kill     sandbox    762d915ff88e signal=15
12:40:32.164 die      sandbox    762d915ff88e exitCode=1
12:40:32.327 start    sandbox    762d915ff88e
12:40:32.479 start    supervisor ab115daae1db
12:40:32.748 health_status: healthy supervisor ab115daae1db

Mechanism

This matches the Investigation section of the issue. The links below point at the code on main at 9f1cdb4ef, the commit the runs used:

1. sandbox stop removes the supervisor container but only stops the sandbox container (the same container id starts again at 296.72). The Docker driver reports an exited container as ContainerExited (lib.rs#L6641).
2. sandbox start takes the lifecycle gate (mod.rs#L2280), commits Starting durably (mod.rs#L2395-L2400) and only then calls the driver (mod.rs#L2517). The Docker driver inspects the container, stages the sandbox bundle and fetches credentials before it asks Docker to start the container (lib.rs#L2657), about 120 ms here; until then Docker still holds the exited container.
3. The sweep hands each backend container to reconcile_snapshot_sandbox (mod.rs#L6379), which takes only the local mutation lock, not the lifecycle gate (the driver-watch path does, mod.rs#L5430). Its updated_at_ms guard passes because Starting was committed before the sweep began. It then re-inspects the driver (mod.rs#L6400-L6405), which still returns the exited container because the driver has not yet asked Docker to start it, and applies that observation (mod.rs#L6417-L6423).
4. The phase merge keeps Error over Starting (mod.rs#L7487-L7490) and logs the two lines above (mod.rs#L7512-L7539). ContainerExited is not in the transient list (mod.rs#L8092), so the failure counts as terminal.
5. The start's settlement write (provisioning_operation.rs#L272-L308) only clears the pending flag and never touches the phase, so once the sweep has written Error the start cannot undo it. The logged conflict is a concurrent write (supervisor registration or the Docker watch), not the sweep; the settlement retries, the RPC completes a second later and the CLI's readiness wait reports the stored Error.

#4983 makes the sweep skip a sandbox whose lifecycle gate is held or whose driver operation is durably pending, which closes step 3; the c592 and a6f6 rows measure it. #4932 reports the same race on v0.0.116 with a deterministic unit-test reproduction and a candidate patch that holds the gate across both sweep paths, and notes that later Ready snapshots do not recover the row because Error is terminal. Its follow-up comment of 2026-10-26 reproduces the race on current main and proposes the same driver_operation_pending skip that #4983 adds, while pointing out that Starting is written before the pending marker is claimed, so a sweep in that pre-claim window gets past the skip. All 7 hits here came after the driver was called, so after the claim; this experiment says nothing about the pre-claim window. #4983 does not reference #4932.

Not checked

• Whether fix(server): defer reconciliation during sandbox lifecycle operations #4983's skip actually fired in the two runs against it. The PR adds no log line, so the gateway log only shows that no start failed.
• Whether anything short of a manual stop and start clears the stored Error. The harness still saw it at round 20, 16 minutes after the hit.
• The Kubernetes and Podman drivers.

Three questions for you and the other maintainers:

1. fix(server): defer reconciliation during sandbox lifecycle operations #4983 guards the sweep. Do two other places want a guard as well, or is the sweep the only path that can do this? The phase merge, which lets an observation of the pre-start container move Starting to Error; and the Docker driver, whose watch path already drops an exit snapshot while a start is in progress (lib.rs#L2903-L2912) but whose GetSandbox path, the one the sweep calls, does not (lib.rs#L1494-L1513).
2. Once a sandbox is in Error, the replacement supervisor registers (auth_epoch=5) and the container is healthy, but the record never recovers. Should the start's settlement or that registration move it back to Ready, or is a manual stop and start the expected recovery?
3. fix(server): defer reconciliation during sandbox lifecycle operations #4983 ships a unit test, and the e2e that met the race in Release Dev (ssh_host_identity_survives_restarts_and_changes_after_recreation) was rerun by hand against it. That e2e meets the race by chance; this loop meets it about once in 35 starts. Would a run of it against each driver be useful as a regression check, and if so, is the harness PR the right place for that conversation?

[shiju-nv]

@TaylorMutch, I have a follow-up for #4932 at #5237, currently based on #5204. It overlaps #4983’s reconciliation guard and adds atomic start ownership and retry handling.

I propose landing #4983 first, then reducing my PR to the remaining changes. Would you prefer that sequence or folding those additions into #4983?