Diagnose and stabilize server shutdown test startup #91
Loading…
Add table
Add a link
Reference in a new issue
No description provided.
Delete branch "fix/bb-shutdown-ci-diagnostics"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
PR91 is a prerequisite for the PR88/PR89 work. BB-97 and BB-99 track separate behavior; this test repair is related to those cards and leaves them open.
The old test used a reserve-release-rebind port handoff, which was a real avoidable race, but CI run 72 did not show a bind failure: the child emitted only its initial starting log line at 10:18:21.04 and the test timed out at 10:18:26.54 without the logged bind stage. The historical runner cause is therefore not confirmed.
The leading explanation is cold SQLite startup on a slow or heavily loaded runner. Opening a new SQLite database in WAL mode and running six migrations performs about 21 fsyncs before bind. In a controlled local reproduction, delaying each fsync by 300ms made cold startup take about 6.4s and delayed bind beyond the five-second budget; at 200ms per fsync, bind completed at 4.33s. This demonstrates a plausible mechanism, not a measurement of run 72's database stage.
The test keeps the child on a cold database inside the original five-second startup deadline. The server logs elapsed milliseconds at connection, migrations, seed, state, router and bind. The test reads the bound address from the child's listening log, not ss, and bounds address discovery and every health probe by one deadline. A child guard kills, waits and joins stdout/stderr readers on failure and unwind; captured output is bounded. SIGTERM remains 2s and SSE EOF remains 1s. The SSE account/token is added only after startup health.
Evidence: exact-head run 74 for
67b648d1aesucceeded through clippy, workspace tests (all 8 shutdown tests), check-docs and web build. That run confirms the cold-start test finishes inside its five-second budget on the runner. However, cargo test captures successful test output, so the per-stage elapsed log lines are not included in the successful job log. The exact stage that delayed run 72 remains unconfirmed. Local locked workspace tests and clippy pass; the exact shutdown binary passed 40 sequential runs and 40 runs under 16 CPU-load processes. The corrected test has no ss dependency; startup discovery/probes share one checked deadline; failure-injection tests cover delayed discovery, hung health, early exit diagnostics, failed SIGTERM, panic unwind and bounded capture.Independent exact-head review: CHANGES REQUESTED.
Reviewed head
c30f27127eagainst main5ff90e8cc2. Complete two-file diff reviewed. Findings tracked as BB-105 (Forgejo #92); preserve PR91 and its branch. No merge and no card completed.Criterion mapping:
c30f271: checkout and clippy success, test failure, check-docs/bakery/web skipped. Read job results AND downloaded full attempt1 logs. shutdown.rs:127 startup failure after5.51s captured only the starting-server line. There is no bound-address log or bind error. Startup had not observably reached the post-DB/post-seed listener stage. Earlier runs67 attempt2,68 attempt2,70 attempt1 also failed the old test at line36; logs discarded the cause. A port race is real but the historical cause is unconfirmed, and current runner failure persists after its removal. Investigate DB migration/seed/runtime and runner latency with evidence, without increasing startup or weakening shutdown/SSE budgets.Required rework:
[ ] shutdown.rs:74-138: bound discovery and HTTP by the original five-second budget, check expiry before accepting success, remove redundant health request, add a delayed/hung-discovery regression.
[ ] shutdown.rs:26-207: guarantee kill+wait and reader cleanup on every exit/panic path; drain complete logs before error reporting, use bounded capture; add forced signal/setup/early-exit failure coverage proving no live child or unreaped process remains.
[ ] shutdown.rs:14-25,74-95: correct the discovery-order comments, handle missing ss/failed status/unsupported Unix clearly (or avoid the external dependency), match child identity exactly. Keep bind-race claims separate from unproven historical causation.
[ ] Diagnose run72 startup failure from the actual runner evidence, preserve all budgets, and obtain a fresh exact-head CI success with every required job step run.
[ ] Reconcile/remove the stale automatic PR91-to-BB-97 closing link through the supported sync fix, not by completing BB-97.
Evidence logs and failure-injection scripts/results retained locally under /tmp/opencode/review-pr91. Scratch checkout remains isolated at ~/.worktrees/breadboard/fix/review-pr91-c30f271. No primary or other worktree changed.
Independent review CHANGES REQUESTED at
c30f27127e: #91 (comment). BB-105 tracks reproduced five-second startup budget violation and live-child leak on failed signal path. Local locked workspace/clippy pass, 30 sequential+20 runs under16 CPU workers pass, but exact-head run72 test fails with only starting-server log; remaining required steps skipped. Historical bind collision is unconfirmed. PR body has no closing reference, but stale closes->BB-97 persists; reconcile before any merge. Preserve PR91/branch, no merge or done.Follow-up on run 73 (exact head
60ad45fe1e): the job passed clippy, all workspace tests including all 8 shutdown tests, check-docs, and web. Its log confirms the cold DB stage was NOT observed because at that head the test prepared/migrated the DB before spawning the child. That meant the CI success did not explain the run 72 delay. I am correcting the test so cold SQLite connection/migrations/seed happen in the child under the original 5s deadline, with SSE user/token setup after health. Run 72 captured onlystartingat 10:18:21.04 and timed out at 10:18:26.54 without the bind log. The port handoff was avoidable, but is not evidenced as the historical cause. A controlled local fault injection of 300ms per SQLite fsync reproduces the same signature, making slow cold SQLite startup a plausible mechanism, not a confirmed measurement of run 72. The original 5s/2s/1s budgets remain unchanged.Independent re-review: CHANGES REQUESTED (body metadata only, code passes).
Reviewed exact head
67b648d1aeagainst base5ff90e8cc2(equals origin/main, mergeable true). Full three-file diff reviewed in isolated scratch worktree; primary checkout untouched. No merge performed.Code criteria, all pass:
Local evidence (isolated scratch, locked flags): cargo clippy --workspace --all-targets --locked -- -D warnings clean; cargo test --workspace --locked green including all 8 shutdown tests; exact compiled shutdown binary 30/30 sequential and 20/20 under 16 CPU hogs; six injection tests individually green; cargo run -p xtask --locked -- check-docs OK. Web build not re-run locally (diff touches no frontend files); covered by CI below.
CI: combined required check success for the exact head: context check / check (push), run 74, Successful in 1m28s, target run 74 jobs/0. Per-step job logs are not reachable through the available read API (actions pages require sign-in), so steps are covered by that green combined status plus the author step report plus the local reproduction above.
Blocker (must fix before merge, one item):
Next action: coordinator has author reword the PR body as above, triggers reconcile, requests fresh review of the new head. No code changes needed.