Investigate request timeouts in concurrent Journal and capture probes #205

Open
opened 2026-09-26 17:53:46 +00:00 by kayg · 19 comments
Owner

Found during the live adversarial round for #165. The server stayed alive, but these probes returned no response before their client deadlines:

  • DAV initial sync: 30 seconds.
  • Calendar Event from Log: 30 seconds.
  • Journal PATCH storm: requests 1–15 timed out at 30 seconds; request 0 returned 200 and requests 16–23 returned 412.
  • Bookmark capture storm: 15 of 16 calls timed out at 10 seconds.
  • Round-two collaboration Note creation: timed out at 30 seconds.

Other calls in the same run returned valid 201, 207, 403, or 412 responses, often after 6–29 seconds. The host was shared with several Cargo builds and a Chromium process during the run. That may explain the latency, but these are timeouts rather than SLOW-only findings, so they need a quiet-host reproduction and a check of per-user Journal queues and bookmark-capture concurrency. Fix any timeout that reproduces without host contention.

Found during the live adversarial round for #165. The server stayed alive, but these probes returned no response before their client deadlines: - DAV initial sync: 30 seconds. - Calendar Event from Log: 30 seconds. - Journal PATCH storm: requests 1–15 timed out at 30 seconds; request 0 returned 200 and requests 16–23 returned 412. - Bookmark capture storm: 15 of 16 calls timed out at 10 seconds. - Round-two collaboration Note creation: timed out at 30 seconds. Other calls in the same run returned valid 201, 207, 403, or 412 responses, often after 6–29 seconds. The host was shared with several Cargo builds and a Chromium process during the run. That may explain the latency, but these are timeouts rather than SLOW-only findings, so they need a quiet-host reproduction and a check of per-user Journal queues and bookmark-capture concurrency. Fix any timeout that reproduces without host contention.
Author
Owner

Additional evidence from the real-server adversarial round for #158 on 2026-09-26 (tests/adversarial/attack2.py):

  • A 16-request bookmark-create burst had 14 HTTP 201 responses with unique IDs and two client timeouts (-1). The server stayed alive; other requests in the same round repeatedly met the probe's SLOW criteria.
  • A Journal PATCH storm using the same entry ETags reported statuses [-1, 200, 412] (-1 means the 30-second client timeout). The follow-up checks found no entry-count, line-count, or joined-line change. The same round had multi-second SLOW responses.

This host was shared. These observations extend the concurrent Journal and capture timeout evidence already tracked here; please reproduce on a quiet host.

Additional evidence from the real-server adversarial round for #158 on 2026-09-26 (`tests/adversarial/attack2.py`): - A 16-request bookmark-create burst had 14 HTTP 201 responses with unique IDs and two client timeouts (`-1`). The server stayed alive; other requests in the same round repeatedly met the probe's SLOW criteria. - A Journal PATCH storm using the same entry ETags reported statuses `[-1, 200, 412]` (`-1` means the 30-second client timeout). The follow-up checks found no entry-count, line-count, or joined-line change. The same round had multi-second SLOW responses. This host was shared. These observations extend the concurrent Journal and capture timeout evidence already tracked here; please reproduce on a quiet host.
Author
Owner

Additional evidence from the post-merge run for #152 on 2026-09-26:

  • tests/adversarial/attack.py sent 16 concurrent bookmark captures. At the probe's 10-second deadline, 4 had returned HTTP 201 with IDs and 12 had no response (-1). The server remained alive.
  • /proc/loadavg read 43.75 34.12 27.58; 17 cargo/rustc processes were active on the shared host.

The probe labels these no-response cases as findings, but this run was under severe host contention and does not establish endpoint behavior on a quiet host. This extends the capture-timeout evidence already tracked here; no importer or search change caused it.

Additional evidence from the post-merge run for #152 on 2026-09-26: - `tests/adversarial/attack.py` sent 16 concurrent bookmark captures. At the probe's 10-second deadline, 4 had returned HTTP 201 with IDs and 12 had no response (`-1`). The server remained alive. - `/proc/loadavg` read `43.75 34.12 27.58`; 17 cargo/rustc processes were active on the shared host. The probe labels these no-response cases as findings, but this run was under severe host contention and does not establish endpoint behavior on a quiet host. This extends the capture-timeout evidence already tracked here; no importer or search change caused it.
Author
Owner

Additional evidence from the #165 post-merge round: GET /api/v1/notes/journal/2020-02-29 did not return within a 6-second client deadline while several adversarial runs and builds were active. The server process remained alive. The Daily note on disk still had 867 bytes, 19 lines and all 5 Log bullets. The round-two probe had mapped a failed GET to [], then reported entry count 5 -> 0; that probe is fixed in #165 commit 3ba137f1 to report the HTTP failure and retain the last confirmed count. This timeout still needs the quiet-host reproduction already tracked here.

Additional evidence from the #165 post-merge round: `GET /api/v1/notes/journal/2020-02-29` did not return within a 6-second client deadline while several adversarial runs and builds were active. The server process remained alive. The Daily note on disk still had 867 bytes, 19 lines and all 5 Log bullets. The round-two probe had mapped a failed GET to `[]`, then reported `entry count 5 -> 0`; that probe is fixed in #165 commit `3ba137f1` to report the HTTP failure and retain the last confirmed count. This timeout still needs the quiet-host reproduction already tracked here.
Author
Owner

Adversarial round for #165, 2026-09-26/27: HTTP 500s during the upload-slot stress phase.

Evidence: the live local server returned 500 {"code":"internal","message":"Authentication service unavailable"} for POST /api/v1/files/mkdir and repeatedly for TUS upload creation (POST /api/v1/files/uploads). The probe reported slot-burn requests 0 through 6 with 500. The server stayed alive. Its log during the same interval recorded recurring SQLite operation failed: pool timed out while waiting for an open connection errors in the backup cron and job worker, plus pool timed out while waiting for an open connection from periodic search reconcile and authentication service unavailable from the pending Home deletion list.

This is a non-SLOW 5xx and is filed for follow-up. The host had many concurrent Rust builds and browser jobs while the adversarial upload and concurrency probes were active, so this run does not isolate a product-only trigger. Please reproduce on a quiet host and capture the failing route's SQLx cause. The probing server remained responsive and the failure coincided with widespread pool-acquire timeouts; I made no auth or pool tuning change based on this shared-host run.

Adversarial round for #165, 2026-09-26/27: HTTP 500s during the upload-slot stress phase. Evidence: the live local server returned `500 {"code":"internal","message":"Authentication service unavailable"}` for `POST /api/v1/files/mkdir` and repeatedly for TUS upload creation (`POST /api/v1/files/uploads`). The probe reported slot-burn requests 0 through 6 with 500. The server stayed alive. Its log during the same interval recorded recurring `SQLite operation failed: pool timed out while waiting for an open connection` errors in the backup cron and job worker, plus `pool timed out while waiting for an open connection` from periodic search reconcile and `authentication service unavailable` from the pending Home deletion list. This is a non-SLOW 5xx and is filed for follow-up. The host had many concurrent Rust builds and browser jobs while the adversarial upload and concurrency probes were active, so this run does not isolate a product-only trigger. Please reproduce on a quiet host and capture the failing route's SQLx cause. The probing server remained responsive and the failure coincided with widespread pool-acquire timeouts; I made no auth or pool tuning change based on this shared-host run.
Author
Owner

Follow-up from the #191 post-merge adversarial run on c96a24f9298a5f27662ead94ed677aae7304d119.

In tests/adversarial/attack2.py log-rewrite storm, concurrent PATCH requests to /api/v1/notes/journal/entries/{block} with the same If-Match version produced statuses [-1, 200, 412]: one request timed out while one succeeded and one returned the expected stale-version response. The probe did not report a line-count change or joined line. The first-round server remained alive. Other worktree builds were active on the shared host during this run. This is a non-SLOW timeout, recorded here for the existing concurrent Journal timeout investigation.

Follow-up from the #191 post-merge adversarial run on `c96a24f9298a5f27662ead94ed677aae7304d119`. In `tests/adversarial/attack2.py` log-rewrite storm, concurrent PATCH requests to `/api/v1/notes/journal/entries/{block}` with the same `If-Match` version produced statuses `[-1, 200, 412]`: one request timed out while one succeeded and one returned the expected stale-version response. The probe did not report a line-count change or joined line. The first-round server remained alive. Other worktree builds were active on the shared host during this run. This is a non-`SLOW` timeout, recorded here for the existing concurrent Journal timeout investigation.
Author
Owner

Additional timeout evidence from the post-merge adversarial round on job/search-palette at ae33137bac8a92426f280d857a64365cda3c7266: 64 concurrent PUT /api/v1/calendar/preferences requests with 16 workers produced one client timeout (-1); the other 63 returned 200. The subsequent GET returned a valid preference shape, and the server stayed alive. Several other worktrees/builds and the 120-photo burst were active on the shared host, so this needs the controlled-load replay already requested here.

Additional timeout evidence from the post-merge adversarial round on `job/search-palette` at `ae33137bac8a92426f280d857a64365cda3c7266`: 64 concurrent `PUT /api/v1/calendar/preferences` requests with 16 workers produced one client timeout (`-1`); the other 63 returned 200. The subsequent GET returned a valid preference shape, and the server stayed alive. Several other worktrees/builds and the 120-photo burst were active on the shared host, so this needs the controlled-load replay already requested here.
Author
Owner

Additional evidence from the post-merge adversarial round for CSP issue #118: the earlier isolated Journal create timeout did not reproduce. logrewrite concurrency reported 6 seeds, 40 creates answered 201, 0 timed out, 8 uploads and 46 entries. The original 30-second timeout from the earlier round remains for quiet-host reproduction; the server stayed alive in both rounds.

Additional evidence from the post-merge adversarial round for CSP issue #118: the earlier isolated Journal create timeout did not reproduce. `logrewrite concurrency` reported 6 seeds, 40 creates answered 201, 0 timed out, 8 uploads and 46 entries. The original 30-second timeout from the earlier round remains for quiet-host reproduction; the server stayed alive in both rounds.
Author
Owner

Additional evidence from the post-merge real-server round on job/menu-icons at cdc09b1d (2026-09-27): the Analytics probe ran 90 reads (each with a 60-second deadline) and 30 Daily-note writes concurrently. One request returned NO RESPONSE (timed out); the current probe labels every result analytics storm, so it does not identify which request timed out. Other requests returned 201 after 20.1–30.1 seconds and were marked SLOW. The Journal race that followed completed with 6 seeds, 40 creates returned 201, 0 create timeouts, 6 uploads and 46 entries. This ran with several other adversarial servers and Rust builds on the shared host, so it needs the controlled-load replay already requested here. Log: target/tmp/menu-icons-adversarial-latest.log in the menu-icons worktree.

Additional evidence from the post-merge real-server round on `job/menu-icons` at `cdc09b1d` (2026-09-27): the Analytics probe ran 90 reads (each with a 60-second deadline) and 30 Daily-note writes concurrently. One request returned `NO RESPONSE (timed out)`; the current probe labels every result `analytics storm`, so it does not identify which request timed out. Other requests returned 201 after 20.1–30.1 seconds and were marked `SLOW`. The Journal race that followed completed with 6 seeds, 40 creates returned 201, 0 create timeouts, 6 uploads and 46 entries. This ran with several other adversarial servers and Rust builds on the shared host, so it needs the controlled-load replay already requested here. Log: `target/tmp/menu-icons-adversarial-latest.log` in the menu-icons worktree.
Author
Owner

Post-merge adversarial run at c2ff7b40: Journal race create checks had 6 seeds, 40 creates returning 201, zero create timeouts, 9 uploads, and 46 expected entries. The move requests did not respond within 30 seconds and were explicitly classified SLOW by the probe under heavy shared-host load. No create identity/content mismatch was reported.

Post-merge adversarial run at c2ff7b40: Journal race create checks had 6 seeds, 40 creates returning 201, zero create timeouts, 9 uploads, and 46 expected entries. The move requests did not respond within 30 seconds and were explicitly classified SLOW by the probe under heavy shared-host load. No create identity/content mismatch was reported.
Author
Owner

New post-merge #165 adversarial result: PROPFIND /dav/calendars/{fixture-user}/ with Depth: 1 returned no HTTP response before the probe deadline during the Reminders collection discovery check. The following probes continued. Neighboring DAV calls returned their expected 207/201/412 statuses but were SLOW (5–21 seconds). Other worktrees had browser, adversarial, and build jobs active, so this needs a quiet-host reproduction; no product-only cause is established. The expected response is 207 with the /reminders/ child collection.

New post-merge #165 adversarial result: `PROPFIND /dav/calendars/{fixture-user}/` with `Depth: 1` returned no HTTP response before the probe deadline during the Reminders collection discovery check. The following probes continued. Neighboring DAV calls returned their expected 207/201/412 statuses but were SLOW (5–21 seconds). Other worktrees had browser, adversarial, and build jobs active, so this needs a quiet-host reproduction; no product-only cause is established. The expected response is 207 with the `/reminders/` child collection.
Author
Owner

Additional post-merge #165 result for #205: the bookmark capture storm returned no HTTP response for all 16 requests (-1 statuses), and 0/16 unique IDs were created. A single bookmark capture immediately before the storm returned 201 in 20.1 seconds. The adversarial runner reported server alive at end: True; neighboring worktrees had active browser/adversarial/build jobs. Please reproduce without shared-host contention before attributing a product cause.

Additional post-merge #165 result for #205: the bookmark capture storm returned no HTTP response for all 16 requests (`-1` statuses), and 0/16 unique IDs were created. A single bookmark capture immediately before the storm returned 201 in 20.1 seconds. The adversarial runner reported `server alive at end: True`; neighboring worktrees had active browser/adversarial/build jobs. Please reproduce without shared-host contention before attributing a product cause.
Author
Owner

Additional post-merge #165 results for #205: the log-rewrite sequence received no HTTP response before its 30-second client deadline for move first and resize first. Other log rewrite writes and reads in the same pass returned expected 200/201 responses, but took 9.5–24.1 seconds. The server was alive earlier in this run; several browser, adversarial, and build jobs were active. These timeouts need quiet-host reproduction before attributing a product cause.

Additional post-merge #165 results for #205: the log-rewrite sequence received no HTTP response before its 30-second client deadline for `move first` and `resize first`. Other log rewrite writes and reads in the same pass returned expected 200/201 responses, but took 9.5–24.1 seconds. The server was alive earlier in this run; several browser, adversarial, and build jobs were active. These timeouts need quiet-host reproduction before attributing a product cause.
Author
Owner

More results from the same post-merge #165 round for #205:

  • Log rewrite edit first, move middle, read before edit middle, edit middle, move last, and resize last each returned no response before the 30-second deadline. (The earlier move first and resize first timeouts are in my previous comment.) The log-rewrite storm returned [-1, 200, 412], then its follow-up read returned 200 in 13.1 seconds.
  • The 70 KB Analytics query received Connection reset by peer. The local calternal-server process was still running when checked.

Successful nearby reads/writes took 13–29 seconds. Multiple worktrees had active adversarial, Cargo, and browser jobs during this run. These timeouts/resets need a quiet-host reproduction before attributing a product-only cause.

More results from the same post-merge #165 round for #205: - Log rewrite `edit first`, `move middle`, `read before edit middle`, `edit middle`, `move last`, and `resize last` each returned no response before the 30-second deadline. (The earlier `move first` and `resize first` timeouts are in my previous comment.) The log-rewrite storm returned `[-1, 200, 412]`, then its follow-up read returned 200 in 13.1 seconds. - The 70 KB Analytics query received `Connection reset by peer`. The local `calternal-server` process was still running when checked. Successful nearby reads/writes took 13–29 seconds. Multiple worktrees had active adversarial, Cargo, and browser jobs during this run. These timeouts/resets need a quiet-host reproduction before attributing a product-only cause.
Author
Owner

Post-merge adversarial evidence from the 2026-09-27 round (the server process remained alive at the end). The host was heavily contended: multiple Chromium processes and concurrent Rust builds were present. Most requests went through the local Node test proxy, and this round has not been reproduced on a quiet host.

Non-SLOW observations to triage:

  • Log rewrite: eight operations timed out at 30 seconds (moves/resizes/edits on first, middle, and last entries, plus a read before editing the middle entry). Later reads often returned 200 after 13–25 seconds. The Journal race subprobe reported 26/41 operations timing out; all 26 timed-out creates later appeared, with 46 total entries and no missing writes.
  • Analytics: 27 of 120 concurrent requests (90 reads and 30 Log writes) returned no response before their client deadline. A 70 KB query was reset by the Node proxy before it reached the Rust server; dev now routes that size probe directly to the backend. After a warmed cache, a Log POST returned 201 in 18.4 seconds, then Analytics returned 200 but failed the expected log_entries == before + 1 check. The cache triggers and existing crate tests cover invalidation, so this one stale result still needs a quiet-host reproduction.
  • Other timed-out requests were a hostile nested tag Log, a cross-midnight Log, three invalid attachment references, seven timezone/Journal cases, four Unicode VTODO reads, and three Unicode Note retitles. Neighboring requests commonly returned expected 201/200/400 statuses after 15–30 seconds.
  • Three Unicode Note creates and the share setup Note were reported as missing, but attack2.py's note() helper discards the HTTP status and response body on non-201. These are unclassified probe outcomes, not confirmed title/data loss.
  • The oversized AI undo probe returned 502 local adversarial server is unavailable. That body is emitted by editor-proxy.mjs when its upstream connection errors, so it does not show that the AI handler returned 502. Dev now routes the oversized body probe directly to the backend.

The slowloris finding from this round was also a proxy misroute: the raw sockets targeted Node, which has no server header timeout. Dev now points the probe at the Rust listener, where the existing silent_partial_and_idle_connections_are_closed test passes (1 passed). No handler change was made from these proxy/load observations.

Post-merge adversarial evidence from the 2026-09-27 round (the server process remained alive at the end). The host was heavily contended: multiple Chromium processes and concurrent Rust builds were present. Most requests went through the local Node test proxy, and this round has not been reproduced on a quiet host. Non-SLOW observations to triage: - Log rewrite: eight operations timed out at 30 seconds (moves/resizes/edits on first, middle, and last entries, plus a read before editing the middle entry). Later reads often returned 200 after 13–25 seconds. The Journal race subprobe reported 26/41 operations timing out; all 26 timed-out creates later appeared, with 46 total entries and no missing writes. - Analytics: 27 of 120 concurrent requests (90 reads and 30 Log writes) returned no response before their client deadline. A 70 KB query was reset by the Node proxy before it reached the Rust server; dev now routes that size probe directly to the backend. After a warmed cache, a Log POST returned 201 in 18.4 seconds, then Analytics returned 200 but failed the expected `log_entries == before + 1` check. The cache triggers and existing crate tests cover invalidation, so this one stale result still needs a quiet-host reproduction. - Other timed-out requests were a hostile nested tag Log, a cross-midnight Log, three invalid attachment references, seven timezone/Journal cases, four Unicode VTODO reads, and three Unicode Note retitles. Neighboring requests commonly returned expected 201/200/400 statuses after 15–30 seconds. - Three Unicode Note creates and the share setup Note were reported as missing, but `attack2.py`'s `note()` helper discards the HTTP status and response body on non-201. These are unclassified probe outcomes, not confirmed title/data loss. - The oversized AI undo probe returned `502 local adversarial server is unavailable`. That body is emitted by `editor-proxy.mjs` when its upstream connection errors, so it does not show that the AI handler returned 502. Dev now routes the oversized body probe directly to the backend. The slowloris finding from this round was also a proxy misroute: the raw sockets targeted Node, which has no server header timeout. Dev now points the probe at the Rust listener, where the existing `silent_partial_and_idle_connections_are_closed` test passes (1 passed). No handler change was made from these proxy/load observations.
Author
Owner

Probe follow-up: commit 2ca6958849 updates note() to retain HTTP status/body and reports malformed 201 responses. The next post-merge adversarial round will classify the earlier Unicode/share setup outcomes.

Probe follow-up: commit 2ca69588493b6aae82bcb02579210f641f3a8710 updates `note()` to retain HTTP status/body and reports malformed 201 responses. The next post-merge adversarial round will classify the earlier Unicode/share setup outcomes.
Author
Owner

The first fonts-branch adversarial run saw DAV initial sync time out while the shared host was heavily loaded and many unrelated endpoints took 5–30 s. The post-merge full run did not report a DAV timeout and the server remained alive. This points to load sensitivity; it still merits a quiet-host replay.

The first fonts-branch adversarial run saw DAV initial sync time out while the shared host was heavily loaded and many unrelated endpoints took 5–30 s. The post-merge full run did not report a DAV timeout and the server remained alive. This points to load sensitivity; it still merits a quiet-host replay.
Author
Owner

The post-merge adversarial round also saw Analytics request timeouts. tests/adversarial/attack2.py ran 90 Analytics reads and 30 Journal writes in a 32-worker pool. Nine Analytics requests returned NO RESPONSE (b'timed out'); successful Analytics responses took up to 27 seconds. The later consistency check passed and the server remained alive.

The host had concurrent Cargo builds and browser probes during this run. This is not a SLOW-only observation, but it still needs a quiet-host reproduction before changing the Analytics path.

The post-merge adversarial round also saw Analytics request timeouts. `tests/adversarial/attack2.py` ran 90 Analytics reads and 30 Journal writes in a 32-worker pool. Nine Analytics requests returned `NO RESPONSE (b'timed out')`; successful Analytics responses took up to 27 seconds. The later consistency check passed and the server remained alive. The host had concurrent Cargo builds and browser probes during this run. This is not a SLOW-only observation, but it still needs a quiet-host reproduction before changing the Analytics path.
Author
Owner

Reproduced the Journal timeout during the audit-bugs adversarial run (2026-09-28). In the journalrace section, seed writes 0, 1, and 2 returned 201 in 5.1–5.7 s. The subsequent GET /api/v1/notes/journal/{day} did not return before the runner's 30-minute overall limit interrupted attack2.py in http.client.getresponse(). The isolated server stayed alive until the runner's cleanup; the run did not reach the journal consistency assertions. This matches the timeout class tracked here. The adversarial run was not repeated.

Reproduced the Journal timeout during the audit-bugs adversarial run (2026-09-28). In the journalrace section, seed writes 0, 1, and 2 returned 201 in 5.1–5.7 s. The subsequent `GET /api/v1/notes/journal/{day}` did not return before the runner's 30-minute overall limit interrupted `attack2.py` in `http.client.getresponse()`. The isolated server stayed alive until the runner's cleanup; the run did not reach the journal consistency assertions. This matches the timeout class tracked here. The adversarial run was not repeated.
Author
Owner

Partial duplicate symptom with #250: both report Calendar Event-from-Log creation timing out at the 30-second client deadline during a shared-host adversarial run. This issue also has distinct DAV, Journal PATCH, bookmark and collaboration results. Recommend linking only the Event-from-Log observation to #250 and keeping those other findings separate.

Partial duplicate symptom with #250: both report Calendar Event-from-Log creation timing out at the 30-second client deadline during a shared-host adversarial run. This issue also has distinct DAV, Journal PATCH, bookmark and collaboration results. Recommend linking only the Event-from-Log observation to #250 and keeping those other findings separate.
Sign in to join this conversation.
No labels
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference
kayg/calternal#205
No description provided.