From 56ebb4aa1a8e4c5a6a049e22897b4f85489ee90a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rapha=C3=ABl=20Titsworth-Morin?= Date: Sat, 5 Sep 2026 16:02:51 +0000 Subject: [PATCH 1/5] fix(api): tolerate concurrent DNS record creation on both create paths MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A deployment stalled with no app-route DNS record and no TLS certificate. The control plane had logged exactly one error in the whole window: a 500 from GET /api/nodes/:id/deploy-release, thrown by upsertAppRouteDNSRecord out of a Promise.all, with Cloudflare's "An identical record already exists." That endpoint upserts every app-route DNS record before returning the node's release payload, so the throw meant the node never received its release and the deployment stalled upstream of anything cert-related. The missing certificate was three layers downstream of the actual failure. upsertAppRouteDNSRecord is a check-then-act with an await in the gap. Its only production call site fans it out over every route via Promise.all, and overlapping release fetches run the whole handler concurrently. Two callers both observe "no record", both POST, and Cloudflare rejects the loser with 81058. Evidence this is a race, not a stale record: - 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; - 81058 means same name AND type AND content (a cross-type collision returns 81053), so identical content = same node IP = two identical concurrent POSTs; - deployment_release_events shows the handler running concurrently: two fetch_started 1s apart and seq=4 written twice by two invocations; - deleteAppRouteDNSRecord was already documented as tolerant of "a record already removed by a concurrent caller" — delete had been hardened for concurrency, create never was. Fix: on the create path, treat the duplicate-record codes as a lost race — re-resolve once and update in place. Scoped to 81057/81058 (81053 is a genuine misconfiguration retrying cannot fix and still throws), to the create path only (!existing), and bounded by DNS_UPSERT_RACE_MAX_RETRIES. Also fixes the same class in createNodeBackendDNSRecord, in the same file, whose failure mode was worse: a blind POST with no lookup at all. Two paths create that record (services/nodes.ts provisioning and the node-lifecycle heartbeat backfill); on conflict the caller 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 — orphaned the real record. It now resolves the winner so the id is persisted, converging the IP first since 81057 does not guarantee matching content. readCloudflareErrorDetail reads {code, message} in one pass because a Response body can only be consumed once; readCloudflareError delegates to it so the five other call sites are unchanged. `code` is parsed as unknown and narrowed with typeof at use — valibot's optional() only bypasses a missing key, so v.optional(v.number()) would fail the whole entry on `code: null` and silently replace Cloudflare's real message with a generic fallback for those five callers. Process fix: .claude/rules/68-external-api-check-then-act.md. Its requirement 6 (check sibling operations in the same module) is what surfaced the createNodeBackendDNSRecord instance. Tests (dns-app-routes 14 -> 23, deploy-release-callback 31 -> 32) cover both tolerated codes, the update-path guard, 81053 and auth controls, the null and stringified code regressions, the single-retry bound, a same-hostname race against a shared fake CF store, the Promise.all fan-out, five sibling tests, and a route-level vertical slice. Each guard verified discriminating once and reverted; notably, on pre-fix dns.ts the new route test fails while the other 31 route tests all pass — the existing suite could not observe the production 500. Co-Authored-By: Claude --- .../rules/68-external-api-check-then-act.md | 137 +++++++ apps/api/src/services/dns.ts | 192 ++++++++-- .../routes/deploy-release-callback.test.ts | 48 +++ .../unit/services/dns-app-routes.test.ts | 340 ++++++++++++++++++ 4 files changed, 685 insertions(+), 32 deletions(-) create mode 100644 .claude/rules/68-external-api-check-then-act.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/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/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', () => { From 224f060c25c5715695b5183d587b6def35c01a09 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rapha=C3=ABl=20Titsworth-Morin?= Date: Sat, 5 Sep 2026 16:03:17 +0000 Subject: [PATCH 2/5] fix(vm-agent): dedupe apply spawns and keep compose alive during slow pulls MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two further defects in the same incident: the cause of the DNS race above, and the failure that was killing deployments outright. 1. Duplicate apply spawns health.go 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 app-route DNS creation. Live evidence, env pr18-preview-3, one node, 13:53-15:19: 16x deployment.apply.fetch_started 8x deployment.apply.started 8x deployment.apply.compose_up_started 0x compose_up_completed An exact 2:1 fetch/apply ratio. The duplicate's Apply() is rejected by the engine's applyMu.TryLock(), which is why applies are half the fetches — but the fetch has already run, and the fetch is what upserts DNS. 16 chances to lose the race on one environment in 85 minutes. claimJob(jobID) is an atomic claim over a shared in-flight set, applied to the apply path and the route-config path, which had the same defect. Released via defer, idempotent, and safe on a nil map so existing test fixtures still work. 2. Compose SIGKILLed mid-pull by the apply idle watchdog The apply is bounded by a 15-minute IDLE timer reset only by ApplyProgressEvents — 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. That is the 8-starts/0-completions column above, cycling every ~14 minutes, and it is what produced `compose up: ... signal: killed (stderr: db Pulling ...)`. Compose streams pull/extract progress to stderr, so that output is now the liveness signal: runCompose wraps stderr in a livenessWriter that pokes the watchdog per write without persisting an event, mirroring newIdleProgressReader which already does exactly this for artifact downloads in the same package. The buffer retains the TAIL, not the head. Compose prints megabytes of progress and then the actual failure (`manifest unknown`, `no such image`, `no space left on device`) on its last lines, so head-retention would discard precisely the diagnostic the buffer exists to preserve. Compaction is amortized — the buffer may reach 2x the cap before trimming — so a multi-megabyte pull costs O(total) copying rather than O(total x limit). 3. The diagnostic that hid it 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 primary with the child result as context, so a self-inflicted timeout is no longer indistinguishable from an OOM kill. Process fix: .claude/rules/53 gains requirement 5c — the mirror image of its existing liveness-as-idleness trap. There a liveness column answered an idleness question; here a progress feed could not observe the work it guarded. Same family, so it extends rule 53 rather than becoming a new file. Tests, all under -race: liveness fires from real child output with the right env/seq; silent-command and out-of-apply controls emit nothing; stderr survives wrapping; the signal continues past the retention cap; tail retention asserted on content both as a unit and end-to-end through a child emitting ~200 KiB before failing; setActiveApplySeq restores on nest; concurrent seq access is race-free. Dedup: duplicate skipped, different seq allowed, claim released on completion, route path guarded, exclusive under 64 goroutines, idempotent release, nil map. Each guard verified discriminating once and reverted: disabling the dedup guard fails exactly the duplicate test with both controls green; a plain stderr buffer fails exactly the liveness test; head-retention fails exactly the two tail tests. vm-agent: build, vet, gofmt clean on all touched files; 23/23 packages pass; deploy and server pass -race. Co-Authored-By: Claude --- ...-handler-isolation-and-liveness-signals.md | 27 ++ packages/vm-agent/internal/deploy/compose.go | 93 +++++- .../internal/deploy/compose_liveness_test.go | 268 ++++++++++++++++++ packages/vm-agent/internal/deploy/engine.go | 22 ++ .../vm-agent/internal/deploy/engine_config.go | 1 + .../server/deploy_apply_dedup_test.go | 239 ++++++++++++++++ packages/vm-agent/internal/server/health.go | 37 ++- packages/vm-agent/internal/server/server.go | 10 + packages/vm-agent/internal/server/vm_jobs.go | 49 ++++ 9 files changed, 741 insertions(+), 5 deletions(-) create mode 100644 packages/vm-agent/internal/deploy/compose_liveness_test.go create mode 100644 packages/vm-agent/internal/server/deploy_apply_dedup_test.go 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/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 From a128f7266b3dfd7bbdb9bf380e59f5a8ec4aff7c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rapha=C3=ABl=20Titsworth-Morin?= Date: Sat, 5 Sep 2026 16:03:17 +0000 Subject: [PATCH 3/5] docs(tasks): record the deployment-stall investigation and post-mortem MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Full incident record: the three defects, the live production evidence (2:1 fetch/apply ratio, 8 compose starts with zero completions), the discriminating- mutation table for every guard, the two bug classes and their process fixes, and the limitations left standing — the unexplained 1-second spacing of the original duplicate fetches, and the deployment_volumes.status staleness filed separately. The log excerpt is formatted one field per line: with `source=api` adjacent to the node ULID, gitleaks' generic-api-key rule matched the high-entropy identifier. It is a public node id that already appears in URLs and logs, not a credential, so the right resolution is to not trip the scanner rather than to self-approve a reviewed-baseline entry (which requires a security owner and an expiry). Co-Authored-By: Claude --- ...026-09-05-fix-app-route-dns-upsert-race.md | 250 ++++++++++++++++++ 1 file changed, 250 insertions(+) create mode 100644 tasks/active/2026-09-05-fix-app-route-dns-upsert-race.md 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..8edc4a9c44 --- /dev/null +++ b/tasks/active/2026-09-05-fix-app-route-dns-upsert-race.md @@ -0,0 +1,250 @@ +# 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. + +## Related finding (NOT fixed here — separate issue) + +**`deployment_volumes.status` is never re-polled.** It is written once from the +provider's transient attach response, and only the *detach* path ever writes +`available` (`deployment-volumes.ts:583-592` vs `:675-684`). A volume attached +mid-provision reads `creating` forever. Cosmetic — the heartbeat gate +`deploymentVolumesReadyForNode()` keys on `attached_server_id`, not `status` — but +actively misleading while debugging, and it cost real time during this +investigation. Filed as an idea; not bundled because it is unrelated to the +deployment-stall chain and would need its own provider-polling design. From 370f1952ed1c0e668c2eabda3f414e5722f27e1d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rapha=C3=ABl=20Titsworth-Morin?= Date: Sat, 5 Sep 2026 16:16:39 +0000 Subject: [PATCH 4/5] fix(api): persist a settled volume status instead of the provider's snapshot MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit attachEnvironmentVolumes wrote `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. So an attached, mounted, fully working volume read `creating` forever. Observed in production on volume 01M1RWP6VA… (pgdata) while its own release events showed volume_mount_completed and volume_mounts_verified — the mount demonstrably worked. Nothing reads the column (every `.status` branch in the consumers is on node.status or environment.status, and the heartbeat gate deploymentVolumesReadyForNode keys on attached_server_id), so this is not a functional bug. It is worse in a specific way: it is the single most obvious "here is your stuck deployment" signal in the table, and it is false. It misdirected this investigation, and would misdirect the next one. Now persists the settled SAM-side fact — the attach call returned and we hold a server id, so `attached` is true and stable. No migration and no constraint widening: the column is plain TEXT with no CHECK (0069_deployment_volumes.sql:14) and `attached` is already in the provider VolumeStatus union. The `failed` semantics on the creation path are untouched. Rule 57 at the storage layer: a remote-owned value written once and never reconciled. Polling was rejected as disproportionate — the fact SAM needs is knowable locally the moment attach returns. Test asserts the settled status survives a provider still reporting `creating`; verified discriminating (restoring the pass-through fails exactly it plus the existing attach assertion). API unit suite 8053/8054, 0 collection errors. Co-Authored-By: Claude --- apps/api/src/services/deployment-volumes.ts | 14 ++++- .../unit/services/deployment-volumes.test.ts | 54 ++++++++++++++++++- ...026-09-05-fix-app-route-dns-upsert-race.md | 35 ++++++++---- 3 files changed, 89 insertions(+), 14 deletions(-) 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/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/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 index 8edc4a9c44..642b0502c5 100644 --- 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 @@ -238,13 +238,28 @@ suggests a second trigger (a manual retry, a `deployment-env` poll, or a heartbe 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. -## Related finding (NOT fixed here — separate issue) - -**`deployment_volumes.status` is never re-polled.** It is written once from the -provider's transient attach response, and only the *detach* path ever writes -`available` (`deployment-volumes.ts:583-592` vs `:675-684`). A volume attached -mid-provision reads `creating` forever. Cosmetic — the heartbeat gate -`deploymentVolumesReadyForNode()` keys on `attached_server_id`, not `status` — but -actively misleading while debugging, and it cost real time during this -investigation. Filed as an idea; not bundled because it is unrelated to the -deployment-stall chain and would need its own provider-polling design. +## 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. From f9697cdc3cff6485efd7cc9ad3d1007637590c6c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rapha=C3=ABl=20Titsworth-Morin?= Date: Sat, 5 Sep 2026 18:02:22 +0000 Subject: [PATCH 5/5] test: fix two time-bomb tests unrelated to this PR's chain MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Both were reported as "pre-existing failures" in earlier CI runs on this branch. They are not flakes and were never going to self-resolve — each hardcodes a historical date and seeds fixture data relative to it, while the PRODUCTION code it exercises checks that data against REAL wall-clock time with no injectable clock. Both were guaranteed to start failing on a specific calendar date regardless of any code change, and did. 1. project-data-snapshot-recovery-wake.test.ts NOW = 2026-08-26T21:10:00Z; seedSnapshot() sets expires_at = NOW + 7 days = 2026-09-02. wakeSessionForSnapshotRecovery -> hasAuthorizedRestorableSnapshot- WakeClaim calls the latter WITHOUT passing `now`, so it defaults to `new Date()` -- real time. From 2026-09-02 onward `expires_at > now` is false, the claim row never matches, and the test's `.resolves.toBe(true)` fails. Fix: freeze the clock (vi.useFakeTimers + setSystemTime(NOW) in beforeEach, vi.useRealTimers in afterEach) so the production default resolves to the fixture's NOW instead of real time. All 7 tests in the file still pass. 2. project-data-tool-payload-archive.test.ts > retrieves archived tool payloads through the MCP tool The file's FIXED_NOW (2026-08-26) is used correctly everywhere else -- threaded explicitly through runArchiveCleanup's `now`/`nowMs` for the archival business logic. But this one test also stamped an MCP token's createdAt with that same FIXED_NOW. validateMcpToken has NO injectable clock (`const now = Date.now()`, hardcoded by design -- it's an auth boundary) and rejects tokens older than DEFAULT_MCP_TOKEN_MAX_LIFETIME_SECONDS (24h). Once real time passed 2026-08-27 the token looked ~10 days old and every call 401'd. Fix: stamp the token with the real current time (`new Date().toISOString()`) instead of the archival fixture's frozen date -- the two clocks are independent and were wrongly conflated. Both fixes verified discriminating (reverting each reproduces its original failure). Full suites after: unit 8054/8054 (was 8053/8054), workers 761/761 locally (was 760/761). Test-only changes -- no production code touched. Filed and resolved: idea 01M1S79XZMF4Q9H53MQTCEQM0M (originally mis-filed as "pre-existing failures", corrected with the actual root cause). Co-Authored-By: Claude --- .../project-data-snapshot-recovery-wake.test.ts | 15 ++++++++++++++- .../project-data-tool-payload-archive.test.ts | 11 ++++++++++- 2 files changed, 24 insertions(+), 2 deletions(-) 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', {