Investigate Log and Files scan storm timeouts

kayg commented

2026-09-30 07:32:12 +00:00

Owner

Evidence

A focused real-server run of tests/adversarial/attack2.py with the composer section passed the #460 attachment race: eight concurrent tus uploads returned 201, one Log attach returned 201, the concurrent Daily note edit returned 200, and the final read retained all eight attachment links and the edit.

The same section then ran its existing 100-write Log storm alongside eight workers listing Files. Within the probe's 120-second worker bound, it recorded 95/100 write responses with status mix 201, 503, and timeout (-1). A 503 body was {"error":{"code":"service_unavailable","message":"Index is busy; retry shortly"}}. Several requests timed out, and the storm reported an unfinished worker. The server remained alive. The probe did not report a leaked atomic-write temp row.

The 503/timeouts happened during a shared-host run with concurrent build and browser jobs. The attachment checks and many storm requests were also marked SLOW. This evidence does not isolate application contention from host contention. Please reproduce under a controlled host load and decide whether Log and Files listing need stronger bounded retry or backpressure behavior. Related prior work: #305 and #427.

## Evidence A focused real-server run of `tests/adversarial/attack2.py` with the `composer` section passed the #460 attachment race: eight concurrent tus uploads returned 201, one Log attach returned 201, the concurrent Daily note edit returned 200, and the final read retained all eight attachment links and the edit. The same section then ran its existing 100-write Log storm alongside eight workers listing Files. Within the probe's 120-second worker bound, it recorded 95/100 write responses with status mix `201`, `503`, and timeout (`-1`). A 503 body was `{"error":{"code":"service_unavailable","message":"Index is busy; retry shortly"}}`. Several requests timed out, and the storm reported an unfinished worker. The server remained alive. The probe did not report a leaked atomic-write temp row. The 503/timeouts happened during a shared-host run with concurrent build and browser jobs. The attachment checks and many storm requests were also marked SLOW. This evidence does not isolate application contention from host contention. Please reproduce under a controlled host load and decide whether Log and Files listing need stronger bounded retry or backpressure behavior. Related prior work: #305 and #427.

kayg referenced this issue

2026-09-30 07:32:43 +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-09-30 07:32:44 +00:00

Log attachment upload returns 500 after creating the files (duplicates on retry) #460

kayg referenced this issue

2026-09-30 11:26:52 +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-09-30 11:27:04 +00:00

Log attachment upload returns 500 after creating the files (duplicates on retry) #460

kayg commented

2026-09-30 22:10:00 +00:00

Author

Owner

Started investigation on branch job/fix-493 at base SHA 6c87f5ff94. I am tracing the Files listing/reconcile and Log write paths, then I will reproduce the contention and add a regression test.

Started investigation on branch job/fix-493 at base SHA 6c87f5ff9442cd658572139bc536d018fd5222a4. I am tracing the Files listing/reconcile and Log write paths, then I will reproduce the contention and add a regression test.

kayg commented

2026-09-30 22:25:05 +00:00

Author

Owner

Code finding: the Files migration triggers increment for every insert, update or delete, including while that folder is already dirty. The real-server change bridge adopts each Log Daily note replacement into , and a stale request schedules a full folder scan. When scans complete between writes, one Log burst can therefore schedule repeated Notes scans and compete for the single SQLite writer. I am checking this with the focused probe and will change the dirty-generation rule so one scan covers the whole burst.

kayg commented

2026-09-30 22:25:21 +00:00

Author

Owner

Correction to my previous comment: shell quoting removed several code identifiers from that comment.

Code finding: the Files migration triggers increment files_folder_reconcile.generation for every files_index insert, update, or delete, even while that folder is already dirty. The real-server change bridge adopts each Log Daily note replacement into files_index, and a stale /files/entries request schedules a full folder scan. When scans complete between writes, one Log burst can therefore schedule repeated Notes scans and compete for the single SQLite writer. I am checking this with the focused probe and will change the dirty-generation rule so one scan covers the whole burst.

Correction to my previous comment: shell quoting removed several code identifiers from that comment. Code finding: the Files migration triggers increment `files_folder_reconcile.generation` for every `files_index` insert, update, or delete, even while that folder is already dirty. The real-server change bridge adopts each Log Daily note replacement into `files_index`, and a stale `/files/entries` request schedules a full folder scan. When scans complete between writes, one Log burst can therefore schedule repeated Notes scans and compete for the single SQLite writer. I am checking this with the focused probe and will change the dirty-generation rule so one scan covers the whole burst.

kayg commented

2026-09-30 22:34:00 +00:00

Author

Owner

Baseline evidence: the focused composer probe completed with 0 findings and 0 SLOW on the local host using the shared release server built at ccfeb2d0df7d3104ffe23bc72fcfa5e04f418fb7 (whose folder-reconcile trigger semantics match this branch). The probe's assertions therefore saw 100/100 Log writes return 201 and 256/256 Files listings return 200. Local load averages were 34.98/29.09/28.02 before and 38.79/31.91/29.13 after. This does not reproduce the historical 95/100 failure, so the old run's host-load contribution remains unisolated. The per-folder dirty-generation amplification is still present in the code and will be covered by a direct regression test.

Baseline evidence: the focused `composer` probe completed with 0 findings and 0 SLOW on the local host using the shared release server built at `ccfeb2d0df7d3104ffe23bc72fcfa5e04f418fb7` (whose folder-reconcile trigger semantics match this branch). The probe's assertions therefore saw 100/100 Log writes return 201 and 256/256 Files listings return 200. Local load averages were 34.98/29.09/28.02 before and 38.79/31.91/29.13 after. This does not reproduce the historical 95/100 failure, so the old run's host-load contribution remains unisolated. The per-folder dirty-generation amplification is still present in the code and will be covered by a direct regression test.

kayg commented

2026-09-30 22:54:39 +00:00

Author

Owner

Baseline profile for #493, run locally against the existing shared release binary ccfeb2d0df7d3104ffe23bc72fcfa5e04f418fb7 before the trigger fix. The fixture had 10,000 files in Notes; the issue's 8 Log writers sent 100 total writes while 8 Files listing workers made 256 total requests. All 100 Log writes returned 201, all 256 listings returned 200, and all workers finished. The burst took 59.303 s; Log p50/p95 latency was 4,275.53/8,913.07 ms, Files listing p50/p95 was 27.66/55.49 ms, server mean/peak CPU was 69.34%/226.74%, and mean/peak RSS was 346,237,887/466,874,368 bytes. Host load average was 14.22/16.05/22.09 before and 16.97/16.40/21.76 after. This is a local measurement, not a perf-VM run.

Baseline profile for #493, run locally against the existing shared release binary `ccfeb2d0df7d3104ffe23bc72fcfa5e04f418fb7` before the trigger fix. The fixture had 10,000 files in `Notes`; the issue's 8 Log writers sent 100 total writes while 8 Files listing workers made 256 total requests. All 100 Log writes returned 201, all 256 listings returned 200, and all workers finished. The burst took 59.303 s; Log p50/p95 latency was 4,275.53/8,913.07 ms, Files listing p50/p95 was 27.66/55.49 ms, server mean/peak CPU was 69.34%/226.74%, and mean/peak RSS was 346,237,887/466,874,368 bytes. Host load average was 14.22/16.05/22.09 before and 16.97/16.40/21.76 after. This is a local measurement, not a perf-VM run.

kayg commented

2026-10-01 00:28:36 +00:00

Author

Owner

Finished #493 on job/fix-493.

Head SHA: a22fa6b2b2a58126b9be99af8bb5be559048c505.

Root cause and fix

Each Files Index insert, update, or delete advanced its folder reconcile generation, even when that folder was already dirty. Log Daily note replacements flow through the Files Index. During a burst, stale Files listings could therefore queue repeated complete scans of Notes. Those scans contend with the Log writes for SQLite's single writer and can return Index is busy.

Migration 0016 now advances a folder generation only on the clean-to-dirty transition. Later Index writes stay in the dirty generation until a scan reconciles it. Existing per-file events and durable Files feed rows remain intact.

The regression test performs five writes, a delete and a reinsert in one dirty window. It checks that the folder generation advances once, every file change still creates its feed row, and a write after reconciliation starts a new generation. Migration fixture setup was updated to omit migration 16 where it tests historical v15 and v14 schemas; the existing version assertions remain unchanged.

Performance profile

The new real-server profile is bench/files_log_storm.py, exposed by bench/run.sh --files-log-storm. It seeds 10,000 files, then runs the issue's 100 Log writes with 8 writers beside 8 Files listing workers making 256 requests. Full results are in docs/perf/runs/2026-10-01T002123Z-85f80390-files-log-storm.json.

Metric	Before, build `ccfeb2d0`	Fixed, build `85f80390`
Log p50 / p95	4,275.53 / 8,913.07 ms	8,755.72 / 13,415.20 ms
Files listing p50 / p95	27.66 / 55.49 ms	13.99 / 41.99 ms
Burst duration	59.303 s	117.633 s
Mean / peak RSS	346.2 / 466.9 MB	284.8 / 482.5 MB
Mean / peak server CPU	69.34 / 226.74%	26.88 / 151.37%
Statuses	100/100 Log 201; 256/256 listings 200	100/100 Log 201; 256/256 listings 200

Both runs were local. The post-fix host load average was 30.87 before and 30.80 after; the baseline was 14.22 before and 16.97 after. The latency and duration figures are not a controlled comparison. Neither run reproduced the historical request failures. The general docs/perf/baseline.json remains unchanged because it is a different workload on the perf-test host.

Gates and adversarial round

cargo fmt --check: exit 0, no output.

cargo clippy -p calternal-plugin-files --all-targets -- -D warnings output:

    Checking calternal-plugin-files v0.0.1 (/home/kayg/Developer/calternal-wt/fix-493/crates/plugins/files)
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 40.72s

cargo test -p calternal-plugin-files output:

test result: ok. 137 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 155.10s

   Doc-tests calternal_plugin_files

running 0 tests

test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

Focused composer/Files adversarial output:

server alive at end: True

==== ROUND 2 FINDINGS 0

==== ROUND 2 SLOW 0

Production server build output: Finished release profile [optimized] target(s) in 33m 53s. cargo clean removed 19,003 files (7.6 GiB); generated SPA build output and temporary benchmark data were deleted.

Decisions where DESIGN was silent

Coalesce only folder reconciliation generations. Keep individual Files events and feed records for every write.
Use 10,000 seeded Files entries for the repeatable worst-case profile. The benchmark records host load so noisy local runs are visible.

Finished #493 on `job/fix-493`. Head SHA: `a22fa6b2b2a58126b9be99af8bb5be559048c505`. **Root cause and fix** Each Files Index insert, update, or delete advanced its folder reconcile generation, even when that folder was already dirty. Log Daily note replacements flow through the Files Index. During a burst, stale Files listings could therefore queue repeated complete scans of Notes. Those scans contend with the Log writes for SQLite's single writer and can return `Index is busy`. Migration 0016 now advances a folder generation only on the clean-to-dirty transition. Later Index writes stay in the dirty generation until a scan reconciles it. Existing per-file events and durable Files feed rows remain intact. The regression test performs five writes, a delete and a reinsert in one dirty window. It checks that the folder generation advances once, every file change still creates its feed row, and a write after reconciliation starts a new generation. Migration fixture setup was updated to omit migration 16 where it tests historical v15 and v14 schemas; the existing version assertions remain unchanged. **Performance profile** The new real-server profile is `bench/files_log_storm.py`, exposed by `bench/run.sh --files-log-storm`. It seeds 10,000 files, then runs the issue's 100 Log writes with 8 writers beside 8 Files listing workers making 256 requests. Full results are in `docs/perf/runs/2026-10-01T002123Z-85f80390-files-log-storm.json`. | Metric | Before, build `ccfeb2d0` | Fixed, build `85f80390` | | --- | ---: | ---: | | Log p50 / p95 | 4,275.53 / 8,913.07 ms | 8,755.72 / 13,415.20 ms | | Files listing p50 / p95 | 27.66 / 55.49 ms | 13.99 / 41.99 ms | | Burst duration | 59.303 s | 117.633 s | | Mean / peak RSS | 346.2 / 466.9 MB | 284.8 / 482.5 MB | | Mean / peak server CPU | 69.34 / 226.74% | 26.88 / 151.37% | | Statuses | 100/100 Log 201; 256/256 listings 200 | 100/100 Log 201; 256/256 listings 200 | Both runs were local. The post-fix host load average was 30.87 before and 30.80 after; the baseline was 14.22 before and 16.97 after. The latency and duration figures are not a controlled comparison. Neither run reproduced the historical request failures. The general `docs/perf/baseline.json` remains unchanged because it is a different workload on the perf-test host. **Gates and adversarial round** `cargo fmt --check`: exit 0, no output. `cargo clippy -p calternal-plugin-files --all-targets -- -D warnings` output: ```text Checking calternal-plugin-files v0.0.1 (/home/kayg/Developer/calternal-wt/fix-493/crates/plugins/files) Finished `dev` profile [unoptimized + debuginfo] target(s) in 40.72s ``` `cargo test -p calternal-plugin-files` output: ```text test result: ok. 137 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 155.10s Doc-tests calternal_plugin_files running 0 tests test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s ``` Focused composer/Files adversarial output: ```text server alive at end: True ==== ROUND 2 FINDINGS 0 ==== ROUND 2 SLOW 0 ``` Production server build output: `Finished `release` profile [optimized] target(s) in 33m 53s`. `cargo clean` removed 19,003 files (7.6 GiB); generated SPA build output and temporary benchmark data were deleted. **Decisions where DESIGN was silent** - Coalesce only folder reconciliation generations. Keep individual Files events and feed records for every write. - Use 10,000 seeded Files entries for the repeatable worst-case profile. The benchmark records host load so noisy local runs are visible.

kayg referenced this issue

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

Issue hygiene sweep 2026-10-03 #1008

Rows
Columns

Investigate Log and Files scan storm timeouts #493

Evidence