fix(TC-1274): bound SQL waits and add an /invoke deadline

[samgbafa]

Refs TC-1274. Merge only after release 1.21.0. It also depends on tinycloud-dev#147 (canonical event codes); log-shipper/canonical.json pins that PR's head, and is re-pinned once it lands.

This bounds and reports SQL stalls. It does not fix their cause, which is still unknown. On 2026-10-17, one /invoke was held for 1,001.8 s and then answered 503, while the ingress had already answered 504 at 60 s. Nothing bounded the per-database operation lock, the hydration lock, the artifact transfer, or the request itself.

Changes

Bounded SQL waits. All are configurable under storage.sql.

• lock_wait_timeout_ms (30 s): the per-(space, db) operation lock.
• hydration_wait_timeout_ms (30 s): a caller waiting for the database to be loaded into the cache.
• artifact_transfer_timeout_ms (45 s): the export probe load, the full-space size check, save and save_delta.
• When a bound expires, the response is 503 sql_busy: <lock_wait|hydration|artifact_transfer>: … with Retry-After: 5. A save that expires after its BEGIN still answers 500 outcome_unknown.

Hydration as one joinable task per database.

• Concurrent callers join the in-flight hydration instead of each starting one.
• Each caller waits up to its own bound. The hydration keeps loading under hydration_max_ms (10 min), so the next request finds the database warm.
• Only the artifact load is bounded. The local cache writes always finish, so none are orphaned. Before this change, dropping a request mid-hydration released the guards while tokio::fs renames kept running.
• The hydration publishes its actor before it leaves the registry.

/invoke deadline.

• Set by invocation.deadline_ms: 55 s by default, below the ingress's 60 s; 0 turns it off.
• New module tinycloud_core::request_cancel holds a per-request deadline and a one-way commit latch. The latch and the cut are a single compare-and-swap.
• Before the first data write, the handler is dropped at its current .await, and the response is 503 request_timeout: no change was applied; retry the request with Retry-After: 1.
• The latch is set before:
  • the KV write transaction's BEGIN;
  • the SQL actor statement (inside the service);
  • a DuckDB statement or import;
  • meeting publication;
  • decrypt.
• After the latch, the request completes and reports its real result. A completion after the deadline logs Request completed after its deadline.
• The invocation's replay row is kept, so a retry must be a new invocation, which the SDK already sends for every call.

Cancellation safety.

• Everything after acquiring the SQL operation lock runs on a spawned task that owns the guard: hydration, the actor statement, and the persist or discard. A dropped caller can't leave a write applied but not persisted.
• Waits and reads before the write are raced against their bound and the deadline. Mutations always run to completion.

Logging. New typed WARN events, with no identifiers beyond the existing request pseudonyms:

• SQL busy: lock wait|hydration|artifact transfer (error_class, stage, bound_ms, waited_ms);
• Request deadline exceeded (stage, deadline_ms);
• Request completed after its deadline.

The log shipper maps them to sql_busy_lock_wait, sql_busy_hydration, sql_busy_artifact_transfer, request_timeout and deadline_overrun. Ownership of these codes was agreed with the TC-959 work. The vendored fields.json and the embedded compose Vector config are regenerated.

Follow-ups, not in this PR

• Detecting a client disconnect under Rocket 0.5: TC-1400.
• Bounding SQLite statement execution: TC-1401.
• database_migration::resolve also reads database_artifact before the SQL service runs. Only the request deadline bounds it today.

Tests

New tests:

• sql::service tc1274_*:
  • a held lock is answered sql_busy: lock_wait, and another database is unaffected;
  • a stalled artifact load is answered sql_busy: artifact_transfer to two callers, with a single load, and the database is still warm afterwards;
  • a request cut by its deadline releases the lock;
  • a latched write past the deadline reports its real outcome;
  • an aborted caller's write is still persisted and seen by a cold service.
• request_cancel unit tests, including a late latch from another task after the cut.
• In the route: the deadline cuts only before the first write.
• The Retry-After fairing sends 5 for sql_busy and 1 for request_timeout.

RED first. Before the implementation, with only the API surface added, 4 of the 5 tc1274_* service tests failed at their assertions. …_cut_by_its_deadline_releases_the_lock already passed on the old code, because dropping the future released the guard. It stays as a guard for the new spawned-task design.

Runs, local, native PostgreSQL 18, no Docker

• cargo test -p tinycloud-core: 478 lib tests plus integration tests pass.
• cargo test -p tinycloud-core --features duckdb: 524 pass. That was 4 of 5 full runs: one run under host load average ~20 had transient_storage_errors_are_unavailable_and_release_the_lock exceed its 10 s per-request timeout, and it did not reproduce in 15 isolated runs or 4 more full runs.
• cargo test -p tinycloud-node (with TINYCLOUD_TEST_BLACKHOLE=1): all pass.
• The node's duckdb test targets pass.
• cargo clippy --workspace --all-targets -D warnings, plus clippy with --features duckdb, and cargo fmt --check: clean.
• Log shipper: node scripts/tc959-check.mjs --canonical … passes, the node --test suites give 32 pass, and native Vector 0.59.0 vector test passes for both profiles, including the 5 new cases.
• js-sdk tests/node-sdk against this branch: 53 pass, 36 fail. That is the same set as main built and run the same way; the failures are environment-dependent (hooks SSE, webhooks, encryption).

Smoke (a real node on PostgreSQL, through the SDK):

• Writes blocked. LOCK TABLE database_artifact IN EXCLUSIVE MODE blocks artifact writes. A write held in its save answered 503 sql_busy: artifact_transfer after 6.1 s (bound 6 s), and nothing was applied: the count was unchanged after the lock was released. A concurrent read answered 503 sql_busy: lock_wait after 2.05 s (bound 2 s).
• All access blocked. ACCESS EXCLUSIVE blocks all artifact access. With a 5 s deadline, a read answered 503 request_timeout after 5.03 s, and the next read after release succeeded.

Review round 1 (TC-1274 comment 0487d405): changes at 80cb849 and d0616fa

The branch is rebased onto main 65d0e3c (after #346), and the compose VECTOR_CONFIG_JSON is regenerated. canonical.json is re-pinned to tinycloud-dev#147 head 5a8280c.

• B1, a save expiring after its statement was sent. RecoveringConnection marks a write as possibly applied when a write statement's future is dropped before its result arrives. This uses a drop guard, InFlightWrite, in run_statement, execute_unprepared and execute_idempotent. A save/save_delta that expires after sending its statement now answers 500 outcome_unknown, never sql_busy.
  • Test: postgres_a_save_expiring_after_its_write_was_sent_is_an_unknown_outcome on PostgreSQL. The delta UPDATE is held by LOCK TABLE database_artifact IN EXCLUSIVE MODE. Its bound expires, then the lock is released, and the in-flight UPDATE commits exactly once.
  • RED without the guard: Busy(ArtifactTransfer). GREEN with it.
• M2. handle() hydrates at most twice, then answers Internal("database actor did not start after hydration").
• M3. A RetireFlight drop guard retires the registry entry, only if it is still this flight, and publishes Failed if the hydration task panics. Test: tc1274_a_panicking_hydration_does_not_wedge_the_database.
• M1. DuckDB is not bounded. The CHANGELOG now says so, and the follow-up is TC-1412.
• Lows
  • The hydration_max warning maps to sql_hydration_timeout, the 6th code in TC-268: add production invoke performance baseline #147. Callers that get that outcome now log SQL busy: artifact transfer.
  • Request deadline exceeded is logged exactly once, by whoever moves the request from open to cut.
  • Only unfreeze_legacy latches publication at the route, and the comment is corrected.
  • Route and KV latches carry debug_assert!.
  • Identity resolution has its own stage, identity_resolution. The SQL path still resolves twice per request, and TC-1403 bounds it.
  • The latched-write test syncs on saves_waiting instead of sleep(500ms).
  • New tests:
    • hydration_max expiry and registry cleanup;
    • every joiner seeing a failed hydration;
    • begin_write refusing a write that is past its deadline;
    • no temp files left after a cut;
    • a Rocket-level request against a stalled SQL hydration getting 503 request_timeout with Retry-After: 1 and CORS.
• Not done: a test for the sql_busy: hydration (writing-files) stage. That phase is local tokio::fs work and can't be stalled deterministically without a test-only hook.
• SDK follow-up: TC-1413. 503 and 500 both map to NETWORK_ERROR, Retry-After is ignored, and a 503 on a conditional KV put is reported as KV_CONFLICT.

Local runs at 80cb849 (native PostgreSQL 18, no Docker):

• cargo fmt --check: clean.
• clippy (workspace -Dwarnings, and with --features duckdb): clean.
• cargo test -p tinycloud-core --features duckdb: no failures.
• cargo test -p tinycloud-node --no-fail-fast with TINYCLOUD_TEST_BLACKHOLE=1: no failures.
• The node's duckdb test targets pass.
• Shipper:
  • tc959-check --canonical passes;
  • node --test gives 33 pass;
  • native Vector 0.59.0 passes both profiles, including the new case.

d0616fa: compose fix. The first regeneration passed '$${TINYCLOUD_LOGSHIP_PROFILE}' as a String.replaceAll replacement string, and in a replacement string $$ means a single $. The embedded config therefore lost its compose escape, and hosted-compose-proof caught it. The compose is now regenerated with a function replacement. The N0 raw lock is re-pinned to 6e3b96c8… in docker.yml n0_hash, scripts/ci/fixtures/tc959-n0-compose.yaml, docs/releasing.md and the TC-959 runbook. scripts/ci/test-deploy-recovery.py passes locally.

CI at d0616fa: all green, including test (workspace, PostgreSQL-backed), hosted-compose-proof, Version guard, clippy and fmt.

[samgbafa]

REQUEST_CHANGES: see TC-1274 (reviewed head 54deefd)

[samgbafa]

REQUEST_CHANGES: see TC-1274 (reviewed head d0616fa)

[samgbafa]

APPROVE: see TC-1274 (reviewed head 4ef15a2)

[samgbafa]

APPROVE: see TC-1317 (delta review of head 32332abddd099fc952f0764ff051400328579fa9 from the approved 4ef15a2: de7a343 and the main merge 32332ab; N0 template 00938226… recomputed). Comment: https://linear.app/tinycloud-labs/issue/TC-1317#comment-cdeb26c7