Flaky fan-out test: TaskFinished never observed under load #178

Closed
opened 2026-09-06 17:34:15 +00:00 by crueber · 3 comments
Owner

Flaky TestFanoutConcurrentEnqueueLosesNothing: TaskFinished never observed under load

make ci failed in internal/notify: TestFanoutConcurrentEnqueueLosesNothing (15.01s) with lost 0/60 fan-out seqs: []. Passes solo (-count=3, -race -count=5).

Analysis (from the failure text + test code)

The missing list is EMPTY — all 60 principals have exactly 1 notification. What never happened within the 15s deadline is the second conjunct: TaskStatus(repo, TaskKindFanout) returning a record with State == TaskFinished (tasks_test.go:448-452). So notifications are delivered; the task's terminal-state observability under full-./... parallel load is what's broken/flaky.

Fix (evidence decides: test bug, implementation bug, or load-only flake)

  • Determine why the finished state isn't observed: task-record lifecycle (removed on completion? recent-ring expiry? reaped?), a drain loop that doesn't terminate promptly under contention, or a status lookup racing completion. Read TaskStatus, the task table janitor/recent-ring, and the drain/end path.
  • If the implementation can genuinely leave a completed task unobservable forever, fix the implementation (terminal state must be observable). If the test's polling contract is wrong (e.g. asserts on a record that is legitimately reaped), fix the test WITHOUT weakening it (still pins no-loss + termination; e.g. poll on quiescence + record history rather than a point-in-time record that may be gone). Per law 11: never weaken a budget/coverage assertion to make it pass.
  • Also glance at the http: TLS handshake error ... bad certificate line seen in the same CI output — determine whether it's expected test noise (a test asserting TLS failure) or a symptom; handle accordingly.

Acceptance criteria

  • make ci green end to end (vet, test, race, cover, contract, e2e), plus the failing test green -race -count=20 in isolation AND under go test -short ./internal/... parallel load.
  • Root cause stated in the PR (test bug vs implementation bug); coverage gate holds on touched packages.
# Flaky TestFanoutConcurrentEnqueueLosesNothing: TaskFinished never observed under load `make ci` failed in `internal/notify`: `TestFanoutConcurrentEnqueueLosesNothing` (15.01s) with `lost 0/60 fan-out seqs: []`. Passes solo (`-count=3`, `-race -count=5`). ## Analysis (from the failure text + test code) The `missing` list is EMPTY — all 60 principals have exactly 1 notification. What never happened within the 15s deadline is the second conjunct: `TaskStatus(repo, TaskKindFanout)` returning a record with `State == TaskFinished` (`tasks_test.go:448-452`). So notifications are delivered; the task's terminal-state observability under full-`./...` parallel load is what's broken/flaky. ## Fix (evidence decides: test bug, implementation bug, or load-only flake) - Determine why the finished state isn't observed: task-record lifecycle (removed on completion? recent-ring expiry? reaped?), a drain loop that doesn't terminate promptly under contention, or a status lookup racing completion. Read `TaskStatus`, the task table janitor/recent-ring, and the drain/end path. - If the implementation can genuinely leave a completed task unobservable forever, fix the implementation (terminal state must be observable). If the test's polling contract is wrong (e.g. asserts on a record that is legitimately reaped), fix the test WITHOUT weakening it (still pins no-loss + termination; e.g. poll on quiescence + record history rather than a point-in-time record that may be gone). Per law 11: never weaken a budget/coverage assertion to make it pass. - Also glance at the `http: TLS handshake error ... bad certificate` line seen in the same CI output — determine whether it's expected test noise (a test asserting TLS failure) or a symptom; handle accordingly. ## Acceptance criteria - [ ] `make ci` green end to end (vet, test, race, cover, contract, e2e), plus the failing test green `-race -count=20` in isolation AND under `go test -short ./internal/...` parallel load. - [ ] Root cause stated in the PR (test bug vs implementation bug); coverage gate holds on touched packages.
Author
Owner

Root cause: test bug, not implementation bug — see PR #179 (#179). Single shared 15s deadline for delivery+termination misreports starvation as 'lost 0/60'; fixed with split polling windows. TLS handshake line is expected TestWebhookInsecureTLS noise (asserted self-signed rejection), now silenced.

Root cause: test bug, not implementation bug — see PR #179 (https://git.packden.us/crueber/walhub/pulls/179). Single shared 15s deadline for delivery+termination misreports starvation as 'lost 0/60'; fixed with split polling windows. TLS handshake line is expected TestWebhookInsecureTLS noise (asserted self-signed rejection), now silenced.
Author
Owner

Review of PR #179 (fix/issue-178, commit a364a8a) — verified in scratch worktree /tmp/pr179 (since removed).

LOAD-BEARING QUESTION (AGENTS.md law 11): does the 15s+15s phase split weaken the test? Verdict: NO, it preserves both pins.

  • No-loss pin unchanged: internal/notify/tasks_test.go:444 phase 1 keeps the exact 15s bound on delivery from wg.Wait() return, same start point and duration as before. Nothing relaxed.
  • Termination pin decoupled, not weakened: old code gave the finish only (15s minus delivery_time) — under load, delivery at 14.9s left 0.1s for finish and misreported a healthy ms-later finish as 'lost 0/60'. New phase 2 (tasks_test.go:466) bounds termination as 15s from delivery-complete. A genuinely stalled drain still fails loudly, with its own diagnostic ('delivered N/60 but task never finished', tasks_test.go:472) instead of the misleading data-loss message. Total wall can reach ~30s only when delivery itself was slow — exactly the loaded case that flaked — and each phase is still independently bounded, so this is a diagnostic split, not kick-the-can. The author's measured <=84ms termination under 4x load leaves huge margin inside the 15s phase-2 bound; the bound stays meaningful (a hung drain fails, just later).
  • Reaping-path check (would collapse the test-bug verdict): confirmed NONE. tasks.go finishLocked (tasks.go:118) moves the record to a bounded recent cache evicted only past 128 keys (tasks.go:126); no TTL, no janitor, no time-based reaping anywhere in tasks.go. Single (repo,kind) key in this test can never hit the 128-key eviction. So a phase-2 timeout genuinely means 'drain stalled', as the comment claims.
  • Diagnostics distinguish the modes: 'lost %d/%d' (delivery, :458) vs 'delivered %d/%d but task never finished' (termination, :472), second one includes TaskStatus dump. Good.
  • TLS ErrorLog silencing (webhooks_test.go:482): server-side handshake-error line only; both assertions untouched (cursor stays 0 without insecure_tls; advances to seq with opt-in). Masks no real failure — the rejected handshake IS the asserted behavior.
  • Production code: diff is tests-only (tasks_test.go + webhooks_test.go, 43+/13-). Verified via diff --name-only.
  • Helper missingNotifs (:480) has t.Helper(); no assertion logic changed, only factored out.

RESULTS (scratch worktree @ a364a8a): gofmt clean; go vet clean; go test -race ./internal/notify/... ok (2.3s); -count=10 fan-out test 10/10 PASS; GOMAXPROCS=2 + taskset-constrained 10/10 PASS; TestWebhookInsecureTLS -count=3 PASS; coverage 96.2% (gate >=95% holds). No fix-push needed — nothing to fix.

MERGE RECOMMENDATION: ready to merge (not merging per instructions; main worktree left untouched).

Review of PR #179 (fix/issue-178, commit a364a8a) — verified in scratch worktree /tmp/pr179 (since removed). LOAD-BEARING QUESTION (AGENTS.md law 11): does the 15s+15s phase split weaken the test? Verdict: NO, it preserves both pins. - No-loss pin unchanged: internal/notify/tasks_test.go:444 phase 1 keeps the exact 15s bound on delivery from wg.Wait() return, same start point and duration as before. Nothing relaxed. - Termination pin decoupled, not weakened: old code gave the finish only (15s minus delivery_time) — under load, delivery at 14.9s left 0.1s for finish and misreported a healthy ms-later finish as 'lost 0/60'. New phase 2 (tasks_test.go:466) bounds termination as 15s from delivery-complete. A genuinely stalled drain still fails loudly, with its own diagnostic ('delivered N/60 but task never finished', tasks_test.go:472) instead of the misleading data-loss message. Total wall can reach ~30s only when delivery itself was slow — exactly the loaded case that flaked — and each phase is still independently bounded, so this is a diagnostic split, not kick-the-can. The author's measured <=84ms termination under 4x load leaves huge margin inside the 15s phase-2 bound; the bound stays meaningful (a hung drain fails, just later). - Reaping-path check (would collapse the test-bug verdict): confirmed NONE. tasks.go finishLocked (tasks.go:118) moves the record to a bounded recent cache evicted only past 128 keys (tasks.go:126); no TTL, no janitor, no time-based reaping anywhere in tasks.go. Single (repo,kind) key in this test can never hit the 128-key eviction. So a phase-2 timeout genuinely means 'drain stalled', as the comment claims. - Diagnostics distinguish the modes: 'lost %d/%d' (delivery, :458) vs 'delivered %d/%d but task never finished' (termination, :472), second one includes TaskStatus dump. Good. - TLS ErrorLog silencing (webhooks_test.go:482): server-side handshake-error line only; both assertions untouched (cursor stays 0 without insecure_tls; advances to seq with opt-in). Masks no real failure — the rejected handshake IS the asserted behavior. - Production code: diff is tests-only (tasks_test.go + webhooks_test.go, 43+/13-). Verified via diff --name-only. - Helper missingNotifs (:480) has t.Helper(); no assertion logic changed, only factored out. RESULTS (scratch worktree @ a364a8a): gofmt clean; go vet clean; go test -race ./internal/notify/... ok (2.3s); -count=10 fan-out test 10/10 PASS; GOMAXPROCS=2 + taskset-constrained 10/10 PASS; TestWebhookInsecureTLS -count=3 PASS; coverage 96.2% (gate >=95% holds). No fix-push needed — nothing to fix. MERGE RECOMMENDATION: ready to merge (not merging per instructions; main worktree left untouched).
Author
Owner

Fixed by PR #179 (review: split preserves the guarantee, reaping-path verified absent; all green), merged. Closing.

Fixed by PR #179 (review: split preserves the guarantee, reaping-path verified absent; all green), merged. Closing.
crueber added this to the v1 milestone 2026-09-10 22:20:56 +00:00
Sign in to join this conversation.
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference
crueber/walhub#178
No description provided.