Skip to content

fix(TC-1317): bound the read-audit wait and skip abandoned records - #350

Merged
samgbafa merged 4 commits into
mainfrom
skgbafa/tc-1317-read-audit-bound
Oct 19, 2026
Merged

samgbafa merged 4 commits into
mainfrom
skgbafa/tc-1317-read-audit-bound

Conversation

@samgbafa

Copy link
Copy Markdown
Contributor

Refs TC-1317. Stacked on #347 (base skgbafa/tc-1274-sql-wait-bounds); it uses #347's request_cancel stage. Merge after 1.21.0, after #347. It also depends on tinycloud-dev#154 (read-audit event codes, stacked on #147); log-shipper/canonical.json pins #154's head 4adaf13 and needs re-pinning once it lands.

Every authorized read waits for its invocation record to commit before its data is returned. That covers KV get, list, metadata and sync, capabilities read, and the authorization step of SQL, DuckDB, space-info, /signed/kv and /encryption/networks. The wait had no bound, and one serial queue serves every account. The Oct 14 all-account read hang fits a self-sustaining backlog of that queue [INFERENCE, TC-1274 05eb8962]. The design was approved by Naomi in ~/scratch/tc1274/read-audit/DESIGN.md.

Changes

  • Bounded wait. database.read_audit_wait_ms, 20 s by default, covers both queue admission and the receipt. On expiry the read gets 503 read_audit_busy: the read audit is backlogged; retry the request with Retry-After: 5, and no data. A request cut by the /invoke deadline while it waits now logs stage="read_audit".
  • The invariant is unchanged and tested: no read's data is returned unless its audit record has committed.
  • Abandoned records are skipped. When a batch forms, the drain drops records whose waiter is already gone (the receipt's Sender::is_closed()) and counts them in abandoned.
    • A closed receipt can never confirm, so a skipped read can never be delivered.
    • A waiter that leaves after formation is still committed, which is the harmless direction.
    • With dead work skipped, a backlog drains on its own instead of needing a restart, and cut SQL requests stay out of the migration attribution evidence.
  • Error classes.
    • A batch that fails with a transient DB error gives its waiters 503 unavailable_retryable.
    • Any other failure gives 500, as before.
    • verify_auth and the encryption routes no longer report infrastructure errors as 401.
  • Panic isolation. A panic in one batch's commit (catch_unwind) fails only that batch; the drain keeps running.
  • Watchdog. A separate 10 s task, which can still report a drain whose batch is hung. Each warning fires at most once a minute and carries counts and durations only:
    • Read audit wait expired → read_audit_busy;
    • Read audit batch slow (over 5 s) → read_audit_batch_slow;
    • Read audit batch failed (with a fixed error_class: a transient class, other or panic) → read_audit_batch_failed;
    • Read audit drain stalled (a batch in flight over 30 s, or queued records with no progress for 10 s) → read_audit_drain_stalled.
    • Code names were agreed with the TC-959 lead. Only the codes ship; the fields stay in local logs, matching the existing diagnostics path.
  • Prometheus (through the existing 5 s sampler):
    • counters tinycloud_read_audit_failed_batches_total, …_abandoned_total, …_busy_total;
    • gauges tinycloud_read_audit_queue_depth and tinycloud_read_audit_in_flight_batch_age_ms.
    • read_audit_commit_stats is replaced by read_audit_health().
  • Compose and lock. The compose VECTOR_CONFIG_JSON is regenerated, so the N0 raw lock moves to 966199dc… (docker.yml n0_hash, the N0 fixture, docs/releasing.md, the TC-959 runbook).
  • Follow-ups, not in this PR:
    • An overall request deadline for /signed/kv and /encryption/networks (TC-1418). Their read-audit wait is now bounded by the core bound; adding the deadline needs per-route write latches, so I filed it rather than wrap them here.
    • Audit throughput (TC-321).

Tests

  • RED first. The API surface was added with no behaviour first. On that base:
    • tc1317_a_held_drain_answers_busy_within_the_bound failed;
    • tc1317_abandoned_records_are_skipped_and_the_drain_recovers hung, because the wait was unbounded;
    • tc1317_a_panicking_batch_does_not_stop_the_drain failed;
    • tc1317_a_transient_batch_failure_is_retryable failed;
    • kv_sync tc1317_a_held_read_audit_bounds_reads_and_spares_writes failed.
    • The invariant test passed on the old code, as it should; it guards the new skip.
  • New tests:
    • tc1317_no_read_is_confirmed_without_its_committed_record: 48 concurrent waiters, a third of them cut. Every confirmed read has its row, and records committed plus abandoned equals 48.
    • tc1317_the_watchdog_reports_a_stalled_drain_once_per_interval.
    • Route test a_kv_read_with_a_stalled_read_audit_is_answered_busy: a real /invoke KV get answers 503 read_audit_busy without the value, then serves it once the drain frees up.
    • Retry-After 5 for read_audit_busy in the fairing test.
  • Adjusted: postgres_read_audit_failed_batch_commits_nothing_and_fails_every_waiter now expects a terminated connection to reach waiters as unavailable_retryable, not the raw driver text.

Runs (local, native PostgreSQL 18, no Docker):

  • cargo fmt --check, plus clippy for the workspace (-Dwarnings) and with --features duckdb: clean.
  • cargo test -p tinycloud-core lib: 490 pass. With --features duckdb: 535 of 536 pass. The one failure was fix(TC-1274): bound SQL waits and add an /invoke deadline #347's transient_storage_errors_are_unavailable_and_release_the_lock, its known load flake, at host load average ~20 to 30. It passed in 40 isolated runs, 30 parallel sql::service runs and 6 more full-binary runs.
  • cargo test -p tinycloud-node with TINYCLOUD_TEST_BLACKHOLE=1: all pass, except 3 policy_v3::account_alias_tests that hit their 10 s fixture timeouts in one run at high load. They passed alone and in 3 more full lib runs (537 of 537).
  • 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 4 new cases;
    • scripts/ci/test-*.py all pass.

Smoke (a real node on PostgreSQL, read_audit_wait_ms=3000, through the SDK). LOCK TABLE invocation IN EXCLUSIVE MODE lets reads through but blocks audit inserts.

  • 3 KV gets each answered 503 read_audit_busy in about 3.1 s.
  • After release, the next get was served in 0.08 s.
  • The node logged:
    • Read audit wait expired (count 1, rate-limited);
    • Read audit drain stalled (in flight 15.9 s, queue 5);
    • then, once PostgreSQL's 30 s statement_timeout ended the held batch: Read audit batch slow (30 001 ms) and Read audit batch failed with error_class="sqlstate_57014".

A read waits at most database.read_audit_wait_ms (20 s) for its audit
record, then answers 503 read_audit_busy without its data. Records whose
reader was already gone when their batch formed are skipped and counted,
so a backlog drains on its own; no read's data is returned unless its
record committed. Transient batch failures are 503 unavailable_retryable,
infrastructure errors are no longer 401, and a panic fails only its batch.
A watchdog logs stalled, slow, failed and expired audits, and Prometheus
gains failure, abandon and busy counters plus queue and in-flight gauges.
@samgbafa

Copy link
Copy Markdown
Contributor Author

REQUEST_CHANGES: see TC-1317 (review of head ec069c461d7d0bf0b92d25c3567cf479310e0ebc, this commit only, on #347 4ef15a2). Comment: https://linear.app/tinycloud-labs/issue/TC-1317#comment-8ac94a98

- R1: the test-only panic fault is per pipeline, not a process-global
  static that another test's drain could consume.
- R2: Rocket-level tests with the read audit held: /signed/kv, SQL and
  /encryption/networks answer 503 read_audit_busy (not 401) and SQL never
  executes; a stranger's read is still 401/403; a deadline shorter than
  the wait answers request_timeout.
- The node refuses to start with database.read_audit_wait_ms = 0.
- A dead drain is counted (stopped) and reported as a stalled drain; a
  batch waiting on the SQLite writer lock counts as in flight.
- Tests: condition-based sync instead of a fixed sleep; commit-semantics
  pipeline tests use a long wait so host load cannot turn them busy.
… into skgbafa/tc-1317-read-audit-bound

# Conflicts:
#	.github/workflows/docker.yml
#	docs/releasing.md
#	docs/runbooks/tc-959-n0-log-shipping.md
@samgbafa

Copy link
Copy Markdown
Contributor Author

APPROVE: see TC-1317 (re-review of head a811986fbe6ed1ecf5216a7e453cb5851ced72e0: fixes f933e2e, merges f58c604 and a811986). One non-blocking test follow-up (F1). Comment: https://linear.app/tinycloud-labs/issue/TC-1317#comment-cdeb26c7

@samgbafa
samgbafa changed the base branch from skgbafa/tc-1274-sql-wait-bounds to main October 19, 2026 11:11
@samgbafa
samgbafa merged commit 307e654 into main Oct 19, 2026
20 checks passed
@samgbafa samgbafa mentioned this pull request Oct 19, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant