kayg commented

Owner

Cold start still takes about 121 s to first correct authenticated Calendar/Note data on the perf VM (release build, merge41 report docs/perf/2026-10-12-merge41.md: /readyz p50 63.8 s, first data p50 121.0 s). The startup-1573d report names collaboration watcher registration as the main remaining delay before listener readiness. Goal: first correct data on a cold default Home well under 30 s without weakening the #1573 safety fixes (journal-protected cleanup, single writer through upgrade drain, Search retry, Task identity, parked ownership retries). Measure only on the perf VM with interleaved pairs against production 8e8409629. Follow-up of #1573.

Cold start still takes about 121 s to first correct authenticated Calendar/Note data on the perf VM (release build, merge41 report docs/perf/2026-10-12-merge41.md: /readyz p50 63.8 s, first data p50 121.0 s). The startup-1573d report names collaboration watcher registration as the main remaining delay before listener readiness. Goal: first correct data on a cold default Home well under 30 s without weakening the #1573 safety fixes (journal-protected cleanup, single writer through upgrade drain, Search retry, Task identity, parked ownership retries). Measure only on the perf VM with interleaved pairs against production 8e8409629. Follow-up of #1573.

kayg commented

2026-10-12 04:25:06 +00:00

Author

Owner

Starting job/cold-1586 from base 8e84096297. I will attribute startup phases on the locked perf VM and post timings before implementation changes.

Starting job/cold-1586 from base 8e840962979acd2bdf58141888618ab5560f728e. I will attribute startup phases on the locked perf VM and post timings before implementation changes.

kayg commented

2026-10-12 05:07:11 +00:00

Author

Owner

Startup phase attribution (base `8e8409629`)

Measured on perf-test VM under perf-run, release binary SHA256 d296f947b356dcd10e394e21f85c7d0051dc8f796d601eac66cfebc77299a3c7, default #549 Home (100,000 Files, 50,000 photos, 5,000 Notes). Lock-time load average before the run: 2.77 / 5.12 / 4.16.

Phase or boundary	Time	Startup role
`collab.hub`	49,436 ms	Synchronous `Hub::new`; recursive collaboration watcher registration gates the live Router
`homes.watcher_register`	49,443 ms	Background Home watcher registration
`search.watcher_register`	59,536 ms	Search actor watcher registration; background, overlaps startup
`notes.recover`	4,093 ms	Pre-live recovery
`users.sync_homes`	2,854 ms	User/Home sync
`files.restore_upload_reservations`	2,695 ms	Upload reservation recovery
`root.open_prepare_recover`	1,067 ms	Root open and journal recovery
`db.migrations`	146 ms	Index migrations
`frontend.assets_retain`	33 ms	Existing build inventory fast path
Other measured phases	<= 79 ms each	Startup setup

The measured phase durations overlap, so they do not sum to the boundary times. /readyz first returned 200 at 61,733 ms. The first correct authenticated Note returned at 118,805 ms; earlier Note reads returned 404. Calendar did not return the seeded correct row during this profile.

This identifies synchronous collaboration watcher registration as the largest direct pre-router phase. The background Home and Search registrations overlap it and add cold-HDD load. The next change will move collaboration watcher registration off the listener path, return retryable 503 + Retry-After: 1 on collaboration routes until it completes, and leave /readyz and other response shapes unchanged.

# Startup phase attribution (base 8e8409629) Measured on perf-test VM under `perf-run`, release binary SHA256 `d296f947b356dcd10e394e21f85c7d0051dc8f796d601eac66cfebc77299a3c7`, default #549 Home (100,000 Files, 50,000 photos, 5,000 Notes). Lock-time load average before the run: 2.77 / 5.12 / 4.16. | Phase or boundary | Time | Startup role | | --- | ---: | --- | | `collab.hub` | 49,436 ms | Synchronous `Hub::new`; recursive collaboration watcher registration gates the live Router | | `homes.watcher_register` | 49,443 ms | Background Home watcher registration | | `search.watcher_register` | 59,536 ms | Search actor watcher registration; background, overlaps startup | | `notes.recover` | 4,093 ms | Pre-live recovery | | `users.sync_homes` | 2,854 ms | User/Home sync | | `files.restore_upload_reservations` | 2,695 ms | Upload reservation recovery | | `root.open_prepare_recover` | 1,067 ms | Root open and journal recovery | | `db.migrations` | 146 ms | Index migrations | | `frontend.assets_retain` | 33 ms | Existing build inventory fast path | | Other measured phases | <= 79 ms each | Startup setup | The measured phase durations overlap, so they do not sum to the boundary times. `/readyz` first returned 200 at 61,733 ms. The first correct authenticated Note returned at 118,805 ms; earlier Note reads returned 404. Calendar did not return the seeded correct row during this profile. This identifies synchronous collaboration watcher registration as the largest direct pre-router phase. The background Home and Search registrations overlap it and add cold-HDD load. The next change will move collaboration watcher registration off the listener path, return retryable 503 + `Retry-After: 1` on collaboration routes until it completes, and leave `/readyz` and other response shapes unchanged.

kayg commented

2026-10-12 05:44:51 +00:00

Author

Owner

The first candidate matrix sample reached correct authenticated Note data in 13.9 s, but the profiler had to force-kill it after its shutdown grace: the recursive collaboration watcher was still registering. The watcher used spawn_blocking, and Tokio runtime teardown waits for an already-running blocking task. I am moving that single registration to a detached worker with a cancellable result receiver and adding a regression test that runtime shutdown returns while watcher work is pending. I stopped the matrix after this first default and 100-file pair; I will rerun the full five-pair matrix after the shutdown fix.

The first candidate matrix sample reached correct authenticated Note data in 13.9 s, but the profiler had to force-kill it after its shutdown grace: the recursive collaboration watcher was still registering. The watcher used `spawn_blocking`, and Tokio runtime teardown waits for an already-running blocking task. I am moving that single registration to a detached worker with a cancellable result receiver and adding a regression test that runtime shutdown returns while watcher work is pending. I stopped the matrix after this first default and 100-file pair; I will rerun the full five-pair matrix after the shutdown fix.

kayg commented

2026-10-12 05:58:16 +00:00

Author

Owner

The first post-fix default pair reached correct candidate Note data in 12.78 s, down from 63.60 s for the exact base. However, the candidate still needed a forced shutdown. The baseline timing table shows homes.watcher_register at 50.50 s; inspection confirms that Home registration still runs in tokio::spawn_blocking, so runtime teardown waits for this second recursive Home walk after the collaboration watcher has been detached. I stopped the matrix after the default pair and am moving Home watcher registration to the same detached worker before rerunning. The Search watcher already runs on its own actor OS thread.

The first post-fix default pair reached correct candidate Note data in 12.78 s, down from 63.60 s for the exact base. However, the candidate still needed a forced shutdown. The baseline timing table shows `homes.watcher_register` at 50.50 s; inspection confirms that Home registration still runs in `tokio::spawn_blocking`, so runtime teardown waits for this second recursive Home walk after the collaboration watcher has been detached. I stopped the matrix after the default pair and am moving Home watcher registration to the same detached worker before rerunning. The Search watcher already runs on its own actor OS thread.

kayg commented

2026-10-12 06:10:04 +00:00

Author

Owner

The candidate-only shutdown profile now exits cleanly while recursive Home and collaboration watcher registration is still running: /readyz 12.43 s, forced_shutdown=false, server exit 0. It ran against the cold default fixture; load_average_before inside the perf-run lease was 1.70 / 0.95 / 1.01. The shared detached worker removed Tokio runtime teardown waits for these in-flight watcher walks. I am resuming the full five-pair interleaved matrix.

The candidate-only shutdown profile now exits cleanly while recursive Home and collaboration watcher registration is still running: `/readyz` 12.43 s, `forced_shutdown=false`, server exit 0. It ran against the cold default fixture; `load_average_before` inside the perf-run lease was 1.70 / 0.95 / 1.01. The shared detached worker removed Tokio runtime teardown waits for these in-flight watcher walks. I am resuming the full five-pair interleaved matrix.

kayg commented

2026-10-12 06:20:18 +00:00

Author

Owner

The first two default pairs have high run-to-run spread but no forced shutdown: pair 1 base/candidate first-correct reads were 63.12 / 3.71 s; pair 2 (reversed order) was 4.19 / 12.88 s. Pair 2 candidate phase timings include 3.40 s notes.recover and 4.00 s tags.recover; pair 2 baseline recorded 23 ms and 16 ms for those phases. Loads recorded inside the perf lease were 2.03 / 1.31 / 1.13 for pair 1 base, 2.45 / 1.81 / 1.35 for pair 1 candidate, 2.16 / 2.03 / 1.52 for pair 2 candidate, and 2.85 / 2.36 / 1.71 for pair 2 baseline. The five-pair matrix is still running; I will use per-scenario medians for the acceptance rule.

The first two default pairs have high run-to-run spread but no forced shutdown: pair 1 base/candidate first-correct reads were 63.12 / 3.71 s; pair 2 (reversed order) was 4.19 / 12.88 s. Pair 2 candidate phase timings include 3.40 s `notes.recover` and 4.00 s `tags.recover`; pair 2 baseline recorded 23 ms and 16 ms for those phases. Loads recorded inside the perf lease were 2.03 / 1.31 / 1.13 for pair 1 base, 2.45 / 1.81 / 1.35 for pair 1 candidate, 2.16 / 2.03 / 1.52 for pair 2 candidate, and 2.85 / 2.36 / 1.71 for pair 2 baseline. The five-pair matrix is still running; I will use per-scenario medians for the acceptance rule.

kayg commented

2026-10-12 06:49:40 +00:00

Author

Owner

Completed on job/cold-1586. Head: 3018df861.

Changes

The server installs the live Router without waiting for recursive Home and collaboration watcher registration. Each watcher uses one detached worker; Tokio shutdown does not join a slow provider walk.
Collaboration routes return the existing documented 503 plus Retry-After: 1 until their watcher is retained. /readyz still reflects database writability.
Added a cold-start concurrency storm that checks readiness, the collaboration retry contract, and cross-User Note isolation.
Measurement report: docs/perf/2026-10-12-startup-1586.md; raw 30-run matrix: docs/perf/runs/2026-10-12-startup-1586.json; summary in docs/perf/baseline.json.

Measurements

Five interleaved release-build pairs per scenario on perf-test-69-63, each under perf-run calternal. The default fixture had 100,000 Files, 50,000 Photos and 5,000 Notes.

Scenario	First correct User data p50 baseline → candidate	Median change	CPU p50 baseline → candidate	Peak RSS p50 baseline → candidate
Default cold Home	62.44 s → 3.71 s	94.1% faster	7.54 s → 1.78 s	111.4 → 110.4 MiB
100-file restart	4.43 s → 4.40 s	0.8% faster	0.52 s → 0.56 s	109.8 → 110.3 MiB
10,000-file restart	13.90 s → 12.26 s	11.8% faster	1.39 s → 1.19 s	111.6 → 112.1 MiB

Default readiness p50 was 61.56 s → 2.66 s. All 30 runs reached correct data, exited 0 and had no forced shutdown. Acceptance passed: default first-correct-data p50 improved by at least 25%, no scenario median regressed by more than 5%, and no hang occurred.

Default startup phase p50 attribution (baseline → candidate): collab.hub 49.682 s → 0 ms; homes.watcher_register 49.685 s → 3.304 s; search.watcher_register 59.383 s → 3.383 s. Candidate collab.watcher_register completed in 3.304 s p50 after Router construction. The full phase timings are in the report and raw file.

Adversarial round

Verbatim output:

PASS startup storm: ready=1.221s; writer handover=one-at-a-time (candidate readyz held at 503); acknowledged Files/Notes/Money=8/8/8; Search reads=16; cross-User startup isolation=1/1; documented 503 responses=64; cleanup retry=60.100s with 24 concurrent Files/Notes/Money batches; post-recovery injection phase=connect-index; Notes 0039/0040 and Calendar 0007 applied
PASS cold startup storm: ready=0.404s; collaboration after /readyz=HTTP 503; collaboration documented 503 responses=16; total documented 503 responses=40; second-User Note isolation=8/8

Gates

Commands used CARGO_PROFILE_DEV_DEBUG=line-tables-only, CARGO_INCREMENTAL=0, CARGO_BUILD_JOBS=4, and the worktree target/tmp for TMPDIR.

cargo fmt --check
(no output; exit 0)

cargo clippy -p calternal-collab --all-targets -- -D warnings
Finished dev profile [unoptimized + debuginfo] target(s) in 9.36s

cargo test -p calternal-collab
test result: ok. 143 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 82.27s
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.31s
test result: ok. 2 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 3.17s
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.34s
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 34.43s
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.95s
test result: ok. 15 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.70s
test result: ok. 12 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 4.12s
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.31s
test result: ok. 5 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.98s
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 10.95s
test result: ok. 2 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.60s
test result: ok. 5 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 14.86s
test result: ok. 15 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.08s
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.41s
test result: ok. 5 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 14.40s
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

cargo clippy -p calternal-server --all-targets -- -D warnings
Finished dev profile [unoptimized + debuginfo] target(s) in 19.20s

cargo test -p calternal-server
test result: ok. 280 passed; 0 failed; 12 ignored; 0 measured; 0 filtered out; finished in 103.12s
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 25.90s
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.17s

Decisions and gaps

DESIGN §59 does not define watcher worker lifetime. I used one detached OS worker per recursive watcher and a cancellable Tokio oneshot result. Collaboration preserves its existing retryable 503; Q-ST1 and response shapes are unchanged. A permanent provider registration error still leaves collaboration retryable and logs a Home watcher failure; no permanent-error retry policy was added.

Expected work is two O(directory count) watcher-registration walks at startup, one per worker. There is no request-time tree scan or per-request database query.

Completed on `job/cold-1586`. Head: `3018df861`. ## Changes - The server installs the live Router without waiting for recursive Home and collaboration watcher registration. Each watcher uses one detached worker; Tokio shutdown does not join a slow provider walk. - Collaboration routes return the existing documented `503` plus `Retry-After: 1` until their watcher is retained. `/readyz` still reflects database writability. - Added a cold-start concurrency storm that checks readiness, the collaboration retry contract, and cross-User Note isolation. - Measurement report: `docs/perf/2026-10-12-startup-1586.md`; raw 30-run matrix: `docs/perf/runs/2026-10-12-startup-1586.json`; summary in `docs/perf/baseline.json`. ## Measurements Five interleaved release-build pairs per scenario on `perf-test-69-63`, each under `perf-run calternal`. The default fixture had 100,000 Files, 50,000 Photos and 5,000 Notes. | Scenario | First correct User data p50 baseline → candidate | Median change | CPU p50 baseline → candidate | Peak RSS p50 baseline → candidate | | --- | ---: | ---: | ---: | ---: | | Default cold Home | 62.44 s → 3.71 s | 94.1% faster | 7.54 s → 1.78 s | 111.4 → 110.4 MiB | | 100-file restart | 4.43 s → 4.40 s | 0.8% faster | 0.52 s → 0.56 s | 109.8 → 110.3 MiB | | 10,000-file restart | 13.90 s → 12.26 s | 11.8% faster | 1.39 s → 1.19 s | 111.6 → 112.1 MiB | Default readiness p50 was 61.56 s → 2.66 s. All 30 runs reached correct data, exited 0 and had no forced shutdown. Acceptance passed: default first-correct-data p50 improved by at least 25%, no scenario median regressed by more than 5%, and no hang occurred. Default startup phase p50 attribution (baseline → candidate): `collab.hub` 49.682 s → 0 ms; `homes.watcher_register` 49.685 s → 3.304 s; `search.watcher_register` 59.383 s → 3.383 s. Candidate `collab.watcher_register` completed in 3.304 s p50 after Router construction. The full phase timings are in the report and raw file. ## Adversarial round Verbatim output: ``` PASS startup storm: ready=1.221s; writer handover=one-at-a-time (candidate readyz held at 503); acknowledged Files/Notes/Money=8/8/8; Search reads=16; cross-User startup isolation=1/1; documented 503 responses=64; cleanup retry=60.100s with 24 concurrent Files/Notes/Money batches; post-recovery injection phase=connect-index; Notes 0039/0040 and Calendar 0007 applied PASS cold startup storm: ready=0.404s; collaboration after /readyz=HTTP 503; collaboration documented 503 responses=16; total documented 503 responses=40; second-User Note isolation=8/8 ``` ## Gates Commands used `CARGO_PROFILE_DEV_DEBUG=line-tables-only`, `CARGO_INCREMENTAL=0`, `CARGO_BUILD_JOBS=4`, and the worktree `target/tmp` for `TMPDIR`. ``` cargo fmt --check (no output; exit 0) cargo clippy -p calternal-collab --all-targets -- -D warnings Finished dev profile [unoptimized + debuginfo] target(s) in 9.36s cargo test -p calternal-collab test result: ok. 143 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 82.27s test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.31s test result: ok. 2 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 3.17s test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.34s test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 34.43s test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.95s test result: ok. 15 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.70s test result: ok. 12 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 4.12s test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.31s test result: ok. 5 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.98s test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 10.95s test result: ok. 2 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.60s test result: ok. 5 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 14.86s test result: ok. 15 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.08s test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.41s test result: ok. 5 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 14.40s test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s cargo clippy -p calternal-server --all-targets -- -D warnings Finished dev profile [unoptimized + debuginfo] target(s) in 19.20s cargo test -p calternal-server test result: ok. 280 passed; 0 failed; 12 ignored; 0 measured; 0 filtered out; finished in 103.12s test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 25.90s test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.17s ``` ## Decisions and gaps DESIGN §59 does not define watcher worker lifetime. I used one detached OS worker per recursive watcher and a cancellable Tokio oneshot result. Collaboration preserves its existing retryable 503; Q-ST1 and response shapes are unchanged. A permanent provider registration error still leaves collaboration retryable and logs a Home watcher failure; no permanent-error retry policy was added. Expected work is two O(directory count) watcher-registration walks at startup, one per worker. There is no request-time tree scan or per-request database query.

kayg commented

2026-10-12 06:52:19 +00:00

Author

Owner

Starting the independent data-safety and behavior review for #1586 on job/rev1586 at 3018df861693d56d1108592340579b1ad6321d3d (base 8e840962979acd2bdf58141888618ab5560f728e). I will exercise the detached Home and collaboration watcher startup paths on a real local server and record evidence in artifacts/rev1586-findings.md.

Starting the independent data-safety and behavior review for #1586 on `job/rev1586` at `3018df861693d56d1108592340579b1ad6321d3d` (base `8e840962979acd2bdf58141888618ab5560f728e`). I will exercise the detached Home and collaboration watcher startup paths on a real local server and record evidence in `artifacts/rev1586-findings.md`.

kayg commented

2026-10-12 07:39:05 +00:00

Author

Owner

The corrected merge40_startup.py run passed on the candidate server. In its cold-start case, a Home with 12,000 empty directories reached /readyz 2.008 seconds before Home and collaboration watcher registration completed. /api/v1/collab/public/retired returned documented 503 Retry-After responses during that window (75 responses across the storm); after registration it returned the expected denial. The cross-User Note check passed 8/8. This fixture has directories, not 10,000 files; direct outside-app changes during registration are still under test.

The corrected `merge40_startup.py` run passed on the candidate server. In its cold-start case, a Home with 12,000 empty directories reached `/readyz` 2.008 seconds before Home and collaboration watcher registration completed. `/api/v1/collab/public/retired` returned documented `503 Retry-After` responses during that window (75 responses across the storm); after registration it returned the expected denial. The cross-User Note check passed 8/8. This fixture has directories, not 10,000 files; direct outside-app changes during registration are still under test.

kayg commented

2026-10-12 08:19:59 +00:00

Author

Owner

Large Home watcher probe in progress. The disposable Home has 10,000 files across per-file directories, a 32-level directory, and 50,000 retained Trash folders. It reached /readyz 1.591 s after launch. Home watcher registration took 4.316 s. Collaboration routes returned documented 503 responses for 4.053 s after /readyz (28 probes). Five app writes (Files folder and upload, Note create and body save, Money transaction) were accepted while both watchers were registering. The fallback Note body save returned successfully while the collaboration route returned 503. Files, Notes, Search, and Money projection checks are still running; shutdown and registration-failure probes remain.

Large Home watcher probe in progress. The disposable Home has 10,000 files across per-file directories, a 32-level directory, and 50,000 retained Trash folders. It reached `/readyz` 1.591 s after launch. Home watcher registration took 4.316 s. Collaboration routes returned documented 503 responses for 4.053 s after `/readyz` (28 probes). Five app writes (Files folder and upload, Note create and body save, Money transaction) were accepted while both watchers were registering. The fallback Note body save returned successfully while the collaboration route returned 503. Files, Notes, Search, and Money projection checks are still running; shutdown and registration-failure probes remain.

kayg commented

2026-10-12 08:29:42 +00:00

Author

Owner

The 10,000-file/deep-tree overlap run completed. /readyz arrived 0.930 s after launch; Home watcher registration took 2.445 s; collaboration registration finished 2.078 s after readiness. The full startup background scan completed 96.593 s after readiness. All five app writes (Files folder/upload, Note create/body, Money transaction) were accepted within 1.047 s while both watcher registrations were active. The fallback Note body remained present after collaboration registration, and Search returned it. Files create/rename/delete, external Note edit, external Money source edit, Search create/edit/rename/delete, and Search Note edit all passed. SIGTERM during a Home walk exited status 0 in 0.366 s. A competing process did not become ready while the first ran; a fresh candidate became ready after shutdown.

The 10,000-file/deep-tree overlap run completed. `/readyz` arrived 0.930 s after launch; Home watcher registration took 2.445 s; collaboration registration finished 2.078 s after readiness. The full startup background scan completed 96.593 s after readiness. All five app writes (Files folder/upload, Note create/body, Money transaction) were accepted within 1.047 s while both watcher registrations were active. The fallback Note body remained present after collaboration registration, and Search returned it. Files create/rename/delete, external Note edit, external Money source edit, Search create/edit/rename/delete, and Search Note edit all passed. SIGTERM during a Home walk exited status 0 in 0.366 s. A competing process did not become ready while the first ran; a fresh candidate became ready after shutdown.

kayg commented

2026-10-12 08:36:03 +00:00

Author

Owner

The permission fault injection made both watcher registrations fail. I restored access and waited for startup work to finish. The collaboration Note WebSocket route then returned 503 Retry-After: 1 on four probes over one second; the detached registration phases did not retry. /healthz remained ok and exposed no watcher fields. The Notes fallback body endpoint still saved a Note during the persistent 503. Search found the new external file in this run, so I did not reproduce a lost Search update. This confirms the failure is silent to health/Admin and leaves collaboration unavailable until process restart.

The permission fault injection made both watcher registrations fail. I restored access and waited for startup work to finish. The collaboration Note WebSocket route then returned `503 Retry-After: 1` on four probes over one second; the detached registration phases did not retry. `/healthz` remained `ok` and exposed no watcher fields. The Notes fallback body endpoint still saved a Note during the persistent 503. Search found the new external file in this run, so I did not reproduce a lost Search update. This confirms the failure is silent to health/Admin and leaves collaboration unavailable until process restart.

kayg commented

2026-10-12 08:41:53 +00:00

Author

Owner

The focused regression probe now injects a denied nested directory only after the candidate Home watcher starts. Both watcher registration workers fail; after restoring access, the Note WebSocket route remains at 503 Retry-After: 1 for 15 seconds.

The new test in tests/adversarial/merge40_startup.py reproduces this exact failure. It changes no product code. I am now merging the current origin/dev once before the requested Rust gates.

The focused regression probe now injects a denied nested directory only after the candidate Home watcher starts. Both watcher registration workers fail; after restoring access, the Note WebSocket route remains at `503 Retry-After: 1` for 15 seconds. The new test in `tests/adversarial/merge40_startup.py` reproduces this exact failure. It changes no product code. I am now merging the current `origin/dev` once before the requested Rust gates.

kayg commented

2026-10-12 08:52:44 +00:00

Author

Owner

BLOCK — #1586 independent review

Reviewed the detached Home and collaboration watcher registration on a real candidate server with a 10,000-file Home, a 32-level tree, and 50,000 retained Trash folders.

Findings

No missed projection changes reproduced. While Home watcher registration ran, external Files create/edit/rename/delete, Note source/body edits, and a Money source update appeared in Files, Notes, Search, and Money after startup reconciliation. Files API writes, Note create/body writes, and a Money transaction also succeeded during both watcher windows.
Collaboration 503 window: /readyz preceded collaboration registration by 2.078 seconds; the route returned 18 documented 503 Retry-After: 1 responses. The Note body fallback API accepted a write during the 503 window, and the body and Search result remained after registration. Source inspection shows the editor retries the WebSocket, then fetches the Note and opens the Markdown fallback after refused handshakes. I did not exercise that UI path in a browser.
Shutdown: SIGTERM during the Home walk exited status 0 in 0.366 seconds. A second server did not become ready while the first still ran; a fresh server became ready after shutdown.
Registration failure: denying a nested directory after watcher registration started caused both workers to log errors. After restoring access, a Note WebSocket request still returned 503 Retry-After: 1 for 15 seconds. /healthz returned ok and exposed no watcher status. The Home worker also did not retry. The fallback Note save still worked, and this failure injection did not reproduce a lost Search result.

The focused live regression probe in tests/adversarial/merge40_startup.py reproduces the collaboration outage after filesystem recovery. It is committed as ba969f7eb and changes no product code. Detailed observations and live output are in artifacts/rev1586-findings.md in the worktree.

Files and final head

tests/adversarial/merge40_startup.py — add a live regression probe for retry after transient registration failure.
Final HEAD: 6c223034892808cd1eb752a44c03f101389e20d3 (includes the required merge of origin/dev).

Gate output

Command run after the merge, with CARGO_PROFILE_DEV_DEBUG=line-tables-only, CARGO_INCREMENTAL=0, TMPDIR=$PWD/target/tmp, and CARGO_BUILD_JOBS=4:

CARGO_BUILD_JOBS=4 cargo test -p calternal-collab -p calternal-server
    Finished `test` profile [unoptimized + debuginfo] target(s) in 4m 33s
test result: ok. 143 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 111.46s

The server suite failed in wire::tests::live_apps_run_in_separate_processes because startup_serves_http_while_upgrade_backfills_wait received 503 for / where it expected 200:

thread 'wire::tests::startup_serves_http_while_upgrade_backfills_wait' (2428527) panicked at crates/calternal-server/src/wire.rs:9361:13:
assertion `left == right` failed: / during backfill
  left: 503
 right: 200
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 291 filtered out; finished in 2.49s

failures:
    wire::tests::live_apps_run_in_separate_processes

test result: FAILED. 279 passed; 1 failed; 12 ignored; 0 measured; 0 filtered out; finished in 27.28s

error: test failed, to rerun pass `-p calternal-server --bin calternal-server`
exit_code=101

Cleanup output:

Removed 9199 files, 13.9GiB total

Known gaps

No browser editor session was run. I verified the fallback Note body API live and inspected the editor retry/fallback code.
The server Rust gate has the failure above. I did not change its expectation or rerun the gate.

Decisions

DESIGN §3 describes periodic reconciliation but does not define retry or health reporting after watcher registration errors. This review remains read-mostly: I committed a failing regression test and made no product change.
The regression probe allows 15 seconds after restoring filesystem access for collaboration to recover. This is a bounded review threshold chosen from the route's one-second Retry-After; DESIGN does not set a recovery interval.
I classify the permanent collaboration outage and missing health signal as BLOCK because all Note collaboration rooms remain unavailable until restart after a transient filesystem error, even though fallback saves still work.

## BLOCK — #1586 independent review Reviewed the detached Home and collaboration watcher registration on a real candidate server with a 10,000-file Home, a 32-level tree, and 50,000 retained Trash folders. ### Findings - **No missed projection changes reproduced.** While Home watcher registration ran, external Files create/edit/rename/delete, Note source/body edits, and a Money source update appeared in Files, Notes, Search, and Money after startup reconciliation. Files API writes, Note create/body writes, and a Money transaction also succeeded during both watcher windows. - **Collaboration 503 window:** `/readyz` preceded collaboration registration by 2.078 seconds; the route returned 18 documented `503 Retry-After: 1` responses. The Note body fallback API accepted a write during the 503 window, and the body and Search result remained after registration. Source inspection shows the editor retries the WebSocket, then fetches the Note and opens the Markdown fallback after refused handshakes. I did not exercise that UI path in a browser. - **Shutdown:** SIGTERM during the Home walk exited status 0 in 0.366 seconds. A second server did not become ready while the first still ran; a fresh server became ready after shutdown. - **Registration failure:** denying a nested directory after watcher registration started caused both workers to log errors. After restoring access, a Note WebSocket request still returned `503 Retry-After: 1` for 15 seconds. `/healthz` returned `ok` and exposed no watcher status. The Home worker also did not retry. The fallback Note save still worked, and this failure injection did not reproduce a lost Search result. The focused live regression probe in `tests/adversarial/merge40_startup.py` reproduces the collaboration outage after filesystem recovery. It is committed as `ba969f7eb` and changes no product code. Detailed observations and live output are in `artifacts/rev1586-findings.md` in the worktree. ### Files and final head - `tests/adversarial/merge40_startup.py` — add a live regression probe for retry after transient registration failure. - Final HEAD: `6c223034892808cd1eb752a44c03f101389e20d3` (includes the required merge of `origin/dev`). ### Gate output Command run after the merge, with `CARGO_PROFILE_DEV_DEBUG=line-tables-only`, `CARGO_INCREMENTAL=0`, `TMPDIR=$PWD/target/tmp`, and `CARGO_BUILD_JOBS=4`: ```text CARGO_BUILD_JOBS=4 cargo test -p calternal-collab -p calternal-server Finished `test` profile [unoptimized + debuginfo] target(s) in 4m 33s test result: ok. 143 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 111.46s ``` The server suite failed in `wire::tests::live_apps_run_in_separate_processes` because `startup_serves_http_while_upgrade_backfills_wait` received 503 for `/` where it expected 200: ```text thread 'wire::tests::startup_serves_http_while_upgrade_backfills_wait' (2428527) panicked at crates/calternal-server/src/wire.rs:9361:13: assertion `left == right` failed: / during backfill left: 503 right: 200 note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 291 filtered out; finished in 2.49s ``` ```text failures: wire::tests::live_apps_run_in_separate_processes test result: FAILED. 279 passed; 1 failed; 12 ignored; 0 measured; 0 filtered out; finished in 27.28s error: test failed, to rerun pass `-p calternal-server --bin calternal-server` exit_code=101 ``` Cleanup output: ```text Removed 9199 files, 13.9GiB total ``` ### Known gaps - No browser editor session was run. I verified the fallback Note body API live and inspected the editor retry/fallback code. - The server Rust gate has the failure above. I did not change its expectation or rerun the gate. ### Decisions - DESIGN §3 describes periodic reconciliation but does not define retry or health reporting after watcher registration errors. This review remains read-mostly: I committed a failing regression test and made no product change. - The regression probe allows 15 seconds after restoring filesystem access for collaboration to recover. This is a bounded review threshold chosen from the route's one-second `Retry-After`; DESIGN does not set a recovery interval. - I classify the permanent collaboration outage and missing health signal as BLOCK because all Note collaboration rooms remain unavailable until restart after a transient filesystem error, even though fallback saves still work.

kayg commented

2026-10-12 08:55:07 +00:00

Author

Owner

Started work on branch job/rev1586 at 6c223034892808cd1eb752a44c03f101389e20d3. The merge-base with current origin/dev (b8bb41f211312dfdf7accf21c132b5b5acf3636c) is 67b05edb0ad91dfa3136dbcfc5f5ac5bb54a0a13. I am addressing the watcher recovery and HTTP-during-backfill blockers, preserving the startup probe, and will compare the two reported server test failures on 8e8409629.

Started work on branch `job/rev1586` at `6c223034892808cd1eb752a44c03f101389e20d3`. The merge-base with current `origin/dev` (`b8bb41f211312dfdf7accf21c132b5b5acf3636c`) is `67b05edb0ad91dfa3136dbcfc5f5ac5bb54a0a13`. I am addressing the watcher recovery and HTTP-during-backfill blockers, preserving the startup probe, and will compare the two reported server test failures on `8e8409629`.

kayg commented

2026-10-12 09:06:06 +00:00

Author

Owner

Evidence: the first targeted Rust test build could not compile calternal-server because apps/web/build/ is absent in this worktree (RustEmbed reports the folder does not exist). The server embeds the production SPA at compile time; I will build the real web bundle before comparing / behavior on 8e8409629 and this branch. No test expectation has been changed.

Evidence: the first targeted Rust test build could not compile `calternal-server` because `apps/web/build/` is absent in this worktree (`RustEmbed` reports the folder does not exist). The server embeds the production SPA at compile time; I will build the real web bundle before comparing `/` behavior on `8e8409629` and this branch. No test expectation has been changed.

kayg commented

2026-10-12 09:22:13 +00:00

Author

Owner

Finding: the two reported wire tests do not fail on the current branch or the requested baseline when the actual production web bundle is embedded. startup_serves_http_while_upgrade_backfills_wait passed on the candidate (8.53 s) and baseline 8e8409629 (11.40 s). live_apps_run_in_separate_processes passed on the candidate (120.37 s) and baseline (104.88 s). The first candidate test attempt had no apps/web/build/ and failed at RustEmbed compilation; I have not reproduced the reported / 503 with a complete bundle. No test expectation was changed. I am treating these failures as environment/build-artifact dependent unless the final run reproduces them.

Finding: the two reported wire tests do not fail on the current branch or the requested baseline when the actual production web bundle is embedded. `startup_serves_http_while_upgrade_backfills_wait` passed on the candidate (8.53 s) and baseline `8e8409629` (11.40 s). `live_apps_run_in_separate_processes` passed on the candidate (120.37 s) and baseline (104.88 s). The first candidate test attempt had no `apps/web/build/` and failed at RustEmbed compilation; I have not reproduced the reported `/` 503 with a complete bundle. No test expectation was changed. I am treating these failures as environment/build-artifact dependent unless the final run reproduces them.

kayg commented

2026-10-12 09:31:49 +00:00

Author

Owner

Post-change test evidence: cargo test -p calternal-collab watcher_ -- --test-threads=1 passed all 5 selected tests, including the new retry and pathless error-kind checks. cargo test -p calternal-server health_route_reports_startup_progress_until_ready -- --test-threads=1 passed. The ignored wire::tests::startup_serves_http_while_upgrade_backfills_wait passed on the modified branch (7.95 s) with the production web bundle embedded; its / request returned 200 during Notes backfill. No assertion or expected status was changed. The separate-process wrapper is running now against the modified branch.

Post-change test evidence: `cargo test -p calternal-collab watcher_ -- --test-threads=1` passed all 5 selected tests, including the new retry and pathless error-kind checks. `cargo test -p calternal-server health_route_reports_startup_progress_until_ready -- --test-threads=1` passed. The ignored `wire::tests::startup_serves_http_while_upgrade_backfills_wait` passed on the modified branch (7.95 s) with the production web bundle embedded; its `/` request returned 200 during Notes backfill. No assertion or expected status was changed. The separate-process wrapper is running now against the modified branch.

kayg commented

2026-10-12 09:35:29 +00:00

Author

Owner

The modified-branch wire::tests::live_apps_run_in_separate_processes wrapper passed (1 passed, 0 failed, 98.53 s); the same wrapper passed on baseline 8e8409629 (104.88 s). I committed the recovery slice as 531967e8c. The small public calternal-collab additions are the shared capped backoff helper, pathless notify error-kind mapper, and watcher status callback type used by the server. They keep retry policy and safe status categories consistent across both watcher owners.

The modified-branch `wire::tests::live_apps_run_in_separate_processes` wrapper passed (1 passed, 0 failed, 98.53 s); the same wrapper passed on baseline `8e8409629` (104.88 s). I committed the recovery slice as `531967e8c`. The small public `calternal-collab` additions are the shared capped backoff helper, pathless notify error-kind mapper, and watcher status callback type used by the server. They keep retry policy and safe status categories consistent across both watcher owners.

kayg commented

2026-10-12 09:42:54 +00:00

Author

Owner

tests/adversarial/merge40_startup.py passed on the modified server. It exercised the existing 15-second watcher recovery deadline, confirmed both health and Admin expose only pathless watcher state, and found the Note written during the denied interval after recovery reconciliation. The startup storm reached readiness in 5.794 s; the cold collaboration storm reached readiness in 3.920 s and kept the documented 503 behavior while registration was pending. The probe expectations were not weakened.

`tests/adversarial/merge40_startup.py` passed on the modified server. It exercised the existing 15-second watcher recovery deadline, confirmed both health and Admin expose only pathless watcher state, and found the Note written during the denied interval after recovery reconciliation. The startup storm reached readiness in 5.794 s; the cold collaboration storm reached readiness in 3.920 s and kept the documented 503 behavior while registration was pending. The probe expectations were not weakened.

kayg commented

2026-10-12 09:48:00 +00:00

Author

Owner

Performance setup finding: the #1586 startup fixture roots were absent on the perf VM. I added matrix --cell default to the existing profile so this job can run the requested three default-Home pairs without preparing the unrelated 100-file and 10,000-file restart cells. I am generating that real fixture and will keep all measured pairs inside perf-run --quiesce leases.

Performance setup finding: the #1586 startup fixture roots were absent on the perf VM. I added `matrix --cell default` to the existing profile so this job can run the requested three default-Home pairs without preparing the unrelated 100-file and 10,000-file restart cells. I am generating that real fixture and will keep all measured pairs inside `perf-run --quiesce` leases.

kayg commented

2026-10-12 09:55:32 +00:00

Author

Owner

Performance setup diagnosis: the copied same-profile debug Server exited before health because the perf VM did not have the prebuilt libsherpa-onnx-c-api.so dependency. I confirmed this from a sanitized loader-category check. The local build has the two required Sherpa/ONNX shared libraries (31 MiB total); I will copy them to this job’s target directory and pass that directory to the existing benchmark --library-dir option. No measured sample was taken from the failed setup attempt.

Performance setup diagnosis: the copied same-profile debug Server exited before health because the perf VM did not have the prebuilt `libsherpa-onnx-c-api.so` dependency. I confirmed this from a sanitized loader-category check. The local build has the two required Sherpa/ONNX shared libraries (31 MiB total); I will copy them to this job’s target directory and pass that directory to the existing benchmark `--library-dir` option. No measured sample was taken from the failed setup attempt.

kayg commented

2026-10-12 10:06:53 +00:00

Author

Owner

Performance setup finding: the matrix profile appends -default to its root prefix, but its validator rejected the unsuffixed /srv/hdd-emu/startup-1573 form. A quiesced setup attempt therefore looked for a double-hyphen path and stopped before any measured server run. I fixed and checked the root-prefix validation in bench/startup-1573.py (51907a50b); the prepared fixture is at the correct default root, so I am restarting the three-pair run with the unsuffixed prefix.

Performance setup finding: the matrix profile appends `-default` to its root prefix, but its validator rejected the unsuffixed `/srv/hdd-emu/startup-1573` form. A quiesced setup attempt therefore looked for a double-hyphen path and stopped before any measured server run. I fixed and checked the root-prefix validation in `bench/startup-1573.py` (`51907a50b`); the prepared fixture is at the correct default root, so I am restarting the three-pair run with the unsuffixed prefix.

kayg commented

2026-10-12 10:31:21 +00:00

Author

Owner

The three quiesced default-Home setup pairs completed with forced_shutdown=false. Baseline first-correct Note times were 118.67–118.89 s; prior candidate release times were 59.43–110.49 s. The fixture returned Note 404 until background Notes projection finished, so these pairs do not reproduce the prepared #1586 cold-start snapshot or its 3.7 s candidate result. I am completing the fixture migrations before the reportable recheck. The current-branch release binary remains reserved for the merge round per the verification policy.

The three quiesced default-Home setup pairs completed with `forced_shutdown=false`. Baseline first-correct Note times were 118.67–118.89 s; prior candidate release times were 59.43–110.49 s. The fixture returned Note 404 until background Notes projection finished, so these pairs do not reproduce the prepared #1586 cold-start snapshot or its 3.7 s candidate result. I am completing the fixture migrations before the reportable recheck. The current-branch release binary remains reserved for the merge round per the verification policy.

kayg commented

2026-10-12 10:42:41 +00:00

Author

Owner

Performance fixture limitation: a 600-second preparation run ended with exit_reason=timeout, server_exit=0, and forced_shutdown=false; notes-stable-identity-v1 remained started and Files reconciliation had no completion marker. The Note became correct at 72.455 s, but the full set of backfills did not complete. I am not running another matrix loop against this incomplete snapshot. The three-pair recheck is preserved in docs/perf/runs/2026-10-12-startup-1586-recheck.json and is labeled as an unprepared-fixture result. A current-branch release rerun with a preprojected snapshot remains for the merge round.

Performance fixture limitation: a 600-second preparation run ended with `exit_reason=timeout`, `server_exit=0`, and `forced_shutdown=false`; `notes-stable-identity-v1` remained started and Files reconciliation had no completion marker. The Note became correct at 72.455 s, but the full set of backfills did not complete. I am not running another matrix loop against this incomplete snapshot. The three-pair recheck is preserved in `docs/perf/runs/2026-10-12-startup-1586-recheck.json` and is labeled as an unprepared-fixture result. A current-branch release rerun with a preprojected snapshot remains for the merge round.

kayg commented

2026-10-12 13:58:00 +00:00

Author

Owner

Resuming the authorized #1586 fix on job/rev1586 from saved HEAD 8307bbe69 (the watcher retry fix is 531967e8c; the required origin/dev merge is present). I read the prior review comments and artifacts/rev1586-findings.md. The retry, pathless health/Admin state, reconciliation probe, and backfill comparison are already in the branch; I am completing final gate/probe checks and the requested cold-start recheck, then I will commit any remaining exact perf-pin refresh and report the results.

Resuming the authorized #1586 fix on `job/rev1586` from saved HEAD `8307bbe69` (the watcher retry fix is `531967e8c`; the required `origin/dev` merge is present). I read the prior review comments and `artifacts/rev1586-findings.md`. The retry, pathless health/Admin state, reconciliation probe, and backfill comparison are already in the branch; I am completing final gate/probe checks and the requested cold-start recheck, then I will commit any remaining exact perf-pin refresh and report the results.

kayg commented

2026-10-12 14:02:03 +00:00

Author

Owner

Perf recheck finding: prepare-fixture --cell default stops after /readyz and does not wait for Note backfills or Files Home reconciliation; its wait-and-verify step currently runs only for the 100 and 10000 restart cells. This matches the earlier recheck's incomplete notes-stable-identity-v1 marker and 404-to-correct Note transition. The run profile supports waiting for both projections, so I will complete the default fixture with that path before the three measured pairs. The perf VM is currently free (perf-run status: free; load average 0.02 / 0.06 / 0.02).

Perf recheck finding: `prepare-fixture --cell default` stops after `/readyz` and does not wait for Note backfills or Files Home reconciliation; its wait-and-verify step currently runs only for the `100` and `10000` restart cells. This matches the earlier recheck's incomplete `notes-stable-identity-v1` marker and 404-to-correct Note transition. The `run` profile supports waiting for both projections, so I will complete the default fixture with that path before the three measured pairs. The perf VM is currently free (`perf-run status`: free; load average 0.02 / 0.06 / 0.02).

Rows
Columns

Startup: cold start still about 2 minutes before first data (watcher registration) #1586

Startup phase attribution (base 8e8409629)

Changes

Measurements

Adversarial round

Gates

Decisions and gaps

BLOCK — #1586 independent review

Findings

Files and final head

Gate output

Known gaps

Decisions

Startup phase attribution (base `8e8409629`)