Merge33 API request timeouts coincide with long Index pool and WAL waits

kayg commented

2026-10-07 16:46:44 +00:00

Owner

Observed during the one bounded merge33b continuation (#1122), head 5382ca7a1; combined release binary built at product-equivalent parent 4f3273473. The direct-backend API probe records request failures, not a synthetic frontend-proxy response.

Evidence so far:

Task create baseline: expected 201, got -1: b'timed out'
Task storm 9..15: NO RESPONSE (b'timed out')
Calendar Event from Log: NO RESPONSE (b'timed out')
Files cursor fixture b: NO RESPONSE (b'timed out')

The tag rename storm completed 100/100. Search, mkdir and rename storms reported no errors. Server diagnostics during these timeouts include connection acquisition of 31.49 s, a 16.96 s SELECT of cron cursor state, a 21.70 s passive WAL checkpoint, and Notes Index operation failed pool_timeout=true. The earlier cross-User matrix completed 938 owned-ID/missing-ID comparisons and 122 Job/Mail/quota comparisons with zero denial failures.

The probe lists these timeout/expected-status rows as findings, without a SLOW prefix. Keep them visible rather than changing the 201 expectations or raising request deadlines. A shared-host load diagnosis must be separated from request-path starvation or a missing admission bound. No actual HTTP 5xx or product crash has been reported for these rows; status -1 is the client's timeout sentinel. The final complete finding list and the credential-redacted server snapshot will be attached on #1122. The 90-minute round continues once; it is not being restarted.

Observed during the one bounded merge33b continuation (#1122), head 5382ca7a1; combined release binary built at product-equivalent parent 4f3273473. The direct-backend API probe records request failures, not a synthetic frontend-proxy response. Evidence so far: ``` Task create baseline: expected 201, got -1: b'timed out' Task storm 9..15: NO RESPONSE (b'timed out') Calendar Event from Log: NO RESPONSE (b'timed out') Files cursor fixture b: NO RESPONSE (b'timed out') ``` The tag rename storm completed 100/100. Search, mkdir and rename storms reported no errors. Server diagnostics during these timeouts include connection acquisition of 31.49 s, a 16.96 s SELECT of cron cursor state, a 21.70 s passive WAL checkpoint, and `Notes Index operation failed pool_timeout=true`. The earlier cross-User matrix completed 938 owned-ID/missing-ID comparisons and 122 Job/Mail/quota comparisons with zero denial failures. The probe lists these timeout/expected-status rows as findings, without a SLOW prefix. Keep them visible rather than changing the 201 expectations or raising request deadlines. A shared-host load diagnosis must be separated from request-path starvation or a missing admission bound. No actual HTTP 5xx or product crash has been reported for these rows; status -1 is the client's timeout sentinel. The final complete finding list and the credential-redacted server snapshot will be attached on #1122. The 90-minute round continues once; it is not being restarted.

kayg referenced this issue from a commit

2026-10-07 17:19:24 +00:00

test(adversarial): replay one Admin timeout with full inventory guards (#1383)

kayg referenced this issue

2026-10-07 17:19:38 +00:00

PROCESS: browser smoke suite of real User flows over a throttled network (deploy gate) #1122

kayg commented

2026-10-07 17:19:39 +00:00

Author

Owner

The combined release continuation completed before the 90-minute limit (exit 1), including API robustness and all 3036 Admin requests. Security: FINDINGS 0/SLOW 5. Cross-User: 938 owned-ID/missing-ID comparisons; Job/Mail/quota 122 comparisons with 0 denial failures. API: 312 finding rows, 242 explicitly SLOW and 70 other rows. The other rows include two fixture inconsistencies plus client timeouts and their dependent upload/projection checks. I did not suppress them or change expectations.

Filed #1381: first-open Appearance assertion runs without opening the app in normal setup; expectation retained for owner review. Filed #1382: Files DAV credential creation can outlive fresh authority; the existing refresh helper is now called before creation, preserving all 200/403/revocation checks. Its focused regression is running. Filed #1383: direct API client timeouts coincide with long Index pool/query/checkpoint waits, with derived fixture failures retained. No actual 5xx, product crash or accepted hostile input is identified in these rows.

The full Admin matrix had one client timeout on GET /api/v1/admin/system/codecs as app_password_notes_full/valid. Replayed that one operation through the same inventory/denial matrix: 25 requests, no failure, exit 0, at load 88.69/82.59/76.70. Commit a9e331a3c adds the focused runner seam; its initial preflight-mode error and correction remain in the logs. This supports a load-related timeout, not an observed authorization grant. The original full-run failure is retained.

Rust workspace tests have begun running after the cold compile. Full clippy already passed. Final readiness is still pending the remaining gates and recorded fixture/timeout gaps.

The combined release continuation completed before the 90-minute limit (exit 1), including API robustness and all 3036 Admin requests. Security: FINDINGS 0/SLOW 5. Cross-User: 938 owned-ID/missing-ID comparisons; Job/Mail/quota 122 comparisons with 0 denial failures. API: 312 finding rows, 242 explicitly SLOW and 70 other rows. The other rows include two fixture inconsistencies plus client timeouts and their dependent upload/projection checks. I did not suppress them or change expectations. Filed #1381: first-open Appearance assertion runs without opening the app in normal setup; expectation retained for owner review. Filed #1382: Files DAV credential creation can outlive fresh authority; the existing refresh helper is now called before creation, preserving all 200/403/revocation checks. Its focused regression is running. Filed #1383: direct API client timeouts coincide with long Index pool/query/checkpoint waits, with derived fixture failures retained. No actual 5xx, product crash or accepted hostile input is identified in these rows. The full Admin matrix had one client timeout on GET /api/v1/admin/system/codecs as app_password_notes_full/valid. Replayed that one operation through the same inventory/denial matrix: 25 requests, no failure, exit 0, at load 88.69/82.59/76.70. Commit a9e331a3c adds the focused runner seam; its initial preflight-mode error and correction remain in the logs. This supports a load-related timeout, not an observed authorization grant. The original full-run failure is retained. Rust workspace tests have begun running after the cold compile. Full clippy already passed. Final readiness is still pending the remaining gates and recorded fixture/timeout gaps.

kayg referenced this issue

2026-10-07 17:30:00 +00:00

Adversarial Files DAV credential creation can outlive fresh owner authority #1382

kayg referenced this issue

2026-10-07 17:30:01 +00:00

PROCESS: browser smoke suite of real User flows over a throttled network (deploy gate) #1122

kayg commented

2026-10-07 17:59:35 +00:00

Author

Owner

Additional journaldup6 / #1295 evidence, head 6519c4615, own debug server and one bounded focused journalrace round.

The selected section finished with 14 finding rows: one actual upload-create 503 and 13 request timeouts. It also reported one SLOW seed (7.3 s, 201). Actual non-SLOW response:

journalrace: sync upload :: ('create', 503, b'{"error":{"code":"service_unavailable","message":"Index is busy; retry shortly"}}')

Other finding rows are SLOW no response in 30s for sync upload or move. Evidence distinguishes unknown admission (no upload ID and no bytes submitted) and a fully sent PATCH refused for stale revision. These are not reported as successful source writes. No status expectation or request deadline changed. Full local evidence: artifacts/journaldup6-journalrace-classified.log. The runner's independent preflight 403 is tracked on #1382.

Additional journaldup6 / #1295 evidence, head `6519c4615`, own debug server and one bounded focused journalrace round. The selected section finished with 14 finding rows: one actual upload-create 503 and 13 request timeouts. It also reported one SLOW seed (7.3 s, 201). Actual non-SLOW response: ``` journalrace: sync upload :: ('create', 503, b'{"error":{"code":"service_unavailable","message":"Index is busy; retry shortly"}}') ``` Other finding rows are `SLOW no response in 30s` for sync upload or move. Evidence distinguishes unknown admission (no upload ID and no bytes submitted) and a fully sent PATCH refused for stale revision. These are not reported as successful source writes. No status expectation or request deadline changed. Full local evidence: `artifacts/journaldup6-journalrace-classified.log`. The runner's independent preflight 403 is tracked on #1382.

kayg referenced this issue

2026-10-07 18:11:50 +00:00

PROCESS: browser smoke suite of real User flows over a throttled network (deploy gate) #1122

kayg commented

2026-10-07 18:11:51 +00:00

Author

Owner

Additional source evidence for #1386: the test deliberately waits 100 ms in Access::note_saved before calling record_note_write. Files note_access retries a stale fingerprint at most eight times with a 20 ms delay. In this gate, each denial was logged after about 200 ms while the same Share and Files Index IDs were present; no Files refresh-complete message preceded the failed upgrade. The result is a real 403, not a client timeout. This suggests the save/reindex window, but it does not prove the cause. Keep the 101 assertion and the identity checks. I did not extend production retry budgets or weaken authorization for this verification failure.

kayg commented

2026-10-07 18:12:38 +00:00

Author

Owner

The Shared Notes diagnostic above belongs to #1386. Relevant #1383 follow-up: the continued Search indexer binary reached a 180-second cap. Its focused retry finished four remaining cases, then reached the job deadline while overflow_recovery_answers_a_queued_integrity_check was pending. No new assertion failure, 5xx or crash was observed. This timeout is not claimed as proven load-only. Remaining check:

cargo test -p calternal-search --test indexer overflow_recovery_answers_a_queued_integrity_check -- --exact --test-threads=4

Final #1122 report is NOT READY at 3e60d38f2b. Web check/test and doctests passed. The real Rust gate blocker is #1386. Build output was removed.

The Shared Notes diagnostic above belongs to #1386. Relevant #1383 follow-up: the continued Search indexer binary reached a 180-second cap. Its focused retry finished four remaining cases, then reached the job deadline while overflow_recovery_answers_a_queued_integrity_check was pending. No new assertion failure, 5xx or crash was observed. This timeout is not claimed as proven load-only. Remaining check: ``` cargo test -p calternal-search --test indexer overflow_recovery_answers_a_queued_integrity_check -- --exact --test-threads=4 ``` Final #1122 report is NOT READY at 3e60d38f2b6f018690f1c89092a06d105ff5699c. Web check/test and doctests passed. The real Rust gate blocker is #1386. Build output was removed.

kayg referenced this issue

2026-10-07 18:23:32 +00:00

Journal: sync retry after 503 duplicates paragraphs #1295

kayg referenced this issue

2026-10-07 20:34:50 +00:00

PROCESS: browser smoke suite of real User flows over a throttled network (deploy gate) #1122

kayg referenced this issue

2026-10-08 02:15:15 +00:00

Journal: sync retry after 503 duplicates paragraphs #1295

kayg referenced this issue

2026-10-08 04:41:46 +00:00

Bulk writes are slow: 5,000 Files and 2,000 Money transactions do not settle in 180 s #1393