Progress tracker: a hung database save blocks reporting, and the heartbeat uses a different clock from the page #51

Closed
opened 2026-10-03 18:48:19 +00:00 by mathias · 1 comment
Owner

Milestone v0.32.0. From #46 items 4 and 5, both reproduced by the phase-1 investigation.

Hung save. Tracker.save runs under the tracker's mutex with no timeout (the pool is pgxpool.New with none). A save that never returns blocks Begin and Advance, which are called by the engine, so a database stall stalls the job's reporting and, once the 5-minute "still running" tick queues on the mutex, the heartbeat log too. (Correction to #46: Beat itself does not take the mutex; only logStill does.) Fix: a per-save context.WithTimeout (about 5 s) in the tracker and the same around Beat; a timed-out save is logged and dropped, as other save failures already are. Red: TestTracker_HungSaveDoesNotBlockReporter (a sink that blocks on ctx.Done(), a short WithSaveTimeout, Begin must return in under 1 s).

Clock skew. alive_at is stamped with the database's NOW() while progress_at and the page's health check use the application clock, and uploadHealth takes the later of the two. Tapir and Postgres are on the same node so skew is about zero today; a database clock more than about 35 s behind would show a healthy job as lost, and one ahead would delay detecting a lost job. Fix: stamp both with the application clock: Heartbeat(ctx, user, id, at) and alive_at = $3 (this changes the Sink and WorkerStore interfaces and their fakes). Red: TestTracker_BeatStampsWithTheAppClock and a store test that alive_at equals the passed time.

Do the hung-save fix first (same package), then the clock. Review: a timed-out save must not swallow a failure the job needs: include in a gatekeeper round. Acceptance: the tests red first; task check and golangci-lint run ./... exit 0.


Created via git-mcp on behalf of @mathias

**Milestone v0.32.0. From #46 items 4 and 5, both reproduced by the phase-1 investigation.** **Hung save.** `Tracker.save` runs under the tracker's mutex with no timeout (the pool is `pgxpool.New` with none). A save that never returns blocks `Begin` and `Advance`, which are called by the engine, so a database stall stalls the job's reporting and, once the 5-minute "still running" tick queues on the mutex, the heartbeat log too. (Correction to #46: `Beat` itself does not take the mutex; only `logStill` does.) **Fix:** a per-save `context.WithTimeout` (about 5 s) in the tracker and the same around `Beat`; a timed-out save is logged and dropped, as other save failures already are. **Red:** `TestTracker_HungSaveDoesNotBlockReporter` (a sink that blocks on `ctx.Done()`, a short `WithSaveTimeout`, `Begin` must return in under 1 s). **Clock skew.** `alive_at` is stamped with the database's `NOW()` while `progress_at` and the page's health check use the application clock, and `uploadHealth` takes the later of the two. Tapir and Postgres are on the same node so skew is about zero today; a database clock more than about 35 s behind would show a healthy job as lost, and one ahead would delay detecting a lost job. **Fix:** stamp both with the application clock: `Heartbeat(ctx, user, id, at)` and `alive_at = $3` (this changes the `Sink` and `WorkerStore` interfaces and their fakes). **Red:** `TestTracker_BeatStampsWithTheAppClock` and a store test that `alive_at` equals the passed time. Do the hung-save fix first (same package), then the clock. **Review:** a timed-out save must not swallow a failure the job needs: include in a gatekeeper round. **Acceptance:** the tests red first; `task check` and `golangci-lint run ./...` exit 0. --- _Created via git-mcp on behalf of @mathias_
mathias added this to the v0.32.0 - audio upload follow-ups milestone 2026-10-03 18:48:19 +00:00
mathias added the risk/mediumsize/stype/fix labels 2026-10-03 18:48:19 +00:00
Author
Owner

Shipped in v0.32.0 (PR #58, merge 85f4cc3; running in production since 2026-10-04, pod 1/1, 0 restarts, now image 7b7da65). Every tracker save and every heartbeat write now runs under a 5 s timeout (WithSaveTimeout, default defaultSaveTimeout), and the heartbeat's alive_at is stamped with the application clock like progress_at, not with the database's NOW().

Evidence: red tests first (tracker_stall_test.go: a hung save does not block the reporter past its timeout, a hung beat does not stop the heartbeat, the still-running log line is not held up behind a hung save, the beat is stamped with the tracker's clock) and a store test. The adversarial review found the production default itself was pinned by nothing (every test used a 50 ms override); a new test builds a Tracker the way production does and asserts the deadline each save and beat receives is between 1 s and 5 s. Mutations that went red: default 0, 1 ms, 1 h, 6 s, dropping the timeout from either context, and jobSink passing time.Now() / zero / at+1ns instead of the tracker's stamp (internal/uploads/jobsink_test.go).

Recorded limits, honest wording now in the code comment: the timeout bounds a write but the saves run under the tracker lock, so a hung database can still slow a job by up to 5 s per transition; a dropped final save is not retried (the row keeps its last saved step and renders consistently, no data loss, reviewer executed it).

Not observed live: a hung database cannot be produced in production, so this rests on the tests and the review. Closing on that basis.


Created via git-mcp on behalf of @mathias

**Shipped in v0.32.0** (PR #58, merge 85f4cc3; running in production since 2026-10-04, pod 1/1, 0 restarts, now image 7b7da65). Every tracker save and every heartbeat write now runs under a 5 s timeout (`WithSaveTimeout`, default `defaultSaveTimeout`), and the heartbeat's `alive_at` is stamped with the application clock like `progress_at`, not with the database's `NOW()`. Evidence: red tests first (`tracker_stall_test.go`: a hung save does not block the reporter past its timeout, a hung beat does not stop the heartbeat, the still-running log line is not held up behind a hung save, the beat is stamped with the tracker's clock) and a store test. The adversarial review found the production default itself was pinned by nothing (every test used a 50 ms override); a new test builds a Tracker the way production does and asserts the deadline each save and beat receives is between 1 s and 5 s. Mutations that went red: default 0, 1 ms, 1 h, 6 s, dropping the timeout from either context, and `jobSink` passing `time.Now()` / zero / `at+1ns` instead of the tracker's stamp (`internal/uploads/jobsink_test.go`). Recorded limits, honest wording now in the code comment: the timeout bounds a write but the saves run under the tracker lock, so a hung database can still slow a job by up to 5 s per transition; a dropped final save is not retried (the row keeps its last saved step and renders consistently, no data loss, reviewer executed it). Not observed live: a hung database cannot be produced in production, so this rests on the tests and the review. Closing on that basis. --- _Created via git-mcp on behalf of @mathias_
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: mathias/tapir#51