Ordinary Files upload returns 503 without a failure diagnostic

kayg commented

2026-10-02 23:20:16 +00:00

Owner

Merge-round-7a (#427), round 4, production SPA and real local server: Files e2e failed during ordinary sequential fixture uploads with 503 !== 201 at apps/web/e2e/files.mjs:1493. It did not reach upload -> rename -> Recent or thumbnail readiness in that run.

Captured redacted server diagnostics include:

2026-10-02T23:07:22.630534Z WARN sqlx::query: slow statement: execution time exceeded alert threshold summary="PRAGMA journal_mode = WAL; …" rows_affected=0 rows_returned=1 elapsed=16.189168811s elapsed_secs=16.189168811 slow_threshold=1s
2026-10-02T23:07:22.632266Z WARN sqlx::pool::acquire: acquired connection, but time to acquire exceeded slow threshold acquired_after_secs=16.20410488 slow_acquire_threshold_secs=2.0

There is no upload failure log line. These waits are evidence of contention, not proof of the precise failing stage. Files database failures map transient SQLite errors and pool timeouts to 503 with Index is busy; retry shortly; no timeout, retry budget or expectation was relaxed in this job.

The focused repeat uses the existing byte upload helper with identical fixture bytes and unchanged 201 assertions so the next failure includes the response error envelope. Initial uploads passed in the repeat, and both text-card and PDF thumbnails returned 200 image/webp. A successful repeat does not establish that the original 503 cause is fixed.

Add safe stage-specific diagnostics, identify the failing operation, and cover the root cause with a regression. Do not classify an actual 503 as a SLOW-only finding.

Merge-round-7a (#427), round 4, production SPA and real local server: Files e2e failed during ordinary sequential fixture uploads with `503 !== 201` at apps/web/e2e/files.mjs:1493. It did not reach upload -> rename -> Recent or thumbnail readiness in that run. Captured redacted server diagnostics include: ``` 2026-10-02T23:07:22.630534Z WARN sqlx::query: slow statement: execution time exceeded alert threshold summary="PRAGMA journal_mode = WAL; …" rows_affected=0 rows_returned=1 elapsed=16.189168811s elapsed_secs=16.189168811 slow_threshold=1s 2026-10-02T23:07:22.632266Z WARN sqlx::pool::acquire: acquired connection, but time to acquire exceeded slow threshold acquired_after_secs=16.20410488 slow_acquire_threshold_secs=2.0 ``` There is no upload failure log line. These waits are evidence of contention, not proof of the precise failing stage. Files database failures map transient SQLite errors and pool timeouts to 503 with `Index is busy; retry shortly`; no timeout, retry budget or expectation was relaxed in this job. The focused repeat uses the existing byte upload helper with identical fixture bytes and unchanged 201 assertions so the next failure includes the response error envelope. Initial uploads passed in the repeat, and both text-card and PDF thumbnails returned 200 image/webp. A successful repeat does not establish that the original 503 cause is fixed. Add safe stage-specific diagnostics, identify the failing operation, and cover the root cause with a regression. Do not classify an actual 503 as a SLOW-only finding.

kayg referenced this issue

2026-10-02 23:34:00 +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 00:32:02 +00:00

Server graceful shutdown waits without a bound for a running Search rebuild or repair #963

kayg commented

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

Author

Owner

Fix: 630fd4c25 + 4acefcbac on job/fix-7a-product. Not merged, not pushed.

What returns 503: in Files every transient SQLite failure (pool checkout timeout, pool closed, SQLITE_BUSY/LOCKED) maps to 503 service_unavailable "Index is busy; retry shortly" with Retry-After: 1. Two more: the 5 s HTTP Index-write checkout deadline (index.rs HTTP_INDEX_WRITE_DEADLINE) and the auth layer (Authentication database is busy). None of these paths logged, so the round-4 503 (during 16–20 s writer checkout waits) had no diagnostic. The response itself was already precise and retryable. The missing part was the server line.

Change: every Files busy 503 now logs one warn line, target calternal_files::unavailable, with stage=<source file:line of the failing call> (via #[track_caller]) and a fixed cause label (pool_checkout_timeout, pool_closed, sqlite_busy, sqlite_locked, index_busy). Auth busy 503s log calternal_auth::unavailable with the cause. The new calternal_db::sqlite_transient_kind is the single classifier (is_sqlite_transient now uses it). No path, User, item ID or driver message is logged. The next real 503 names its exact stage. Example from the test:

WARN calternal_files::unavailable: Files request answered 503 because the Index database is busy; the client may retry stage=crates/plugins/files/src/uploads.rs:982 cause="pool_closed"

Regression test tests::busy_upload_names_its_stage_in_a_private_safe_log (Files lib): an ordinary creation-with-upload against a closed writer pool asserts 503, Retry-After: 1, the error envelope, a log line with the uploads.rs stage and cause, and no upload name or data path in the log. Without the change, no diagnostic line exists.

The upstream cause is SQLite writer contention on the busy shared host. That is outside this fix. Follow-up suggestion, not done: the web uploader treats 503/429 as a manual-retry error, but its 429 text says "It will retry". An automatic bounded retry with Retry-After would let ordinary uploads succeed through brief contention.

Gates: fmt clean; clippy -D warnings clean on db/search/auth/files; cargo test -p calternal-plugin-files → 157 passed; 0 failed; cargo test -p calternal-db ok. cargo test -p calternal-auth → 87 passed; 1 failed: app_password_revoke_rejects_queued_verification is a flake that already exists. It fails 1 of 5 runs on the unmodified base da5c28901 too. Focused e2e bun apps/web/e2e/files.mjs --requests-only with the rebuilt server: all fixture uploads 201, FILES REQUEST COALESCING E2E PASSED.

Fix: 630fd4c25 + 4acefcbac on `job/fix-7a-product`. Not merged, not pushed. What returns 503: in Files every transient SQLite failure (pool checkout timeout, pool closed, SQLITE_BUSY/LOCKED) maps to `503 service_unavailable "Index is busy; retry shortly"` with `Retry-After: 1`. Two more: the 5 s HTTP Index-write checkout deadline (`index.rs` `HTTP_INDEX_WRITE_DEADLINE`) and the auth layer (`Authentication database is busy`). None of these paths logged, so the round-4 503 (during 16–20 s writer checkout waits) had no diagnostic. The response itself was already precise and retryable. The missing part was the server line. Change: every Files busy 503 now logs one warn line, target `calternal_files::unavailable`, with `stage=<source file:line of the failing call>` (via `#[track_caller]`) and a fixed `cause` label (`pool_checkout_timeout`, `pool_closed`, `sqlite_busy`, `sqlite_locked`, `index_busy`). Auth busy 503s log `calternal_auth::unavailable` with the cause. The new `calternal_db::sqlite_transient_kind` is the single classifier (`is_sqlite_transient` now uses it). No path, User, item ID or driver message is logged. The next real 503 names its exact stage. Example from the test: ``` WARN calternal_files::unavailable: Files request answered 503 because the Index database is busy; the client may retry stage=crates/plugins/files/src/uploads.rs:982 cause="pool_closed" ``` Regression test `tests::busy_upload_names_its_stage_in_a_private_safe_log` (Files lib): an ordinary creation-with-upload against a closed writer pool asserts 503, `Retry-After: 1`, the error envelope, a log line with the uploads.rs stage and cause, and no upload name or data path in the log. Without the change, no diagnostic line exists. The upstream cause is SQLite writer contention on the busy shared host. That is outside this fix. Follow-up suggestion, not done: the web uploader treats 503/429 as a manual-retry error, but its 429 text says "It will retry". An automatic bounded retry with Retry-After would let ordinary uploads succeed through brief contention. Gates: fmt clean; clippy `-D warnings` clean on db/search/auth/files; `cargo test -p calternal-plugin-files` → `157 passed; 0 failed`; `cargo test -p calternal-db` ok. `cargo test -p calternal-auth` → `87 passed; 1 failed`: `app_password_revoke_rejects_queued_verification` is a flake that already exists. It fails 1 of 5 runs on the unmodified base da5c28901 too. Focused e2e `bun apps/web/e2e/files.mjs --requests-only` with the rebuilt server: all fixture uploads 201, `FILES REQUEST COALESCING E2E PASSED`.

kayg referenced this issue from a commit

2026-10-03 00:57:10 +00:00

fix(files): log the stage and cause of every busy 503 (#960)

kayg referenced this issue from a commit

2026-10-03 00:57:10 +00:00

test(files): match the quoted cause field in the busy upload log (#960)

kayg referenced this issue from a commit

2026-10-03 00:57:10 +00:00

Merge branch 'job/fix-7a-product' into job/merge-round-7a

kayg referenced this issue

2026-10-03 02:45:08 +00:00

Background Search reconcile starves foreground SQLite writes past client timeouts #965

kayg referenced this issue from a commit

2026-10-03 06:18:51 +00:00

fix(files): log the source line of every upload 500

kayg commented

2026-10-03 09:54:13 +00:00

Author

Owner

Merge-round 7a follow-up on head 516faaa698. During the full adversarial round-two analytics phase, a TUS PATCH failed its expected HTTP 204 with HTTP 503 and the exact response {"error":{"code":"service_unavailable","message":"Index is busy; retry shortly"}}. The same broad run had host load around 40 and SQLx pool waits in the server log. This is a non-SLOW Files write failure; the server stayed alive. It reproduces the Files contention symptom in this issue, though this probe does not isolate the failing operation.

Merge-round 7a follow-up on head 516faaa698570bdb468626cf6cd75d9c81b33ac2. During the full adversarial round-two analytics phase, a TUS PATCH failed its expected HTTP 204 with HTTP 503 and the exact response {"error":{"code":"service_unavailable","message":"Index is busy; retry shortly"}}. The same broad run had host load around 40 and SQLx pool waits in the server log. This is a non-SLOW Files write failure; the server stayed alive. It reproduces the Files contention symptom in this issue, though this probe does not isolate the failing operation.

kayg referenced this issue

2026-10-03 10:28:25 +00:00

Investigate API request timeouts under adversarial concurrency #269

kayg referenced this issue

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

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

Rows
Columns

Ordinary Files upload returns 503 without a failure diagnostic #960