carlos / platform Public

An awake exec instance is not restarted when a release is adopted: it serves the old build for 110-200s Issue open

Claimed by claude~paul@keymail.dev 2 weeks ago

Reported by Tony Wood (bdn/woodfamilytrust on the flagship): "regular issues with deployment and it not bringing the new instance up. having to restart the instance several times".

Measured from carlos logs, 3 to 5 Oct 2026:

  • 20 releases took 110 to 200s from ship to the new build serving. 17 took longer than carlos deploy's 120s watch.
  • 33 manual carlos restart calls in the same three days.
  • No deploy shows an "instance restarting" line. Every stop lands on an activator sweep tick.

Cause (from the code and the log shape; no box journal read):

  1. The agent's pass sees the promote within seconds but cannot write /opt/carlos, so staging is blocked and it relays to root (carlos adopt --stage-only, carlos-stage.path).
  2. The root pass stages, repoints live/<host> and stamps the version. Its restart callback is rootRestartRoute (bounce nil, internal/host/agent.go), and a hibernate-flagged route gets no restart callback at all there. It cycles no exec child, by design: the children belong to the agent.
  3. The agent's next look finds cur == ver in adoptHost and returns. An already-staged edge route is not in the fast sweep either. So the adopt-time bounce added on 2026-08-08 (4fb01ce2, e676e72d) never runs for a version that needed staging, which is every new release on a real box.
  4. The only thing left is the activator sweep's build convergence: a 30s tick plus ConvergeGrace of 90s.

Two things make it worse:

  • carlos restart issued before the root pass finishes relaunches the old build. The child then starts a fresh 90s grace when the symlink moves.
  • The stage relay is throttled to one request a minute and a throttled request is dropped, not deferred. A second release inside a minute waits for the next serial bump or the hourly pass.

Fix on branch fix-adopted-exec-restart: the agent finishes the restart half of an adoption it delegated. On its 2s tick it compares each awake exec child's spawn version with live/<host>; where they differ and the route's stamped version agrees with the symlink, it cycles the child at once. The 90s grace stays as the backstop for drift nothing stamped. A dropped stage request is retried when the throttle window ends.

Not in this fix: Paul's ruling of 2026-10-05, that a shipped release reaches running instances immediately unless configured not to and swaps in with zero downtime. The swap today is stop-then-wake (new requests held, in-flight drained). The handover, the opt-out and the pacing asked for in #230 need a spec.

Confirmed in the flagship box journal (i-092c0c1eea75723cb, 2026-10-05, lic.bdn.oncarlos.com, five deploys):

| agent asks for a root pass | root pass repoints | activator cycles the child | ask to cycle | |---|---|---|---| | 17:03:26 | 17:03:34 | 17:05:21 | 115s | | 17:16:10 | 17:16:18 | 17:18:21 | 131s | | 17:32:37 | 17:32:44 | 17:34:21 | 104s | | 18:32:39 | 18:32:47 | 18:34:51 | 132s | | 18:36:36 | 18:36:44 | 18:38:21 | 105s |

The root pass's own line is repointed f6b60bd -> 8b59789 (edge; hibernating — runs it on next wake), and the cycle is the sweep's serving … but live symlink is now … — cycling onto the new build. Adoption takes about 8 seconds. The other 95 to 125 seconds are the sweep's first sighting plus ConvergeGrace.

One correction to the opening post. I listed the stage relay's one-a-minute throttle as making this worse. The code does drop a throttled request, but the journal shows no case of it: seven blocked stages, seven requests, seven root passes. It is a latent risk, not part of this bug, and the branch does not change it.

Fix pushed on fix-adopted-exec-restart (11047d35, d40e40aa): activator Drifted / ConvergeAdopted and a converge leg on the agent's 2s tick. TestRootAdoptionOfAWarmExecInstanceIsFinishedByTheAgent runs the real pass on both sides and fails with the leg disabled. With it, ask to cycle should be about 10 seconds.

Branch fix-adopted-exec-restart is ready for Paul to merge (tip 0d3f9f9c). The full local gate (make test) passes on that tip.

Two rounds of Astra review:

  • Round 1, accept with fixes, all applied. - The leg cycled every drifted instance of an app on one tick. It now cycles one per 2s tick, in host order. - A slower adopt pass could bounce an instance that had already been cycled and re-woken on the new build. Adopt passes now use BounceAdopted, which leaves a child alone when it already runs the build live/<host> names. carlos restart keeps the unconditional bounce. - A second regression test runs the real release pass, a real activator and the leg as fastConvergeLoop builds it.
  • Round 2, no defects, two test gaps. One closed (the adopt dispatch is pinned to the version-aware bounce). One declined: a test for the single assignment of the leg in fastConvergeLoop, which is thin and untested by that file's own convention.

A trap for anyone extending these tests: activator.Service.Owns stays true while an entry drains, so it cannot tell a spared instance from one being stopped. The tests count the backend's spawns after a request.

Left alone on purpose:

  • The stage relay's dropped-when-throttled request (latent, not seen in the journal).
  • Bounce logging "(carlos restart)" for an adoption on the direct path. Changing it is member-facing copy.
  • Workers, which stay with the sweep's grace.

Nothing here takes effect until the flagship boxes run it.

Rolled in v0.23.0 (2026-10-05 21:05 UTC), all four flagship boxes current. Measured with a throwaway app, bab/adopt-probe, whose /healthz names its own build. Two deploys to an awake instance on the IE box took 58s and 105s end to end, down from 110–200s but well short of seconds. The journal shows where the time went:

| | p2 | p3 | |---|---|---| | promote | ~21:12:44 | ~21:14:55 | | agent notices, asks root | 21:12:42* | 21:15:38 | | root repoints and stamps | 21:12:50 | 21:15:46 | | converge leg cycles | 21:13:39 | 21:16:34 |

\* that ask was for lic's concurrent deploy; probe1 rode the same root pass.

Two gaps, both the agent's fast tick:

  1. Stamp to cycle, ~48s. The converge leg rode the fast tick, and a tick runs 25–50s whenever the serial moves. Console activity across all tenants moves it about once a minute. Fixed on fix-converge-own-loop: the leg has its own 2s loop. Astra round 1 found a real P1 in that: a release and a config change arriving together could cycle onto the old config. Bounce now holds a bounce that lands during an instance's wake and spends it when the wake finishes, which also closes the older race between any wake and a config write. Round 2: accept with fixes, applied.
  2. Promote to notice, 16–43s. Instance reconcile, sidecar reconcile and ListAllRecords (moves, steering) each list every object under apps/: 59,288 keys on the flagship, 50,695 of them log chunks, for 152 instance records. Fixed on fix-reconcile-listing: they walk app directories with ListDirs and list only instances/ or sidecars/. Under review. The domains reconcile still lists all of apps/; it reads several kinds of key from that one listing and needs its own change.

The fast tick now logs any serial pass over 5s, broken down by stage, so the next measurement comes from the box itself.

Hotfix 82c5e17b rolled to all four flagship boxes (22:33–22:5x UTC): v0.23.0 plus fix-converge-own-loop and fix-reconcile-listing, both merged on main. It was rolled as a local build via carlos system update --file, branch hotfix-v0.23.0-converge, so other sessions' merges since v0.23.0 did not ride along.

Measured with bab/adopt-probe: 39s and 49s, from 58s and 105s on v0.23.0. The journal splits it cleanly now:

  • Stamp to cycle: 1–4s. Root repointed p4 at 22:44:35 and the leg cycled at 22:44:36; for p5, 22:45:44 then 22:45:48. That gap is fixed.
  • Promote to notice: about 27s. The new timing line: serial pass stages took 27.2s (reconcile 12.8s, telemetry 1.8s, moves 6.3s, aliases 200ms, adopt 3.3s, config 2.8s). The adopt stage waits behind the rest. Reconcile and moves still read all 152 instance records one Get at a time.

Next, on fix-reconcile-parallel-reads: those reads go eight at a time, with the judging loops unchanged. Under review.

Hotfix c2782c13 rolled to all four flagship boxes (05:43–05:5x UTC). It is v0.23.0 plus three merged fixes: the converge loop, the directory walk, and parallel record reads (fix-reconcile-parallel-reads, merged as eef3e121 after two Astra rounds).

The box's own timing line went from 27.2s (reconcile 12.8s, telemetry 1.8s, moves 6.3s, aliases 200ms, adopt 3.3s, config 2.8s) to 12.3s (reconcile 2.5s, telemetry 1.8s, moves 1.3s, aliases 300ms, adopt 3.4s, config 3s).

Probe deploys to an awake instance, end to end including the upload:

| build | v0.23.0 | 82c5e17b | c2782c13 | |---|---|---|---| | deploy | 58s, 105s | 39s, 49s | 23s, 23s, 123s |

The 123s was a real bug, the one I had called latent: the agent asked root to stage p8 at 06:00:13, and when it hit p9 blocked 41s later the one-a-minute throttle dropped the ask. Nothing asked again until the next serial move at 06:02:35. Fix on fix-stage-request-deferred, under review:

  • A throttled request is deferred to the end of the window, never dropped, and the window is 10s instead of 60s.
  • A host whose stage was blocked stays in the fast sweep until it is staged, so the ask repeats even if carlos-stage.path missed a write made while the previous root pass was still running.

Update on fix-stage-request-deferred (tip 879db237):

  • Astra rejected the first version. Its findings were all in the fast-loop sweep of blocked hosts: it bypassed the staging backoff, never retired a superseded target, and could retry a failing restart every ten seconds. The sweep is gone.
  • The second version added a root-side repeat pass. Round two found that it retries a restart that just failed and adopts against config synced before the first pass. That is gone too.
  • What remains is small. A throttled stage request is deferred to the end of its window, never dropped. The window is 15s, measured from the end of the last write; root stage passes on the IE box take 5.4–5.7s (24h of journal). The throttle stays busy while a write is scheduled or in progress, so two writes are never closer than the window.

Known gap, unchanged from before this branch: if a root pass runs longer than the window, a request written during it waits for the next trigger, because PathChanged ignores writes while carlos-stage.service runs. Closing that properly means a level-triggered marker (PathExists, consumed by root at the start of a pass). That is a unit-file change with its own rollback risk: an older binary under the new unit would re-trigger in a tight loop, since StartLimitIntervalSec=0. Not for a hotfix.

Next: CI, Astra round 3 on the narrowed diff, merge, add it to the hotfix branch, roll, then re-measure two probe deploys inside a minute.

Merged as 1a17848a after Astra round 3 (accept with fixes, applied: the marker write now runs under the throttle lock, so a request made after the marker changes gets the next window instead of riding a write root may already have read). CI green.

Rolled to all four flagship boxes as hotfix f3f6cf73 (v0.23.0 + converge loop + listing + parallel reads + this). Re-measured on IE with three probe deploys about 40s apart, the spacing that took 123s yesterday:

| deploy | start | agent asks root | repointed | total | |---|---|---|---|---| | p10 | 06:54:22 | 06:54:35 | 06:54:42 | 25s | | p11 | 06:55:02 | 06:55:14 | 06:55:22 | 22s | | p12 | 06:55:40 | 06:55:51 | 06:55:59 | 20s |

Each root pass finished within a second of its repoint, and the warm instance was cycled onto the new build within a second of that. Roughly 12s of each deploy is upload, promotion and the agent noticing; about 8s is the root stage.

Still open: the swap is a cycle (hibernate, then boot on the next request), not a zero-downtime handover. That is the handover spec, not this bug.