Repository navigation
fix(tests): diagnose the observe-test hang and bring the merge shard under budget (0507) - #396
Merged
danielhanold merged 11 commits intoOct 5, 2026
Conversation
Docket-Plan-Path: docs/superpowers/plans/2026-10-05-flaky-tests-track-and-stabilize-intermittent-suite-failures.md
…eports what was stuck TestObserveRunningThenTerminal no longer discards readManifest's error or signalGroup's result, and when its unchanged 30s wait expires it reports the last Observe state/error, group and supervisor liveness, and live.lock state (describeStuckRun). Mutation-tested: both mutations reddened.
## A1 reproduction (2026-10-05T14:29:24Z) ``` cpu 50 0 0 4 - 4.78 cpu 50 0 0 4 - 7.68 cpu 50 0 0 4 - 10.75 cpu 50 0 0 4 - 10.75 cpu 50 0 0 4 - 13.17 cpu 50 0 0 4 - 14.44 cpu 50 0 0 4 - 16.00 cpu 50 0 0 4 - 17.85 cpu 50 0 0 4 - 17.85 cpu 50 0 0 4 - 19.62 cpu 50 0 0 4 - 21.65 cpu 50 0 0 4 - 22.08 cpu 50 0 0 4 - 23.03 cpu 50 0 0 4 - 23.03 cpu 50 0 0 4 - 24.39 cpu 50 0 0 4 - 25.56 cpu 50 0 0 4 - 27.36 cpu 50 0 0 4 - 27.81 cpu 50 0 0 4 - 27.81 cpu 50 0 0 4 - 27.91 cpu 50 0 0 4 - 28.47 cpu 50 0 0 4 - 28.68 cpu 50 0 0 4 - 30.38 cpu 50 0 0 4 - 30.38 cpu 50 0 0 4 - 30.51 cpu 50 0 0 4 - 31.75 cpu 50 0 0 4 - 31.61 cpu 50 0 0 4 - 32.20 cpu 50 0 0 4 - 32.20 cpu 50 0 0 4 - 34.67 cpu 50 0 0 4 - 35.98 cpu 50 0 0 4 - 37.66 cpu 50 0 0 4 - 39.13 cpu 50 0 0 4 - 39.13 cpu 50 0 0 4 - 38.08 cpu 50 0 0 4 - 45.52 cpu 50 0 0 4 - 49.96 cpu 50 0 0 4 - 52.53 cpu 50 0 0 4 - 53.20 cpu 50 0 0 4 - 53.20 gosuite 50 0 0 4 - 49.32 gosuite 50 0 0 4 - 45.69 gosuite 50 0 0 5 - 42.35 gosuite 50 0 0 4 - 40.56 gosuite 50 0 0 4 - 37.96 gosuite 50 0 0 4 - 37.96 gosuite 50 0 0 3 - 35.16 gosuite 50 0 0 4 - 32.50 gosuite 50 0 0 3 - 32.50 gosuite 50 0 0 4 - 30.22 gosuite 50 0 0 3 - 28.36 gosuite 50 0 0 3 - 26.57 gosuite 50 0 0 4 - 26.57 gosuite 50 0 0 4 - 24.60 gosuite 50 0 0 5 - 22.95 gosuite 50 0 0 4 - 21.51 gosuite 50 0 0 4 - 20.19 gosuite 50 0 0 3 - 20.19 gosuite 50 0 0 4 - 18.81 gosuite 50 0 0 4 - 17.47 gosuite 50 0 0 3 - 16.31 gosuite 50 0 0 4 - 16.31 gosuite 50 0 0 3 - 16.04 gosuite 50 0 0 4 - 14.92 gosuite 50 0 0 4 - 14.92 gosuite 50 0 0 4 - 14.12 gosuite 50 0 0 5 - 13.31 gosuite 50 0 0 3 - 12.49 gosuite 50 0 0 4 - 12.05 gosuite 50 0 0 4 - 12.05 gosuite 50 0 0 3 - 11.40 gosuite 50 0 0 4 - 10.81 gosuite 50 0 0 4 - 10.18 gosuite 50 0 0 3 - 10.18 gosuite 50 0 0 4 - 10.17 gosuite 50 0 0 4 - 9.59 gosuite 50 0 0 4 - 8.99 gosuite 50 0 0 5 - 8.99 gosuite 50 0 0 4 - 8.91 gosuite 50 0 0 4 - 8.83 ``` REPRO-TOTAL profile=gosuite iterations=2000 hangs=0 other_failures=0 seconds=154 REPRO-TOTAL profile=cpu iterations=2000 hangs=0 other_failures=0 seconds=160 REPRO-VERDICT not-reproduced
The bounded A1 reproduction (see the previous commit) produced no failure, so no root-cause fix is claimed. Task 1's diagnostics (no discarded errors, stuck-run report on timeout) are the A4 outcome; the next sighting will name what was stuck. The 30s deadline is unchanged.
TestIntegrationFinalizeMerge* now call t.Parallel() (every top-level test, and every t.Run closure that builds its own fixture; the pure ConditionAssembly subtests stay as they were under a parallel parent). The shared fixture takes an injected planning-node builder (setupRebaseFixtureWithNode / setupMergeFixtureWithNode; the old setupRebaseFixtureStatus / setupMergeFixture delegate with planningDepsFor, so every other caller is unchanged) and the shard uses parallelPlanningNode, which isolates the global-config layer once per process with os.Setenv instead of t.Setenv (the e2eNode precedent). The new TestIntegrationFinalizeMergeParallelNodeIsolatesGlobalConfig pins that isolation; mutation-tested (deleting the os.Setenv turns it red with 'XDG_CONFIG_HOME = "", want the isolated dir ...'). Package-state audit: no test in finalize_merge_integration_test.go assigns a package-level hook/seam/Fn/Func/Override, calls os/t.Setenv or Chdir, and neither finalize_merge.go nor the test file declares a package var (before this change). Traced fixture helpers (setupRebaseFixture chain, buildConfiguredRepo/newDocketModeRepo, runGit/tryGit, writerAdvance, carryDroppedCommit, testsupport.TempDir) touch only per-test state, Once-guarded process config, or the mutex-guarded drain map; the only t.Setenv in the chain was newGitClient via planningDepsFor, now bypassed. No test stays sequential. -race run of ^TestIntegrationFinalizeMerge: clean (no DATA RACE). Quiet solo measurements (shared protocol): - MEASURE label=B-before file=tests/test_go_integration_app_merge.sh runs=42.3,42.6,44.1 median=42.6 loads=4.72,4.51,4.55 quiet=yes rc=0,0,0 ncpu=11 - MEASURE label=B-after file=tests/test_go_integration_app_merge.sh runs=10.0,10.0,10.5 median=10.0 loads=5.40,6.69,9.38 quiet=yes rc=0,0,0 ncpu=11 Median 42.6s -> 10.0s, under the 25s target; runtime-budgets.tsv row unchanged.
… measurement No code change: every Part C lever was measured and none produced a win above run-to-run noise, and the after median already meets the 25s target, so the fallback (row re-set) does not apply and tests/runtime-budgets.tsv keeps tests/test_go_finalize_e2e.sh at 30s. Levers (each measured, each rejected): - -vet=off on the matrix run: go test's vet subset is cached; measured 0.5s vs 0.5s warm and 1.86-1.91s vs 1.79-1.80s right after a source edit (~0.1s). Not a measurable win; vet line and assert untouched. - Fake gh build: 0.11-0.27s per fresh temp dir (well under the 2s bar); the docket build is cached (0.2-0.6s). Left alone. - Per-test redundant setup: the critical path is TestE2EStack, a strictly sequential chain (two stacked implement() runs at ~6s each through real production transactions, then the blocked merge, child merge+closeout and root carry); solo it takes 18-21s. No step is test-only or identical to another test's work in a shareable way: the other tests each mutate their own reachImplemented fixture (claim, worktree, PR state), so sharing would need a cloned-snapshot fixture rewriting absolute worktree/run-dir paths, and it would only ease contention, not shorten the Stack critical path. Phase timings before (warm, e2e-phases.sh): PHASE vet 0.2s rc=0 PHASE testcompile 0.2s rc=0 PHASE docketbuild 0.2s rc=0 PHASE testrun 26.8s rc=0 Slowest tests (all parallel): --- PASS: TestE2EStack (26.64s) --- PASS: TestE2EConflictAndRepair (19.31s) --- PASS: TestE2EResponseLossConvergence (18.24s) Solo TestE2EStack: 20.8s real (8.8s user, 8.5s sys). Quiet solo measurements (shared protocol; same tree for both labels, the 4s gap is machine noise - the before runs started at load 8.4-10.2): - MEASURE label=C-before file=tests/test_go_finalize_e2e.sh runs=27.3,28.2,31.1 median=28.2 loads=9.29,8.40,10.23 quiet=yes rc=0,0,0 ncpu=11 - MEASURE label=C-after file=tests/test_go_finalize_e2e.sh runs=24.1,24.3,25.0 median=24.3 loads=5.62,7.29,9.09 quiet=yes rc=0,0,0 ncpu=11 Completeness-assert mutations: narrowing -run to TestE2EStack turns "every declared top-level TestE2E test actually ran" NOT OK (rc=1). Renaming func TestE2EStack to testE2EStackRenamed stays green (rc=0): the rename drops the function from both the declared and the ran count. That gap is pre-existing and not widened here; recorded for review.
tests/test_go_race.sh needs no code work; its quiet median puts the earlier 117s (change 0517) and 94s (PR 361) readings on record as contended measurements, not growth. Its quiet median (44.6s) is under its 60s row. Measurement note: a first D warm run (54.2s, rc=1) was discarded as a harness artifact. The caller's TMPDIR ended in "/", so the private TMPDIR became ".../T//m0507.*" and TestNoGitGuardShadowsGitOnPath's string comparison of the shim path failed in four packages. One cli agent test also failed with EOF on that run. With TMPDIR normalized (trailing slash stripped), the warm run and runs 1-3 were green (rc=0). ## A1 reproduction (2026-10-05T14:29:24Z) ``` cpu 50 0 0 4 - 4.78 cpu 50 0 0 4 - 7.68 cpu 50 0 0 4 - 10.75 cpu 50 0 0 4 - 10.75 cpu 50 0 0 4 - 13.17 cpu 50 0 0 4 - 14.44 cpu 50 0 0 4 - 16.00 cpu 50 0 0 4 - 17.85 cpu 50 0 0 4 - 17.85 cpu 50 0 0 4 - 19.62 cpu 50 0 0 4 - 21.65 cpu 50 0 0 4 - 22.08 cpu 50 0 0 4 - 23.03 cpu 50 0 0 4 - 23.03 cpu 50 0 0 4 - 24.39 cpu 50 0 0 4 - 25.56 cpu 50 0 0 4 - 27.36 cpu 50 0 0 4 - 27.81 cpu 50 0 0 4 - 27.81 cpu 50 0 0 4 - 27.91 cpu 50 0 0 4 - 28.47 cpu 50 0 0 4 - 28.68 cpu 50 0 0 4 - 30.38 cpu 50 0 0 4 - 30.38 cpu 50 0 0 4 - 30.51 cpu 50 0 0 4 - 31.75 cpu 50 0 0 4 - 31.61 cpu 50 0 0 4 - 32.20 cpu 50 0 0 4 - 32.20 cpu 50 0 0 4 - 34.67 cpu 50 0 0 4 - 35.98 cpu 50 0 0 4 - 37.66 cpu 50 0 0 4 - 39.13 cpu 50 0 0 4 - 39.13 cpu 50 0 0 4 - 38.08 cpu 50 0 0 4 - 45.52 cpu 50 0 0 4 - 49.96 cpu 50 0 0 4 - 52.53 cpu 50 0 0 4 - 53.20 cpu 50 0 0 4 - 53.20 gosuite 50 0 0 4 - 49.32 gosuite 50 0 0 4 - 45.69 gosuite 50 0 0 5 - 42.35 gosuite 50 0 0 4 - 40.56 gosuite 50 0 0 4 - 37.96 gosuite 50 0 0 4 - 37.96 gosuite 50 0 0 3 - 35.16 gosuite 50 0 0 4 - 32.50 gosuite 50 0 0 3 - 32.50 gosuite 50 0 0 4 - 30.22 gosuite 50 0 0 3 - 28.36 gosuite 50 0 0 3 - 26.57 gosuite 50 0 0 4 - 26.57 gosuite 50 0 0 4 - 24.60 gosuite 50 0 0 5 - 22.95 gosuite 50 0 0 4 - 21.51 gosuite 50 0 0 4 - 20.19 gosuite 50 0 0 3 - 20.19 gosuite 50 0 0 4 - 18.81 gosuite 50 0 0 4 - 17.47 gosuite 50 0 0 3 - 16.31 gosuite 50 0 0 4 - 16.31 gosuite 50 0 0 3 - 16.04 gosuite 50 0 0 4 - 14.92 gosuite 50 0 0 4 - 14.92 gosuite 50 0 0 4 - 14.12 gosuite 50 0 0 5 - 13.31 gosuite 50 0 0 3 - 12.49 gosuite 50 0 0 4 - 12.05 gosuite 50 0 0 4 - 12.05 gosuite 50 0 0 3 - 11.40 gosuite 50 0 0 4 - 10.81 gosuite 50 0 0 4 - 10.18 gosuite 50 0 0 3 - 10.18 gosuite 50 0 0 4 - 10.17 gosuite 50 0 0 4 - 9.59 gosuite 50 0 0 4 - 8.99 gosuite 50 0 0 5 - 8.99 gosuite 50 0 0 4 - 8.91 gosuite 50 0 0 4 - 8.83 ``` REPRO-TOTAL profile=gosuite iterations=2000 hangs=0 other_failures=0 seconds=154 REPRO-TOTAL profile=cpu iterations=2000 hangs=0 other_failures=0 seconds=160 REPRO-VERDICT not-reproduced - MEASURE label=B-before file=tests/test_go_integration_app_merge.sh runs=42.3,42.6,44.1 median=42.6 loads=4.72,4.51,4.55 quiet=yes rc=0,0,0 ncpu=11 - MEASURE label=B-after file=tests/test_go_integration_app_merge.sh runs=10.0,10.0,10.5 median=10.0 loads=5.40,6.69,9.38 quiet=yes rc=0,0,0 ncpu=11 - MEASURE label=C-before file=tests/test_go_finalize_e2e.sh runs=27.3,28.2,31.1 median=28.2 loads=9.29,8.40,10.23 quiet=yes rc=0,0,0 ncpu=11 PHASE vet 0.2s rc=0 PHASE testcompile 0.2s rc=0 PHASE docketbuild 0.2s rc=0 PHASE testrun 26.8s rc=0 Per-test (slowest first): --- PASS: TestE2EStack (26.64s) --- PASS: TestE2EConflictAndRepair (19.31s) --- PASS: TestE2EResponseLossConvergence (18.24s) --- PASS: TestE2EOrdinaryFinalize (18.24s) --- PASS: TestE2ENoPathDocketDependency (18.17s) --- PASS: TestE2EUnsupportedConfigRefused (16.99s) --- PASS: TestE2EMergeSelectsRebaseShape (16.35s) --- PASS: TestE2EMergeCommitShape (16.18s) --- PASS: TestE2EMergeMethodUnavailable (15.87s) --- PASS: TestE2EOutOfBandMergeRecovered (15.81s) --- PASS: TestE2ESquashOnlyShape (11.76s) --- PASS: TestE2EHaltResumeAndReclaim (9.37s) - MEASURE label=C-after file=tests/test_go_finalize_e2e.sh runs=24.1,24.3,25.0 median=24.3 loads=5.62,7.29,9.09 quiet=yes rc=0,0,0 ncpu=11 - MEASURE label=D file=tests/test_go_race.sh runs=44.1,44.6,45.0 median=44.6 loads=4.23,3.65,3.48 quiet=yes rc=0,0,0 ncpu=11
…nding 3) Quiet solo median after parallelization is 10.0s (10.0/10.0/10.5); rounding rule gives 15s, not 30s.
danielhanold
deleted the
fix/flaky-tests-track-and-stabilize-intermittent-suite-failures
branch
October 5, 2026 16:11
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
Change 0507: fixes and records the four suite problems it was opened for.
internal/processTestObserveRunningThenTerminal): not reproduced in 4,000 iterations under two load profiles. The test no longer discards thereadManifest/signalGrouperrors, and on the unchanged 30s expiry it now reports what was stuck (last Observe state/error, live group members, live-lock holder). Root cause stays open.tests/test_go_integration_app_merge.sh: 42.6s -> 10.0s quiet solo median. The merge tests run in parallel via a planning-node builder that isolates the global config dir once per process (new mutation-tested isolation test). Budget row lowered 30 -> 15 by the sizing rule.tests/test_go_finalize_e2e.sh: every candidate cut was measured and rejected; no code change. Medians on the identical tree were 23-28.2s. Human decision: keep the 30s row or apply the spec fallback (35s). See the results file.tests/test_go_race.sh: 44.6s quiet solo median against its 60s row. Recorded only.Measurements and methodology: see the results file and the empty record commits on the branch.
Review
Whole-branch review (deep tier): 4 findings.
Note: at the 15s row, the full parallel suite prints a
BUDGET WATCH:screening line for the merge file (42s under -j11, streak 2/5); its quiet solo runs are 9-10.5s.Build evidence
command: go run ./cmd/docket development test
result: green
head_sha: 0cdf698
ran_at: 2026-10-05T15:22:57Z