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

.github/workflows/docker.yml

@@ -666,9 +666,9 @@ jobs:
           native = 'ghcr.io/tinycloudlabs/tinycloud-node'
           reviewed = native + '@sha256:4bdae4fc232d886bb56bfbce4ec62ed4b8fb4e1369a01f6afb73d06dd68c188f'
           # TC-959: main's N0 compose (#349 c33c2302…) with the 95m ingress body
-          # cap (raw d95bfb70…) and TC-1274's Vector config (raw b25b8414…),
-          # its single node digest normalized to 64 zeros.
-          n0_template_hash = '009382266172b76ae1858aa79060da5f58ece66a758dd8fd876b96367d96e1db'
+          # cap (raw d95bfb70…) and the TC-1274 + TC-1317 Vector config
+          # (raw 1228d819…), its single node digest normalized to 64 zeros.
+          n0_template_hash = '7fabba70e71423faa2c8b61981d4a7c95ac7c2552074af81c0877af774d6b383'
           node_pin = re.compile(rb'(?m)^    image: ghcr\.io/tinycloudlabs/tinycloud-node@sha256:([0-9a-f]{64})$')
           def n0_template(raw):
               pins = list(node_pin.finditer(raw))

CHANGELOG.md

@@ -2,6 +2,14 @@
 
 ## [Unreleased]
 
+- Authorized reads no longer wait without limit for their audit record (TC-1317). Every read (KV get/list/metadata/sync, capabilities read, and the authorization step of SQL, DuckDB, space info, `/signed/kv` and `/encryption/networks`) waits for its invocation record to commit before its data is returned. That wait used to have no bound, and one serial queue served every account.
+  - **Bounded wait.** A read waits at most `database.read_audit_wait_ms` (20 s) and is then answered `503 read_audit_busy: the read audit is backlogged; retry the request` with `Retry-After: 5`, without its data. The node refuses to start with `read_audit_wait_ms = 0`, which would answer every read busy. A batch that fails with a transient database error is now `503 unavailable_retryable` instead of 500; other batch failures stay 500, and none of them is reported as 401 any more.
+  - **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, records whose reader already gave up or was cut are dropped and counted instead of committed. Their data was never returned. This lets a backlog drain on its own instead of needing a restart, and keeps cut SQL requests out of the database-migration attribution evidence.
+  - **Panic isolation.** A panic while committing one batch fails only that batch; the queue keeps working.
+  - **Visibility.** New Prometheus metrics: `tinycloud_read_audit_failed_batches_total`, `tinycloud_read_audit_abandoned_total`, `tinycloud_read_audit_busy_total`, and the gauges `tinycloud_read_audit_queue_depth` and `tinycloud_read_audit_in_flight_batch_age_ms`. A watchdog logs `Read audit wait expired`, `Read audit batch slow` (over 5 s), `Read audit batch failed` and `Read audit drain stalled` (a batch in flight over 30 s, including a SQLite writer-lock wait; queued records with no progress for 10 s; or a dead drain, whose reads fail as stopped), each at most once a minute, with counts and durations only. The log shipper maps them to `read_audit_busy`, `read_audit_batch_slow`, `read_audit_batch_failed` and `read_audit_drain_stalled`. A request cut by the `/invoke` deadline while it waits on its audit now logs `stage="read_audit"`.
+  - **N0 compose.** The embedded Vector configuration is regenerated for these codes, so the reviewed N0 compose template changes to `7fabba70…` (raw `1228d819…`; `docs/releasing.md`).
+  - **Not covered.** An overall request deadline for `/signed/kv` and `/encryption/networks` is TC-1418; the audit queue's throughput is TC-321.
 - SQL requests no longer wait without limit, and `/invoke` has a deadline (TC-1274). The cause of the original stall is still unknown; this change bounds the waits and reports them.
   - **Bounded waits.** A SQL request waits at most `storage.sql.lock_wait_timeout_ms` (30 s) for its database's operation lock, `hydration_wait_timeout_ms` (30 s) for the database to be loaded into the node's cache, and `artifact_transfer_timeout_ms` (45 s) for a durable artifact load or save. It then answers `503 sql_busy: <lock_wait|hydration|artifact_transfer>: …` with `Retry-After: 5`. A save that times out after its write statement was sent is `500 outcome_unknown`: PostgreSQL may still commit that statement.
   - **Hydration keeps going.** Concurrent requests share one hydration, and it continues after its callers give up (up to `hydration_max_ms`, 10 min), so the next request finds the database warm.

docs/releasing.md

@@ -309,11 +309,12 @@ Before any CVM mutation the workflow requires:
 
 - the main compose, with its one node digest replaced by 64 zeros, to hash
   to the reviewed N0 template
-  **`009382266172b76ae1858aa79060da5f58ece66a758dd8fd876b96367d96e1db`**
-  (raw `b25b8414c784ee7d66d6e3a507d3dba29818aca5cbf339e85bcb667e2316e20d` normalized: the 1.21.0 compose
+  **`7fabba70e71423faa2c8b61981d4a7c95ac7c2552074af81c0877af774d6b383`**
+  (raw `1228d81927fc0a3fbba85745103e77b3112606f5d314d15974d400b222409350` normalized: the 1.21.0 compose
   `d95bfb707871c1d626c4a8f2b8d32d354103edbb5077847c6a21fe5f7f6cfa50`, template
   `51f8e9e9…`, with only the embedded Vector config regenerated for TC-1274's
-  warning codes. That compose is the #349 compose
+  and TC-1317's warning codes; TC-1274 alone was template `00938226…`, raw
+  `b25b8414…`. That compose is the #349 compose
   `c33c23021589163b62a71ef245b7194717711922027629f155bdd5cff806b8c7`, which
   keeps `TINYCLOUD_EPOCH_HEAD_BACKFILL__ENABLED: "false"`, with only
   `CLIENT_MAX_BODY_SIZE=32m` → `95m`). Ingress, socat, Vector and the log
@@ -378,8 +379,8 @@ gh workflow run docker.yml -R TinyCloudLabs/tinycloud-node --ref main \
 
 The served/OCI identity remains **1.20.6-dstack / e18578ff9162986ddd813259c60f73866e3e60d1**.
 With the template lock on main this redeploys exactly main's raw compose
-`b25b8414c784ee7d66d6e3a507d3dba29818aca5cbf339e85bcb667e2316e20d`
-(the 1.21.0 compose `d95bfb70…` with TC-1274's Vector config), whatever digest
+`1228d81927fc0a3fbba85745103e77b3112606f5d314d15974d400b222409350`
+(the 1.21.0 compose `d95bfb70…` with the TC-1274 and TC-1317 Vector config), whatever digest
 main's template currently pins. It is not a rollback of a
 later release across a schema migration. Current pre-N0 tag/pinned
 equivalents are separately hash-checked; arbitrary same-image config

docs/runbooks/tc-959-n0-log-shipping.md

@@ -147,7 +147,7 @@ Keep these identities distinct:
 | Before: verifier `docker_compose_file` / hash | Raw preserved pre-N0 compose: `df239749ca0a9c09893a855ae2a8abb94090b8556515ad002105c58ac91f4c91` |
 | Before: application `compose_hash` | `bfe9028a58b23238188aa7d70b82282a7cd6414cd83dcc47a3b295c6f64fe2f8`; a distinct reported identity, not the raw-file hash |
 | After: current profile-enabled raw compose | `c33c23021589163b62a71ef245b7194717711922027629f155bdd5cff806b8c7`; bind this artifact to the final reviewed PR head before any promotion |
-| After the main release: template-locked raw compose | `b25b8414c784ee7d66d6e3a507d3dba29818aca5cbf339e85bcb667e2316e20d` (the 1.21.0 compose `d95bfb70…`, template `51f8e9e9…`, with TC-1274's regenerated Vector config); node digest normalized, template `009382266172b76ae1858aa79060da5f58ece66a758dd8fd876b96367d96e1db`. See [`docs/releasing.md`](../releasing.md#main-release-with-n0-log-shipping-one-dispatch) |
+| After the main release: template-locked raw compose | `1228d81927fc0a3fbba85745103e77b3112606f5d314d15974d400b222409350` (the 1.21.0 compose `d95bfb70…`, template `51f8e9e9…`, with the TC-1274 and TC-1317 regenerated Vector config); node digest normalized, template `7fabba70e71423faa2c8b61981d4a7c95ac7c2552074af81c0877af774d6b383`. See [`docs/releasing.md`](../releasing.md#main-release-with-n0-log-shipping-one-dispatch) |
 
 The raw after hash identifies the profile-enabled compose, not deployment approval. Record its final reviewed PR head and required CI evidence in the officer handoff. Do not infer a raw-file hash from the distinct application-reported compose hash.
 

log-shipper/canonical.json

@@ -1,6 +1,6 @@
 {
   "repo": "samgbafa/tinycloud-dev",
-  "revision": "5a8280c65c6417c02edb4ea7025d5593c65585f8",
+  "revision": "4adaf13b33c85d0a18f63126fc877776c4ee3dbb",
   "path": "ops/logging/fields.json",
-  "sha256": "ac5e127a5a223ea32fa9cb1644b60315ff5c79abcf2f677a14fef7cb0c416437"
+  "sha256": "02463b9370d88eff282d9c3f5b738f18a169ad6276bacdb9c3d4e60264fb062a"
 }

log-shipper/cases.mjs

@@ -43,6 +43,7 @@ export const vectorTests = [
   ...[['SQL busy: lock wait', 'sql_busy_lock_wait'], ['SQL busy: hydration', 'sql_busy_hydration'], ['SQL busy: artifact transfer', 'sql_busy_artifact_transfer']].map(([message, code]) => check(`SQL busy warning maps to ${code} without its fields`, envelope({ timestamp, level: 'WARN', target: 'tinycloud_core::sql::service', fields: { message, service: 'sql', error_class: 'sql_busy', stage: canary, bound_ms: 30000, waited_ms: 30001 } }), `.event == "node_warning" && .event_code == "${code}" && .event_count == 1`)),
   ...[['Request deadline exceeded', 'request_timeout'], ['Request completed after its deadline', 'deadline_overrun']].map(([message, code]) => check(`request deadline warning maps to ${code} without its fields`, envelope({ timestamp, level: 'WARN', target: 'tinycloud_core::request_cancel', fields: { message, error_class: canary, stage: canary, deadline_ms: 55000 } }), `.event == "node_warning" && .event_code == "${code}" && .event_count == 1`)),
   check('hydration timeout warning maps to sql_hydration_timeout without its fields', envelope({ timestamp, level: 'WARN', target: 'tinycloud_core::sql::service', fields: { message: 'Database hydration gave up loading its artifact', service: 'sql', error_class: canary, bound_ms: 600000 } }), '.event == "node_warning" && .event_code == "sql_hydration_timeout" && .event_count == 1'),
+  ...[['Read audit wait expired', 'read_audit_busy'], ['Read audit batch slow', 'read_audit_batch_slow'], ['Read audit batch failed', 'read_audit_batch_failed'], ['Read audit drain stalled', 'read_audit_drain_stalled']].map(([message, code]) => check(`read-audit warning maps to ${code} without its fields`, envelope({ timestamp, level: 'WARN', target: 'tinycloud_core::read_audit', fields: { message, error_class: canary, count: 3, queue_depth: 1024, in_flight_batch_age_ms: 30001, abandoned: 7 } }), `.event == "node_warning" && .event_code == "${code}" && .event_count == 1`)),
   check('dependency warning is a fixed unclassified diagnostic', envelope({ timestamp, level: 'WARN', target: 'hyper::proto', fields: { message: canary, error: canary } }), '.event == "node_warning" && .event_code == "unclassified" && .event_count == 1'),
   check('dependency error without a message still counts', envelope({ timestamp, level: 'ERROR', target: 'sqlx::pool', fields: { error: canary } }), '.event == "node_error" && .event_code == "unclassified" && .event_count == 1'),
   check('warning without a target or fields still counts', envelope({ timestamp, level: 'WARN' }), '.event == "node_warning" && .event_code == "unclassified" && .event_count == 1'),

log-shipper/diagnostics.json

@@ -53,7 +53,11 @@
     "SQL busy: artifact transfer": "sql_busy_artifact_transfer",
     "Request deadline exceeded": "request_timeout",
     "Request completed after its deadline": "deadline_overrun",
-    "Database hydration gave up loading its artifact": "sql_hydration_timeout"
+    "Database hydration gave up loading its artifact": "sql_hydration_timeout",
+    "Read audit wait expired": "read_audit_busy",
+    "Read audit batch slow": "read_audit_batch_slow",
+    "Read audit batch failed": "read_audit_batch_failed",
+    "Read audit drain stalled": "read_audit_drain_stalled"
   },
   "prefix": {
     "dstack socket available but get_info failed: ": "dstack_get_info_failed",

log-shipper/fields.json

@@ -78,7 +78,7 @@
         "status": { "type": "integer", "min": 100, "max": 599 },
         "latency_us": { "type": "integer", "min": 0, "max": 9007199254740991 },
         "request_time_seconds": { "type": "number", "min": 0, "max": 86400 },
-        "event_code": { "type": "enum", "values": ["invocation_replay_insert_failed", "invocation_replay_cleanup_failed", "dstack_get_info_failed", "share_local_tee_identity", "retention_hook_delivery_prune_failed", "retention_dead_letter_prune_failed", "retention_signed_ticket_prune_failed", "quota_invalid_body", "quota_fallback", "tunnel_state_load_failed", "tunnel_address_invalid", "link_state_load_failed", "link_bind_invalid", "link_address_invalid", "link_bind_failed", "link_bind_state_write_failed", "link_tls_config_failed", "link_listener_error", "link_listener_state_write_failed", "link_auto_renew_config_failed", "link_auto_renew_failed", "link_cert_reload_failed", "link_cert_state_missing", "link_listener_cert_reload_failed", "link_disable_failed", "link_connection_error", "link_listener_accept_failed", "webhook_delivery_failed", "webhook_dispatcher_failed", "share_authorization_failed", "share_native_authorization_denied", "share_native_kv_put_failed", "share_v2_readiness_failed", "share_invitation_key_missing", "share_invitation_key_mismatch", "share_policy_denied", "attestation_quote_failed", "hook_events_read_failed", "hook_rows_load_failed", "missing_committed_hook_row", "webhook_enqueue_failed", "tunnel_connection_prepare_failed", "tunnel_idle_timeout", "tunnel_read_failed", "tunnel_malformed_frame", "tunnel_relay_error", "tunnel_write_failed", "tunnel_state_record_failed", "tunnel_state_clear_failed", "tunnel_auth_rejected", "network_did_resolution_enabled", "unclassified", "sql_busy_lock_wait", "sql_busy_hydration", "sql_busy_artifact_transfer", "request_timeout", "deadline_overrun", "sql_hydration_timeout"] },
+        "event_code": { "type": "enum", "values": ["invocation_replay_insert_failed", "invocation_replay_cleanup_failed", "dstack_get_info_failed", "share_local_tee_identity", "retention_hook_delivery_prune_failed", "retention_dead_letter_prune_failed", "retention_signed_ticket_prune_failed", "quota_invalid_body", "quota_fallback", "tunnel_state_load_failed", "tunnel_address_invalid", "link_state_load_failed", "link_bind_invalid", "link_address_invalid", "link_bind_failed", "link_bind_state_write_failed", "link_tls_config_failed", "link_listener_error", "link_listener_state_write_failed", "link_auto_renew_config_failed", "link_auto_renew_failed", "link_cert_reload_failed", "link_cert_state_missing", "link_listener_cert_reload_failed", "link_disable_failed", "link_connection_error", "link_listener_accept_failed", "webhook_delivery_failed", "webhook_dispatcher_failed", "share_authorization_failed", "share_native_authorization_denied", "share_native_kv_put_failed", "share_v2_readiness_failed", "share_invitation_key_missing", "share_invitation_key_mismatch", "share_policy_denied", "attestation_quote_failed", "hook_events_read_failed", "hook_rows_load_failed", "missing_committed_hook_row", "webhook_enqueue_failed", "tunnel_connection_prepare_failed", "tunnel_idle_timeout", "tunnel_read_failed", "tunnel_malformed_frame", "tunnel_relay_error", "tunnel_write_failed", "tunnel_state_record_failed", "tunnel_state_clear_failed", "tunnel_auth_rejected", "network_did_resolution_enabled", "unclassified", "sql_busy_lock_wait", "sql_busy_hydration", "sql_busy_artifact_transfer", "request_timeout", "deadline_overrun", "sql_hydration_timeout", "read_audit_busy", "read_audit_batch_slow", "read_audit_batch_failed", "read_audit_drain_stalled"] },
         "event_count": { "type": "integer", "min": 1, "max": 9007199254740991 },
         "reason": { "type": "enum", "values": ["malformed_envelope", "unexpected_label", "unlabelled", "non_json", "oversized", "partial", "invalid_fields", "unknown_target", "filtered_level"] },
         "count": { "type": "integer", "min": 1, "max": 9007199254740991 },

tinycloud-core/src/db.rs

@@ -258,6 +258,10 @@ pub enum TxError<S: StorageSetup, K: Secrets> {
     Encryption(#[from] crate::encryption::EncryptionError),
     #[error("delegation-chain-traversal-limit-exceeded")]
     ChainTraversalLimitExceeded,
+    /// The read's audit record was not confirmed; its data was not returned
+    /// (TC-1317).
+    #[error(transparent)]
+    ReadAudit(#[from] crate::read_audit::ReadAuditError),
 }
 
 #[non_exhaustive]
@@ -456,9 +460,20 @@ impl<C, B, K> SpaceDatabase<C, B, K>
 where
     K: Secrets,
 {
-    /// Number of durable read-audit records and group commits completed.
-    pub fn read_audit_commit_stats(&self) -> (u64, u64) {
-        self.read_audit.stats()
+    /// Counts and ages of the read-audit pipeline, for metrics and logs.
+    pub fn read_audit_health(&self) -> crate::read_audit::ReadAuditHealth {
+        self.read_audit.health()
+    }
+
+    /// Bound how long a read waits for its audit record (TC-1317). Takes
+    /// effect for waits that start afterwards.
+    pub fn set_read_audit_wait(&self, wait: std::time::Duration) {
+        self.read_audit.set_wait(wait);
+    }
+
+    #[cfg(test)]
+    pub(crate) fn read_audit_pipeline(&self) -> &crate::read_audit::ReadAuditPipeline {
+        &self.read_audit
     }
 
     pub async fn stage_key(&self, space_id: &SpaceId) -> Result<String, K::Error> {
@@ -2702,7 +2717,7 @@ where
             crate::telemetry::StageOutcome::from(record_result.is_ok()),
             read_audit_start.elapsed(),
         );
-        record_result?;
+        record_result.map_err(TxError::<B, K>::from)?;
         Ok((
             TransactResult {
                 commits: HashMap::new(),

tinycloud-core/src/kv_sync.rs

@@ -927,6 +927,8 @@ pub(crate) mod tests {
         Put(&'a str, &'a [u8]),
         PutMeta(&'a str, &'a [u8], &'a [(&'a str, &'a str)]),
         Del(&'a str),
+        /// A read: it goes through the read-audit pipeline (TC-1317).
+        Get(&'a str),
     }
 
     impl Owner {
@@ -956,6 +958,7 @@ pub(crate) mod tests {
                 let (key, ability) = match op {
                     Op::Put(key, _) | Op::PutMeta(key, _, _) => (key, "tinycloud.kv/put"),
                     Op::Del(key) => (key, "tinycloud.kv/del"),
+                    Op::Get(key) => (key, "tinycloud.kv/get"),
                 };
                 let resource = (*space).clone().to_resource(
                     "kv".parse::<Service>().unwrap(),
@@ -1043,7 +1046,7 @@ pub(crate) mod tests {
             let (key, value, metadata) = match op {
                 Op::Put(key, value) => (key, value, &[][..]),
                 Op::PutMeta(key, value, metadata) => (key, value, *metadata),
-                Op::Del(_) => continue,
+                Op::Del(_) | Op::Get(_) => continue,
             };
             let mut stage = HashBuffer::new(Vec::new());
             stage.write_all(value).await.unwrap();
@@ -1077,6 +1080,46 @@ pub(crate) mod tests {
             .unwrap()
     }
 
+    /// TC-1317: with the read-audit drain held, a KV read answers busy at
+    /// its bound without returning data, while KV writes, which are not
+    /// audited reads, are unaffected.
+    #[tokio::test]
+    async fn tc1317_a_held_read_audit_bounds_reads_and_spares_writes() {
+        let db = sqlite_db().await;
+        db.set_read_audit_wait(std::time::Duration::from_millis(200));
+        let owner = Owner::generate();
+        host(&db, &owner).await;
+        run(&db, &owner, &[Op::Put("notes/a", b"a")]).await;
+
+        let held = db.read_audit_pipeline().hold_drain().await;
+        let read = tokio::time::timeout(
+            std::time::Duration::from_secs(10),
+            invoke(
+                &db,
+                &owner,
+                &[Op::Get("notes/a")],
+                KvInvokeOptions::default(),
+            ),
+        )
+        .await
+        .expect("a read must not wait past its bound");
+        let error = read.expect_err("a read whose audit is not confirmed must fail");
+        assert!(error.starts_with("read_audit_busy:"), "{error}");
+        tokio::time::timeout(
+            std::time::Duration::from_secs(10),
+            invoke(
+                &db,
+                &owner,
+                &[Op::Put("notes/b", b"b")],
+                KvInvokeOptions::default(),
+            ),
+        )
+        .await
+        .expect("a write does not wait on the read audit")
+        .unwrap();
+        drop(held);
+    }
+
     /// A delivered change: the key and its etag, `None` for a tombstone.
     pub(crate) type Delivered = (String, Option<Hash>);