Skip to content

fix: stop apply checks hanging when a stack status update hits SQLITE_BUSY - #248

Merged
ivank merged 2 commits into
mainfrom
fix/apply-tick-sqlite-busy
Sep 23, 2026
Merged

ivank merged 2 commits into
mainfrom
fix/apply-tick-sqlite-busy

Conversation

@fh-code-agent

@fh-code-agent fh-code-agent Bot commented Sep 23, 2026

Copy link
Copy Markdown
Contributor

Summary

A post-merge apply can hang forever in the report phase with one stack stuck at running. The apply itself finished, and terraform state holds the new resources. The execution record and the apply/<env> check just never conclude.

This PR fixes it in three layers:

  • stop the lost write at its source (SQLite);
  • make the runner retry the one call whose loss strands a run;
  • let a successful apply's final report close out any stack whose completion update never arrived.

Root cause

Measured, on a real 3-stack apply, from serve's request logs, the build log and the stored execution:

  • The serve ran as a single instance, with no restart or scale event.
  • Exactly one request failed during the run: POST /api/update → 500 in 18 ms. It came at the moment the third stack finished applying, while a sibling stack's update and two /api/logs posts were in flight.
  • The 500 never reached storage. A later successful update re-projects every stack, and the third stack still read running.
  • /api/phase (report) and /api/finalize both returned 200 afterwards. The apply check still never concluded, because driveApply reports success only when every stack is terminal. A non-failed apply Finalize did nothing about a stack still marked running, even though the comment in run apply says it covers a missed tick.
  • The runner discards every client error (_ = client.Update(...), 10 s timeout, no retry), so the build log showed nothing.
  • It recurs. Fast (single-digit to ~20 ms) /api/* 500s appear regularly under concurrent stack updates. On a plan run, the non-failed finalize concludes the run regardless of a missing tick. On an apply, any one of them lost on a stack's terminal update strands the check.

In short: under concurrent stack status updates, the event store's read-then-write deferred transaction fails with SQLITE_BUSY immediately (busy_timeout doesn't apply to a deferred-to-write upgrade), the runner drops the error, and the apply check never completes.

Inferred, because the handler doesn't log the error text, then reproduced in a test:

  • EventStore.Append opens a DEFERRED transaction and reads (SELECT MAX(version)) before it writes.
  • In WAL mode, if another connection commits between that read and the INSERT, SQLite returns SQLITE_BUSY at once and never calls the busy_timeout handler, because waiting cannot refresh a stale read snapshot.
  • busy_timeout(5000) therefore never helped this path. The per-stream mutex and EventStore.mu don't help either, since other tables (logs, claims, projections) are written on other pool connections.

Changes

  1. internal/store/db.go: open with _txlock=immediate. Every db.Begin becomes BEGIN IMMEDIATE, so a read-then-write transaction takes the write lock up front. busy_timeout applies there, so the transaction waits instead of failing. busy_timeout is now set before journal_mode(WAL), so a new pool connection's pragma waits too.
  2. internal/runner/client.go: Client.Update retries on transport errors and 5xx, 3 attempts with linear backoff (0.5 s, 1 s). A 4xx is returned at once. Re-sending a tick is idempotent, since the fold just sets the status again. run wrap now prints a status it failed to record instead of discarding the error.
  3. internal/server/handlers.go: a successful apply finalize concludes stacks whose tick was lost.
    • "Successful" is defined from what the runner actually sends. run apply emits PhaseReport only after the terramate apply script returns, then Finalize{Failed: applyErr != nil}. The mid-apply classify Finalize is also non-failed, but it lands before PhaseApplying.
    • So a non-failed Finalize received while the execution's phase is report is the success signal.
    • On that signal serve ticks each still-non-terminal stack (pending / running / initializing / initialized) to safe, with a detail saying so, and drives the check to its conclusion.
    • A failed finalize is unchanged: those stacks fold to aborted and the check concludes failure.

Tests

  • internal/store/busy_test.go, TestAppendSurvivesConcurrentWriters: concurrent Appends racing autocommit writers on the same file DB.
    • On main it fails every run with database is locked (5) (SQLITE_BUSY).
    • With the fix it passed 70 of 70 runs.
    • Removing only _txlock=immediate makes it fail again.
  • internal/runner/client_retry_test.go, TestUpdateRetriesTransient5xx: covers one 500 then ok (2 calls), a persistent 500 (3 calls, then an error) and a 4xx (1 call, no retry).
  • internal/server/apply_lost_tick_test.go replays the failing sequence: init with 3 stacks, a classify finalize, applying, all three running, two terminal ticks, report, then finalize.
    • TestSuccessfulApplyFinalizeConcludesLostTick: 3 of 3 stacks safe, execution success, check run success. Against the old handler it reproduces the stuck state exactly: the third stack running, in_progress, no conclusion.
    • TestFailedApplyFinalizeDoesNotConcludeLostTick: the unreported stack becomes aborted rather than safe; execution and check both end failure.
    • The replay also asserts that the mid-apply classify finalize concludes nothing.
  • go vet ./... is clean. go test ./... passes.
    • Two unrelated cmd/tfstackplan tests each failed once across about 6 local full-suite runs: TestApplyPhaseEmittedAfterGate on an IPv6 dial to oauth2.googleapis.com, and TestRunPlanAbortsDeferredFinalize.
    • Both pass 40 of 40 in isolation on this branch and on main.
    • Full-suite runs came out 3 of 3 clean on both, and the cmd/tfstackplan package 8 of 8 clean on both.

Risks and limitations

  • BEGIN IMMEDIATE on every transaction, including any that only read, serializes transactions against each other. That's fine for a single-instance serve with a small write rate. A transaction held across a network call would now block writers for up to 5 s instead of failing fast. I found none, but reviewers should keep an eye out.
  • The success conclusion trusts the runner's success signal. If terramate exited 0 without running a stack, that stack would read safe. Terramate runs every stack it was given or exits non-zero, so this shouldn't happen, but it is now an assumption. A stack concluded this way carries the detail text, and a real nochange stack whose tick was lost will read safe.
  • The report phase event itself can be lost. Layer 3 then doesn't fire, and the run stays pending, which is the old behavior and the safe direction. Layers 1 and 2 make that much less likely.
  • Older records are not changed. Executions already stranded in a live DB stay as they are until they are superseded or the serve restarts, since its DB is ephemeral.

🤖 Generated with Claude Code

ivank and others added 2 commits September 23, 2026 12:54
An apply hung in 'report' with one stack 'running': that stack's
terminal /api/update 500'd in 18ms and the runner dropped it, and
driveApply concludes only when every stack is terminal.

- store: open with _txlock=immediate so read-then-write transactions
  (EventStore.Append, claims) take the write lock up front, where
  busy_timeout applies; set busy_timeout before journal_mode.
- runner: retry Update on transport errors and 5xx; log a tick that
  still is not recorded instead of discarding it.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
A non-failed Finalize received while an apply execution is in the
report phase is the runner's terminal success signal: PhaseReport is
emitted only after the terramate apply script returns, and the final
Finalize carries Failed = (applyErr != nil). The mid-apply classify
Finalize is also non-failed but lands before PhaseApplying.

On that signal, tick every still-non-terminal stack to safe and drive
the check to its conclusion. A failed finalize is unchanged: it still
folds those stacks to aborted and concludes failure.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
@fh-code-agent
fh-code-agent Bot requested a review from a team as a code owner September 23, 2026 07:40
@ivank ivank self-assigned this Sep 23, 2026
@github-code-quality

Copy link
Copy Markdown

Code Coverage Overview

Languages: Go

Go / code-coverage/go

The overall line coverage in commit a2a80f4 in the fix/apply-tick-sqlit... branch remains at 71%, unchanged from commit 191a75c in the main branch.

Show a line coverage summary of the most impacted files.
File main 191a75c fix/apply-tick-sqlit... a2a80f4 +/-
internal/cache/cache.go 49% 47% -2%
cmd/tfstackplan/wrap.go 72% 71% -1%
internal/server/handlers.go 59% 58% -1%
internal/runner/client.go 60% 62% +2%
internal/server/viewdata.go 80% 86% +6%
internal/store/db.go 57% 64% +7%

@ivank
ivank merged commit eb99f50 into main Sep 23, 2026
9 checks passed
@ivank
ivank deleted the fix/apply-tick-sqlite-busy branch September 23, 2026 07:54
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant