mirror of
https://github.com/coder/coder.git
synced 2026-09-24 06:47:27 +08:00
Bobby Ho
8a510314df
## Summary Each of the five `TestPrebuildsAutobuild` subtests spent about 30 seconds of its 60 second context budget waiting for a prebuilt workspace whose build job had already been created and queued. On a quiet machine the remaining budget is enough and the test passes; under `test-go-race-pg` it is not, and the subtest fails at `found 0 running prebuilds so far, want 1`. Worth being precise about the shape, because it changes the fix: this is not a data race. The 30 second stall is deterministic and every run pays it in full. Only the *failure* is intermittent, because it depends on whether the leftover budget covers the rest of the test. Refs: https://github.com/coder/internal/issues/1578 ## Problem `StoreReconciler` publishes `provisioner_job_posted` to pubsub so that provisionerd wakes up and acquires a newly created job. That publish does not happen inline. `publishProvisionerJob` performs a non-blocking send onto an internal buffered channel, and the goroutine that drains that channel and calls `provisionerjobs.PostJob` is created inside `StoreReconciler.Run`: ```go // enterprise/coderd/prebuilds/reconcile.go, inside Run() wg.Add(1) go func() { defer wg.Done() for { select { case <-ctx.Done(): return case job := <-c.provisionNotifyCh: err := provisionerjobs.PostJob(c.pubsub, job) ... } } }() ``` These tests drive the reconciler directly through `SnapshotState` / `CalculateActions` / `ReconcilePreset` and never start `Run`. The notification therefore lands in a cap-10 channel with no reader, the non-blocking send succeeds silently, and provisionerd does not learn about the job until the Acquirer's 30 second backup poll fires. Laid out as a relay across goroutines, the hand-off is severed at the first hop: ```mermaid flowchart LR subgraph G1["goroutine: test body"] T1["ReconcilePreset()"] T2["testutil.Eventually<br/>1s poll of the DB"] end subgraph G2["goroutine: Run() drain worker"] D["case job := <-provisionNotifyCh:<br/>PostJob(pubsub, job)"] end subgraph G3["goroutine: pubsub listener"] H["Acquirer.jobPosted<br/>-> clearOrPend(domain)"] end subgraph G4["goroutine: domain.poll"] P["ticker 30s, REAL clock<br/>-> clearOrPend(domain)"] end subgraph G5["goroutine: provisionerd AcquireJob"] A["select { <-ctx.Done() ; <-clearance }"] end CH1[["provisionNotifyCh<br/>chan ProvisionerJob, cap 10"]] CH2[["clearance<br/>chan struct{}, cap 1"]] DB[("Postgres")] T1 -- "non-blocking send" --> CH1 CH1 -. "NO READER:<br/>Run() never started" .-> D D -. "never reached" .-> H H -. "never fires" .-> CH2 P -- "every 30s:<br/>the only live writer" --> CH2 CH2 --> A A -- "AcquireProvisionerJob" --> DB T2 -- "GetRunningPrebuiltWorkspaces" --> DB style G2 fill:#f2f2f2,stroke-dasharray: 5 5 style CH1 fill:#ffe5e5,stroke:#cc0000,stroke-width:2px ``` Two properties turn this into a quiet latency bug rather than an obvious failure: - The channel is **buffered**, so a send with no reader succeeds instead of blocking or panicking. The writer never learns that nobody is listening. - `domain.poll` ticks on the **real** clock, so the test's mock clock cannot skip it. That is the entire 30 seconds. From the CI job that filed the ticket, every job created through the HTTP API is picked up in about a millisecond, and only the reconciler-created prebuild job is not: ```text 19:11:40.760 pubsub: publish event=provisioner_job_posted <- template import job 19:11:40.761 acquirer: got job posting <- picked up in 1ms ... 19:11:40.903 prebuild job scheduled job_id=ac196e6e-... (no "pubsub: publish", no "acquirer: got job posting") 19:11:41 .. 19:12:10 30 x "found 0 running prebuilds so far, want 1" 19:12:10.803 acquirer: successfully acquired job ac196e6e-... <- 29.899s later, via backup poll ``` Corroboration from the existing test suite: `FailureTTLOnlyAfterClaimed` had already run into this. It builds its Acquirer on a mock clock and calls `acquirerClock.Advance(30 * time.Second)` right after reconciling, with a comment about the backup-poll ticker. A previous author found the same dependency and worked around it by making the poll fire instantly rather than by restoring the notification. ### Where that lands in the test Each subtest is three helpers called in order. They never call each other; they communicate through Postgres plus one returned value. `runReconciliationLoop` performs no writes itself, they all happen inside `ReconcilePreset`, whose transaction has committed by the time it returns. ```mermaid sequenceDiagram autonumber participant T as test body participant H1 as runReconciliationLoop participant H2 as getRunningPrebuilds participant H3 as claimPrebuild participant R as StoreReconciler participant DB as Postgres participant PD as provisionerd T->>H1: (t, ctx, db, reconciler, presets) H1->>R: ReconcilePreset R->>DB: InsertWorkspace(owner=prebuilds) R->>DB: builder.Build -> build(start) + job(pending) R->>DB: COMMIT R->>R: publishProvisionerJob -> provisionNotifyCh<br/>non-blocking send, no reader, DROPPED R-->>H1: nil Note over H1,PD: nothing publishes provisioner_job_posted H1-->>T: void T->>H2: (t, ctx, db, want=1) loop 30 polls, 1s apart H2->>DB: GetRunningPrebuiltWorkspaces DB-->>H2: 0 rows (job still pending) end PD->>DB: acquire, via the 30s backup poll PD->>DB: CompleteJob, IsPrebuild so deadline stays zero H2->>DB: GetRunningPrebuiltWorkspaces DB-->>H2: 1 row (succeeded) H2->>DB: UPDATE agents SET lifecycle_state='ready' H2-->>T: rows, test captures prebuild.ID T->>H3: (client, userClient, user, version, presetID) H3->>DB: CreateUserWorkspace(presetID)<br/>-> ClaimPrebuiltWorkspace, requires ready DB-->>H3: same workspace, new owner H3-->>T: workspace Note over T: require.Equal(prebuild.ID, workspace.ID)<br/>~30s of the 60s budget already gone ``` The defect is in `runReconciliationLoop`, but the waiting, and therefore the failing log line, is in `getRunningPrebuilds`. Note also that `claimPrebuild` was never affected: it builds through the HTTP API, which publishes on the normal `wsbuilder` path, so its job was always acquired in about a millisecond. The bug was never "prebuild jobs are slow", it was "jobs created by the reconciler, driven directly, are never announced". ## Fix Publish the pending provisioner jobs on the reconciler's behalf, in the test helper, immediately after reconciling. No production code changes. ```mermaid flowchart LR subgraph G1["goroutine: test body"] T1["ReconcilePreset()"] T3["NEW: post pending jobs<br/>provisionerjobs.PostJob(pb, job)"] end subgraph G3["goroutine: pubsub listener"] H["Acquirer.jobPosted<br/>-> clearOrPend(domain)"] end subgraph G5["goroutine: provisionerd AcquireJob"] A["unblocks on <-clearance"] end CH2[["clearance<br/>chan struct{}, cap 1"]] DB[("Postgres")] T1 --> T3 T3 -- "publish provisioner_job_posted" --> H H -- "send" --> CH2 CH2 --> A A -- "AcquireProvisionerJob, ~1ms" --> DB style T3 fill:#e5ffe5,stroke:#007700,stroke-width:2px ``` This works because provisionerd is already subscribed and already parked in `select { <-ctx.Done(); <-clearance }`. It needs exactly one write to `clearance`, and today the only live writer is the 30 second poll ticker. Publishing to pubsub gives `jobPosted` a reason to fire, and `clearOrPendLocked` performs that write immediately. Posting every still-`pending` job, rather than trying to identify the one just created, keeps the helper idempotent and avoids coupling to whichever clock stamped `created_at`. Re-posting a job that was already acquired is harmless: the Acquirer re-queries and finds nothing. The same three helpers after the change. `getRunningPrebuilds` collapses to a single poll, and nothing else about the test moves: ```mermaid sequenceDiagram autonumber participant T as test body participant H1 as runReconciliationLoop participant H2 as getRunningPrebuilds participant H3 as claimPrebuild participant R as StoreReconciler participant PS as Pubsub participant DB as Postgres participant PD as provisionerd T->>H1: (t, ctx, db, pb, reconciler, presets) H1->>R: ReconcilePreset R->>DB: InsertWorkspace + build(start) + job(pending), COMMIT R->>R: publishProvisionerJob still dropped<br/>(production path, unchanged) R-->>H1: nil Note over H1,DB: job row is committed and visible,<br/>which is why the query below finds it H1->>DB: GetProvisionerJobsCreatedAfter(zero time) DB-->>H1: all jobs, filtered in Go to status=pending H1->>PS: PostJob -> provisioner_job_posted PS->>PD: acquirer wakes, clearance write H1-->>T: void PD->>DB: acquire in ~1ms, then CompleteJob T->>H2: (t, ctx, db, want=1) H2->>DB: GetRunningPrebuiltWorkspaces DB-->>H2: 1 row (succeeded), queued_for ~3ms H2->>DB: UPDATE agents SET lifecycle_state='ready' H2-->>T: rows, test captures prebuild.ID T->>H3: (client, userClient, user, version, presetID) H3->>DB: CreateUserWorkspace(presetID) -> claim DB-->>H3: same workspace, new owner H3-->>T: workspace Note over T: same assertions, ~55s of budget still unspent ``` `getRunningPrebuilds` still polls, still forces agents ready, `claimPrebuild` still claims, and every assertion is unchanged. Its floor is now one `testutil.IntervalSlow` tick, about a second, because `testutil.Eventually` fires on a ticker rather than checking immediately. Note that `publishProvisionerJob` at `reconcile.go:940` is still dropped. That call site is correct; it simply has no drain worker behind it when `Run` is not started. The `PostJob` added here is a manual redo of what it already intended. Starting `reconciler.Run(ctx)` instead would be closer to production, but `Run` also starts a reconciliation ticker on the **mock** clock, and these tests jump that clock by hours. Each jump would fire an unscheduled `ReconcileAll` that rebuilds a replacement prebuild mid-assertion, which is the opposite of what a deflake should introduce. ## Measurements Single subtest with `-race` against Postgres, the closest local approximation of `test-go-race-pg`, three iterations: | Run | before | after | |-----|--------|--------| | 1 | 58.85s | 30.68s | | 2 | 55.42s | 35.64s | | 3 | 57.47s | 31.30s | The baseline passed all three, at 1.1s to 4.6s of margin against the 60 second context. That is the flake caught in the act: locally green, one scheduling hiccup from red. After the change the margin is 24s to 29s. All five subtests against real Postgres go from roughly 35s each to 6.76s each, and `queued_for` on the prebuild job drops from 29.975s to single-digit milliseconds. ## Also in this change Two smaller items in the same helper, both aimed at the next person to see this symptom. Diagnostics while waiting for prebuilds: poll count, elapsed time, and `queued_for` (`started_at - created_at` on the provisioner job), plus a warning naming this defect if the wait exceeds 10 seconds. `queued_for` is the field that discriminates: about 0 means the notification arrived and any slowness is elsewhere, about 30 seconds means it was lost and the backup poll took over. There is deliberately no duration computed against `completed_at`. A single `provisioner_jobs` row mixes time bases in these tests: `created_at` and `started_at` come from the real clock, while `completed_at` is stamped by `CompleteJob` from the injected mock clock. My first version of the logging did subtract them and printed `ran_for=-22543h3m21s`. `getRunningPrebuilds` also now resets its accumulator each poll. It appended rows on every iteration without clearing, so an iteration that appended and then returned early on a transient error would double count and leave the expected count permanently unreachable, producing this same `found N running prebuilds` symptom for an unrelated reason.