SEARCH: server restart exited with Tantivy LockBusy; later start succeeded

kayg commented

2026-09-30 09:24:58 +00:00

Owner

Observed while doing #393 on branch job/mac-393. The server built from dc3325b1cd was stopped with SIGTERM at 09:03 UTC. A rebuilt binary with the DAV priority fix at 0057b7b51 was started against the same throwaway Home at 09:03:53 UTC. It exited at 09:03:58 with:

Error: Tantivy(LockFailure(LockBusy, Some("Failed to acquire index lock. If you are using a regular directory, this means there is already an `IndexWriter` working on this `Directory`, in this process or in a different process.")))

At 09:17 UTC, no process using this job's server binary remained. fuser and /proc/locks showed no holder of the throwaway Home's Tantivy lock files. A second start at 09:18:38 reached listening at 09:18:42. No lock or Index file was removed or changed between attempts. API and native Mac DAV traffic then worked.

The root cause is not established. The shared host was under load. It is not yet proved whether this was a shutdown race, a filesystem locking error reported as LockBusy, or another startup path. Keep the real startup failure separate from slow-response findings. Follow up with a rapid stop/start regression and the underlying lock error, while keeping all source files intact. This job did not change Search behavior.

Observed while doing #393 on branch job/mac-393. The server built from dc3325b1cd was stopped with SIGTERM at 09:03 UTC. A rebuilt binary with the DAV priority fix at 0057b7b51 was started against the same throwaway Home at 09:03:53 UTC. It exited at 09:03:58 with: ``` Error: Tantivy(LockFailure(LockBusy, Some("Failed to acquire index lock. If you are using a regular directory, this means there is already an `IndexWriter` working on this `Directory`, in this process or in a different process."))) ``` At 09:17 UTC, no process using this job's server binary remained. fuser and /proc/locks showed no holder of the throwaway Home's Tantivy lock files. A second start at 09:18:38 reached listening at 09:18:42. No lock or Index file was removed or changed between attempts. API and native Mac DAV traffic then worked. The root cause is not established. The shared host was under load. It is not yet proved whether this was a shutdown race, a filesystem locking error reported as LockBusy, or another startup path. Keep the real startup failure separate from slow-response findings. Follow up with a rapid stop/start regression and the underlying lock error, while keeping all source files intact. This job did not change Search behavior.

kayg referenced this issue

2026-09-30 09:28:17 +00:00

APPLE INTEROP: exhaustive Reminders + Calendar knob matrix on the real Mac, both directions #393

kayg referenced this issue

2026-09-30 09:58:02 +00:00

APPLE INTEROP: exhaustive Reminders + Calendar knob matrix on the real Mac, both directions #393

kayg commented

2026-09-30 22:41:31 +00:00

Author

Owner

Started on job/restart-505 at base 5896bf2bc7. I am tracing the Search Index writer lifecycle and server SIGTERM path before changing startup recovery.

Started on job/restart-505 at base 5896bf2bc75b5089ef19df0784103c6d353ac37f. I am tracing the Search Index writer lifecycle and server SIGTERM path before changing startup recovery.

kayg commented

2026-09-30 22:51:18 +00:00

Author

Owner

Finding: the locked Tantivy version is 0.26.2. Its MmapDirectory uses an OS advisory lock for .tantivy-writer.lock; the filename alone does not mean a writer is active. Recovery will serialize startup, probe the lock through calternal-fs, and unlink only after the probe acquires the lock. I will also make SIGTERM await the Search actor final commit and writer release.

kayg commented

2026-09-30 23:34:54 +00:00

Author

Owner

Search lifecycle slice committed as 86004f556. One full test pass initially had the existing staged_publication_waits_for_search_readers_before_swapping_directories test time out at its 5 s wait; running that case alone passed in 4.11 s, and the full calternal-search suite then passed (33 passed, 1 ignored). The added retry runs on spawn_blocking so it does not block the server runtime.

Search lifecycle slice committed as 86004f556. One full test pass initially had the existing `staged_publication_waits_for_search_readers_before_swapping_directories` test time out at its 5 s wait; running that case alone passed in 4.11 s, and the full `calternal-search` suite then passed (33 passed, 1 ignored). The added retry runs on spawn_blocking so it does not block the server runtime.

kayg commented

2026-10-01 00:18:03 +00:00

Author

Owner

Finding: cargo test -p calternal-server now passes the same-Home restart regression: the second Indexer cannot start while the first owns the Search writer, then starts after the first completes shutdown. Result: 86 passed, 0 failed, 2 ignored. cargo clippy -p calternal-server --all-targets -- -D warnings also passed.

Finding: `cargo test -p calternal-server` now passes the same-Home restart regression: the second Indexer cannot start while the first owns the Search writer, then starts after the first completes shutdown. Result: 86 passed, 0 failed, 2 ignored. `cargo clippy -p calternal-server --all-targets -- -D warnings` also passed.

kayg commented

2026-10-01 00:26:57 +00:00

Author

Owner

Merge integration finding: origin/dev adds per-User Search generations and a RebuildUser actor command. I retained those changes, keyed the safe startup gate by validated Index directory for both shared and private active writers, and made shutdown answer a queued RebuildUser request instead of leaving its oneshot caller pending. The post-merge crate gates are running now.

Merge integration finding: `origin/dev` adds per-User Search generations and a `RebuildUser` actor command. I retained those changes, keyed the safe startup gate by validated Index directory for both shared and private active writers, and made shutdown answer a queued `RebuildUser` request instead of leaving its oneshot caller pending. The post-merge crate gates are running now.

kayg commented

2026-10-01 00:54:08 +00:00

Author

Owner

The existing Search performance profile restarted the server only after the previous process stopped, so it did not measure this issue's overlapping writer lock. I extended its 100k mixed-Home run to start the replacement server first, wait for the real LockBusy log, send SIGTERM to the old process, verify graceful exit, and record three p50/p95 restart samples plus CPU and RSS.

kayg commented

2026-10-01 01:47:56 +00:00

Author

Owner

Performance finding from the completed local 100k mixed-Home profile: all three replacement servers reached the real LockBusy retry and restarted successfully. The previous process's graceful stop measured p50 18.280 s / p95 26.324 s under local load average 18.04 at start (baseline host: perf-test, 0.73 / 0.40 / 0.46). I corrected the profile to time from the LockBusy warning to Tantivy's lock-acquired log; the first run measured time-to-warning instead, so I will use the corrected run for the final comparison. The existing baseline sequential restart is 1.226 s.

kayg referenced this issue from a commit

2026-10-01 01:55:38 +00:00

Measure Search LockBusy wait duration

kayg commented

2026-10-01 02:19:51 +00:00

Author

Owner

Completed

Search startup now retries Tantivy LockBusy for up to 30 seconds, logs contention and successful acquisition, and removes a stale lock file only after the OS lock probe confirms that no writer holds it. Shared and per-User indexes use the same recovery gate. SIGTERM shutdown drains the Search actor's pending paths, commits, drops the writer, then lets the process exit.

A same-Home regression test starts two production Indexer lifecycles concurrently and checks that the second waits for the first shutdown. The real-server Search profile also started a second release server while the first held the 100k Home; all three samples observed LockBusy, the first server drained on SIGTERM, and the replacement became ready.

Files

crates/calternal-fs/src/root.rs, crates/calternal-fs/src/lib.rs
crates/calternal-search/src/index.rs, crates/calternal-search/src/indexer.rs
crates/calternal-server/src/main.rs, crates/calternal-server/src/wire.rs
bench/run.sh, tests/perf/search_scale.py, tests/perf/upload_scale.py

Gates

Run after merging origin/dev. Rust gate output captured:

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

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

cargo test -p calternal-fs
 test result: ok. 53 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 29.14s
 test result: ok. 42 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 3.00s
 test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

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

cargo test -p calternal-search
36 unit tests passed, 1 ignored; integration suites passed: ask eval 1, citations 1, indexer 21, operators 5, query properties 2, relevance 1 (2 ignored), retrieval 4; doc tests passed.

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

cargo test -p calternal-server
 test result: ok. 94 passed; 0 failed; 3 ignored; 0 measured; 0 filtered out; finished in 23.92s

python3 -m py_compile tests/perf/search_scale.py tests/perf/upload_scale.py, the LockBusy metric parser smoke check, and git diff --check passed. cargo clean removed 12.4 GiB of job build output; web build output and Python cache were removed.

Performance

Local 100k mixed Search profile, 3 overlapping restart samples. Lock wait is read from the server's waited_ms log field:

Writer-lock wait p50/p95: 6.997/11.437 s. Previous process shutdown p50/p95: 7.096/11.657 s. Replacement readiness p50/p95: 15.289/18.547 s.
Overlap resources: mean RSS 126 MB, peak RSS 330 MB, peak CPU 220%.
Existing-index restart readiness: 3.221 s; baseline in docs/perf/baseline.json: 1.226 s.
Full reindex: 220.88 s; query p50/p95 212.68/386.44 ms with zero query failures. Baseline: 39.81 s and 203.65/265.40 ms.
This was local on an 8-CPU host with load average 37.36/31.95/24.48 at start and 28.06/31.05/29.28 at end. The baseline used the separate 4-CPU perf-test host at 0.73/0.40/0.46 start load; these timings are not directly comparable. The baseline has no overlapping-restart measurement.

Decisions and gaps

DESIGN does not set lock-wait timing. I used a 30-second bound and 100 ms retry interval. A startup still returns a clear timeout error if another writer remains active beyond the bound.
Startup coordination uses a fixed, directory-handle-relative flock sidecar for each shared or per-User Index. Recovery removes only a regular lock file whose OS lock is available and whose inode is unchanged.
The Cargo regression test covers the production Indexer start/shutdown lifecycle in one process. The release-server profile covers separate server processes on the same Home.

Head: 9f25ce71a902da59a58599f6e793441a1a582a75. The branch includes the single origin/dev merge (adb7d0de0) and commits for stale-lock recovery, graceful writer drain, same-Home restart coverage, and the Search restart profile.

## Completed Search startup now retries Tantivy `LockBusy` for up to 30 seconds, logs contention and successful acquisition, and removes a stale lock file only after the OS lock probe confirms that no writer holds it. Shared and per-User indexes use the same recovery gate. SIGTERM shutdown drains the Search actor's pending paths, commits, drops the writer, then lets the process exit. A same-Home regression test starts two production Indexer lifecycles concurrently and checks that the second waits for the first shutdown. The real-server Search profile also started a second release server while the first held the 100k Home; all three samples observed LockBusy, the first server drained on SIGTERM, and the replacement became ready. ## Files - `crates/calternal-fs/src/root.rs`, `crates/calternal-fs/src/lib.rs` - `crates/calternal-search/src/index.rs`, `crates/calternal-search/src/indexer.rs` - `crates/calternal-server/src/main.rs`, `crates/calternal-server/src/wire.rs` - `bench/run.sh`, `tests/perf/search_scale.py`, `tests/perf/upload_scale.py` ## Gates Run after merging `origin/dev`. Rust gate output captured: ```text cargo fmt --all -- --check (exit 0; no output) cargo clippy -p calternal-fs --all-targets -- -D warnings Finished `dev` profile [unoptimized + debuginfo] target(s) in 7.69s cargo test -p calternal-fs test result: ok. 53 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 29.14s test result: ok. 42 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 3.00s test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s cargo clippy -p calternal-search --all-targets -- -D warnings Finished `dev` profile [unoptimized + debuginfo] target(s) in 33.74s cargo test -p calternal-search 36 unit tests passed, 1 ignored; integration suites passed: ask eval 1, citations 1, indexer 21, operators 5, query properties 2, relevance 1 (2 ignored), retrieval 4; doc tests passed. cargo clippy -p calternal-server --all-targets -- -D warnings Finished `dev` profile [unoptimized + debuginfo] target(s) in 1m 36s cargo test -p calternal-server test result: ok. 94 passed; 0 failed; 3 ignored; 0 measured; 0 filtered out; finished in 23.92s ``` `python3 -m py_compile tests/perf/search_scale.py tests/perf/upload_scale.py`, the LockBusy metric parser smoke check, and `git diff --check` passed. `cargo clean` removed 12.4 GiB of job build output; web build output and Python cache were removed. ## Performance Local 100k mixed Search profile, 3 overlapping restart samples. Lock wait is read from the server's `waited_ms` log field: - Writer-lock wait p50/p95: 6.997/11.437 s. Previous process shutdown p50/p95: 7.096/11.657 s. Replacement readiness p50/p95: 15.289/18.547 s. - Overlap resources: mean RSS 126 MB, peak RSS 330 MB, peak CPU 220%. - Existing-index restart readiness: 3.221 s; baseline in `docs/perf/baseline.json`: 1.226 s. - Full reindex: 220.88 s; query p50/p95 212.68/386.44 ms with zero query failures. Baseline: 39.81 s and 203.65/265.40 ms. - This was local on an 8-CPU host with load average 37.36/31.95/24.48 at start and 28.06/31.05/29.28 at end. The baseline used the separate 4-CPU perf-test host at 0.73/0.40/0.46 start load; these timings are not directly comparable. The baseline has no overlapping-restart measurement. ## Decisions and gaps - DESIGN does not set lock-wait timing. I used a 30-second bound and 100 ms retry interval. A startup still returns a clear timeout error if another writer remains active beyond the bound. - Startup coordination uses a fixed, directory-handle-relative `flock` sidecar for each shared or per-User Index. Recovery removes only a regular lock file whose OS lock is available and whose inode is unchanged. - The Cargo regression test covers the production Indexer start/shutdown lifecycle in one process. The release-server profile covers separate server processes on the same Home. Head: `9f25ce71a902da59a58599f6e793441a1a582a75`. The branch includes the single `origin/dev` merge (`adb7d0de0`) and commits for stale-lock recovery, graceful writer drain, same-Home restart coverage, and the Search restart profile.

kayg referenced this issue

2026-10-02 06:34:22 +00:00

Log attachments: deleted file still shown, attachments not live, batch send not live, Log order, raw camera names #427

kayg referenced this issue

2026-10-03 12:51:31 +00:00

Issue hygiene sweep 2026-10-03 #1008