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

.github/workflows/docker.yml

@@ -666,8 +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…), its single node digest normalized to 64 zeros.
-          n0_template_hash = '51f8e9e93edc0e16025d27ee42abe003ed5d1cf26ba8f437d5120894aca64bdb'
+          # cap (raw d95bfb70…) and TC-1274's Vector config (raw b25b8414…),
+          # its single node digest normalized to 64 zeros.
+          n0_template_hash = '009382266172b76ae1858aa79060da5f58ece66a758dd8fd876b96367d96e1db'
           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))
@@ -707,7 +708,6 @@ jobs:
           def require_release_descends(revision):
               if not re.fullmatch(r'[0-9a-f]{40}', running) or running == revision or not is_ancestor(running, revision):
                   raise SystemExit('::error::Released image must be a strict descendant of the running production revision; deployment not attempted')
-
           pre_n0_hash = 'df239749ca0a9c09893a855ae2a8abb94090b8556515ad002105c58ac91f4c91'
           pre_n0_template_hash = '28302d6761d841b7cc5c11314aed2d377735e6bbdcaf85972a752e03bc9fdc93'
           rollback = os.environ.get('ROLLBACK_PRE_N0') == 'true'

.gitignore

@@ -5,3 +5,4 @@
 .env
 bun.lockb
 bun.lock
+__pycache__/

CHANGELOG.md

@@ -2,6 +2,15 @@
 
 ## [Unreleased]
 
+- 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.
+  - **Request deadline.** `/invoke` has a deadline, `invocation.deadline_ms` (55 s, below the ingress's 60 s; `0` turns it off). A request that hasn't started a data write by then is stopped and answered `503 request_timeout: no change was applied; retry the request` with `Retry-After: 1`. A request that has started one (a KV write transaction, a SQL statement, a DuckDB statement or import, a meeting publication, a decrypt) completes and reports its real result, and the node logs `Request completed after its deadline`. The invocation's replay row is kept, so a retry must be a fresh invocation, which the SDK already sends for every call.
+  - **Write safety.** A SQL write and its durable save always finish together, even if the request is stopped while waiting.
+  - **Logging.** Typed warnings `SQL busy: lock wait|hydration|artifact transfer` (fields `error_class`, `stage`, `bound_ms`, `waited_ms`), `Database hydration gave up loading its artifact` and `Request deadline exceeded` (`stage`, `deadline_ms`) are new. The log shipper maps them to `sql_busy_*`, `sql_hydration_timeout`, `request_timeout` and `deadline_overrun`. The embedded Vector configuration is regenerated, so the reviewed N0 compose template changes to `00938226…` (raw `b25b8414…`; `docs/releasing.md`).
+  - **Not covered.** DuckDB's lock and hydration waits are still unbounded, and a DuckDB request is not cut by the deadline once it reaches the DuckDB service; this is unchanged from before (TC-1412). Disconnect detection is TC-1400, bounding SQLite statement execution is TC-1401, and bounding identity resolution's artifact read is TC-1403 (until then only the deadline bounds it).
+  - **Any write statement cut short counts as possibly applied.** A write statement (autocommit or `execute_idempotent`) whose future is dropped before its result arrives is now recorded as possibly applied, so the failure is reported as an unknown outcome instead of a safe retry.
+
 ## [1.21.0] - 2026-10-18
 
 ### Release notes

docs/releasing.md

@@ -309,12 +309,15 @@ 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
-  **`51f8e9e93edc0e16025d27ee42abe003ed5d1cf26ba8f437d5120894aca64bdb`**
-  (raw `d95bfb707871c1d626c4a8f2b8d32d354103edbb5077847c6a21fe5f7f6cfa50` normalized: the #349 compose
+  **`009382266172b76ae1858aa79060da5f58ece66a758dd8fd876b96367d96e1db`**
+  (raw `b25b8414c784ee7d66d6e3a507d3dba29818aca5cbf339e85bcb667e2316e20d` 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
   `c33c23021589163b62a71ef245b7194717711922027629f155bdd5cff806b8c7`, which
-  keeps `TINYCLOUD_EPOCH_HEAD_BACKFILL__ENABLED: "false"` and #346's Vector
-  config, with only `CLIENT_MAX_BODY_SIZE=32m` → `95m`). Ingress, socat,
-  Vector and the log profile stay byte-exact;
+  keeps `TINYCLOUD_EPOCH_HEAD_BACKFILL__ENABLED: "false"`, with only
+  `CLIENT_MAX_BODY_SIZE=32m` → `95m`). Ingress, socat, Vector and the log
+  profile stay byte-exact;
 - the deployed compose to differ from that template only by
   `deploy_image_digest`;
 - OCI labels `1.21.0-dstack` / `<release-commit-sha>`, the `v1.21.0` tag on
@@ -375,8 +378,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
-`d95bfb707871c1d626c4a8f2b8d32d354103edbb5077847c6a21fe5f7f6cfa50`
-(the #349 compose `c33c2302…` plus the 95m ingress body cap), whatever digest
+`b25b8414c784ee7d66d6e3a507d3dba29818aca5cbf339e85bcb667e2316e20d`
+(the 1.21.0 compose `d95bfb70…` with TC-1274's 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 | `d95bfb707871c1d626c4a8f2b8d32d354103edbb5077847c6a21fe5f7f6cfa50` (main's compose with only `CLIENT_MAX_BODY_SIZE=32m` → `95m`); node digest normalized, template `51f8e9e93edc0e16025d27ee42abe003ed5d1cf26ba8f437d5120894aca64bdb`. See [`docs/releasing.md`](../releasing.md#main-release-with-n0-log-shipping-one-dispatch) |
+| 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) |
 
 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": "76bd10752a52f179ac2a49214f488236d02f8192",
+  "revision": "5a8280c65c6417c02edb4ea7025d5593c65585f8",
   "path": "ops/logging/fields.json",
-  "sha256": "95944326fb37a7e7d3cddae16b0d8a722076d7dd9e20700ee565a73a9a567e15"
+  "sha256": "ac5e127a5a223ea32fa9cb1644b60315ff5c79abcf2f677a14fef7cb0c416437"
 }

log-shipper/cases.mjs

@@ -40,6 +40,9 @@ export const vectorTests = [
   check('known warning strips all free text', envelope({ timestamp, level: 'WARN', target: 'tinycloud::runtime', fields: { message: 'invalid link bind address; LAN listener not started', err: canary, bind: canary } }), '.event == "node_warning" && .event_code == "link_bind_invalid" && .event_count == 1'),
   check('unmatched warning becomes typed unclassified', envelope({ timestamp, level: 'WARN', target: 'tinycloud::tunnel::connection', fields: { message: canary, remote: canary } }), '.event == "node_warning" && .event_code == "unclassified" && .event_count == 1'),
   check('application error remains typed without error value', envelope({ timestamp, level: 'ERROR', target: 'tinycloud::share_email', fields: { message: 'native share KV put failed', failure: canary } }), '.event == "node_error" && .event_code == "share_native_kv_put_failed" && .event_count == 1'),
+  ...[['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'),
   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

@@ -47,7 +47,13 @@
     "tunnel: failed to record runtime state": "tunnel_state_record_failed",
     "tunnel: failed to clear runtime state after disable": "tunnel_state_clear_failed",
     "tunnel authentication rejected": "tunnel_auth_rejected",
-    "network DID resolution enabled: did:web/did:tz fetches use the unhardened ssi client (TC-1080)": "network_did_resolution_enabled"
+    "network DID resolution enabled: did:web/did:tz fetches use the unhardened ssi client (TC-1080)": "network_did_resolution_enabled",
+    "SQL busy: lock wait": "sql_busy_lock_wait",
+    "SQL busy: hydration": "sql_busy_hydration",
+    "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"
   },
   "prefix": {
     "dstack socket available but get_info failed: ": "dstack_get_info_failed",

log-shipper/fields.json

@@ -78,14 +78,15 @@
         "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"] },
+        "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_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 },
         "request_id": { "type": "string", "regex": "^[0-9a-f]{8}-[0-9a-f]{4}-[1-8][0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$", "max_len": 36 },
         "request_id_replaced": { "type": "boolean" },
         "account_hash": { "type": "string", "regex": "^[0-9a-f]{64}$", "max_len": 64 },
-        "space_hash": { "type": "string", "regex": "^[0-9a-f]{64}$", "max_len": 64 }
+        "space_hash": { "type": "string", "regex": "^[0-9a-f]{64}$", "max_len": 64 },
+        "db_hash": { "type": "string", "regex": "^[0-9a-f]{64}$", "max_len": 64 }
       }
     },
     "tinychat-backend": { "events": [], "fields": {} },

tinycloud-core/Cargo.toml

@@ -50,7 +50,7 @@ multihash-derive = "0.9"
 rusqlite.workspace = true
 sqlparser.workspace = true
 tracing.workspace = true
-tokio.workspace = true
+tokio = { workspace = true, features = ["sync", "time"] }
 duckdb = { version = "1.1", features = ["bundled", "appender-arrow"], optional = true }
 arrow = { version = "56", features = ["ipc"], optional = true }
 tempfile = "3"
@@ -84,6 +84,6 @@ unicode-normalization = "0.1"
 [dev-dependencies]
 sea-orm = { version = "1.1", features = ["runtime-tokio-rustls", "sqlx-sqlite"] }
 async-std = { version = "1", features = ["attributes"] }
-tokio.workspace = true
+tokio = { workspace = true, features = ["test-util"] }
 iri-string.workspace = true
 proptest = "1"

tinycloud-core/src/db.rs

@@ -2217,6 +2217,12 @@ where
             Some(lock) => Some(lock.lock().await),
             None => None,
         };
+        // TC-1274: the write transaction begins here, so the request deadline
+        // may no longer cut this request; it completes and reports its outcome.
+        // The handler task is never polled after a cut, so this is not
+        // refused here.
+        let latched = crate::request_cancel::latch();
+        debug_assert!(latched, "a cut handler is not polled again");
         let begin_start = Instant::now();
         let tx_result = self.begin_graph_transaction().await;
         crate::telemetry::observe_stage(