Server startup waits on an upgrade backfill (startup test times out on dev) #1161

Open
opened 2026-10-05 19:12:19 +00:00 by kayg · 9 comments
Owner

Server test fails on dev: startup_serves_http_while_upgrade_backfills_wait

Seen by #851, #1145 and others on 2026-10-05 (also isolated runs): HTTP startup waited for an upgrade backfill: Elapsed(()) — the test's 15 s budget for HTTP to serve while upgrade backfills run is exceeded. Production evidence: after the #851 deploy (batch 14, migrations 0026/0027 content-type rebuild) /healthz took 27 s instead of the usual 6 s.

Find whether HTTP startup now waits on a backfill (e.g. the content-type rebuild, the Note identity backfill #1132, the date backfill #1148) instead of running it in the background, contrary to DESIGN (HTTP must listen first; backfills run after, with progress; #1011). Fix the code path, keep the test's expectation, and add a test per backfill that HTTP answers /healthz within the budget while the backfill is running (simulate a large Home). Also expose backfill progress on /healthz state (coordinate with #1156's migrating state; one shape). Gates per crate quoted; three consecutive green runs of the server suite under load.

## Server test fails on dev: startup_serves_http_while_upgrade_backfills_wait Seen by #851, #1145 and others on 2026-10-05 (also isolated runs): `HTTP startup waited for an upgrade backfill: Elapsed(())` — the test's 15 s budget for HTTP to serve while upgrade backfills run is exceeded. Production evidence: after the #851 deploy (batch 14, migrations 0026/0027 content-type rebuild) /healthz took 27 s instead of the usual 6 s. Find whether HTTP startup now waits on a backfill (e.g. the content-type rebuild, the Note identity backfill #1132, the date backfill #1148) instead of running it in the background, contrary to DESIGN (HTTP must listen first; backfills run after, with progress; #1011). Fix the code path, keep the test's expectation, and add a test per backfill that HTTP answers /healthz within the budget while the backfill is running (simulate a large Home). Also expose backfill progress on /healthz state (coordinate with #1156's `migrating` state; one shape). Gates per crate quoted; three consecutive green runs of the server suite under load.
Author
Owner

Started investigation on branch job/startup-1161, based on d57992dea7. I am tracing startup migration and backfill ordering plus /healthz progress state before changing the listener path.

Started investigation on branch job/startup-1161, based on d57992dea77a5c031b1494fe9e5b608505b707e8. I am tracing startup migration and backfill ordering plus /healthz progress state before changing the listener path.
Author
Owner

Finding from source: wire::build_live_app awaits Db::apply_migration_sets_with_snapshot before returning, and main binds the listener only after build_live_app completes. When any migration is pending, calternal-db calls VACUUM INTO for a full Index snapshot first (crates/calternal-db/src/migrations.rs and snapshot.rs). Files migrations 0026/0027 only add MIME rebuild progress state; the row-by-row content-type rebuild is scheduled after Files reconciliation on the post-bind worker (crates/plugins/files/src/index.rs). This makes a full Index snapshot a plausible cause of the observed 27 s health delay; I am checking the live-app test under the current branch before finalizing the fix.

Finding from source: wire::build_live_app awaits Db::apply_migration_sets_with_snapshot before returning, and main binds the listener only after build_live_app completes. When any migration is pending, calternal-db calls VACUUM INTO for a full Index snapshot first (crates/calternal-db/src/migrations.rs and snapshot.rs). Files migrations 0026/0027 only add MIME rebuild progress state; the row-by-row content-type rebuild is scheduled after Files reconciliation on the post-bind worker (crates/plugins/files/src/index.rs). This makes a full Index snapshot a plausible cause of the observed 27 s health delay; I am checking the live-app test under the current branch before finalizing the fix.
Author
Owner

Server suite run 1 reached both new startup backfill cases, then failed in the existing startup_search_reconciliation_keeps_calendar_writes_responsive_on_large_home child. Evidence: search_reconcile_calendar_write_profile files=20000 writes=32 p50_ms=13696 p95_ms=13943 p95_budget_ms=10000; the child reports Calendar write p95 13.943s over its 10s budget. This is a SLOW-only result on the shared loaded host. I left the existing expectation unchanged and am continuing the requested server suite runs.

Server suite run 1 reached both new startup backfill cases, then failed in the existing `startup_search_reconciliation_keeps_calendar_writes_responsive_on_large_home` child. Evidence: `search_reconcile_calendar_write_profile files=20000 writes=32 p50_ms=13696 p95_ms=13943 p95_budget_ms=10000`; the child reports Calendar write p95 13.943s over its 10s budget. This is a SLOW-only result on the shared loaded host. I left the existing expectation unchanged and am continuing the requested server suite runs.
Author
Owner

Server suite runs 2 and 3 still reached the new startup scenarios, but the existing large-Home search/calendar-write profile failed under current host load. Run 2 measured p95=10.065s against its unchanged 10s budget. Run 3 timed out 20s calendar-feed creates; the profile finished in 64.25s. These are SLOW-only load findings; no expectation or budget was changed. I am continuing the requested consecutive full-suite runs.

Server suite runs 2 and 3 still reached the new startup scenarios, but the existing large-Home search/calendar-write profile failed under current host load. Run 2 measured p95=10.065s against its unchanged 10s budget. Run 3 timed out 20s calendar-feed creates; the profile finished in 64.25s. These are SLOW-only load findings; no expectation or budget was changed. I am continuing the requested consecutive full-suite runs.
Author
Owner

Server suite run 4 again passed the startup cases but failed only the existing large-Home search/calendar-write profile: calendar-write p95=19.535s against the unchanged 10s budget (profile duration 60.42s). This remains a SLOW-only result under shared host load; I did not change its threshold. I will continue the requested stability runs.

Server suite run 4 again passed the startup cases but failed only the existing large-Home search/calendar-write profile: calendar-write p95=19.535s against the unchanged 10s budget (profile duration 60.42s). This remains a SLOW-only result under shared host load; I did not change its threshold. I will continue the requested stability runs.
Author
Owner

Server suite run 5 again passed both new startup scenarios and failed only the existing large-Home search/calendar-write timing profile. It measured p50=13.783s and p95=14.140s against the unchanged p95 budget of 10s. This is another SLOW-only result on the shared host; no assertion or budget was changed.

Server suite run 5 again passed both new startup scenarios and failed only the existing large-Home search/calendar-write timing profile. It measured p50=13.783s and p95=14.140s against the unchanged p95 budget of 10s. This is another SLOW-only result on the shared host; no assertion or budget was changed.
Author
Owner

Server suite run 6 exposed a test-only completion deadline: the new Notes startup case had already observed /healthz in the notes-upgrade-backfills phase and served /healthz, /readyz and / during it, but its 30s wait for the migration markers to finish expired on the large fixture under load. I extended only that eventual-completion wait to 90s; the health response budget remains 15s. The focused test now passes: test wire::tests::startup_serves_http_while_upgrade_backfills_wait ... ok (1 passed; 0 failed; 0 ignored; 266 filtered out; 36.44s).

Server suite run 6 exposed a test-only completion deadline: the new Notes startup case had already observed `/healthz` in the `notes-upgrade-backfills` phase and served `/healthz`, `/readyz` and `/` during it, but its 30s wait for the migration markers to finish expired on the large fixture under load. I extended only that eventual-completion wait to 90s; the health response budget remains 15s. The focused test now passes: `test wire::tests::startup_serves_http_while_upgrade_backfills_wait ... ok` (1 passed; 0 failed; 0 ignored; 266 filtered out; 36.44s).
Author
Owner

After widening the Notes test's eventual-completion wait, server suite run 7 passed that startup scenario but again failed only the existing large-Home search/calendar-write profile: p95=19.376s against 10s (profile duration 72.23s). The 15s startup /healthz expectation and health-during-backfill checks remain unchanged. Repeated SLOW failures under shared host load prevent the requested three-green streak; no threshold was changed.

After widening the Notes test's eventual-completion wait, server suite run 7 passed that startup scenario but again failed only the existing large-Home search/calendar-write profile: p95=19.376s against 10s (profile duration 72.23s). The 15s startup `/healthz` expectation and health-during-backfill checks remain unchanged. Repeated SLOW failures under shared host load prevent the requested three-green streak; no threshold was changed.
Author
Owner

#1161 completion report

Branch: job/startup-1161
Base: 41bf97fb2861ea6e4ea70aab7d3b15a1c9aa278d (origin/dev)
Head: 49cdeed981129f5b0cce9d038cf8dacfd86bf2a0

Commits:

  • 0e063629d Expose startup progress on healthz
  • 49cdeed98 Refresh exact perf coverage for startup health

Built

  • Bind the HTTP listener before media checks, Index setup and migrations. The initial router answers /healthz; it returns Connection: close so clients reconnect after the live router is installed. Other paths return a retryable unavailable response until setup ends.
  • Publish one health shape through startup and live routing: {"state":"migrating","progress":{"phase":"…"}}, then {"state":"ok","progress":null} after startup backfills complete. Phase names are content-free and cover setup, Notes backfills, Search and Files reconciliation, and the Files content-type backfill.
  • Add large-Home HTTP health tests for the Notes upgrade backfills (including the date/identity migrations) and the Files content-type backfill. Each checks the 15-second health budget while its backfill phase is active.
  • Add the health operation to OpenAPI and its public read policy. Refresh exact performance coverage and remove stale exceptions; the ratchet lowered from 22,104 to 22,028.

Files

crates/calternal-server/src/{main.rs,serve.rs,wire.rs}, crates/plugins/files/src/lib.rs, contracts/action-policy.json, contracts/openapi.json, and contracts/perf/{adoption-1058.json,exceptions.json,ratchet.json,registry.json}.

Gates

  • cargo fmt --check: exit 0, no output.
  • cargo clippy -p calternal-server --all-targets -- -D warnings: Finished \dev` profile [unoptimized + debuginfo] target(s) in 35.67s`.
  • cargo clippy -p calternal-plugin-files --all-targets -- -D warnings: Finished \dev` profile [unoptimized + debuginfo] target(s) in 23.09s`.
  • cargo test -p calternal-plugin-files (serial): test result: ok. 258 passed; 0 failed; 4 ignored; 0 measured; 0 filtered out; finished in 897.75s.
  • Focused startup tests passed: test wire::tests::startup_serves_http_while_upgrade_backfills_wait ... ok and test wire::tests::startup_serves_http_while_content_type_backfill_runs ... ok.
  • Focused Search and OpenAPI tests passed: test tests::search_route_rejects_an_invalid_time_zone_header ... ok; test tests::openapi_contains_reference_plugin_and_search_paths ... ok.
  • cd apps/web && bun run check: perf-lint: PASS; 0 violations; 22028 scoped exceptions; svelte-check found 0 errors and 4 warnings in 3 files.
  • cargo clean: Removed 19400 files, 15.6GiB total. apps/web/build and the local target/ are absent. Worktree is clean.

Known gaps

The requested three consecutive green server-suite runs were not achieved. Seven full server-suite runs reached the startup tests, but the existing SLOW test startup_search_reconciliation_keeps_calendar_writes_responsive_on_large_home repeatedly exceeded its unchanged 10-second Calendar-write budget under shared-host load. The last run passed both startup backfill cases and measured the existing profile at p95 19.376 seconds (72.23 seconds total). Earlier exact profile output was search_reconcile_calendar_write_profile files=20000 writes=32 p50_ms=13696 p95_ms=13943 p95_budget_ms=10000. No test threshold changed.

The full bun run test and the startup performance profile were not run in this job because it exceeded the four-hour job timebox. For the merge round:

  • Run cd apps/web && bun run test --maxWorkers=2 and require the full Vitest suite to pass.
  • Run cargo test -p calternal-server -- --test-threads=4 three consecutive times; verify the backfill cases and the unchanged Search/Calendar timing behavior.
  • Run tests/adversarial/run.sh against the merged server and include startup /healthz protocol and request-burst coverage.
  • Run bun bench/startup-1011.mjs with the updated shared release binary. It must report the startup health latency, interactive readiness, CPU/RSS and health burst profile against the 15-second budget.

Decisions

  • Reuse the #1156 migrating state and represent progress as a single content-free phase string. I did not add a percentage because startup phases have different units.
  • Close startup-health connections after each response. This makes clients select the installed live router on their next request.

UX gaps closed: not applicable; this change has no UI.
UX gaps left: none.

#1161 completion report Branch: `job/startup-1161` Base: `41bf97fb2861ea6e4ea70aab7d3b15a1c9aa278d` (`origin/dev`) Head: `49cdeed981129f5b0cce9d038cf8dacfd86bf2a0` Commits: - `0e063629d` Expose startup progress on healthz - `49cdeed98` Refresh exact perf coverage for startup health ## Built - Bind the HTTP listener before media checks, Index setup and migrations. The initial router answers `/healthz`; it returns `Connection: close` so clients reconnect after the live router is installed. Other paths return a retryable unavailable response until setup ends. - Publish one health shape through startup and live routing: `{"state":"migrating","progress":{"phase":"…"}}`, then `{"state":"ok","progress":null}` after startup backfills complete. Phase names are content-free and cover setup, Notes backfills, Search and Files reconciliation, and the Files content-type backfill. - Add large-Home HTTP health tests for the Notes upgrade backfills (including the date/identity migrations) and the Files content-type backfill. Each checks the 15-second health budget while its backfill phase is active. - Add the health operation to OpenAPI and its public read policy. Refresh exact performance coverage and remove stale exceptions; the ratchet lowered from 22,104 to 22,028. ## Files `crates/calternal-server/src/{main.rs,serve.rs,wire.rs}`, `crates/plugins/files/src/lib.rs`, `contracts/action-policy.json`, `contracts/openapi.json`, and `contracts/perf/{adoption-1058.json,exceptions.json,ratchet.json,registry.json}`. ## Gates - `cargo fmt --check`: exit 0, no output. - `cargo clippy -p calternal-server --all-targets -- -D warnings`: `Finished \`dev\` profile [unoptimized + debuginfo] target(s) in 35.67s`. - `cargo clippy -p calternal-plugin-files --all-targets -- -D warnings`: `Finished \`dev\` profile [unoptimized + debuginfo] target(s) in 23.09s`. - `cargo test -p calternal-plugin-files` (serial): `test result: ok. 258 passed; 0 failed; 4 ignored; 0 measured; 0 filtered out; finished in 897.75s`. - Focused startup tests passed: `test wire::tests::startup_serves_http_while_upgrade_backfills_wait ... ok` and `test wire::tests::startup_serves_http_while_content_type_backfill_runs ... ok`. - Focused Search and OpenAPI tests passed: `test tests::search_route_rejects_an_invalid_time_zone_header ... ok`; `test tests::openapi_contains_reference_plugin_and_search_paths ... ok`. - `cd apps/web && bun run check`: `perf-lint: PASS; 0 violations; 22028 scoped exceptions`; `svelte-check found 0 errors and 4 warnings in 3 files`. - `cargo clean`: `Removed 19400 files, 15.6GiB total`. `apps/web/build` and the local `target/` are absent. Worktree is clean. ## Known gaps The requested three consecutive green server-suite runs were not achieved. Seven full server-suite runs reached the startup tests, but the existing SLOW test `startup_search_reconciliation_keeps_calendar_writes_responsive_on_large_home` repeatedly exceeded its unchanged 10-second Calendar-write budget under shared-host load. The last run passed both startup backfill cases and measured the existing profile at p95 19.376 seconds (72.23 seconds total). Earlier exact profile output was `search_reconcile_calendar_write_profile files=20000 writes=32 p50_ms=13696 p95_ms=13943 p95_budget_ms=10000`. No test threshold changed. The full `bun run test` and the startup performance profile were not run in this job because it exceeded the four-hour job timebox. For the merge round: - Run `cd apps/web && bun run test --maxWorkers=2` and require the full Vitest suite to pass. - Run `cargo test -p calternal-server -- --test-threads=4` three consecutive times; verify the backfill cases and the unchanged Search/Calendar timing behavior. - Run `tests/adversarial/run.sh` against the merged server and include startup `/healthz` protocol and request-burst coverage. - Run `bun bench/startup-1011.mjs` with the updated shared release binary. It must report the startup health latency, interactive readiness, CPU/RSS and health burst profile against the 15-second budget. ## Decisions - Reuse the #1156 `migrating` state and represent progress as a single content-free phase string. I did not add a percentage because startup phases have different units. - Close startup-health connections after each response. This makes clients select the installed live router on their next request. UX gaps closed: not applicable; this change has no UI. UX gaps left: none.
Sign in to join this conversation.
No labels
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
kayg/calternal#1161
No description provided.