diff --git a/.claude/rules/53-scheduled-handler-isolation-and-liveness-signals.md b/.claude/rules/53-scheduled-handler-isolation-and-liveness-signals.md index c021c67528..2a2c9031ef 100644 --- a/.claude/rules/53-scheduled-handler-isolation-and-liveness-signals.md +++ b/.claude/rules/53-scheduled-handler-isolation-and-liveness-signals.md @@ -91,6 +91,28 @@ error.** Two distinct sub-classes, both present above: `background_tasks_changed` wholesale-replace was the pre-existing prior art that the new reporter had not reproduced). +5c. **A progress watchdog must be fed by a signal that can observe its longest step.** + The mirror image of rule 5: there, a liveness column answered an idleness question; here, + a progress feed cannot see the work it guards. The apply idle watchdog + (`runDetachedDeploymentApply`) reset its 15-minute timer only on `ApplyProgressEvent`s — + the events that become `deployment_release_events` rows — while the longest step in an + apply, `docker compose up`, emits exactly one at start and nothing until it returns. A + legitimately slow image pull was therefore indistinguishable from a hung apply and got + SIGKILLed mid-pull, repeatedly: 6 cycles in 85 minutes on one production environment, + every one killed at the timeout, with zero completions. + + Ask, for every watchdog: **which step is the longest, and does it emit the signal the + timer listens for?** If not, feed the timer from something that step actually produces — + child stdout/stderr, bytes transferred, a poll of external state — as + `newIdleProgressReader` already did for artifact downloads in the same package. A sibling + in the same codebase getting this right is the strongest hint that the new one is wrong. + + Two traps when adding such a feed: (a) keep it off the persistence path — a liveness poke + is not an event, and persisting one per output line would trade a hang for a flood; and + (b) if you cap retained child output for the error message, **keep the tail**. The failure + reason is on the last lines, so head-retention silently discards exactly the diagnostic + the buffer exists to preserve. + 6. **Precondition deferrals must not consume destructive retry budgets or leave immortal retry states.** A lifecycle loop may discover work before a later runtime event makes it safe (for example, task completion is recorded before the completing prompt reports idle, or a final @@ -124,6 +146,8 @@ Before merging a change to a scheduled handler or an idleness predicate: - [ ] The completion log names failed steps - [ ] The failure-recording path cannot itself abort the handler - [ ] No idleness predicate reads a column any keepalive path writes +- [ ] Every progress watchdog is fed by a signal its LONGEST step actually emits +- [ ] Capped child-output buffers retain the tail, not the head - [ ] Every leased/capped set has a named answer to "what evicts an entry that never reports a terminal state?", and it is not process death - [ ] Precondition deferrals preserve the destructive retry budget and remain durably selectable @@ -136,6 +160,9 @@ Before merging a change to a scheduled handler or an idleness predicate: - `.claude/rules/51-server-side-node-class-gates.md` — role/class gates on destroy paths - `.claude/rules/39-debug-before-redesign.md` — this outage was found by tracing the existing path, not by redesigning it +- Implementation (5c): `packages/vm-agent/internal/deploy/compose.go` (`livenessWriter`), + `internal/server/health.go` (`runDetachedDeploymentApply`); prior art + `internal/deploy/artifact_client.go` (`newIdleProgressReader`) - Implementation: `apps/api/src/scheduled/sweep-isolation.ts`, `apps/api/src/scheduled/node-cleanup/shared.ts` (`LAST_WORKSPACE_ACTIVITY_SQL`) - Task: `tasks/archive/2026-08-06-fix-node-reaping-orphan-reconciliation.md` diff --git a/.claude/rules/68-external-api-check-then-act.md b/.claude/rules/68-external-api-check-then-act.md new file mode 100644 index 0000000000..d9850e658b --- /dev/null +++ b/.claude/rules/68-external-api-check-then-act.md @@ -0,0 +1,137 @@ +# A Conflict From a Remote Uniqueness Constraint Is a Signal, Not a Failure + +## When This Applies + +Any "create it if it isn't there" against an **external API that enforces its own +uniqueness constraint** — Cloudflare DNS records, cloud provider resources with unique +names, registry tags, Stripe idempotency keys, GitHub labels/branches. The shape is: + +```ts +const existing = await find(name); // CHECK +await (existing ? update(existing) : create()); // ACT — await in the gap +``` + +It applies with full force when the call site is a fan-out (`Promise.all`, a sweep, a +retried handler), or when the same endpoint can run concurrently for the same resource. + +## Why This Rule Exists + +`upsertAppRouteDNSRecord` looked up an app-route A record and created it when absent. +`GET /api/nodes/:id/deploy-release` upserts every route through `Promise.all` before +returning the node's release payload, and overlapping release fetches ran that handler +concurrently. Two callers both saw "no record", both POSTed, and Cloudflare rejected the +loser with 81058 `An identical record already exists.` + +That throw propagated out of `Promise.all`, 500'd the release fetch, and the node never +received its payload. A **self-correcting** condition — the record now exists, which is +exactly what the caller wanted — became a permanent deployment wedge, three layers +upstream of the symptom anyone could see (a missing TLS certificate). + +The tell was already in the file: the sibling `deleteAppRouteDNSRecord` carried a comment +about tolerating "a record already removed by a concurrent caller", and had a test for it. +The delete path had been hardened for concurrency. The create path, with the identical +race, had not. + +## Class of Bug + +**Check-then-act against a remote uniqueness constraint, with the conflict treated as +fatal.** This is the cross-isolate sibling of `.claude/rules/45` (Durable Object +check-then-act across `await`). + +A mutex is usually the *wrong* remedy here, but not an impossible one — a Durable Object +keyed on the resource can serialize callers across isolates. Reject it deliberately rather +than by assumption: it adds a hop, a failure mode, and a hot key to a path that the remote +API already adjudicates correctly and in one round trip. Where a cheap in-process dedup +already exists on the *caller* side, though, preventing the overlap is strictly better than +tolerating it — it removes all the other duplicated work too, not just the one operation +loud enough to fail. Check for that before settling for tolerance, and record which you +chose and why. + +Tells: + +- A `find` → `if (found) update else create` with an `await` between the two. +- A call site that fans the helper out over a list, or a handler that can run twice for the + same resource (retry, poll, duplicate heartbeat). +- Error handling that treats every non-2xx identically (`if (!res.ok) throw`). +- A sibling function in the same file already documented as concurrency-tolerant. + +## Hard Requirements + +1. **Treat the "already exists" conflict as success-with-a-different-shape.** Re-resolve + once and update in place, or return the existing resource. Do not fail the caller — the + post-condition it asked for now holds. + +2. **Distinguish "someone beat me to it" from "this can never work".** Branch on the + provider's numeric/typed error code, not on message text. An identical-record conflict is + recoverable; a *different-type* collision (Cloudflare 81053: an A/AAAA/CNAME already + occupies that host), a quota error, or an auth error is not, and must keep surfacing. + Enumerate the tolerated codes explicitly and comment why each neighbour is excluded + (`.claude/rules/67`). + +3. **Bound the recovery.** Exactly one re-resolve-and-update retry. A resource that keeps + duplicating must surface the error rather than loop. + +4. **Scope the tolerance to the path that can actually race.** Only the create path loses + this race; do not widen the tolerance to the update path, where the same code means + something else. + +5. **Read the error body once.** A `Response` body can only be consumed once, so a helper + that branches on the code must read code and message together rather than calling a + message-only reader and then re-reading. + +6. **Check the sibling operations in the same module, and fix them in the same change.** + If delete is concurrency-tolerant and create is not (or vice versa), that asymmetry is + the bug, not a style difference. This requirement caught a second live instance in the + PR that introduced this rule: `createNodeBackendDNSRecord` in the same file was a blind + POST with no lookup at all, and its loser's failure mode was worse — the caller stamps + `nodes.error_message`, leaves `backend_dns_record_id` NULL, retries the same losing POST + on every heartbeat forever, and orphans the real record at delete time because deletion + keys on that null id. Do not ship the rule without applying it to its own module. + +7. **Prefer prior art in this repo over a new invention.** `ensureBranchExists` + (`apps/api/src/services/github-app.ts`) already solved this class against the GitHub API, + treating a `422` on create as `status: 'exists'`. Match the existing shape. + +## Required Tests + +- **The race, per tolerated code:** lookup returns empty, create returns the conflict, + re-resolve returns the winner's resource, update succeeds. Assert the returned id and that + the retry used `PUT` against the winner. +- **A control per excluded neighbour:** the different-type collision and an unrelated + failure (auth/quota) must still throw, with **no** retry attempted. +- **Boundedness:** a create that keeps conflicting surfaces the error after one retry. +- **The `!create`-path guard has its own control.** Assert the *update* path still throws on + the same code. Without it, deleting the `!existing &&` conjunct — a one-token diff that + widens the tolerance exactly as requirement 4 forbids — leaves the suite fully green. +- **The real call-site shape:** run the helper through the same `Promise.all` fan-out + production uses, with one member losing the race, and assert the whole batch resolves. + Drive it against a small shared fake store keyed by resource name, so the interleaving + decides the winner rather than a pre-scripted call sequence; a scripted "loser" over two + *different* resources proves only that there is no cross-call state leakage. +- **A route/handler-level test at the real entry point.** Testing the helper alone does not + prove the endpoint survives: on the pre-fix code every one of the 31 existing tests for + the affected route passed while production was returning 500 (rule 35, rule 62). +- **Proven discriminating:** disable the tolerance and confirm exactly the race tests go red + while every control stays green. Verify this once. + +## Quick Compliance Check + +- [ ] The conflict response is treated as convergence, not failure +- [ ] Tolerated codes are enumerated by code, with excluded neighbours justified in a comment +- [ ] Recovery is bounded to a single retry +- [ ] Tolerance is scoped to the create path only +- [ ] The error body is read once for both code and message +- [ ] Sibling operations in the module were checked for the same asymmetry +- [ ] Race tests, per-neighbour controls, boundedness, and a fan-out test all exist +- [ ] The race tests were verified to fail with the tolerance removed + +## References + +- Task: `tasks/active/2026-09-05-fix-app-route-dns-upsert-race.md` +- Implementation: `apps/api/src/services/dns.ts` (`upsertAppRouteDNSRecord`, + `CF_DNS_DUPLICATE_RECORD_CODES`); call sites `apps/api/src/routes/deploy-release-callback.ts:306,328` +- `.claude/rules/45-durable-object-concurrency-mutex.md` — the same bug within one DO, where + a mutex *is* the remedy +- `.claude/rules/67-shared-predicates-that-trigger-actions.md` — keep the tolerated set no + coarser than the evidence +- `.claude/rules/11-fail-fast-patterns.md` — fail closed, but only on genuinely fatal conditions diff --git a/apps/api/src/services/deployment-volumes.ts b/apps/api/src/services/deployment-volumes.ts index 5da986e5f1..1099151e2b 100644 --- a/apps/api/src/services/deployment-volumes.ts +++ b/apps/api/src/services/deployment-volumes.ts @@ -577,10 +577,20 @@ export async function attachEnvironmentVolumes( location: vol.location, }); + // Persist the settled SAM-side fact, not the provider's transient snapshot. + // Hetzner commonly still reports `creating` at the instant attach returns, + // and NOTHING ever re-polls this row — the only other writer is the detach + // path. Persisting that snapshot left attached, mounted, fully working + // volumes reading `creating` forever, which is exactly the false signal that + // misdirected the 2026-09-05 stuck-deployment investigation. The attach call + // returned successfully and we hold a server id, so `attached` is the true + // and stable statement about this row. + const settledStatus = 'attached'; + await db .update(schema.deploymentVolumes) .set({ - status: attached.status, + status: settledStatus, attachedServerId: attached.attachedServerId ?? serverId, linuxDevice: attached.linuxDevice ?? null, updatedAt: now, @@ -589,7 +599,7 @@ export async function attachEnvironmentVolumes( results.push({ ...vol, - status: attached.status, + status: settledStatus, attachedServerId: attached.attachedServerId ?? serverId, linuxDevice: attached.linuxDevice ?? null, updatedAt: now, diff --git a/apps/api/src/services/dns.ts b/apps/api/src/services/dns.ts index b9ed65168e..43e6d93bde 100644 --- a/apps/api/src/services/dns.ts +++ b/apps/api/src/services/dns.ts @@ -13,10 +13,62 @@ const DEFAULT_DNS_TTL = 60; /** Default timeout for Cloudflare API calls (per Constitution Principle XI) */ const DEFAULT_CF_API_TIMEOUT_MS = 30_000; +// `code` is deliberately `unknown` rather than `v.optional(v.number())`. Valibot's +// optional() only bypasses a missing/undefined key, so `code: null` or a stringified +// code would fail the whole entry — and readCloudflareErrorDetail swallows parse +// failures and falls back to a generic message. That would silently discard +// Cloudflare's real error text for every caller, including the five that never asked +// to branch on the code at all. Parse permissively; narrow to a number at use. const cloudflareErrorSchema = v.object({ - errors: v.optional(v.array(v.object({ message: v.string() }))), + errors: v.optional(v.array(v.object({ + code: v.optional(v.unknown()), + message: v.string(), + }))), }); +/** + * Cloudflare DNS API error codes meaning "this exact record already exists". + * + * Raised when a concurrent caller created the record between our lookup and our + * create. Recoverable: re-resolve and update the record in place. + * + * Deliberately EXCLUDES 81053 ("An A, AAAA, or CNAME record with that host + * already exists"), which reports a different-type collision — a real + * misconfiguration that retrying cannot fix and must keep surfacing. + */ +const CF_DNS_DUPLICATE_RECORD_CODES = new Set([81057, 81058]); + +/** + * Attempts for a create that lost a duplicate-record race: the original, plus one + * re-resolve-and-update. Not env-exposed — this bounds an internal recovery loop + * against a constraint that resolves in a single round trip, not a caller-facing + * retry policy. + */ +const DNS_UPSERT_RACE_MAX_RETRIES = 1; + +/** True when a failed create can be recovered by resolving the winner's record. */ +function isDuplicateRecordConflict(code: number | null): boolean { + return code !== null && CF_DNS_DUPLICATE_RECORD_CODES.has(code); +} + +/** + * Resolve the record a duplicate-create conflict refers to, or null. + * + * A failed lookup is not allowed to mask the original conflict, so it degrades to + * null and the caller surfaces the create error it already has. + */ +async function findRecordAfterConflict( + hostname: string, + env: Env, +): Promise<{ id: string; content?: string } | null> { + try { + return await findDNSRecordByName(hostname, env); + } catch (err) { + log.warn('dns.conflict_lookup_failed', { hostname, error: String(err) }); + return null; + } +} + const dnsRecordIdResponseSchema = v.object({ result: v.object({ id: v.string() }), }); @@ -31,15 +83,33 @@ const dnsRecordListResponseSchema = v.object({ })), }); -async function readCloudflareError(response: Response, fallback: string): Promise { +/** + * Read the first Cloudflare API error as a `{ code, message }` pair. + * + * A Response body can only be consumed once, so callers that need to branch on + * the numeric code must read both together rather than calling + * {@link readCloudflareError} and then re-reading the body. + */ +async function readCloudflareErrorDetail( + response: Response, + fallback: string, +): Promise<{ code: number | null; message: string }> { try { const error = await readResponseJson(response, cloudflareErrorSchema, 'cloudflare.dns.error'); - return error.errors?.[0]?.message || fallback; + const first = error.errors?.[0]; + // Only a real number is usable for branching; anything else is treated as + // "no code", which keeps the message intact and excludes it from any retry. + const code = typeof first?.code === 'number' ? first.code : null; + return { code, message: first?.message || fallback }; } catch { - return fallback; + return { code: null, message: fallback }; } } +async function readCloudflareError(response: Response, fallback: string): Promise { + return (await readCloudflareErrorDetail(response, fallback)).message; +} + /** * Get DNS TTL from env or use default (per constitution principle XI). */ @@ -230,37 +300,62 @@ export async function upsertAppRouteDNSRecord( ip: string, env: Env, ): Promise { - const existing = await findDNSRecordByName(hostname, env); - const timeoutMs = getTimeoutMs(env.CF_API_TIMEOUT_MS, DEFAULT_CF_API_TIMEOUT_MS); - const body = JSON.stringify({ - type: 'A', - name: hostname, - content: ip, - ttl: getDnsTTL(env), - proxied: false, - }); - - const response = await fetchWithTimeout( - existing - ? `${CLOUDFLARE_API_BASE}/zones/${env.CF_ZONE_ID}/dns_records/${existing.id}` - : `${CLOUDFLARE_API_BASE}/zones/${env.CF_ZONE_ID}/dns_records`, - { - method: existing ? 'PUT' : 'POST', - headers: { - Authorization: `Bearer ${env.CF_API_TOKEN}`, - 'Content-Type': 'application/json', + // Check-then-act across an await: concurrent callers can both observe "no + // record" and both POST, and Cloudflare rejects the loser as a duplicate. + // This is reachable in production — `deploy-release-callback.ts` upserts every + // route through Promise.all, and overlapping node release fetches run that + // whole handler concurrently. The loser used to throw, which failed the node's + // release fetch with a 500 and wedged the deployment before any cert work. + // Re-resolve once and update in place so the loser converges instead. + for (let attempt = 0; attempt <= DNS_UPSERT_RACE_MAX_RETRIES; attempt++) { + const existing = await findDNSRecordByName(hostname, env); + const timeoutMs = getTimeoutMs(env.CF_API_TIMEOUT_MS, DEFAULT_CF_API_TIMEOUT_MS); + const body = JSON.stringify({ + type: 'A', + name: hostname, + content: ip, + ttl: getDnsTTL(env), + proxied: false, + }); + + const response = await fetchWithTimeout( + existing + ? `${CLOUDFLARE_API_BASE}/zones/${env.CF_ZONE_ID}/dns_records/${existing.id}` + : `${CLOUDFLARE_API_BASE}/zones/${env.CF_ZONE_ID}/dns_records`, + { + method: existing ? 'PUT' : 'POST', + headers: { + Authorization: `Bearer ${env.CF_API_TOKEN}`, + 'Content-Type': 'application/json', + }, + body, }, - body, - }, - timeoutMs, - ); + timeoutMs, + ); - if (!response.ok) { - throw new Error(await readCloudflareError(response, `Failed to upsert app route DNS record: ${response.status}`)); + if (response.ok) { + const data = await readResponseJson(response, dnsRecordIdResponseSchema, 'cloudflare.dns.upsert_app_route_record'); + return data.result.id; + } + + const detail = await readCloudflareErrorDetail( + response, + `Failed to upsert app route DNS record: ${response.status}`, + ); + + // `!existing` is load-bearing: only the create path can lose this race. On the + // update path the same code means something else, and widening the tolerance + // there would retry a PUT against a record we already resolved (rule 67/68 §4). + const lostCreateRace = !existing && isDuplicateRecordConflict(detail.code); + if (!lostCreateRace || attempt === DNS_UPSERT_RACE_MAX_RETRIES) { + throw new Error(detail.message); + } + + log.info('dns.app_route_upsert_race_retry', { hostname, code: detail.code }); } - const data = await readResponseJson(response, dnsRecordIdResponseSchema, 'cloudflare.dns.upsert_app_route_record'); - return data.result.id; + // Unreachable: the loop either returns or throws on its final attempt. + throw new Error(`Failed to upsert app route DNS record for ${hostname}`); } /** @@ -417,7 +512,40 @@ export async function createNodeBackendDNSRecord( ); if (!response.ok) { - throw new Error(await readCloudflareError(response, `Failed to create backend DNS record: ${response.status}`)); + const detail = await readCloudflareErrorDetail( + response, + `Failed to create backend DNS record: ${response.status}`, + ); + + // Same concurrent-create race as upsertAppRouteDNSRecord, and the reason this + // sibling is fixed alongside it (rule 68 §6). Two paths create this record — + // node provisioning (services/nodes.ts) and the heartbeat backfill + // (routes/node-lifecycle.ts) — and the loser used to throw. That path only + // stamps nodes.error_message and leaves backend_dns_record_id NULL, so every + // later heartbeat retried the same losing POST forever, and node deletion + // (which deletes by that id) left the real record orphaned in the zone. + // Resolving the winner lets the id be persisted, which fixes both. + if (isDuplicateRecordConflict(detail.code)) { + const existing = await findRecordAfterConflict( + getNodeBackendHostname(nodeId, env.BASE_DOMAIN), + env, + ); + if (existing) { + // 81057 does not guarantee matching content; converge the IP before + // handing back an id the caller will treat as authoritative. + if (existing.content !== ip) { + await updateDNSRecord(existing.id, ip, env); + } + log.info('dns.node_backend_create_race_resolved', { + nodeId, + recordId: existing.id, + code: detail.code, + }); + return existing.id; + } + } + + throw new Error(detail.message); } const data = await readResponseJson(response, dnsRecordIdResponseSchema, 'cloudflare.dns.create_backend_record'); diff --git a/apps/api/tests/unit/routes/deploy-release-callback.test.ts b/apps/api/tests/unit/routes/deploy-release-callback.test.ts index 4c77c19b9e..ae71fb01a1 100644 --- a/apps/api/tests/unit/routes/deploy-release-callback.test.ts +++ b/apps/api/tests/unit/routes/deploy-release-callback.test.ts @@ -323,6 +323,54 @@ describe('deploy release callback route', () => { vi.unstubAllGlobals(); }); + // Vertical-slice regression for the 2026-09-05 production wedge. Two overlapping + // deploy-release fetches both upsert the same route list via Promise.all; both saw + // "no record", both POSTed, and Cloudflare rejected the loser with 81058. That threw + // out of Promise.all and 500'd this endpoint, so the node never got its release + // payload and the deployment stalled before any DNS/cert work. + // + // The helper-level tests in dns-app-routes.test.ts cannot observe this: the pre-fix + // dns.ts passes all 31 tests in THIS file, so only a route-level test proves the + // endpoint itself survives. See .claude/rules/35 and .claude/rules/68. + it('still returns 200 when a concurrent caller wins the DNS create race (regression)', async () => { + stubHappyPathDb(); + + // Route 1 creates normally. Route 2 loses the race: its POST is rejected as a + // duplicate, then the re-resolve finds the winner's record and the PUT succeeds. + const fetchMock = vi + .fn() + // two lookups (Promise.all, both empty) + .mockResolvedValueOnce(new Response(JSON.stringify({ result: [] }), { status: 200 })) + .mockResolvedValueOnce(new Response(JSON.stringify({ result: [] }), { status: 200 })) + // route 1 create succeeds + .mockResolvedValueOnce(new Response(JSON.stringify({ result: { id: 'dns-r1' } }), { status: 200 })) + // route 2 create loses the race + .mockResolvedValueOnce(new Response(JSON.stringify({ + errors: [{ code: 81058, message: 'An identical record already exists.' }], + }), { status: 400 })) + // route 2 re-resolve now sees the winner's record + .mockResolvedValueOnce(new Response(JSON.stringify({ + result: [{ id: 'dns-r2-winner', name: 'r2-api-8080-env-1.apps.sammy.party', type: 'A', content: '203.0.113.10', proxied: false }], + }), { status: 200 })) + // route 2 updates it in place + .mockResolvedValueOnce(new Response(JSON.stringify({ result: { id: 'dns-r2-winner' } }), { status: 200 })); + vi.stubGlobal('fetch', fetchMock); + + const response = await requestDeployRelease(); + const body = await response.json(); + + // The payload the node needs is delivered, not a 500. + expect(response.status, JSON.stringify(body)).toBe(200); + expect(body.routes).toHaveLength(2); + expect(body.signature).toBeDefined(); + + // The loser really did take the recovery path (6 calls, not 4). + expect(fetchMock).toHaveBeenCalledTimes(6); + const [retryUrl, retryInit] = fetchMock.mock.calls[5]!; + expect(String(retryUrl)).toContain('/dns_records/dns-r2-winner'); + expect(retryInit.method).toBe('PUT'); + }); + it('returns signed route targets, publishes loopback Compose ports, and creates grey-cloud DNS records', async () => { const dateNow = vi.spyOn(Date, 'now').mockReturnValue(1_700_000_000_000); stubHappyPathDb(); diff --git a/apps/api/tests/unit/services/deployment-volumes.test.ts b/apps/api/tests/unit/services/deployment-volumes.test.ts index d3c89694a0..4965989dea 100644 --- a/apps/api/tests/unit/services/deployment-volumes.test.ts +++ b/apps/api/tests/unit/services/deployment-volumes.test.ts @@ -813,13 +813,63 @@ describe('attachEnvironmentVolumes', () => { // D1 was updated expect(db.update).toHaveBeenCalled(); - // Returned results reflect attached state + // Returned results reflect attached state. The status is the settled SAM-side + // fact ('attached'), not the provider's transient snapshot — see the + // regression test below for why. expect(results).toHaveLength(1); - expect(results[0].status).toBe('in-use'); + expect(results[0].status).toBe('attached'); expect(results[0].attachedServerId).toBe('srv-target'); expect(results[0].linuxDevice).toBe('/dev/sdb'); }); + // Regression: Hetzner commonly still reports `creating` at the instant attach + // returns, and nothing ever re-polls this row — the only other writer is the + // detach path. Persisting the provider's snapshot left attached, mounted, + // fully working volumes reading `creating` forever. Observed in production on + // 2026-09-05 on a volume whose mount had already been verified, and it + // misdirected the stuck-deployment investigation. + it('persists a settled status when the provider still reports a transient one', async () => { + const provider = makeMockProvider({ + attachResult: makeVolumeInstance({ + status: 'creating', + attachedServerId: 'srv-target', + linuxDevice: '/dev/sdb', + }), + }); + setupProvider(provider); + + const volumeRows: MockRow[] = [ + { + id: 'vol-1', + environmentId: 'env-001', + name: 'pgdata', + providerVolumeId: 'prov-vol-1', + providerName: 'hetzner', + sizeGb: 10, + location: 'nbg1', + status: 'available', + attachedServerId: null, + linuxDevice: null, + createdAt: '2026-06-12T00:00:00Z', + updatedAt: '2026-06-12T00:00:00Z', + }, + ]; + const db = createMockDb(volumeRows); + + const results = await attachEnvironmentVolumes( + db as any, + mockEnv, + 'user-1', + 'env-001', + 'srv-target', + 'nbg1' + ); + + expect(results[0].status).toBe('attached'); + expect(results[0].status).not.toBe('creating'); + expect(results[0].attachedServerId).toBe('srv-target'); + }); + it('resolves the provider from volume rows when attaching non-default provider volumes', async () => { const provider = makeMockProvider(); setupProvider(provider, 'scaleway'); diff --git a/apps/api/tests/unit/services/dns-app-routes.test.ts b/apps/api/tests/unit/services/dns-app-routes.test.ts index 233013ff2f..d923486f26 100644 --- a/apps/api/tests/unit/services/dns-app-routes.test.ts +++ b/apps/api/tests/unit/services/dns-app-routes.test.ts @@ -2,6 +2,7 @@ import { afterEach, describe, expect, it, vi } from 'vitest'; import { cleanupAppRouteDNSRecords, + createNodeBackendDNSRecord, deleteAppRouteDNSRecord, upsertAppRouteDNSRecord, } from '../../../src/services/dns'; @@ -11,6 +12,7 @@ function env() { CF_API_TOKEN: 'cf-token', CF_ZONE_ID: 'zone-1', DNS_TTL_SECONDS: '120', + BASE_DOMAIN: 'example.com', } as any; } @@ -58,6 +60,344 @@ describe('upsertAppRouteDNSRecord', () => { proxied: false, }); }); + + // Regression: production wedge on 2026-09-05. Two overlapping + // GET /api/nodes/:id/deploy-release requests each ran the whole handler, which + // upserts every route via Promise.all. Both observed "no record", both POSTed, + // and Cloudflare rejected the loser with 81058 "An identical record already + // exists." That threw, 500'd the release fetch, and the node never received + // its payload — so the deployment stalled before any DNS/cert work. + describe('concurrent create race (Cloudflare duplicate-record codes)', () => { + for (const code of [81057, 81058]) { + it(`recovers when a concurrent caller wins the create (code ${code})`, async () => { + const fetchMock = vi.fn() + // 1. our lookup: nothing yet + .mockResolvedValueOnce(new Response(JSON.stringify({ result: [] }), { status: 200 })) + // 2. our create: the other caller got there first + .mockResolvedValueOnce(new Response(JSON.stringify({ + errors: [{ code, message: 'An identical record already exists.' }], + }), { status: 400 })) + // 3. re-resolve: now we can see the winner's record + .mockResolvedValueOnce(new Response(JSON.stringify({ + result: [{ id: 'dns-winner', name: 'r1-web.apps.example.com', type: 'A', content: '203.0.113.10', proxied: false }], + }), { status: 200 })) + // 4. update it in place + .mockResolvedValueOnce(new Response(JSON.stringify({ result: { id: 'dns-winner' } }), { status: 200 })); + vi.stubGlobal('fetch', fetchMock); + + await expect(upsertAppRouteDNSRecord('r1-web.apps.example.com', '203.0.113.10', env())) + .resolves.toBe('dns-winner'); + + expect(fetchMock).toHaveBeenCalledTimes(4); + const [retryUrl, retryInit] = fetchMock.mock.calls[3]!; + expect(String(retryUrl)).toContain('/dns_records/dns-winner'); + expect(retryInit.method).toBe('PUT'); + expect(JSON.parse(retryInit.body)).toMatchObject({ + type: 'A', + content: '203.0.113.10', + proxied: false, + }); + }); + } + + // Discriminating control for the `!existing` guard specifically. Without this, + // deleting `!existing &&` from the predicate — a one-token diff that widens the + // tolerance to the update path — leaves the whole suite green. Rule 68 §4 makes + // create-path-only a hard requirement; this is what enforces it. + it('does NOT retry when the UPDATE path returns a duplicate code', async () => { + const fetchMock = vi.fn() + // lookup finds an existing record, so this is the PUT path + .mockResolvedValueOnce(new Response(JSON.stringify({ + result: [{ id: 'dns-existing', name: 'r1-web.apps.example.com', type: 'A', content: '198.51.100.2', proxied: false }], + }), { status: 200 })) + .mockResolvedValueOnce(new Response(JSON.stringify({ + errors: [{ code: 81058, message: 'An identical record already exists.' }], + }), { status: 400 })); + vi.stubGlobal('fetch', fetchMock); + + await expect(upsertAppRouteDNSRecord('r1-web.apps.example.com', '203.0.113.10', env())) + .rejects.toThrow('An identical record already exists.'); + + // Exactly one lookup + one PUT. A third call would mean the update path retried. + expect(fetchMock).toHaveBeenCalledTimes(2); + expect(fetchMock.mock.calls[1]![1].method).toBe('PUT'); + }); + + // Discriminating control: a different-type collision is a real + // misconfiguration. Retrying cannot fix it, so it must still surface. + it('still throws on a different-type collision (81053), which retrying cannot fix', async () => { + const fetchMock = vi.fn() + .mockResolvedValueOnce(new Response(JSON.stringify({ result: [] }), { status: 200 })) + .mockResolvedValueOnce(new Response(JSON.stringify({ + errors: [{ code: 81053, message: 'An A, AAAA, or CNAME record with that host already exists.' }], + }), { status: 400 })); + vi.stubGlobal('fetch', fetchMock); + + await expect(upsertAppRouteDNSRecord('r1-web.apps.example.com', '203.0.113.10', env())) + .rejects.toThrow('An A, AAAA, or CNAME record with that host already exists.'); + + // No retry attempted. + expect(fetchMock).toHaveBeenCalledTimes(2); + }); + + // Discriminating control: unrelated failures must not be swallowed. + it('still throws on an unrelated create failure (auth error)', async () => { + const fetchMock = vi.fn() + .mockResolvedValueOnce(new Response(JSON.stringify({ result: [] }), { status: 200 })) + .mockResolvedValueOnce(new Response(JSON.stringify({ + errors: [{ code: 10000, message: 'Authentication error' }], + }), { status: 403 })); + vi.stubGlobal('fetch', fetchMock); + + await expect(upsertAppRouteDNSRecord('r1-web.apps.example.com', '203.0.113.10', env())) + .rejects.toThrow('Authentication error'); + expect(fetchMock).toHaveBeenCalledTimes(2); + }); + + // Regression: `code` is parsed as unknown, not `v.optional(v.number())`. + // Valibot's optional() only bypasses a missing key, so a null/stringified code + // would fail the whole error entry, get swallowed by the parse catch, and + // replace Cloudflare's real message with a generic fallback — degrading errors + // for every caller of readCloudflareError, not just this one. + for (const [label, code] of [['null', null], ['stringified', '81058']] as const) { + it(`preserves the real Cloudflare message when code is ${label}`, async () => { + const fetchMock = vi.fn() + .mockResolvedValueOnce(new Response(JSON.stringify({ result: [] }), { status: 200 })) + .mockResolvedValueOnce(new Response(JSON.stringify({ + errors: [{ code, message: 'Rate limited by Cloudflare' }], + }), { status: 429 })); + vi.stubGlobal('fetch', fetchMock); + + // Real message survives, and a non-numeric code is never treated as retryable. + await expect(upsertAppRouteDNSRecord('r1-web.apps.example.com', '203.0.113.10', env())) + .rejects.toThrow('Rate limited by Cloudflare'); + expect(fetchMock).toHaveBeenCalledTimes(2); + }); + } + + // Bounded: a record that keeps duplicating must not loop forever. + it('retries at most once, then surfaces the duplicate error', async () => { + const duplicate = () => new Response(JSON.stringify({ + errors: [{ code: 81058, message: 'An identical record already exists.' }], + }), { status: 400 }); + const fetchMock = vi.fn() + .mockResolvedValueOnce(new Response(JSON.stringify({ result: [] }), { status: 200 })) + .mockResolvedValueOnce(duplicate()) + // re-resolve still sees nothing (winner deleted it again) + .mockResolvedValueOnce(new Response(JSON.stringify({ result: [] }), { status: 200 })) + .mockResolvedValueOnce(duplicate()); + vi.stubGlobal('fetch', fetchMock); + + await expect(upsertAppRouteDNSRecord('r1-web.apps.example.com', '203.0.113.10', env())) + .rejects.toThrow('An identical record already exists.'); + + expect(fetchMock).toHaveBeenCalledTimes(4); + }); + + // The real incident shape: two overlapping deploy-release handler invocations + // upsert the SAME hostname concurrently. Driven against a shared fake CF record + // store rather than a pre-scripted call sequence, so the interleaving — not the + // script — decides who wins, and both callers must converge on one record id. + it('two concurrent callers for the SAME hostname converge on one record', async () => { + const HOST = 'r1-web.apps.example.com'; + const store = new Map(); + let nextId = 1; + + const fetchMock = vi.fn(async (url: any, init: any) => { + const u = new URL(String(url)); + const method = init?.method ?? 'GET'; + // Yield so the two callers genuinely interleave across the await boundary. + await Promise.resolve(); + + if (method === 'GET') { + const name = u.searchParams.get('name')!; + const hit = store.get(name); + return new Response(JSON.stringify({ result: hit ? [hit] : [] }), { status: 200 }); + } + + if (method === 'POST') { + const body = JSON.parse(init.body); + if (store.has(body.name)) { + // Cloudflare enforces uniqueness; the loser gets 81058. + return new Response(JSON.stringify({ + errors: [{ code: 81058, message: 'An identical record already exists.' }], + }), { status: 400 }); + } + const rec = { id: `dns-${nextId++}`, name: body.name, type: 'A', content: body.content }; + store.set(body.name, rec); + return new Response(JSON.stringify({ result: { id: rec.id } }), { status: 200 }); + } + + if (method === 'PUT') { + // Route by record id, not a catch-all, so a future third case cannot + // silently pass by matching the wrong record. + const id = u.pathname.split('/').pop()!; + const rec = [...store.values()].find((r) => r.id === id); + if (!rec) return new Response(JSON.stringify({ errors: [{ code: 81044, message: 'Record not found.' }] }), { status: 404 }); + rec.content = JSON.parse(init.body).content; + return new Response(JSON.stringify({ result: { id: rec.id } }), { status: 200 }); + } + throw new Error(`unexpected method ${method}`); + }); + vi.stubGlobal('fetch', fetchMock); + + const ids = await Promise.all([ + upsertAppRouteDNSRecord(HOST, '203.0.113.10', env()), + upsertAppRouteDNSRecord(HOST, '203.0.113.10', env()), + ]); + + // Neither call threw, both agree on the single record, and exactly one exists. + expect(ids[0]).toBe(ids[1]); + expect(store.size).toBe(1); + expect(store.get(HOST)!.content).toBe('203.0.113.10'); + }); + + // The Promise.all fan-out over DIFFERENT hostnames, as deploy-release-callback + // does it: one member losing the race must not reject the batch that gates the + // node's release payload. + it('a losing route does not fail the Promise.all batch that gates the release fetch', async () => { + const store = new Map(); + // r2 is already claimed by a concurrent caller before either of our creates. + store.set('r2-api.apps.example.com', { + id: 'dns-b-winner', name: 'r2-api.apps.example.com', type: 'A', content: '203.0.113.10', + }); + const seenGet = new Set(); + let nextId = 1; + + const fetchMock = vi.fn(async (url: any, init: any) => { + const u = new URL(String(url)); + const method = init?.method ?? 'GET'; + await Promise.resolve(); + + if (method === 'GET') { + const name = u.searchParams.get('name')!; + // First lookup for r2 races ahead of the winner's write, so our caller + // believes the record is absent and takes the create path. + if (name === 'r2-api.apps.example.com' && !seenGet.has(name)) { + seenGet.add(name); + return new Response(JSON.stringify({ result: [] }), { status: 200 }); + } + const hit = store.get(name); + return new Response(JSON.stringify({ result: hit ? [hit] : [] }), { status: 200 }); + } + if (method === 'POST') { + const body = JSON.parse(init.body); + if (store.has(body.name)) { + return new Response(JSON.stringify({ + errors: [{ code: 81058, message: 'An identical record already exists.' }], + }), { status: 400 }); + } + const rec = { id: `dns-a-${nextId++}`, name: body.name, type: 'A', content: body.content }; + store.set(body.name, rec); + return new Response(JSON.stringify({ result: { id: rec.id } }), { status: 200 }); + } + if (method === 'PUT') { + const id = u.pathname.split('/').pop()!; + const rec = [...store.values()].find((r) => r.id === id); + if (!rec) return new Response(JSON.stringify({ errors: [{ code: 81044, message: 'Record not found.' }] }), { status: 404 }); + rec.content = JSON.parse(init.body).content; + return new Response(JSON.stringify({ result: { id: rec.id } }), { status: 200 }); + } + throw new Error(`unexpected method ${method}`); + }); + vi.stubGlobal('fetch', fetchMock); + + const ids = await Promise.all([ + upsertAppRouteDNSRecord('r1-web.apps.example.com', '203.0.113.10', env()), + upsertAppRouteDNSRecord('r2-api.apps.example.com', '203.0.113.10', env()), + ]); + + expect(ids[0]).toBe('dns-a-1'); + expect(ids[1]).toBe('dns-b-winner'); + }); + }); +}); + +// The sibling create in the same module (rule 68 §6). Two paths create this record — +// node provisioning and the heartbeat backfill — and the loser's failure mode is worse +// than the app-route one was: node-lifecycle.ts only stamps nodes.error_message and +// leaves backend_dns_record_id NULL, so every later heartbeat retries the same losing +// POST forever, and node deletion (which deletes by that id) orphans the real record. +describe('createNodeBackendDNSRecord', () => { + afterEach(() => { + vi.unstubAllGlobals(); + }); + + it('creates the orange-clouded backend record on the happy path', async () => { + const fetchMock = vi.fn() + .mockResolvedValueOnce(new Response(JSON.stringify({ result: { id: 'dns-node' } }), { status: 200 })); + vi.stubGlobal('fetch', fetchMock); + + await expect(createNodeBackendDNSRecord('NODE-1', '203.0.113.10', env())).resolves.toBe('dns-node'); + expect(fetchMock).toHaveBeenCalledTimes(1); + expect(JSON.parse(fetchMock.mock.calls[0]![1].body)).toMatchObject({ + type: 'A', + name: 'node-1.vm', + proxied: true, + }); + }); + + it('resolves the winner when a concurrent caller already created it', async () => { + const fetchMock = vi.fn() + .mockResolvedValueOnce(new Response(JSON.stringify({ + errors: [{ code: 81058, message: 'An identical record already exists.' }], + }), { status: 400 })) + // lookup by the full backend hostname finds the winner, same IP + .mockResolvedValueOnce(new Response(JSON.stringify({ + result: [{ id: 'dns-winner', name: 'node-1.vm.example.com', type: 'A', content: '203.0.113.10', proxied: true }], + }), { status: 200 })); + vi.stubGlobal('fetch', fetchMock); + + // Returning the id is what lets the caller persist backend_dns_record_id, + // which is what stops the forever-retry and the delete-time orphan. + await expect(createNodeBackendDNSRecord('NODE-1', '203.0.113.10', env())).resolves.toBe('dns-winner'); + expect(String(fetchMock.mock.calls[1]![0])).toContain('name=node-1.vm.example.com'); + // Content already matches, so no corrective PUT. + expect(fetchMock).toHaveBeenCalledTimes(2); + }); + + it('converges the IP when the winning record points elsewhere (81057)', async () => { + const fetchMock = vi.fn() + .mockResolvedValueOnce(new Response(JSON.stringify({ + errors: [{ code: 81057, message: 'Record already exists.' }], + }), { status: 400 })) + .mockResolvedValueOnce(new Response(JSON.stringify({ + result: [{ id: 'dns-stale', name: 'node-1.vm.example.com', type: 'A', content: '198.51.100.9', proxied: true }], + }), { status: 200 })) + .mockResolvedValueOnce(new Response(JSON.stringify({ result: { id: 'dns-stale' } }), { status: 200 })); + vi.stubGlobal('fetch', fetchMock); + + await expect(createNodeBackendDNSRecord('NODE-1', '203.0.113.10', env())).resolves.toBe('dns-stale'); + const [updateUrl, updateInit] = fetchMock.mock.calls[2]!; + expect(String(updateUrl)).toContain('/dns_records/dns-stale'); + expect(JSON.parse(updateInit.body)).toMatchObject({ content: '203.0.113.10' }); + }); + + // Control: an unrelated failure must still surface, with no lookup attempted. + it('still throws on an unrelated create failure', async () => { + const fetchMock = vi.fn() + .mockResolvedValueOnce(new Response(JSON.stringify({ + errors: [{ code: 10000, message: 'Authentication error' }], + }), { status: 403 })); + vi.stubGlobal('fetch', fetchMock); + + await expect(createNodeBackendDNSRecord('NODE-1', '203.0.113.10', env())) + .rejects.toThrow('Authentication error'); + expect(fetchMock).toHaveBeenCalledTimes(1); + }); + + // A failed lookup must not mask the original conflict with a confusing error. + it('surfaces the original conflict when the winner cannot be resolved', async () => { + const fetchMock = vi.fn() + .mockResolvedValueOnce(new Response(JSON.stringify({ + errors: [{ code: 81058, message: 'An identical record already exists.' }], + }), { status: 400 })) + .mockResolvedValueOnce(new Response('boom', { status: 500 })); + vi.stubGlobal('fetch', fetchMock); + + await expect(createNodeBackendDNSRecord('NODE-1', '203.0.113.10', env())) + .rejects.toThrow('An identical record already exists.'); + }); }); describe('deleteAppRouteDNSRecord', () => { diff --git a/apps/api/tests/unit/services/project-data-snapshot-recovery-wake.test.ts b/apps/api/tests/unit/services/project-data-snapshot-recovery-wake.test.ts index 7b6a7e4ba0..f4a1526755 100644 --- a/apps/api/tests/unit/services/project-data-snapshot-recovery-wake.test.ts +++ b/apps/api/tests/unit/services/project-data-snapshot-recovery-wake.test.ts @@ -1,5 +1,5 @@ import Database from 'better-sqlite3'; -import { beforeEach, describe, expect, it, vi } from 'vitest'; +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; import * as schema from '../../../src/db/schema'; import type { Env } from '../../../src/env'; @@ -92,6 +92,15 @@ function seedSnapshot( } beforeEach(() => { + // wakeSessionForSnapshotRecovery -> hasAuthorizedRestorableSnapshotWakeClaim + // does not accept an injected clock; it defaults to `new Date()`. Every fixture + // in this file (expires_at, sleeping_at, etc.) is seeded relative to `NOW`, so + // without freezing the clock the whole suite is a time bomb: it silently starts + // failing the moment real wall-clock time passes NOW + 7 days (the shortest + // relative offset used below), regardless of any code change. That is exactly + // what happened — this passed for months and broke on 2026-09-02. + vi.useFakeTimers(); + vi.setSystemTime(NOW); sqlite = new Database(':memory:'); createSchemaTables(sqlite, [schema.sessionSnapshots, schema.tasks, schema.workspaces]); wakeSessionRpc = vi.fn( @@ -115,6 +124,10 @@ beforeEach(() => { } as unknown as Env; }); +afterEach(() => { + vi.useRealTimers(); +}); + describe('wakeSessionForSnapshotRecovery', () => { it('allows a stopped ProjectData session to wake only with an authorized restorable claim', async () => { seedWorkspace(); diff --git a/apps/api/tests/workers/project-data-tool-payload-archive.test.ts b/apps/api/tests/workers/project-data-tool-payload-archive.test.ts index 06402fc5cb..6cf90faf2e 100644 --- a/apps/api/tests/workers/project-data-tool-payload-archive.test.ts +++ b/apps/api/tests/workers/project-data-tool-payload-archive.test.ts @@ -731,12 +731,21 @@ describe('ProjectData tool payload R2 archival', () => { { now: FIXED_NOW } ); const token = `${projectId}-token`; + // validateMcpToken checks token age against REAL wall-clock time + // (`Date.now()`, apps/api/src/services/mcp-token.ts) — it has no injectable + // clock, unlike the archival business logic above, which explicitly threads + // `now`/`nowMs` through runArchiveCleanup. Stamping createdAt with the + // archival fixture's FIXED_NOW (2026-08-26) made this token look far older + // than DEFAULT_MCP_TOKEN_MAX_LIFETIME_SECONDS (24h) the moment real time + // passed that date, and validateMcpToken fails closed on an expired token — + // hence the 401. The two clocks are independent; the token must use the real + // one. await storeMcpToken(env.KV, token, { taskId: `${projectId}-task`, projectId, userId, workspaceId: `${projectId}-workspace`, - createdAt: new Date(FIXED_NOW).toISOString(), + createdAt: new Date().toISOString(), }); const response = await callMcpTool(token, 'get_archived_tool_payloads', { diff --git a/packages/vm-agent/internal/deploy/compose.go b/packages/vm-agent/internal/deploy/compose.go index da00a6ae73..0a159a9131 100644 --- a/packages/vm-agent/internal/deploy/compose.go +++ b/packages/vm-agent/internal/deploy/compose.go @@ -13,6 +13,12 @@ import ( "time" ) +// composeOutputRetentionBytes caps how much compose output is kept for the error +// message. A long pull can emit megabytes of progress lines; the tail is what +// matters diagnostically and the whole thing would otherwise be embedded in an +// error string and a DB column. +const composeOutputRetentionBytes = 64 * 1024 + func (e *Engine) composeConfigPreflight(ctx context.Context, composeFile string, interpolationEnv map[string]string) error { return e.runCompose(ctx, composeFile, interpolationEnv, "config", "-q") } @@ -54,6 +60,87 @@ func (e *Engine) composeBinary() string { return parts[0] } +// setActiveApplySeq records which release the running apply belongs to, so +// liveness signals emitted from a child process can be addressed to the right +// watchdog. Returns a function restoring the previous value. +func (e *Engine) setActiveApplySeq(seq int64) func() { + e.activeSeqMu.Lock() + previous := e.activeSeq + e.activeSeq = seq + e.activeSeqMu.Unlock() + return func() { + e.activeSeqMu.Lock() + e.activeSeq = previous + e.activeSeqMu.Unlock() + } +} + +// signalLiveness pokes the apply watchdog without persisting a release event. +func (e *Engine) signalLiveness() { + if e == nil || e.cfg.ApplyLiveness == nil { + return + } + e.activeSeqMu.RLock() + seq := e.activeSeq + e.activeSeqMu.RUnlock() + if seq <= 0 { + // Outside an apply (teardown, manual down) there is no watchdog to feed. + return + } + e.cfg.ApplyLiveness(e.cfg.EnvironmentID, seq) +} + +// livenessWriter mirrors child output into a bounded TAIL buffer while reporting +// that the process is still producing output. It is the child-process analogue +// of newIdleProgressReader, which does the same for artifact downloads. +// +// Tail, not head: compose prints megabytes of "Pulling fs layer" progress and +// then the actual failure (`no such image`, `unauthorized`, `no space left on +// device`) on the LAST lines. Retaining the first N bytes would discard exactly +// the diagnostic this buffer exists to preserve. +// +// os/exec serializes writes to cmd.Stderr on one copier goroutine and Cmd.Wait +// blocks until that goroutine finishes, so neither the buffer nor reads after +// cmd.Run returns need additional locking. +type livenessWriter struct { + buf bytes.Buffer + signal func() + // limit caps retained output. The liveness signal keeps firing past the cap, + // so a very chatty pull cannot be killed as "stalled" merely because its + // output stopped being recorded. + limit int +} + +func (w *livenessWriter) Write(p []byte) (int, error) { + w.buf.Write(p) + // Amortized compaction: let the buffer reach 2x the cap before trimming, so a + // multi-megabyte pull costs O(total) copying rather than O(total x limit). + if w.limit > 0 && w.buf.Len() > 2*w.limit { + w.compact() + } + if w.signal != nil { + w.signal() + } + return len(p), nil +} + +// compact discards all but the trailing `limit` bytes. +func (w *livenessWriter) compact() { + if w.limit <= 0 || w.buf.Len() <= w.limit { + return + } + b := w.buf.Bytes() + tail := append([]byte(nil), b[len(b)-w.limit:]...) + w.buf.Reset() + w.buf.Write(tail) +} + +// String returns at most `limit` trailing bytes of the child's output. +func (w *livenessWriter) String() string { + w.compact() + return w.buf.String() +} + func (e *Engine) runCompose(ctx context.Context, composeFile string, interpolationEnv map[string]string, args ...string) error { parts := strings.Fields(e.cfg.ComposeCmd) cmdArgs := append(parts[1:], "--project-name", e.cfg.ComposeProjectName, "-f", composeFile) @@ -61,8 +148,10 @@ func (e *Engine) runCompose(ctx context.Context, composeFile string, interpolati cmd := exec.CommandContext(ctx, parts[0], cmdArgs...) cmd.Env = mergeEnv(os.Environ(), interpolationEnv) - var stderr bytes.Buffer - cmd.Stderr = &stderr + // Compose streams pull/extract progress to stderr. Treat every write as proof + // of life so a slow-but-progressing pull is not mistaken for a hung apply. + stderr := &livenessWriter{signal: e.signalLiveness, limit: composeOutputRetentionBytes} + cmd.Stderr = stderr redactor := newEnvRedactor(interpolationEnv) if err := cmd.Run(); err != nil { diff --git a/packages/vm-agent/internal/deploy/compose_liveness_test.go b/packages/vm-agent/internal/deploy/compose_liveness_test.go new file mode 100644 index 0000000000..fc7da2466a --- /dev/null +++ b/packages/vm-agent/internal/deploy/compose_liveness_test.go @@ -0,0 +1,268 @@ +package deploy + +import ( + "context" + "os" + "path/filepath" + "strings" + "sync" + "sync/atomic" + "testing" +) + +// writeComposeScript writes an executable stub standing in for `docker compose`. +func writeComposeScript(t *testing.T, body string) string { + t.Helper() + path := filepath.Join(t.TempDir(), "compose-stub.sh") + if err := os.WriteFile(path, []byte("#!/bin/sh\n"+body+"\n"), 0o755); err != nil { + t.Fatalf("write compose script: %v", err) + } + return path +} + +// A compose command that keeps producing output must keep the apply watchdog +// alive. This is the 2026-09-05 incident: `docker compose up` emits one release +// event when it starts and then nothing, so a legitimately slow image pull hit +// the idle timeout and was SIGKILLed mid-pull. Compose reports pull progress on +// stderr, so that output is what proves liveness. +func TestRunComposeSignalsLivenessFromChildOutput(t *testing.T) { + // Emits to stderr repeatedly, the way `docker compose up` reports pull progress. + script := writeComposeScript(t, ` +i=0 +while [ $i -lt 5 ]; do + echo "Pulling fs layer $i" >&2 + i=$((i+1)) +done +`) + + var signals atomic.Int64 + var gotEnv atomic.Value + var gotSeq atomic.Int64 + + engine := NewEngine(nil, nil, EngineConfig{ + EnvironmentID: "env-1", + ComposeCmd: script, + ApplyLiveness: func(environmentID string, seq int64) { + signals.Add(1) + gotEnv.Store(environmentID) + gotSeq.Store(seq) + }, + }) + + // Apply normally sets this; set it directly since we are calling runCompose. + restore := engine.setActiveApplySeq(7) + defer restore() + + if err := engine.runCompose(context.Background(), "compose.yaml", nil, "up", "-d"); err != nil { + t.Fatalf("runCompose: %v", err) + } + + if signals.Load() == 0 { + t.Fatal("child output produced no liveness signals — a slow pull would be killed as stalled") + } + if env, _ := gotEnv.Load().(string); env != "env-1" { + t.Fatalf("liveness environmentID = %q, want env-1", env) + } + if got := gotSeq.Load(); got != 7 { + t.Fatalf("liveness seq = %d, want 7 (the active apply)", got) + } +} + +// Control: a command that produces NO output must not fabricate liveness. +// Without this, a signal fired unconditionally per invocation would look like +// the fix while leaving a genuinely hung compose undetectable. +func TestRunComposeSilentCommandProducesNoLiveness(t *testing.T) { + script := writeComposeScript(t, `exit 0`) + + var signals atomic.Int64 + engine := NewEngine(nil, nil, EngineConfig{ + EnvironmentID: "env-1", + ComposeCmd: script, + ApplyLiveness: func(string, int64) { signals.Add(1) }, + }) + defer engine.setActiveApplySeq(7)() + + if err := engine.runCompose(context.Background(), "compose.yaml", nil, "up", "-d"); err != nil { + t.Fatalf("runCompose: %v", err) + } + if signals.Load() != 0 { + t.Fatalf("silent command emitted %d liveness signals, want 0", signals.Load()) + } +} + +// Outside an apply there is no watchdog to feed, so liveness must stay quiet +// rather than addressing signals to seq 0. +func TestRunComposeOutsideApplyEmitsNoLiveness(t *testing.T) { + script := writeComposeScript(t, `echo "tearing down" >&2`) + + var signals atomic.Int64 + engine := NewEngine(nil, nil, EngineConfig{ + EnvironmentID: "env-1", + ComposeCmd: script, + ApplyLiveness: func(string, int64) { signals.Add(1) }, + }) + // activeSeq deliberately left at 0 (no apply in flight). + + if err := engine.runCompose(context.Background(), "compose.yaml", nil, "down"); err != nil { + t.Fatalf("runCompose: %v", err) + } + if signals.Load() != 0 { + t.Fatalf("teardown emitted %d liveness signals, want 0", signals.Load()) + } +} + +// The stderr captured for the error message must survive being wrapped for +// liveness, since it is the operator's only view of why compose failed. +func TestRunComposePreservesStderrInError(t *testing.T) { + script := writeComposeScript(t, ` +echo "no such image: ghcr.io/example/missing:1" >&2 +exit 1 +`) + + engine := NewEngine(nil, nil, EngineConfig{ + EnvironmentID: "env-1", + ComposeCmd: script, + ApplyLiveness: func(string, int64) {}, + }) + defer engine.setActiveApplySeq(7)() + + err := engine.runCompose(context.Background(), "compose.yaml", nil, "up", "-d") + if err == nil { + t.Fatal("expected runCompose to fail") + } + if !strings.Contains(err.Error(), "no such image") { + t.Fatalf("error lost compose stderr: %v", err) + } +} + +// Retained output is capped, but the liveness signal must keep firing past the +// cap — otherwise a very chatty pull would go silent and be killed as stalled +// precisely because it was producing too much output. +func TestLivenessWriterSignalsPastRetentionCap(t *testing.T) { + var signals atomic.Int64 + w := &livenessWriter{signal: func() { signals.Add(1) }, limit: 8} + + chunk := []byte("0123456789") + for i := 0; i < 5; i++ { + if n, err := w.Write(chunk); err != nil || n != len(chunk) { + t.Fatalf("Write = (%d, %v), want (%d, nil)", n, err, len(chunk)) + } + } + + if got := len(w.String()); got != 8 { + t.Fatalf("retained %d bytes, want cap of 8", got) + } + if got := signals.Load(); got != 5 { + t.Fatalf("signals = %d, want 5 (one per write, including past the cap)", got) + } +} + +// The cap must retain the TAIL. Compose prints megabytes of progress and then +// the actual failure on its last lines, so head-retention would discard exactly +// the diagnostic the buffer exists to preserve. +func TestLivenessWriterRetainsTailNotHead(t *testing.T) { + w := &livenessWriter{limit: 16} + + w.Write([]byte("EARLY-PROGRESS-NOISE-")) + for i := 0; i < 50; i++ { + w.Write([]byte("Pulling fs layer ")) + } + w.Write([]byte("FATAL: no such image")) + + got := w.String() + if len(got) > 16 { + t.Fatalf("retained %d bytes, want <= 16", len(got)) + } + if !strings.Contains(got, "no such image") { + t.Fatalf("tail lost the failure reason; retained %q", got) + } + if strings.Contains(got, "EARLY-PROGRESS") { + t.Fatalf("retained the head instead of the tail: %q", got) + } +} + +// End-to-end through the real child process, emitting well over the 64 KiB +// retention cap so the trimming path is actually exercised: a compose run that +// emits a lot of progress and then fails must surface the failing line. +func TestRunComposeErrorKeepsTailOfChattyOutput(t *testing.T) { + script := writeComposeScript(t, ` +i=0 +while [ $i -lt 3000 ]; do + echo "Pulling fs layer $i ................................................" >&2 + i=$((i+1)) +done +echo "FATAL: manifest unknown for ghcr.io/example/db:17" >&2 +exit 1 +`) + + engine := NewEngine(nil, nil, EngineConfig{ + EnvironmentID: "env-1", + ComposeCmd: script, + ApplyLiveness: func(string, int64) {}, + }) + defer engine.setActiveApplySeq(7)() + + err := engine.runCompose(context.Background(), "compose.yaml", nil, "up", "-d") + if err == nil { + t.Fatal("expected runCompose to fail") + } + if !strings.Contains(err.Error(), "manifest unknown") { + t.Fatalf("error lost the failing tail line: %v", err) + } +} + +// setActiveApplySeq must restore the previous value so a nested/reverting apply +// cannot leave liveness addressed to the wrong release. +func TestSetActiveApplySeqRestoresPrevious(t *testing.T) { + engine := NewEngine(nil, nil, EngineConfig{EnvironmentID: "env-1"}) + + restoreOuter := engine.setActiveApplySeq(3) + func() { + defer engine.setActiveApplySeq(9)() + engine.activeSeqMu.RLock() + inner := engine.activeSeq + engine.activeSeqMu.RUnlock() + if inner != 9 { + t.Fatalf("inner activeSeq = %d, want 9", inner) + } + }() + + engine.activeSeqMu.RLock() + outer := engine.activeSeq + engine.activeSeqMu.RUnlock() + if outer != 3 { + t.Fatalf("activeSeq after inner restore = %d, want 3", outer) + } + restoreOuter() +} + +// The liveness callback is invoked from the goroutine draining child output +// while Apply writes activeSeq, so the pair must be race-free under -race. +func TestActiveApplySeqConcurrentAccess(t *testing.T) { + engine := NewEngine(nil, nil, EngineConfig{ + EnvironmentID: "env-1", + ApplyLiveness: func(string, int64) {}, + }) + + var wg sync.WaitGroup + stop := make(chan struct{}) + + wg.Add(1) + go func() { + defer wg.Done() + for { + select { + case <-stop: + return + default: + engine.signalLiveness() + } + } + }() + + for i := int64(1); i <= 200; i++ { + engine.setActiveApplySeq(i)() + } + close(stop) + wg.Wait() +} diff --git a/packages/vm-agent/internal/deploy/engine.go b/packages/vm-agent/internal/deploy/engine.go index 7f71a2d156..66720c25ae 100644 --- a/packages/vm-agent/internal/deploy/engine.go +++ b/packages/vm-agent/internal/deploy/engine.go @@ -40,6 +40,11 @@ type Engine struct { // Observed state (thread-safe reads) observedMu sync.RWMutex observed ObservedState + + // Seq of the apply currently running. Read from the goroutine draining a + // child process's output, written by Apply, so it needs its own guard. + activeSeqMu sync.RWMutex + activeSeq int64 } // DockerLoginFunc is the signature for authenticating to a container registry. @@ -47,6 +52,17 @@ type DockerLoginFunc func(ctx context.Context, registry, username, password stri type ApplyProgressFunc func(ctx context.Context, event ApplyProgressEvent) +// ApplyLivenessFunc reports that a long-running apply step is still doing work, +// WITHOUT persisting a release event. +// +// The apply watchdog is an idle timer fed by ApplyProgressFunc, i.e. by the same +// events that become deployment_release_events rows. `docker compose up` emits +// one event when it starts and then nothing until it returns, so a legitimately +// slow image pull looked identical to a hung apply and got SIGKILLed at the idle +// timeout. Compose reports pull/extract progress on stderr continuously, so that +// output is the liveness signal — but it is far too chatty to persist as events. +type ApplyLivenessFunc func(environmentID string, seq int64) + type ApplyProgressEvent struct { EnvironmentID string NodeID string @@ -178,6 +194,12 @@ func (e *Engine) Apply(ctx context.Context, payload *ApplyPayload) error { } defer e.applyMu.Unlock() + // Address liveness signals from child processes (compose) to this release's + // watchdog for the duration of the apply, including the revert path. + if payload != nil { + defer e.setActiveApplySeq(payload.Seq)() + } + // Get current applied seq for verification currentSeq, err := e.disk.CurrentSeq() if err != nil { diff --git a/packages/vm-agent/internal/deploy/engine_config.go b/packages/vm-agent/internal/deploy/engine_config.go index 3810eaa999..27b98691d0 100644 --- a/packages/vm-agent/internal/deploy/engine_config.go +++ b/packages/vm-agent/internal/deploy/engine_config.go @@ -28,6 +28,7 @@ type EngineConfig struct { ArtifactIdleTimeout time.Duration PreflightCommandTimeout time.Duration ApplyProgress ApplyProgressFunc + ApplyLiveness ApplyLivenessFunc DockerLogin DockerLoginFunc // defaults to cache.DockerLogin if nil MountChecker MountChecker // defaults to RealMountChecker if nil VolumeMounter VolumeMounter // defaults to RealVolumeMounter if nil diff --git a/packages/vm-agent/internal/server/deploy_apply_dedup_test.go b/packages/vm-agent/internal/server/deploy_apply_dedup_test.go new file mode 100644 index 0000000000..9e4ffdf02b --- /dev/null +++ b/packages/vm-agent/internal/server/deploy_apply_dedup_test.go @@ -0,0 +1,239 @@ +package server + +import ( + "net/http" + "net/http/httptest" + "path/filepath" + "strings" + "sync" + "sync/atomic" + "testing" + "time" + + "github.com/workspace/vm-agent/internal/config" + "github.com/workspace/vm-agent/internal/deploy" + "github.com/workspace/vm-agent/internal/persistence" +) + +// applyDedupHarness stands up a Server plus a control-plane stub that counts +// deploy-release fetches and blocks until released, so a second invocation can +// be attempted while the first is genuinely still running. +type applyDedupHarness struct { + server *Server + engine *deploy.Engine + fetches *atomic.Int64 + release chan struct{} +} + +func newApplyDedupHarness(t *testing.T) *applyDedupHarness { + t.Helper() + + fetches := &atomic.Int64{} + release := make(chan struct{}) + ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + if strings.Contains(r.URL.Path, "/deploy-release") || strings.Contains(r.URL.Path, "/deploy-routes") { + fetches.Add(1) + select { + case <-release: + case <-r.Context().Done(): + } + w.WriteHeader(http.StatusConflict) + return + } + w.WriteHeader(http.StatusNotFound) + })) + t.Cleanup(ts.Close) + + store, err := persistence.Open(filepath.Join(t.TempDir(), "vm-agent.db")) + if err != nil { + t.Fatalf("Open persistence store: %v", err) + } + t.Cleanup(func() { _ = store.Close() }) + + s := &Server{ + config: &config.Config{ + NodeID: "node-1", + ControlPlaneURL: ts.URL, + CallbackToken: "callback-token", + DeployApplyIdleTimeout: 10 * time.Second, + }, + store: store, + applyWatchdogs: make(map[string]chan struct{}), + inFlightJobs: make(map[string]struct{}), + } + + disk, err := deploy.NewDiskState(filepath.Join(t.TempDir(), "state")) + if err != nil { + t.Fatalf("NewDiskState: %v", err) + } + engine := deploy.NewEngine(disk, nil, deploy.EngineConfig{ + EnvironmentID: "env-1", + NodeID: "node-1", + ControlPlaneURL: ts.URL, + HTTPClient: deploy.NewArtifactHTTPClient(deploy.ArtifactHTTPClientConfig{}), + ApplyProgress: s.persistApplyProgress, + ApplyLiveness: s.signalApplyLiveness, + }) + + return &applyDedupHarness{ + server: s, + engine: engine, + fetches: fetches, + release: release, + } +} + +// waitForFetches blocks until the stub has served n fetches, or fails the test. +// Deliberately a real deadline: an earlier version used `select` with a +// `default` branch, which makes the `time.After` case unreachable and turns the +// wait into an unbounded busy loop. +func (h *applyDedupHarness) waitForFetches(t *testing.T, n int64) { + t.Helper() + deadline := time.Now().Add(5 * time.Second) + for time.Now().Before(deadline) { + if h.fetches.Load() >= n { + return + } + time.Sleep(2 * time.Millisecond) + } + t.Fatalf("timed out waiting for %d control-plane fetches (saw %d)", n, h.fetches.Load()) +} + +// The incident's upstream cause: the heartbeat re-advertises a pending release +// on every tick until observed.AppliedSeq advances, and that only happens after +// a full successful apply. Any release slower than one heartbeat interval used +// to spawn another concurrent apply per tick — each re-running the whole +// control-plane fetch, which is where the app-route DNS create race lives. +func TestRunDetachedDeploymentApplySkipsDuplicateInFlightJob(t *testing.T) { + h := newApplyDedupHarness(t) + + var wg sync.WaitGroup + wg.Add(1) + go func() { + defer wg.Done() + h.server.runDetachedDeploymentApply("env-1", 7, h.engine) + }() + + h.waitForFetches(t, 1) + + // Second heartbeat tick for the SAME release while the first is still running. + h.server.runDetachedDeploymentApply("env-1", 7, h.engine) + + if got := h.fetches.Load(); got != 1 { + t.Fatalf("deploy-release fetches = %d, want 1 (duplicate should be skipped)", got) + } + + close(h.release) + wg.Wait() +} + +// Discriminating control: a genuinely different release must NOT be skipped, or +// the guard would stall every subsequent deployment. +func TestRunDetachedDeploymentApplyAllowsDifferentSeq(t *testing.T) { + h := newApplyDedupHarness(t) + close(h.release) // let fetches return immediately + + h.server.runDetachedDeploymentApply("env-1", 7, h.engine) + h.server.runDetachedDeploymentApply("env-1", 8, h.engine) + + if got := h.fetches.Load(); got != 2 { + t.Fatalf("deploy-release fetches = %d, want 2 (distinct seqs must both run)", got) + } +} + +// The claim must be released when an apply finishes, or a retry of the same seq +// after a transient failure would be skipped forever and the node would silently +// stop applying that release. +func TestRunDetachedDeploymentApplyReleasesClaimOnCompletion(t *testing.T) { + h := newApplyDedupHarness(t) + close(h.release) + + h.server.runDetachedDeploymentApply("env-1", 7, h.engine) + h.server.runDetachedDeploymentApply("env-1", 7, h.engine) + + if got := h.fetches.Load(); got != 2 { + t.Fatalf("deploy-release fetches = %d, want 2 (claim must be released after completion)", got) + } +} + +// Route-config applies are spawned from the same heartbeat loop and need the +// same guard. +func TestRunDetachedDeploymentRouteApplySkipsDuplicateInFlightJob(t *testing.T) { + h := newApplyDedupHarness(t) + + var wg sync.WaitGroup + wg.Add(1) + go func() { + defer wg.Done() + h.server.runDetachedDeploymentRouteApply("env-1", 3, h.engine) + }() + + h.waitForFetches(t, 1) + + h.server.runDetachedDeploymentRouteApply("env-1", 3, h.engine) + + if got := h.fetches.Load(); got != 1 { + t.Fatalf("route-config fetches = %d, want 1 (duplicate should be skipped)", got) + } + + close(h.release) + wg.Wait() +} + +// claimJob is reached from many heartbeat goroutines at once; it must hand out +// exactly one claim per id under -race. +func TestClaimJobIsExclusiveUnderConcurrency(t *testing.T) { + s := &Server{inFlightJobs: make(map[string]struct{})} + + var claimed atomic.Int64 + var wg sync.WaitGroup + for i := 0; i < 64; i++ { + wg.Add(1) + go func() { + defer wg.Done() + if _, ok := s.claimJob("job-1"); ok { + claimed.Add(1) + } + }() + } + wg.Wait() + + if got := claimed.Load(); got != 1 { + t.Fatalf("concurrent claims granted = %d, want exactly 1", got) + } +} + +// Releasing twice must not corrupt the set or free a claim someone else holds. +func TestClaimJobReleaseIsIdempotent(t *testing.T) { + s := &Server{inFlightJobs: make(map[string]struct{})} + + release, ok := s.claimJob("job-1") + if !ok { + t.Fatal("first claim was refused") + } + release() + release() + + release2, ok2 := s.claimJob("job-1") + if !ok2 { + t.Fatal("claim after release was refused") + } + + if _, ok3 := s.claimJob("job-1"); ok3 { + t.Fatal("second concurrent claim granted after re-claim — release() freed a live claim") + } + release2() +} + +// A nil map (as older test fixtures construct) must not panic. +func TestClaimJobHandlesNilMap(t *testing.T) { + s := &Server{} + release, ok := s.claimJob("job-1") + if !ok { + t.Fatal("claim on nil map was refused") + } + if _, ok2 := s.claimJob("job-1"); ok2 { + t.Fatal("duplicate claim granted after lazy map init") + } + release() +} diff --git a/packages/vm-agent/internal/server/health.go b/packages/vm-agent/internal/server/health.go index ae02a3d101..a78cccec02 100644 --- a/packages/vm-agent/internal/server/health.go +++ b/packages/vm-agent/internal/server/health.go @@ -376,6 +376,18 @@ func (s *Server) sendNodeHeartbeat() { func (s *Server) runDetachedDeploymentApply(environmentID string, seq int64, engine *deploy.Engine) { jobID := applyJobID(environmentID, seq) + + // Skip if an identical apply is already running. Deferred so the claim is + // released even if the apply panics — otherwise this job id stays wedged and + // the node stops applying that release entirely. + releaseClaim, claimed := s.claimJob(jobID) + if !claimed { + slog.Info("deploy: apply already in flight; skipping duplicate", + "environmentId", environmentID, "seq", seq) + return + } + defer releaseClaim() + s.persistVMJobStart(jobID, vmJobKindApply, environmentID, vmJobStatusStarting, "accepted") cleanup := s.registerApplyWatchdog(jobID) defer cleanup() @@ -416,11 +428,19 @@ func (s *Server) runDetachedDeploymentApply(environmentID string, seq int64, eng } timer.Reset(idleTimeout) case <-timer.C: - err := fmt.Errorf("deployment apply stalled: no progress for %s", idleTimeout) - cancel(err) + stallErr := fmt.Errorf("deployment apply stalled: no progress for %s", idleTimeout) + cancel(stallErr) applyErr := <-done + + // The child's error is a CONSEQUENCE of the cancel above — compose + // reports `signal: killed` because we killed it. Reporting only that + // discards the diagnosis and makes a self-inflicted timeout + // indistinguishable from an OOM kill, which is exactly how the + // 2026-09-05 incident presented. Keep the stall as the primary cause + // and carry the child's output as context. + err := stallErr if applyErr != nil { - err = applyErr + err = fmt.Errorf("%w (child result: %v)", stallErr, applyErr) } s.persistVMJobComplete(jobID, vmJobStatusFailed, "stalled", err.Error(), nil) slog.Error("deploy: fetch and apply stalled", @@ -432,6 +452,17 @@ func (s *Server) runDetachedDeploymentApply(environmentID string, seq int64, eng func (s *Server) runDetachedDeploymentRouteApply(environmentID string, revision int64, engine *deploy.Engine) { jobID := routeConfigJobID(environmentID, revision) + + // Same duplicate-spawn guard as the apply path: pending route configs are + // re-advertised every heartbeat until observed.RoutingRevision catches up. + releaseClaim, claimed := s.claimJob(jobID) + if !claimed { + slog.Info("deploy: route config apply already in flight; skipping duplicate", + "environmentId", environmentID, "revision", revision) + return + } + defer releaseClaim() + s.persistVMJobStart(jobID, vmJobKindRouteConfig, environmentID, vmJobStatusStarting, "accepted") idleTimeout := s.config.DeployApplyIdleTimeout diff --git a/packages/vm-agent/internal/server/server.go b/packages/vm-agent/internal/server/server.go index dc435b4784..b9ba846561 100644 --- a/packages/vm-agent/internal/server/server.go +++ b/packages/vm-agent/internal/server/server.go @@ -124,6 +124,14 @@ type Server struct { sessionSnapshotLocks map[string]*sync.Mutex sessionSnapshotRunner func(context.Context, *sessionSnapshotHandlerInput) (map[string]interface{}, error) + // inFlightJobs dedupes detached deployment work by job id. The heartbeat + // re-advertises a pending release on every tick until observed.AppliedSeq + // catches up, and that only happens after a full successful apply — so + // without this, any release slower than one heartbeat interval spawns another + // concurrent apply per tick, each re-running the whole control-plane fetch. + inFlightJobsMu sync.Mutex + inFlightJobs map[string]struct{} + // Deployment mode — one Engine per placed deployment environment. deployMu sync.Mutex deployEngines map[string]*deploy.Engine @@ -553,6 +561,7 @@ func New(cfg *config.Config) (*Server, error) { done: make(chan struct{}), publishJobs: make(map[string]publishJobState), applyWatchdogs: make(map[string]chan struct{}), + inFlightJobs: make(map[string]struct{}), deployEngines: make(map[string]*deploy.Engine), deployRetiring: make(map[string]bool), } @@ -688,6 +697,7 @@ func (s *Server) ensureDeployEngine(environmentID string) *deploy.Engine { }), ArtifactIdleTimeout: s.config.DeployArtifactIdleTimeout, ApplyProgress: s.persistApplyProgress, + ApplyLiveness: s.signalApplyLiveness, ACMEEmail: s.config.DeployACMEEmail, ACMECA: s.config.DeployACMECA, }) diff --git a/packages/vm-agent/internal/server/vm_jobs.go b/packages/vm-agent/internal/server/vm_jobs.go index 4be98642de..206ecae7b5 100644 --- a/packages/vm-agent/internal/server/vm_jobs.go +++ b/packages/vm-agent/internal/server/vm_jobs.go @@ -6,6 +6,7 @@ import ( "fmt" "log/slog" "strings" + "sync" "github.com/workspace/vm-agent/internal/deploy" "github.com/workspace/vm-agent/internal/persistence" @@ -82,6 +83,45 @@ func (s *Server) persistApplyProgress(_ context.Context, event deploy.ApplyProgr } } +// claimJob reserves a detached-deployment job id, returning a release function +// and whether the claim succeeded. A false claim means an identical job is +// already running and this invocation must be skipped. +// +// The heartbeat re-advertises a pending release on every tick until +// observed.AppliedSeq advances, which only happens after a full successful +// apply. Any release slower than one heartbeat interval therefore used to spawn +// another concurrent apply per tick, each re-running the whole control-plane +// fetch: re-decrypting secrets, re-minting a registry credential, regenerating +// presigned artifact URLs, re-signing the payload, and racing on app-route DNS +// creation (the failure loud enough to 500 — see .claude/rules/68). +// +// The release is invoked via defer so it runs on every exit path. (This codebase +// has no recover() anywhere, so a panic would take the process down and clear the +// map regardless — the defer is defence for future call sites that return early, +// not protection against a panic that cannot currently be survived.) +func (s *Server) claimJob(jobID string) (release func(), claimed bool) { + if s == nil { + return func() {}, true + } + s.inFlightJobsMu.Lock() + defer s.inFlightJobsMu.Unlock() + if s.inFlightJobs == nil { + s.inFlightJobs = make(map[string]struct{}) + } + if _, exists := s.inFlightJobs[jobID]; exists { + return func() {}, false + } + s.inFlightJobs[jobID] = struct{}{} + var once sync.Once + return func() { + once.Do(func() { + s.inFlightJobsMu.Lock() + delete(s.inFlightJobs, jobID) + s.inFlightJobsMu.Unlock() + }) + }, true +} + func (s *Server) registerApplyWatchdog(jobID string) func() { if s == nil { return func() {} @@ -97,6 +137,15 @@ func (s *Server) registerApplyWatchdog(jobID string) func() { } } +// signalApplyLiveness feeds the apply watchdog from a long-running child process +// without persisting a release event. See deploy.ApplyLivenessFunc. +func (s *Server) signalApplyLiveness(environmentID string, seq int64) { + if s == nil || strings.TrimSpace(environmentID) == "" { + return + } + s.signalApplyProgress(applyJobID(environmentID, seq)) +} + func (s *Server) signalApplyProgress(jobID string) { if s == nil { return diff --git a/tasks/active/2026-09-05-fix-app-route-dns-upsert-race.md b/tasks/active/2026-09-05-fix-app-route-dns-upsert-race.md new file mode 100644 index 0000000000..642b0502c5 --- /dev/null +++ b/tasks/active/2026-09-05-fix-app-route-dns-upsert-race.md @@ -0,0 +1,265 @@ +# Fix: concurrent `upsertAppRouteDNSRecord` create race wedges deployments + +**Status:** implemented, PR open +**Discovered:** 2026-09-05, debugging a stuck deployment on the `defanglabs.ca` install + +## Problem + +A deployment environment stalled with no app-route DNS record and no TLS certificate. +The node had booted fine and was heartbeating. The control plane had logged exactly one +error in the whole window: + +``` + time : 12:55:58 + source : api + node : 01M1RS3F0SKBQSPMRVSJQSSMF2 + message : An identical record already exists. + context : {"path":"/api/nodes/01M1RS3F…/deploy-release","method":"GET","status":500} + stack : Error: An identical record already exists. + at upsertAppRouteDNSRecord (index.js:137759) + at async Promise.all (index 0) +``` + +`GET /api/nodes/:id/deploy-release` is the handler the deployment node calls to fetch its +release payload. It upserts every app-route DNS record before returning that payload. One +upsert threw, so the whole request 500'd and the node never received its release — the +deployment stalled *upstream* of anything cert-related. + +## Root cause + +`upsertAppRouteDNSRecord` (`apps/api/src/services/dns.ts`) is a check-then-act with an +`await` in the gap: + +```ts +const existing = await findDNSRecordByName(hostname, env); // CHECK +... +method: existing ? 'PUT' : 'POST', // ACT +``` + +It is invoked concurrently — `deploy-release-callback.ts:306` and `:328` upsert every route +through `Promise.all`, and overlapping node release fetches run that whole handler more than +once. Two callers both observe "no record", both `POST`, and Cloudflare rejects the loser +with 81058. `!response.ok` threw straight out through `Promise.all`. + +### Evidence this is a race, not a stale-record bug + +1. The lookup is an exact `?type=A&name=` match, so "not found, then rejected as duplicate" + can only mean the record appeared between the two calls. +2. Cloudflare's "An identical record already exists" (81058) means same name **and** type + **and** content — a different-type collision returns 81053 instead. Identical content = + the same node IP = two identical concurrent POSTs. +3. `deployment_release_events` for a live environment shows the handler running concurrently: + two `fetch_started` events 1s apart, two `fetch_completed`, and `seq=4` written twice by + two invocations that each allocated it independently. +4. The sibling `deleteAppRouteDNSRecord` is already documented as tolerant of "a record + already removed by a concurrent caller". The delete path was hardened for concurrency; + the create path never was. + +## Fix + +Treat Cloudflare's duplicate-record codes on the **create** path as a lost race: re-resolve +once and update the record in place. Bounded to a single retry. + +- Scoped to codes `81057` / `81058` only. `81053` (different-type collision) is a genuine + misconfiguration that retrying cannot fix and must keep surfacing. +- Scoped to the create path (`!existing`) — only that path can lose this race. +- `readCloudflareErrorDetail` reads `{ code, message }` in one pass, because a `Response` + body can only be consumed once. `readCloudflareError` delegates to it, so every other + call site is unchanged. + +## Also fixed: the sibling in the same module + +`createNodeBackendDNSRecord` (same file) had the identical race with a worse failure mode, +found by the architecture reviewer against this PR's own rule 68 §6. It was a blind POST +with no lookup at all. Two paths create that record — node provisioning +(`services/nodes.ts:373`) and the heartbeat backfill (`routes/node-lifecycle.ts:446`) — and +the loser threw. The catch at `node-lifecycle.ts:460` only stamps `nodes.error_message` and +leaves `backend_dns_record_id` NULL, so: + +- every later heartbeat retried the same losing POST, forever (no backfill job exists), and +- node deletion, which deletes by that id, left the real record orphaned in the zone. + +Now resolves the winner on conflict and returns its id, so the id gets persisted — which +fixes both consequences. 81057 does not guarantee matching content, so the IP is converged +with a `PUT` before the id is handed back. + +## Tests + +`apps/api/tests/unit/services/dns-app-routes.test.ts` (14 → 23): + +- recovers when a concurrent caller wins the create (81057 and 81058) +- **control:** the UPDATE path does NOT retry on the same code — enforces rule 68 §4 +- **control:** still throws on 81053 different-type collision, with no retry +- **control:** still throws on an unrelated failure (auth error) +- **regression:** `code: null` / stringified code preserve the real Cloudflare message +- retries at most once, then surfaces the duplicate error (no unbounded loop) +- two concurrent callers for the SAME hostname converge on one record, driven against a + shared fake CF store so the interleaving picks the winner +- a losing route does not fail the `Promise.all` batch that gates the release fetch +- five tests for the `createNodeBackendDNSRecord` sibling (happy path, winner resolution, + IP convergence on 81057, unrelated-failure control, unresolvable-winner control) + +`apps/api/tests/unit/routes/deploy-release-callback.test.ts` (31 → 32): + +- **vertical slice:** the endpoint still returns 200 when a route loses the create race + +**Proven discriminating** (each verified once, then reverted): + +| Mutation | Result | +|---|---| +| tolerance disabled | 4 race tests red, 10 controls green | +| `!existing` removed (widen to update path) | exactly the update-path control red | +| sibling conflict-recovery disabled | exactly the 2 sibling recovery tests red | +| `code: v.optional(v.number())` restored | exactly the 2 message-preservation tests red | +| pre-fix `dns.ts` + route suite | the new route test red; **the other 31 all passed** | + +That last row is the point: the route suite could not observe the production 500 before +this PR added a test at the real entry point. + +Full API unit suite: 8052/8053 passing, 0 collection errors, total reconciled 8043 → 8053 +(+10). The single failure — `wakeSessionForSnapshotRecovery ... authorized restorable +claim` — is pre-existing and unrelated, verified by stashing these changes and re-running. + +## Post-mortem + +- **What broke:** deployments stalled with no DNS record and no certificate. The visible + symptom (missing cert) was three layers downstream of the actual failure. +- **Root cause:** check-then-act against an external API that enforces its own uniqueness + constraint, with the conflict treated as fatal. +- **Why it wasn't caught:** the existing tests covered create-when-absent and + update-when-present — the two *sequential* outcomes. Nothing exercised two callers + interleaving, even though the only production call site is a `Promise.all` fan-out. +- **Class of bug:** *check-then-act against a remote uniqueness constraint.* The local + analogue (rule 45) is about Durable Object `await` interleaving and is solved with a + mutex. A mutex is not proportionate across isolates when the remote API already + adjudicates the conflict in one round trip, so the control-plane fix converges on its + answer instead. Review then showed the overlap itself was preventable one layer up, on + the caller: this PR does both — remove the cause (dedup guard) and survive it anyway + (tolerance), because old agents keep retrying until they are replaced. +- **Aggravating factor:** the conflict was fatal on a path that gates an entire + deployment. A recoverable, self-correcting condition became a permanent wedge. +- **Second class of bug, same incident:** *a watchdog fed by a signal that cannot observe + the work it is guarding.* The apply idle timer was reset only by release events, and the + longest step in an apply emits none — so the guard was structurally blind to exactly the + operation most likely to be slow. The generalisation is rule 53's "a signal that cannot + answer the question being asked of it", applied to a child process rather than a column. + +## Process fix + +`.claude/rules/68-external-api-check-then-act.md` — added. + +## Live production evidence for both fixes (env `pr18-preview-3`, 2026-09-05) + +Captured from `deployment_release_events` while this branch was being written. A +single environment, one node, 13:53 → 15:19: + +``` + 12x deployment.apply.fetch_started 13:53:16 -> 15:18:16 + 11x deployment.apply.fetch_completed 13:53:18 -> 15:18:20 + 6x deployment.apply.started 13:53:19 -> 15:18:21 + 6x deployment.apply.compose_up_started 13:55:48 -> 15:19:20 + 0x (no compose_up_completed, ever) +``` + +Two independent confirmations: + +1. **12 fetches for 6 applies — an exact 2:1 ratio.** Every apply is preceded by + two `fetch_started`. The duplicate goroutine's `Apply()` is rejected by the + engine's `applyMu.TryLock()`, which is why applies are half the fetches — but + the fetch itself has already run, and the fetch is what upserts DNS. Those are + 12 opportunities to lose the create race, on one environment, in 85 minutes. +2. **6 compose_up starts, zero completions**, cycling roughly every 14 minutes — + matching `DefaultDeployApplyIdleTimeout` of 15 minutes. Each apply reaches + compose up, emits no further `ApplyProgressEvent`, and is SIGKILLed by the + idle watchdog mid-pull. + +This is why both fixes are in this PR: the DNS tolerance stops the race being +fatal, the dedup guard stops it being attempted twice per cycle, and the compose +liveness signal stops the apply being killed while it is genuinely working. + +## Also fixed: the duplicate-spawn root cause (vm-agent) + +`health.go:319-339` spawned a new `runDetachedDeploymentApply` goroutine on every +heartbeat for every pending release, with no in-flight check. `observed.AppliedSeq` +only advances after a *fully successful* apply, so any release slower than one +heartbeat interval accumulated another concurrent apply per tick — each re-running +the whole control-plane fetch (re-decrypting secrets, re-minting a registry +credential, regenerating presigned artifact URLs, re-signing the payload, and +racing on DNS). + +Added `claimJob(jobID)`, an atomic claim over a shared in-flight set, applied to +both the apply path and the route-config path (which had the same defect). The +release runs via `defer` so a panicking apply cannot wedge a job id permanently — +that would silently stop the node applying that release at all. + +## Also fixed: compose killed mid-pull by the apply idle watchdog + +`runDetachedDeploymentApply` bounds the apply with a 15-minute **idle** timer that +is reset only by `ApplyProgressEvent`s — the same events that become +`deployment_release_events` rows. `docker compose up` emits exactly one +(`compose_up_started`) and then nothing until it returns, so a legitimately slow +image pull was indistinguishable from a hung apply and got SIGKILLed. + +Compose streams pull/extract progress to stderr continuously, so that output is +now the liveness signal: `runCompose` wraps stderr in a `livenessWriter` that pokes +the watchdog on every write without persisting an event. This mirrors +`newIdleProgressReader`, which already does exactly this for artifact downloads. +Retained output is capped at 64 KiB for the error message, but the signal keeps +firing past the cap — otherwise a very chatty pull would be killed *because* it +produced too much output. + +The cap retains the **tail**, not the head. The first cut kept the head, which the +go-specialist review caught: compose prints megabytes of "Pulling fs layer" and +then the actual failure (`manifest unknown`, `no such image`, `no space left on +device`) on its last lines, so head-retention would have discarded precisely the +diagnostic this buffer exists to preserve — silently re-introducing the +diagnosability bug being fixed three paragraphs above. Compaction is amortized +(the buffer is allowed to reach 2x the cap before trimming) so a multi-megabyte +pull costs O(total) copying rather than O(total x limit). + +Also fixed the diagnostic that hid this: `health.go` overwrote the accurate +`"deployment apply stalled: no progress for 15m0s"` with the child's +`signal: killed`, which is a *consequence* of our own cancel. The stall is now the +primary error with the child result as context, so a self-inflicted timeout is no +longer indistinguishable from an OOM kill. + +## Known limitation: the DNS fix tolerates the race rather than preventing it + +The `dns.ts` tolerance is retained even though the dedup guard now prevents the overlap, +because `GET /deploy-release` is deliberately retry-tolerant by design — a node must be +able to re-fetch after a lost response, and old agents will keep doing so until they are +replaced (rule 54: the control-plane fix must stand alone for already-deployed agents). +Defence in depth is the point: the guard removes the cause, the tolerance survives it. + +**Still unexplained:** the two original `fetch_started` events were 1 second apart, which +does not match the 60s default `HEARTBEAT_INTERVAL`. The `pr18-preview-3` data shows the +2:1 fetch/apply ratio the goroutine-per-heartbeat bug predicts, but the 1-second spacing +suggests a second trigger (a manual retry, a `deployment-env` poll, or a heartbeat burst) +that was not identified. The dedup guard closes the window regardless of which path spawned +the duplicate, since it keys on the job id rather than the caller. + +## Also fixed: `deployment_volumes.status` frozen at the provider's snapshot + +`attachEnvironmentVolumes` persisted `attached.status` straight from the +provider's `attachVolume` response. Hetzner commonly still reports `creating` at +that instant, and **nothing ever re-polls the row** — the only other writer is the +detach path (`deployment-volumes.ts:583-592` vs `:675-684`). So an attached, +mounted, fully working volume read `creating` forever. + +Observed in production on volume `01M1RWP6VA…` (`pgdata`) while its own +`deployment_release_events` showed `volume_mount_completed` and +`volume_mounts_verified` — the mount demonstrably worked. It is the single most +obvious "here is your stuck deployment" signal, and it is a false one; it +misdirected this investigation before code reading showed the heartbeat gate +(`node-lifecycle.ts:89-127`) keys on `attached_server_id`, not `status`. + +Now persists the settled SAM-side fact (`attached`) rather than a transient +snapshot that will never be corrected. No migration and no constraint widening: +the column is plain `TEXT` with no `CHECK` (`0069_deployment_volumes.sql:14`) and +`attached` is already a member of the provider `VolumeStatus` union. `failed` +semantics on the creation path are untouched. + +This is rule 57 (write-only cross-boundary state must be reconciled, not just +reported) at the storage layer: a remote-owned value written once and never +reconciled. Reconciliation by polling was rejected as disproportionate — the +value SAM needs is knowable locally the moment attach returns.