kayg/calternal-v0

Archived

Watch

Fork 0

Server startup backfill test times out under live-app process wrapper #1569

Closed

opened 2026-10-11 01:38:27 +00:00 by kayg · 4 comments

kayg commented

2026-10-11 01:38:27 +00:00

Owner

Found while verifying #1566 at 5bb674ef9458c4cc311aa8d81121b2eba9e607cd (base merge39 5efdab060, merged origin/dev once). The Money ownership regression, Money crate suites, workspace Clippy, and release-server focused/full XUser matrices pass. No server source or assertion changed in this branch.

The full workspace cargo test -- --test-threads=4 exits 101 in wire::tests::live_apps_run_in_separate_processes. Its child startup_serves_http_while_upgrade_backfills_wait times out at crates/calternal-server/src/wire.rs:9173, waiting for the background backfill completion within the existing 90-second bound.

Verbatim workspace failure:

background backfills did not finish: Elapsed(())
test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 288 filtered out; finished in 95.61s
test result: FAILED. 276 passed; 1 failed; 12 ignored; 0 measured; 0 filtered out; finished in 129.37s
exit=101

Direct isolated replay uses the exact workspace test binary, RUST_MIN_STACK=8388608, TMPDIR=<worktree>/target/tmp:

calternal_server-9b055861aeff8c64 wire::tests::startup_serves_http_while_upgrade_backfills_wait --ignored --exact --nocapture --test-threads=1
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 288 filtered out; finished in 9.46s
exit=0

The process-isolation wrapper also fails when run alone with the same binary and environment:

calternal_server-9b055861aeff8c64 wire::tests::live_apps_run_in_separate_processes --exact --nocapture --test-threads=1
background backfills did not finish: Elapsed(())
test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 288 filtered out; finished in 96.38s
test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 288 filtered out; finished in 123.16s
exit=101

No timeout or expectation was changed. One full run and these focused replays were performed; no full-suite loop. The direct pass does not clear the wrapper failure. Investigate the wrapper/child startup conditions and backfill scheduling, then rerun the complete workspace gate. Logs remain in the #1566 worktree under artifacts/fix1566/test-workspace.log, startup-latency-binary.log, and live-apps-isolated.log.

Found while verifying #1566 at `5bb674ef9458c4cc311aa8d81121b2eba9e607cd` (base merge39 `5efdab060`, merged origin/dev once). The Money ownership regression, Money crate suites, workspace Clippy, and release-server focused/full XUser matrices pass. No server source or assertion changed in this branch. The full workspace `cargo test -- --test-threads=4` exits 101 in `wire::tests::live_apps_run_in_separate_processes`. Its child `startup_serves_http_while_upgrade_backfills_wait` times out at `crates/calternal-server/src/wire.rs:9173`, waiting for the background backfill completion within the existing 90-second bound. Verbatim workspace failure: ```text background backfills did not finish: Elapsed(()) test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 288 filtered out; finished in 95.61s test result: FAILED. 276 passed; 1 failed; 12 ignored; 0 measured; 0 filtered out; finished in 129.37s exit=101 ``` Direct isolated replay uses the exact workspace test binary, `RUST_MIN_STACK=8388608`, `TMPDIR=<worktree>/target/tmp`: ```text calternal_server-9b055861aeff8c64 wire::tests::startup_serves_http_while_upgrade_backfills_wait --ignored --exact --nocapture --test-threads=1 test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 288 filtered out; finished in 9.46s exit=0 ``` The process-isolation wrapper also fails when run alone with the same binary and environment: ```text calternal_server-9b055861aeff8c64 wire::tests::live_apps_run_in_separate_processes --exact --nocapture --test-threads=1 background backfills did not finish: Elapsed(()) test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 288 filtered out; finished in 96.38s test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 288 filtered out; finished in 123.16s exit=101 ``` No timeout or expectation was changed. One full run and these focused replays were performed; no full-suite loop. The direct pass does not clear the wrapper failure. Investigate the wrapper/child startup conditions and backfill scheduling, then rerun the complete workspace gate. Logs remain in the #1566 worktree under `artifacts/fix1566/test-workspace.log`, `startup-latency-binary.log`, and `live-apps-isolated.log`.

kayg referenced this issue

2026-10-11 01:39:04 +00:00

Money cleared cold path returns 503 and queues foreign or missing Budgets #1566

kayg commented

2026-10-11 01:40:53 +00:00

Author

Owner

Starting investigation on branch job/fix1569 at 5bb674ef94 (base noted by the issue: merge39 5efdab060). I will reproduce the wrapper failure on the requested revisions, inspect the spawned child environment and backfill state, then make the smallest fix and run the requested gates.

Starting investigation on branch job/fix1569 at 5bb674ef9458c4cc311aa8d81121b2eba9e607cd (base noted by the issue: merge39 5efdab060). I will reproduce the wrapper failure on the requested revisions, inspect the spawned child environment and backfill state, then make the smallest fix and run the requested gates.

kayg commented

2026-10-11 02:07:26 +00:00

Author

Owner

Finding: the timeout checks a transient marker count. backfill_after_serving_excluding runs five per-User Notes migrations in sequence (identity, dates, Daily note bridge tags, Daily note identity, and Daily note navigation). The test polls every 25 ms and waits for the marker count to equal exactly 3. If migrations four and five commit between polls, the count moves from 3 to 5 and the test waits until its 90-second timeout even though the backfill completed. StartupProgress already advances beyond notes-upgrade-backfills only after the full Notes call returns.

The failure logs in the #1566 worktree confirm the timeout at this exact count wait, while the direct child passed. I built the web app and ran the wrapper on 4ebeba0b8 (pass, 100.14 s), 5efdab060 after clearing the stale auth artifact (pass, 103.13 s), and 5bb674ef9 (pass, 119.87 s; after rebuilding Notes from source, pass, 91.86 s). The failure did not reproduce on this host. I will update the wrapper test to wait for the phase transition and report the startup phase, Notes migration markers, and durable job states if the 90-second bound expires.

Finding: the timeout checks a transient marker count. `backfill_after_serving_excluding` runs five per-User Notes migrations in sequence (identity, dates, Daily note bridge tags, Daily note identity, and Daily note navigation). The test polls every 25 ms and waits for the marker count to equal exactly 3. If migrations four and five commit between polls, the count moves from 3 to 5 and the test waits until its 90-second timeout even though the backfill completed. `StartupProgress` already advances beyond `notes-upgrade-backfills` only after the full Notes call returns. The failure logs in the #1566 worktree confirm the timeout at this exact count wait, while the direct child passed. I built the web app and ran the wrapper on 4ebeba0b8 (pass, 100.14 s), 5efdab060 after clearing the stale auth artifact (pass, 103.13 s), and 5bb674ef9 (pass, 119.87 s; after rebuilding Notes from source, pass, 91.86 s). The failure did not reproduce on this host. I will update the wrapper test to wait for the phase transition and report the startup phase, Notes migration markers, and durable job states if the 90-second bound expires.

kayg referenced this issue from a commit

2026-10-11 02:54:41 +00:00

test(server): wait for Notes backfill completion (#1569)

kayg referenced this issue

2026-10-11 03:01:57 +00:00

Money register contract tests fail in workspace suite #1570

kayg commented

2026-10-11 03:02:19 +00:00

Author

Owner

Completed on branch job/fix1569.

Root cause: the test polled for exactly three Notes migration markers. The backfill records five markers sequentially, so a poll could miss the transient count of three and wait until timeout after all work had finished. The test now waits for the startup phase to leave notes-upgrade-backfills, confirms all five marker names, and prints startup, migration and durable job state if the 90-second bound expires. The bound is unchanged.

Classification: the wrapper test passed on 4ebeba0b8 (origin/dev), 5efdab060 (merge39) and 5bb674ef9 (job base). It also passed after the change. Since merge39 passed, the requested bisect condition did not occur. This race did not reproduce on this host; the change fixes the test's transient-state assumption and improves timeout diagnostics.

Files: crates/calternal-server/src/wire.rs
Head: 0866ca3b225e1d0964d80dccab14d5dc1b96b69e
Commit: test(server): wait for Notes backfill completion (#1569)

Final gates (verbatim result lines):

$ cargo fmt --check; echo exit=$?
exit=0

$ cargo clippy -p calternal-server --all-targets -- -D warnings; echo exit=$?
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 18.53s
exit=0

$ cargo test -p calternal-server
 test result: ok. 277 passed; 0 failed; 12 ignored; 0 measured; 0 filtered out; finished in 117.60s
 test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 25.34s
 test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.13s
exit=0

$ cargo test
 test result: FAILED. 180 passed; 2 failed; 3 ignored; 0 measured; 0 filtered out; finished in 1193.17s
error: test failed, to rerun pass `-p calternal-plugin-money --lib`
exit=101

The two workspace failures are in calternal-plugin-money: register_writes_publish_before_reads and register_mark_writes_touch_constant_rows_with_card_history. Neither test nor Money implementation was changed. I filed the evidence for triage as #1570.

Decisions: the completion condition follows the server's startup phase instead of an intermediate marker count. The five marker names are asserted to prove the full current Notes backfill set completed. No DESIGN decision was needed and no product behavior changed.

Completed on branch `job/fix1569`. Root cause: the test polled for exactly three Notes migration markers. The backfill records five markers sequentially, so a poll could miss the transient count of three and wait until timeout after all work had finished. The test now waits for the startup phase to leave `notes-upgrade-backfills`, confirms all five marker names, and prints startup, migration and durable job state if the 90-second bound expires. The bound is unchanged. Classification: the wrapper test passed on 4ebeba0b8 (origin/dev), 5efdab060 (merge39) and 5bb674ef9 (job base). It also passed after the change. Since merge39 passed, the requested bisect condition did not occur. This race did not reproduce on this host; the change fixes the test's transient-state assumption and improves timeout diagnostics. Files: `crates/calternal-server/src/wire.rs` Head: `0866ca3b225e1d0964d80dccab14d5dc1b96b69e` Commit: `test(server): wait for Notes backfill completion (#1569)` Final gates (verbatim result lines): ```text $ cargo fmt --check; echo exit=$? exit=0 $ cargo clippy -p calternal-server --all-targets -- -D warnings; echo exit=$? Finished `dev` profile [unoptimized + debuginfo] target(s) in 18.53s exit=0 $ cargo test -p calternal-server test result: ok. 277 passed; 0 failed; 12 ignored; 0 measured; 0 filtered out; finished in 117.60s test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 25.34s test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.13s exit=0 $ cargo test test result: FAILED. 180 passed; 2 failed; 3 ignored; 0 measured; 0 filtered out; finished in 1193.17s error: test failed, to rerun pass `-p calternal-plugin-money --lib` exit=101 ``` The two workspace failures are in `calternal-plugin-money`: `register_writes_publish_before_reads` and `register_mark_writes_touch_constant_rows_with_card_history`. Neither test nor Money implementation was changed. I filed the evidence for triage as #1570. Decisions: the completion condition follows the server's startup phase instead of an intermediate marker count. The five marker names are asserted to prove the full current Notes backfill set completed. No DESIGN decision was needed and no product behavior changed.

kayg referenced this issue

2026-10-11 08:18:15 +00:00

Merge round 40: Users settings, Money register UI, reminders, Calendar and startup speed #1574

kayg commented

2026-10-11 20:08:43 +00:00

Author

Owner

Deployed to calternal.cloud in merge round 40 (build c0f8da461, 01:38 IST 2026-10-12). Health state ok, /readyz 200, served-page check passed. Pre-deploy backup taken.

Deployed to calternal.cloud in merge round 40 (build c0f8da461, 01:38 IST 2026-10-12). Health state ok, /readyz 200, served-page check passed. Pre-deploy backup taken.

kayg closed this issue

2026-10-11 20:08:44 +00:00

Commenting is not possible because the repository is archived.

No labels

No milestone

No project

No assignees

1 participant

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-v0#1569

No description provided.

Rows
Columns