diff --git a/.github/workflows/docker.yml b/.github/workflows/docker.yml index 13e372c9..9cbf6335 100644 --- a/.github/workflows/docker.yml +++ b/.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' diff --git a/.gitignore b/.gitignore index d6f9bc58..475be5d7 100644 --- a/.gitignore +++ b/.gitignore @@ -5,3 +5,4 @@ .env bun.lockb bun.lock +__pycache__/ diff --git a/CHANGELOG.md b/CHANGELOG.md index f67c4401..046c264e 100644 --- a/CHANGELOG.md +++ b/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: : …` 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 diff --git a/docker-compose.dstack-postgres.yaml b/docker-compose.dstack-postgres.yaml index 535642ab..7041d572 100644 --- a/docker-compose.dstack-postgres.yaml +++ b/docker-compose.dstack-postgres.yaml @@ -164,7 +164,7 @@ services: environment: TINYCLOUD_LOGSHIP_PROFILE: ${TINYCLOUD_LOGSHIP_PROFILE:-errors_slow} BETTERSTACK_SOURCE_TOKEN: ${BETTERSTACK_SOURCE_TOKEN:?seal the node source token before enabling log shipping} - VECTOR_CONFIG_JSON: "{\"data_dir\":\"/var/lib/vector\",\"sources\":{\"gelf_in\":{\"type\":\"socket\",\"mode\":\"udp\",\"address\":\"0.0.0.0:12201\",\"max_length\":262144,\"receive_buffer_bytes\":8388608,\"framing\":{\"method\":\"chunked_gelf\",\"chunked_gelf\":{\"decompression\":\"Auto\"}},\"decoding\":{\"codec\":\"bytes\"}}},\"transforms\":{\"gelf_envelope\":{\"type\":\"remap\",\"inputs\":[\"gelf_in\"],\"source\":\"packet = string(.message) ?? \\\"\\\"\\nif length(packet) > 262144 {\\n . = {\\\"reason\\\": \\\"oversized\\\"}\\n} else {\\n outer, err = parse_json(packet)\\n if err != null || !is_object(outer) || (outer.version != \\\"1.1\\\" && outer.version != \\\"1.0\\\") {\\n . = {\\\"reason\\\": \\\"malformed_envelope\\\"}\\n } else if exists(outer.partial_message) || exists(outer._partial_message) {\\n . = {\\\"reason\\\": \\\"partial\\\"}\\n } else {\\n label = get(outer, [\\\"_tc.logship\\\"]) ?? null\\n . = {\\\"_tc.logship\\\": label, \\\"message\\\": outer.short_message}\\n }\\n}\",\"drop_on_error\":true,\"drop_on_abort\":true},\"logship_gate\":{\"type\":\"remap\",\"inputs\":[\"gelf_envelope\"],\"source\":\"if exists(.reason) {\\n . = {\\\"reason\\\": .reason}\\n} else {\\nlabel = string(get(., [\\\"_tc.logship\\\"]) ?? null) ?? \\\"\\\"\\nraw = .message\\nreason = \\\"\\\"\\nif label == \\\"\\\" { reason = \\\"unlabelled\\\" }\\nelse if !includes([\\\"tinycloud-node\\\", \\\"tinycloud-ingress\\\"], label) { reason = \\\"unexpected_label\\\" }\\nelse if exists(.partial_message) { reason = \\\"partial\\\" }\\nelse if !is_string(raw) { reason = \\\"malformed_envelope\\\" }\\nelse if length(string!(raw)) > 65536 { reason = \\\"oversized\\\" }\\nif reason != \\\"\\\" {\\n . = {\\\"reason\\\": reason}\\n} else {\\n parsed, err = parse_json(string!(raw))\\n if err != null || !is_object(parsed) { . = {\\\"reason\\\": \\\"non_json\\\"} }\\n else if exists(parsed.partial_message) { . = {\\\"reason\\\": \\\"partial\\\"} }\\n else {\\n target = string(parsed.target) ?? \\\"\\\"\\n level = downcase(string(parsed.level) ?? \\\"\\\")\\n if label == \\\"tinycloud-node\\\" && !includes([\\\"warn\\\", \\\"error\\\"], level) && target != \\\"tinycloud\\\" && !starts_with(target, \\\"tinycloud::\\\") && target != \\\"tinycloud_core\\\" && !starts_with(target, \\\"tinycloud_core::\\\") {\\n . = {\\\"reason\\\": \\\"unknown_target\\\"}\\n } else if label == \\\"tinycloud-node\\\" && !includes([\\\"warn\\\", \\\"error\\\"], level) && (target != \\\"tinycloud::request\\\" || level != \\\"info\\\") {\\n . = {\\\"reason\\\": \\\"filtered_level\\\"}\\n } else { . = {\\\"label\\\": label, \\\"parsed\\\": parsed} }\\n }\\n}\\n}\",\"drop_on_error\":true,\"drop_on_abort\":true},\"gate_route\":{\"type\":\"route\",\"inputs\":[\"logship_gate\"],\"route\":{\"candidate\":\"exists(.parsed)\",\"rejected\":\"exists(.reason)\"}},\"allowlist\":{\"type\":\"remap\",\"inputs\":[\"gate_route.candidate\"],\"source\":\"# Only this fresh object can leave the process boundary. No envelope, span,\\n# message, error, identity, URI or unknown key is copied into it.\\nj = .parsed\\nlabel = .label\\nout = {}\\nts = \\\"\\\"\\nif label == \\\"tinycloud-node\\\" {\\n target = string(j.target) ?? \\\"\\\"\\n level = downcase(string!(j.level))\\n f = object(j.fields) ?? {}\\n msg = string(f.message) ?? \\\"\\\"\\n ts = string!(j.timestamp)\\n if target == \\\"tinycloud::request\\\" && level == \\\"info\\\" && msg == \\\"request\\\" {\\n method = string!(f.method)\\n if includes([\\\"TRACE\\\", \\\"CONNECT\\\"], method) { method = \\\"\\\" }\\n route = string!(f.route)\\n # Literal Rocket template aliases only; never split an arbitrary URI.\\n aliases = {\\\"/attestation?\\\":\\\"/attestation\\\",\\\"/.well-known/encryption/network/?\\\":\\\"/.well-known/encryption/network/\\\",\\\"/hooks/events?\\\":\\\"/hooks/events\\\",\\\"/hooks/webhooks?\\\":\\\"/hooks/webhooks\\\",\\\"/public//kv?\\\":\\\"/public//kv\\\"}\\n canonical_route = get(aliases, [route]) ?? null\\n if is_string(canonical_route) { route = canonical_route }\\n if !includes([\\\"GET\\\",\\\"HEAD\\\",\\\"POST\\\",\\\"PUT\\\",\\\"PATCH\\\",\\\"DELETE\\\",\\\"OPTIONS\\\",\\\"\\\"], method) || !includes([\\\"/healthz\\\",\\\"/info\\\",\\\"/version\\\",\\\"/invoke\\\",\\\"/delegate\\\",\\\"/revoke\\\",\\\"/attestation\\\",\\\"/signed/kv\\\",\\\"/signed/kv/\\\",\\\"/admin/quota\\\",\\\"/admin/quota/\\\",\\\"/admin/usage\\\",\\\"/hooks/events\\\",\\\"/hooks/tickets\\\",\\\"/hooks/webhooks\\\",\\\"/hooks/webhooks/\\\",\\\"/delegation/query\\\",\\\"/delegation/status\\\",\\\"/encryption/networks\\\",\\\"/encryption/networks/\\\",\\\"/encryption/networks//revoke\\\",\\\"/encryption/networks//decrypt\\\",\\\"/policy/v3/status\\\",\\\"/policy/v3/status/\\\",\\\"/policy/v3/policies\\\",\\\"/policy/v3/challenges\\\",\\\"/policy/v3/delegations\\\",\\\"/policy/v3/enforcer-bindings\\\",\\\"/policy/v3/deliveries/authorize\\\",\\\"/.well-known/tinycloud/node-keys\\\",\\\"/.well-known/encryption/network/\\\",\\\"/public//kv\\\",\\\"/public//kv/\\\",\\\"/peer/generate/\\\",\\\"/evidences/\\\",\\\"/share/v2/readiness\\\",\\\"/share/v2/policies\\\",\\\"/share/v2/policy/challenges\\\",\\\"/share/v2/policy/session\\\",\\\"/share/v2/invoke\\\",\\\"/share/v2/deliveries/authorize\\\",\\\"/<_s..>\\\",\\\"/public/<_space_id>/kv/<_key..>\\\",\\\"\\\"], route) { abort }\\n status = f.status\\n latency = f.latency_us\\n if !is_integer(status) || !is_integer(latency) { abort }\\n status = int!(status)\\n latency = int!(latency)\\n if status < 100 || status > 599 || latency < 0 || latency > 9007199254740991 { abort }\\n out = {\\\"event\\\": \\\"node_request\\\", \\\"svc\\\": \\\"api\\\", \\\"level\\\": \\\"info\\\", \\\"method\\\": method, \\\"route\\\": route, \\\"status\\\": status, \\\"latency_us\\\": latency}\\n # N2 correlation fields: copied only when they have exactly the node's emitted shape; anything else is dropped\\n # (the event still ships). The pseudonyms are keyed HMAC-SHA256 digests, never raw identifiers.\\n rid = string(f.request_id) ?? \\\"\\\"\\n if match(rid, r'^[0-9a-f]{8}-[0-9a-f]{4}-[1-8][0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$') { out.request_id = rid }\\n replaced = f.request_id_replaced\\n if is_boolean(replaced) { out.request_id_replaced = replaced }\\n account = string(f.account_hash) ?? \\\"\\\"\\n if match(account, r'^[0-9a-f]{64}$') { out.account_hash = account }\\n space = string(f.space_hash) ?? \\\"\\\"\\n if match(space, r'^[0-9a-f]{64}$') { out.space_hash = space }\\n } else {\\n if !includes([\\\"warn\\\", \\\"error\\\"], level) { abort }\\n code = \\\"unclassified\\\"\\n if target == \\\"tinycloud\\\" || starts_with(target, \\\"tinycloud::\\\") || target == \\\"tinycloud_core\\\" || starts_with(target, \\\"tinycloud_core::\\\") {\\n codes = {\\\"invocation replay insert failed\\\":\\\"invocation_replay_insert_failed\\\",\\\"invocation replay cleanup failed\\\":\\\"invocation_replay_cleanup_failed\\\",\\\"share-v2 local-tee feature active: deriving a deterministic, non-attested TEE identity from node key material\\\":\\\"share_local_tee_identity\\\",\\\"retention: delivered hook delivery prune failed\\\":\\\"retention_hook_delivery_prune_failed\\\",\\\"retention: dead-letter hook delivery prune failed\\\":\\\"retention_dead_letter_prune_failed\\\",\\\"retention: signed KV ticket prune failed\\\":\\\"retention_signed_ticket_prune_failed\\\",\\\"failed to load tunnel state; tunnel not started\\\":\\\"tunnel_state_load_failed\\\",\\\"invalid loopback API address; tunnel not started\\\":\\\"tunnel_address_invalid\\\",\\\"failed to load link state; LAN listener not started\\\":\\\"link_state_load_failed\\\",\\\"invalid link bind address; LAN listener not started\\\":\\\"link_bind_invalid\\\",\\\"invalid loopback API address; LAN listener not started\\\":\\\"link_address_invalid\\\",\\\"failed to bind link LAN listener; LAN listener not started\\\":\\\"link_bind_failed\\\",\\\"failed to build TLS config; LAN listener not started\\\":\\\"link_tls_config_failed\\\",\\\"link LAN listener exited with error\\\":\\\"link_listener_error\\\",\\\"failed to record link listener bind state\\\":\\\"link_listener_state_write_failed\\\",\\\"failed to record link listener bind failure\\\":\\\"link_bind_state_write_failed\\\",\\\"failed to load config for auto-renew\\\":\\\"link_auto_renew_config_failed\\\",\\\"link auto-renew failed\\\":\\\"link_auto_renew_failed\\\",\\\"failed to hot-reload renewed link cert\\\":\\\"link_cert_reload_failed\\\",\\\"link auto-renew succeeded but no state.json found; skipping cert hot-reload\\\":\\\"link_cert_state_missing\\\",\\\"failed to reload TLS material after link auto-renew\\\":\\\"link_listener_cert_reload_failed\\\",\\\"link disable: service delete failed; local state removed anyway\\\":\\\"link_disable_failed\\\",\\\"link connection error\\\":\\\"link_connection_error\\\",\\\"link listener accept error\\\":\\\"link_listener_accept_failed\\\",\\\"webhook delivery attempt failed\\\":\\\"webhook_delivery_failed\\\",\\\"webhook dispatcher loop failed\\\":\\\"webhook_dispatcher_failed\\\",\\\"addressed delegation authorization failed\\\":\\\"share_authorization_failed\\\",\\\"native share authorization denied\\\":\\\"share_native_authorization_denied\\\",\\\"native share KV put failed\\\":\\\"share_native_kv_put_failed\\\",\\\"share v2 readiness probe failed\\\":\\\"share_v2_readiness_failed\\\",\\\"share v2 is enabled but shareEmail.invitationPublicKey is unset\\\":\\\"share_invitation_key_missing\\\",\\\"configured share invitation key does not match the node's derived signing key\\\":\\\"share_invitation_key_mismatch\\\",\\\"share/v2 policy challenge denied\\\":\\\"share_policy_denied\\\",\\\"failed to read committed hook events\\\":\\\"hook_events_read_failed\\\",\\\"failed to load kv write hook rows\\\":\\\"hook_rows_load_failed\\\",\\\"failed to load kv delete hook rows\\\":\\\"hook_rows_load_failed\\\",\\\"missing committed kv hook row for invocation\\\":\\\"missing_committed_hook_row\\\",\\\"database write committed but webhook enqueue failed\\\":\\\"webhook_enqueue_failed\\\",\\\"tunnel: failed to prepare connection attempt\\\":\\\"tunnel_connection_prepare_failed\\\",\\\"tunnel: no frame within idle timeout; treating connection as dead\\\":\\\"tunnel_idle_timeout\\\",\\\"tunnel: read error\\\":\\\"tunnel_read_failed\\\",\\\"tunnel: dropping malformed frame\\\":\\\"tunnel_malformed_frame\\\",\\\"tunnel: relay sent an error frame\\\":\\\"tunnel_relay_error\\\",\\\"tunnel: failed to write frame\\\":\\\"tunnel_write_failed\\\",\\\"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\\\"}\\n known = get(codes, [msg]) ?? null\\n if is_string(known) { code = known }\\n if starts_with(msg, \\\"quota service returned \\\") { code = \\\"quota_fallback\\\" }\\nif starts_with(msg, \\\"Failed to get TDX quote: \\\") { code = \\\"attestation_quote_failed\\\" }\\nif starts_with(msg, \\\"quota service returned an invalid body: \\\") { code = \\\"quota_invalid_body\\\" }\\nif starts_with(msg, \\\"dstack socket available but get_info failed: \\\") { code = \\\"dstack_get_info_failed\\\" }\\n }\\n event = if level == \\\"warn\\\" { \\\"node_warning\\\" } else { \\\"node_error\\\" }\\n out = {\\\"event\\\": event, \\\"svc\\\": \\\"api\\\", \\\"level\\\": level, \\\"event_code\\\": code, \\\"event_count\\\": 1}\\n }\\n} else {\\n ts = string!(j.time)\\n method = string!(j.method)\\n route = string!(j.route)\\n if route == \\\"\\\" { route = \\\"\\\" }\\n if !includes([\\\"GET\\\",\\\"HEAD\\\",\\\"POST\\\",\\\"PUT\\\",\\\"PATCH\\\",\\\"DELETE\\\",\\\"OPTIONS\\\",\\\"\\\"], method) || !includes([\\\"/healthz\\\",\\\"/info\\\",\\\"/version\\\",\\\"/invoke\\\",\\\"/delegate\\\",\\\"/revoke\\\",\\\"/attestation\\\",\\\"/signed/kv\\\",\\\"/signed/kv/\\\",\\\"/admin/quota\\\",\\\"/admin/quota/\\\",\\\"/admin/usage\\\",\\\"/hooks/events\\\",\\\"/hooks/tickets\\\",\\\"/hooks/webhooks\\\",\\\"/hooks/webhooks/\\\",\\\"/delegation/query\\\",\\\"/delegation/status\\\",\\\"/encryption/networks\\\",\\\"/encryption/networks/\\\",\\\"/encryption/networks//revoke\\\",\\\"/encryption/networks//decrypt\\\",\\\"/policy/v3/status\\\",\\\"/policy/v3/status/\\\",\\\"/policy/v3/policies\\\",\\\"/policy/v3/challenges\\\",\\\"/policy/v3/delegations\\\",\\\"/policy/v3/enforcer-bindings\\\",\\\"/policy/v3/deliveries/authorize\\\",\\\"/.well-known/tinycloud/node-keys\\\",\\\"/.well-known/encryption/network/\\\",\\\"/public//kv\\\",\\\"/public//kv/\\\",\\\"/peer/generate/\\\",\\\"/evidences/\\\",\\\"/share/v2/readiness\\\",\\\"/share/v2/policies\\\",\\\"/share/v2/policy/challenges\\\",\\\"/share/v2/policy/session\\\",\\\"/share/v2/invoke\\\",\\\"/share/v2/deliveries/authorize\\\",\\\"/<_s..>\\\",\\\"/public/<_space_id>/kv/<_key..>\\\",\\\"\\\"], route) { abort }\\n status = j.status\\n request_time = j.request_time\\n if !is_integer(status) || !(is_integer(request_time) || is_float(request_time)) { abort }\\n status = int!(status)\\n request_time = to_float!(request_time)\\n if status < 100 || status > 599 || request_time < 0 || request_time > 86400 { abort }\\n out = {\\\"event\\\": \\\"ingress_request\\\", \\\"svc\\\": \\\"ingress\\\", \\\"level\\\": \\\"info\\\", \\\"method\\\": method, \\\"route\\\": route, \\\"status\\\": status, \\\"request_time_seconds\\\": request_time}\\n}\\nif length(ts) > 64 { abort }\\nparsed_ts = parse_timestamp!(ts, format: \\\"%+\\\")\\nout.ts = format_timestamp!(parsed_ts, format: \\\"%Y-%m-%dT%H:%M:%S%.3fZ\\\")\\n. = out\\n\",\"drop_on_error\":true,\"drop_on_abort\":true,\"reroute_dropped\":true},\"gate_counts\":{\"type\":\"remap\",\"inputs\":[\"gate_route.rejected\",\"gate_route._unmatched\",\"allowlist.dropped\",\"event_route._unmatched\"],\"source\":\"reason = .reason\\nif !includes([\\\"malformed_envelope\\\",\\\"unexpected_label\\\",\\\"unlabelled\\\",\\\"non_json\\\",\\\"oversized\\\",\\\"partial\\\",\\\"invalid_fields\\\",\\\"unknown_target\\\",\\\"filtered_level\\\"], reason) { reason = \\\"invalid_fields\\\" }\\n. = {\\\"reason\\\": reason, \\\"count\\\": 1}\",\"drop_on_error\":true,\"drop_on_abort\":true},\"gate_reduce\":{\"type\":\"reduce\",\"inputs\":[\"gate_counts\"],\"group_by\":[\"reason\"],\"end_every_period_ms\":60000,\"expire_after_ms\":75000,\"flush_period_ms\":1000,\"merge_strategies\":{\"count\":\"sum\"}},\"gate_output\":{\"type\":\"remap\",\"inputs\":[\"gate_reduce\"],\"source\":\". = {\\\"ts\\\": format_timestamp!(now(), format: \\\"%Y-%m-%dT%H:%M:%S%.3fZ\\\"), \\\"level\\\": \\\"warn\\\", \\\"event\\\": \\\"logship_gate_summary_total\\\", \\\"svc\\\": \\\"logship\\\", \\\"reason\\\": .reason, \\\"count\\\": .count}\",\"drop_on_error\":true,\"drop_on_abort\":true},\"request_profile\":{\"type\":\"filter\",\"inputs\":[\"allowlist\"],\"condition\":\"\\\"$${TINYCLOUD_LOGSHIP_PROFILE}\\\" == \\\"all_requests\\\" || includes([\\\"node_warning\\\", \\\"node_error\\\"], .event) || (int(.status) ?? 0) >= 400 || (.event == \\\"node_request\\\" && (int(.latency_us) ?? 0) > 1000000) || (.event == \\\"ingress_request\\\" && (to_float(.request_time_seconds) ?? 0.0) > 1.000000)\"},\"event_route\":{\"type\":\"route\",\"inputs\":[\"request_profile\"],\"route\":{\"request\":\".event == \\\"node_request\\\" || .event == \\\"ingress_request\\\"\",\"diagnostic\":\".event == \\\"node_warning\\\" || .event == \\\"node_error\\\"\"}},\"diagnostic_reduce\":{\"type\":\"reduce\",\"inputs\":[\"event_route.diagnostic\"],\"group_by\":[\"event\",\"event_code\",\"level\",\"svc\"],\"end_every_period_ms\":60000,\"expire_after_ms\":75000,\"flush_period_ms\":1000,\"merge_strategies\":{\"event_count\":\"sum\",\"ts\":\"discard\"}},\"diagnostic_output\":{\"type\":\"remap\",\"inputs\":[\"diagnostic_reduce\"],\"source\":\". = {\\\"ts\\\": format_timestamp!(now(), format: \\\"%Y-%m-%dT%H:%M:%S%.3fZ\\\"), \\\"level\\\": .level, \\\"event\\\": .event, \\\"svc\\\": \\\"api\\\", \\\"event_code\\\": .event_code, \\\"event_count\\\": .event_count}\",\"drop_on_error\":true,\"drop_on_abort\":true}},\"sinks\":{\"betterstack\":{\"type\":\"http\",\"inputs\":[\"event_route.request\",\"diagnostic_output\",\"gate_output\"],\"method\":\"post\",\"uri\":\"https://s2795437.us-west-2a.betterstackdata.com/\",\"encoding\":{\"codec\":\"json\"},\"framing\":{\"method\":\"newline_delimited\"},\"compression\":\"gzip\",\"auth\":{\"strategy\":\"bearer\",\"token\":\"SECRET[bs.bs_token]\"},\"batch\":{\"max_bytes\":262144,\"timeout_secs\":1},\"buffer\":{\"type\":\"memory\",\"max_events\":1000,\"when_full\":\"block\"},\"request\":{\"timeout_secs\":10,\"retry_max_duration_secs\":300},\"healthcheck\":{\"enabled\":false}}},\"secret\":{\"bs\":{\"type\":\"directory\",\"path\":\"/var/lib/vector/secrets\",\"remove_trailing_whitespace\":true}}}" + VECTOR_CONFIG_JSON: "{\"data_dir\":\"/var/lib/vector\",\"sources\":{\"gelf_in\":{\"type\":\"socket\",\"mode\":\"udp\",\"address\":\"0.0.0.0:12201\",\"max_length\":262144,\"receive_buffer_bytes\":8388608,\"framing\":{\"method\":\"chunked_gelf\",\"chunked_gelf\":{\"decompression\":\"Auto\"}},\"decoding\":{\"codec\":\"bytes\"}}},\"transforms\":{\"gelf_envelope\":{\"type\":\"remap\",\"inputs\":[\"gelf_in\"],\"source\":\"packet = string(.message) ?? \\\"\\\"\\nif length(packet) > 262144 {\\n . = {\\\"reason\\\": \\\"oversized\\\"}\\n} else {\\n outer, err = parse_json(packet)\\n if err != null || !is_object(outer) || (outer.version != \\\"1.1\\\" && outer.version != \\\"1.0\\\") {\\n . = {\\\"reason\\\": \\\"malformed_envelope\\\"}\\n } else if exists(outer.partial_message) || exists(outer._partial_message) {\\n . = {\\\"reason\\\": \\\"partial\\\"}\\n } else {\\n label = get(outer, [\\\"_tc.logship\\\"]) ?? null\\n . = {\\\"_tc.logship\\\": label, \\\"message\\\": outer.short_message}\\n }\\n}\",\"drop_on_error\":true,\"drop_on_abort\":true},\"logship_gate\":{\"type\":\"remap\",\"inputs\":[\"gelf_envelope\"],\"source\":\"if exists(.reason) {\\n . = {\\\"reason\\\": .reason}\\n} else {\\nlabel = string(get(., [\\\"_tc.logship\\\"]) ?? null) ?? \\\"\\\"\\nraw = .message\\nreason = \\\"\\\"\\nif label == \\\"\\\" { reason = \\\"unlabelled\\\" }\\nelse if !includes([\\\"tinycloud-node\\\", \\\"tinycloud-ingress\\\"], label) { reason = \\\"unexpected_label\\\" }\\nelse if exists(.partial_message) { reason = \\\"partial\\\" }\\nelse if !is_string(raw) { reason = \\\"malformed_envelope\\\" }\\nelse if length(string!(raw)) > 65536 { reason = \\\"oversized\\\" }\\nif reason != \\\"\\\" {\\n . = {\\\"reason\\\": reason}\\n} else {\\n parsed, err = parse_json(string!(raw))\\n if err != null || !is_object(parsed) { . = {\\\"reason\\\": \\\"non_json\\\"} }\\n else if exists(parsed.partial_message) { . = {\\\"reason\\\": \\\"partial\\\"} }\\n else {\\n target = string(parsed.target) ?? \\\"\\\"\\n level = downcase(string(parsed.level) ?? \\\"\\\")\\n if label == \\\"tinycloud-node\\\" && !includes([\\\"warn\\\", \\\"error\\\"], level) && target != \\\"tinycloud\\\" && !starts_with(target, \\\"tinycloud::\\\") && target != \\\"tinycloud_core\\\" && !starts_with(target, \\\"tinycloud_core::\\\") {\\n . = {\\\"reason\\\": \\\"unknown_target\\\"}\\n } else if label == \\\"tinycloud-node\\\" && !includes([\\\"warn\\\", \\\"error\\\"], level) && (target != \\\"tinycloud::request\\\" || level != \\\"info\\\") {\\n . = {\\\"reason\\\": \\\"filtered_level\\\"}\\n } else { . = {\\\"label\\\": label, \\\"parsed\\\": parsed} }\\n }\\n}\\n}\",\"drop_on_error\":true,\"drop_on_abort\":true},\"gate_route\":{\"type\":\"route\",\"inputs\":[\"logship_gate\"],\"route\":{\"candidate\":\"exists(.parsed)\",\"rejected\":\"exists(.reason)\"}},\"allowlist\":{\"type\":\"remap\",\"inputs\":[\"gate_route.candidate\"],\"source\":\"# Only this fresh object can leave the process boundary. No envelope, span,\\n# message, error, identity, URI or unknown key is copied into it.\\nj = .parsed\\nlabel = .label\\nout = {}\\nts = \\\"\\\"\\nif label == \\\"tinycloud-node\\\" {\\n target = string(j.target) ?? \\\"\\\"\\n level = downcase(string!(j.level))\\n f = object(j.fields) ?? {}\\n msg = string(f.message) ?? \\\"\\\"\\n ts = string!(j.timestamp)\\n if target == \\\"tinycloud::request\\\" && level == \\\"info\\\" && msg == \\\"request\\\" {\\n method = string!(f.method)\\n if includes([\\\"TRACE\\\", \\\"CONNECT\\\"], method) { method = \\\"\\\" }\\n route = string!(f.route)\\n # Literal Rocket template aliases only; never split an arbitrary URI.\\n aliases = {\\\"/attestation?\\\":\\\"/attestation\\\",\\\"/.well-known/encryption/network/?\\\":\\\"/.well-known/encryption/network/\\\",\\\"/hooks/events?\\\":\\\"/hooks/events\\\",\\\"/hooks/webhooks?\\\":\\\"/hooks/webhooks\\\",\\\"/public//kv?\\\":\\\"/public//kv\\\"}\\n canonical_route = get(aliases, [route]) ?? null\\n if is_string(canonical_route) { route = canonical_route }\\n if !includes([\\\"GET\\\",\\\"HEAD\\\",\\\"POST\\\",\\\"PUT\\\",\\\"PATCH\\\",\\\"DELETE\\\",\\\"OPTIONS\\\",\\\"\\\"], method) || !includes([\\\"/healthz\\\",\\\"/info\\\",\\\"/version\\\",\\\"/invoke\\\",\\\"/delegate\\\",\\\"/revoke\\\",\\\"/attestation\\\",\\\"/signed/kv\\\",\\\"/signed/kv/\\\",\\\"/admin/quota\\\",\\\"/admin/quota/\\\",\\\"/admin/usage\\\",\\\"/hooks/events\\\",\\\"/hooks/tickets\\\",\\\"/hooks/webhooks\\\",\\\"/hooks/webhooks/\\\",\\\"/delegation/query\\\",\\\"/delegation/status\\\",\\\"/encryption/networks\\\",\\\"/encryption/networks/\\\",\\\"/encryption/networks//revoke\\\",\\\"/encryption/networks//decrypt\\\",\\\"/policy/v3/status\\\",\\\"/policy/v3/status/\\\",\\\"/policy/v3/policies\\\",\\\"/policy/v3/challenges\\\",\\\"/policy/v3/delegations\\\",\\\"/policy/v3/enforcer-bindings\\\",\\\"/policy/v3/deliveries/authorize\\\",\\\"/.well-known/tinycloud/node-keys\\\",\\\"/.well-known/encryption/network/\\\",\\\"/public//kv\\\",\\\"/public//kv/\\\",\\\"/peer/generate/\\\",\\\"/evidences/\\\",\\\"/share/v2/readiness\\\",\\\"/share/v2/policies\\\",\\\"/share/v2/policy/challenges\\\",\\\"/share/v2/policy/session\\\",\\\"/share/v2/invoke\\\",\\\"/share/v2/deliveries/authorize\\\",\\\"/<_s..>\\\",\\\"/public/<_space_id>/kv/<_key..>\\\",\\\"\\\"], route) { abort }\\n status = f.status\\n latency = f.latency_us\\n if !is_integer(status) || !is_integer(latency) { abort }\\n status = int!(status)\\n latency = int!(latency)\\n if status < 100 || status > 599 || latency < 0 || latency > 9007199254740991 { abort }\\n out = {\\\"event\\\": \\\"node_request\\\", \\\"svc\\\": \\\"api\\\", \\\"level\\\": \\\"info\\\", \\\"method\\\": method, \\\"route\\\": route, \\\"status\\\": status, \\\"latency_us\\\": latency}\\n # N2 correlation fields: copied only when they have exactly the node's emitted shape; anything else is dropped\\n # (the event still ships). The pseudonyms are keyed HMAC-SHA256 digests, never raw identifiers.\\n rid = string(f.request_id) ?? \\\"\\\"\\n if match(rid, r'^[0-9a-f]{8}-[0-9a-f]{4}-[1-8][0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$') { out.request_id = rid }\\n replaced = f.request_id_replaced\\n if is_boolean(replaced) { out.request_id_replaced = replaced }\\n account = string(f.account_hash) ?? \\\"\\\"\\n if match(account, r'^[0-9a-f]{64}$') { out.account_hash = account }\\n space = string(f.space_hash) ?? \\\"\\\"\\n if match(space, r'^[0-9a-f]{64}$') { out.space_hash = space }\\n } else {\\n if !includes([\\\"warn\\\", \\\"error\\\"], level) { abort }\\n code = \\\"unclassified\\\"\\n if target == \\\"tinycloud\\\" || starts_with(target, \\\"tinycloud::\\\") || target == \\\"tinycloud_core\\\" || starts_with(target, \\\"tinycloud_core::\\\") {\\n codes = {\\\"invocation replay insert failed\\\":\\\"invocation_replay_insert_failed\\\",\\\"invocation replay cleanup failed\\\":\\\"invocation_replay_cleanup_failed\\\",\\\"share-v2 local-tee feature active: deriving a deterministic, non-attested TEE identity from node key material\\\":\\\"share_local_tee_identity\\\",\\\"retention: delivered hook delivery prune failed\\\":\\\"retention_hook_delivery_prune_failed\\\",\\\"retention: dead-letter hook delivery prune failed\\\":\\\"retention_dead_letter_prune_failed\\\",\\\"retention: signed KV ticket prune failed\\\":\\\"retention_signed_ticket_prune_failed\\\",\\\"failed to load tunnel state; tunnel not started\\\":\\\"tunnel_state_load_failed\\\",\\\"invalid loopback API address; tunnel not started\\\":\\\"tunnel_address_invalid\\\",\\\"failed to load link state; LAN listener not started\\\":\\\"link_state_load_failed\\\",\\\"invalid link bind address; LAN listener not started\\\":\\\"link_bind_invalid\\\",\\\"invalid loopback API address; LAN listener not started\\\":\\\"link_address_invalid\\\",\\\"failed to bind link LAN listener; LAN listener not started\\\":\\\"link_bind_failed\\\",\\\"failed to build TLS config; LAN listener not started\\\":\\\"link_tls_config_failed\\\",\\\"link LAN listener exited with error\\\":\\\"link_listener_error\\\",\\\"failed to record link listener bind state\\\":\\\"link_listener_state_write_failed\\\",\\\"failed to record link listener bind failure\\\":\\\"link_bind_state_write_failed\\\",\\\"failed to load config for auto-renew\\\":\\\"link_auto_renew_config_failed\\\",\\\"link auto-renew failed\\\":\\\"link_auto_renew_failed\\\",\\\"failed to hot-reload renewed link cert\\\":\\\"link_cert_reload_failed\\\",\\\"link auto-renew succeeded but no state.json found; skipping cert hot-reload\\\":\\\"link_cert_state_missing\\\",\\\"failed to reload TLS material after link auto-renew\\\":\\\"link_listener_cert_reload_failed\\\",\\\"link disable: service delete failed; local state removed anyway\\\":\\\"link_disable_failed\\\",\\\"link connection error\\\":\\\"link_connection_error\\\",\\\"link listener accept error\\\":\\\"link_listener_accept_failed\\\",\\\"webhook delivery attempt failed\\\":\\\"webhook_delivery_failed\\\",\\\"webhook dispatcher loop failed\\\":\\\"webhook_dispatcher_failed\\\",\\\"addressed delegation authorization failed\\\":\\\"share_authorization_failed\\\",\\\"native share authorization denied\\\":\\\"share_native_authorization_denied\\\",\\\"native share KV put failed\\\":\\\"share_native_kv_put_failed\\\",\\\"share v2 readiness probe failed\\\":\\\"share_v2_readiness_failed\\\",\\\"share v2 is enabled but shareEmail.invitationPublicKey is unset\\\":\\\"share_invitation_key_missing\\\",\\\"configured share invitation key does not match the node's derived signing key\\\":\\\"share_invitation_key_mismatch\\\",\\\"share/v2 policy challenge denied\\\":\\\"share_policy_denied\\\",\\\"failed to read committed hook events\\\":\\\"hook_events_read_failed\\\",\\\"failed to load kv write hook rows\\\":\\\"hook_rows_load_failed\\\",\\\"failed to load kv delete hook rows\\\":\\\"hook_rows_load_failed\\\",\\\"missing committed kv hook row for invocation\\\":\\\"missing_committed_hook_row\\\",\\\"database write committed but webhook enqueue failed\\\":\\\"webhook_enqueue_failed\\\",\\\"tunnel: failed to prepare connection attempt\\\":\\\"tunnel_connection_prepare_failed\\\",\\\"tunnel: no frame within idle timeout; treating connection as dead\\\":\\\"tunnel_idle_timeout\\\",\\\"tunnel: read error\\\":\\\"tunnel_read_failed\\\",\\\"tunnel: dropping malformed frame\\\":\\\"tunnel_malformed_frame\\\",\\\"tunnel: relay sent an error frame\\\":\\\"tunnel_relay_error\\\",\\\"tunnel: failed to write frame\\\":\\\"tunnel_write_failed\\\",\\\"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\\\",\\\"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\\\"}\\n known = get(codes, [msg]) ?? null\\n if is_string(known) { code = known }\\n if starts_with(msg, \\\"quota service returned \\\") { code = \\\"quota_fallback\\\" }\\nif starts_with(msg, \\\"Failed to get TDX quote: \\\") { code = \\\"attestation_quote_failed\\\" }\\nif starts_with(msg, \\\"quota service returned an invalid body: \\\") { code = \\\"quota_invalid_body\\\" }\\nif starts_with(msg, \\\"dstack socket available but get_info failed: \\\") { code = \\\"dstack_get_info_failed\\\" }\\n }\\n event = if level == \\\"warn\\\" { \\\"node_warning\\\" } else { \\\"node_error\\\" }\\n out = {\\\"event\\\": event, \\\"svc\\\": \\\"api\\\", \\\"level\\\": level, \\\"event_code\\\": code, \\\"event_count\\\": 1}\\n }\\n} else {\\n ts = string!(j.time)\\n method = string!(j.method)\\n route = string!(j.route)\\n if route == \\\"\\\" { route = \\\"\\\" }\\n if !includes([\\\"GET\\\",\\\"HEAD\\\",\\\"POST\\\",\\\"PUT\\\",\\\"PATCH\\\",\\\"DELETE\\\",\\\"OPTIONS\\\",\\\"\\\"], method) || !includes([\\\"/healthz\\\",\\\"/info\\\",\\\"/version\\\",\\\"/invoke\\\",\\\"/delegate\\\",\\\"/revoke\\\",\\\"/attestation\\\",\\\"/signed/kv\\\",\\\"/signed/kv/\\\",\\\"/admin/quota\\\",\\\"/admin/quota/\\\",\\\"/admin/usage\\\",\\\"/hooks/events\\\",\\\"/hooks/tickets\\\",\\\"/hooks/webhooks\\\",\\\"/hooks/webhooks/\\\",\\\"/delegation/query\\\",\\\"/delegation/status\\\",\\\"/encryption/networks\\\",\\\"/encryption/networks/\\\",\\\"/encryption/networks//revoke\\\",\\\"/encryption/networks//decrypt\\\",\\\"/policy/v3/status\\\",\\\"/policy/v3/status/\\\",\\\"/policy/v3/policies\\\",\\\"/policy/v3/challenges\\\",\\\"/policy/v3/delegations\\\",\\\"/policy/v3/enforcer-bindings\\\",\\\"/policy/v3/deliveries/authorize\\\",\\\"/.well-known/tinycloud/node-keys\\\",\\\"/.well-known/encryption/network/\\\",\\\"/public//kv\\\",\\\"/public//kv/\\\",\\\"/peer/generate/\\\",\\\"/evidences/\\\",\\\"/share/v2/readiness\\\",\\\"/share/v2/policies\\\",\\\"/share/v2/policy/challenges\\\",\\\"/share/v2/policy/session\\\",\\\"/share/v2/invoke\\\",\\\"/share/v2/deliveries/authorize\\\",\\\"/<_s..>\\\",\\\"/public/<_space_id>/kv/<_key..>\\\",\\\"\\\"], route) { abort }\\n status = j.status\\n request_time = j.request_time\\n if !is_integer(status) || !(is_integer(request_time) || is_float(request_time)) { abort }\\n status = int!(status)\\n request_time = to_float!(request_time)\\n if status < 100 || status > 599 || request_time < 0 || request_time > 86400 { abort }\\n out = {\\\"event\\\": \\\"ingress_request\\\", \\\"svc\\\": \\\"ingress\\\", \\\"level\\\": \\\"info\\\", \\\"method\\\": method, \\\"route\\\": route, \\\"status\\\": status, \\\"request_time_seconds\\\": request_time}\\n}\\nif length(ts) > 64 { abort }\\nparsed_ts = parse_timestamp!(ts, format: \\\"%+\\\")\\nout.ts = format_timestamp!(parsed_ts, format: \\\"%Y-%m-%dT%H:%M:%S%.3fZ\\\")\\n. = out\\n\",\"drop_on_error\":true,\"drop_on_abort\":true,\"reroute_dropped\":true},\"gate_counts\":{\"type\":\"remap\",\"inputs\":[\"gate_route.rejected\",\"gate_route._unmatched\",\"allowlist.dropped\",\"event_route._unmatched\"],\"source\":\"reason = .reason\\nif !includes([\\\"malformed_envelope\\\",\\\"unexpected_label\\\",\\\"unlabelled\\\",\\\"non_json\\\",\\\"oversized\\\",\\\"partial\\\",\\\"invalid_fields\\\",\\\"unknown_target\\\",\\\"filtered_level\\\"], reason) { reason = \\\"invalid_fields\\\" }\\n. = {\\\"reason\\\": reason, \\\"count\\\": 1}\",\"drop_on_error\":true,\"drop_on_abort\":true},\"gate_reduce\":{\"type\":\"reduce\",\"inputs\":[\"gate_counts\"],\"group_by\":[\"reason\"],\"end_every_period_ms\":60000,\"expire_after_ms\":75000,\"flush_period_ms\":1000,\"merge_strategies\":{\"count\":\"sum\"}},\"gate_output\":{\"type\":\"remap\",\"inputs\":[\"gate_reduce\"],\"source\":\". = {\\\"ts\\\": format_timestamp!(now(), format: \\\"%Y-%m-%dT%H:%M:%S%.3fZ\\\"), \\\"level\\\": \\\"warn\\\", \\\"event\\\": \\\"logship_gate_summary_total\\\", \\\"svc\\\": \\\"logship\\\", \\\"reason\\\": .reason, \\\"count\\\": .count}\",\"drop_on_error\":true,\"drop_on_abort\":true},\"request_profile\":{\"type\":\"filter\",\"inputs\":[\"allowlist\"],\"condition\":\"\\\"$${TINYCLOUD_LOGSHIP_PROFILE}\\\" == \\\"all_requests\\\" || includes([\\\"node_warning\\\", \\\"node_error\\\"], .event) || (int(.status) ?? 0) >= 400 || (.event == \\\"node_request\\\" && (int(.latency_us) ?? 0) > 1000000) || (.event == \\\"ingress_request\\\" && (to_float(.request_time_seconds) ?? 0.0) > 1.000000)\"},\"event_route\":{\"type\":\"route\",\"inputs\":[\"request_profile\"],\"route\":{\"request\":\".event == \\\"node_request\\\" || .event == \\\"ingress_request\\\"\",\"diagnostic\":\".event == \\\"node_warning\\\" || .event == \\\"node_error\\\"\"}},\"diagnostic_reduce\":{\"type\":\"reduce\",\"inputs\":[\"event_route.diagnostic\"],\"group_by\":[\"event\",\"event_code\",\"level\",\"svc\"],\"end_every_period_ms\":60000,\"expire_after_ms\":75000,\"flush_period_ms\":1000,\"merge_strategies\":{\"event_count\":\"sum\",\"ts\":\"discard\"}},\"diagnostic_output\":{\"type\":\"remap\",\"inputs\":[\"diagnostic_reduce\"],\"source\":\". = {\\\"ts\\\": format_timestamp!(now(), format: \\\"%Y-%m-%dT%H:%M:%S%.3fZ\\\"), \\\"level\\\": .level, \\\"event\\\": .event, \\\"svc\\\": \\\"api\\\", \\\"event_code\\\": .event_code, \\\"event_count\\\": .event_count}\",\"drop_on_error\":true,\"drop_on_abort\":true}},\"sinks\":{\"betterstack\":{\"type\":\"http\",\"inputs\":[\"event_route.request\",\"diagnostic_output\",\"gate_output\"],\"method\":\"post\",\"uri\":\"https://s2795437.us-west-2a.betterstackdata.com/\",\"encoding\":{\"codec\":\"json\"},\"framing\":{\"method\":\"newline_delimited\"},\"compression\":\"gzip\",\"auth\":{\"strategy\":\"bearer\",\"token\":\"SECRET[bs.bs_token]\"},\"batch\":{\"max_bytes\":262144,\"timeout_secs\":1},\"buffer\":{\"type\":\"memory\",\"max_events\":1000,\"when_full\":\"block\"},\"request\":{\"timeout_secs\":10,\"retry_max_duration_secs\":300},\"healthcheck\":{\"enabled\":false}}},\"secret\":{\"bs\":{\"type\":\"directory\",\"path\":\"/var/lib/vector/secrets\",\"remove_trailing_whitespace\":true}}}" entrypoint: - /bin/sh - -ec diff --git a/docs/releasing.md b/docs/releasing.md index ca9b5e80..8e496571 100644 --- a/docs/releasing.md +++ b/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` / ``, 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 diff --git a/docs/runbooks/tc-959-n0-log-shipping.md b/docs/runbooks/tc-959-n0-log-shipping.md index 8a23367a..b9ee8997 100644 --- a/docs/runbooks/tc-959-n0-log-shipping.md +++ b/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. diff --git a/log-shipper/canonical.json b/log-shipper/canonical.json index afeb3816..0a0cfd6c 100644 --- a/log-shipper/canonical.json +++ b/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" } diff --git a/log-shipper/cases.mjs b/log-shipper/cases.mjs index 37e01583..e53a95da 100644 --- a/log-shipper/cases.mjs +++ b/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'), diff --git a/log-shipper/diagnostics.json b/log-shipper/diagnostics.json index 1c4cd00c..faa08ef7 100644 --- a/log-shipper/diagnostics.json +++ b/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", diff --git a/log-shipper/fields.json b/log-shipper/fields.json index b56b6e1d..32e30759 100644 --- a/log-shipper/fields.json +++ b/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": {} }, diff --git a/scripts/ci/fixtures/tc959-n0-compose.yaml b/scripts/ci/fixtures/tc959-n0-compose.yaml index 535642ab..7041d572 100644 --- a/scripts/ci/fixtures/tc959-n0-compose.yaml +++ b/scripts/ci/fixtures/tc959-n0-compose.yaml @@ -164,7 +164,7 @@ services: environment: TINYCLOUD_LOGSHIP_PROFILE: ${TINYCLOUD_LOGSHIP_PROFILE:-errors_slow} BETTERSTACK_SOURCE_TOKEN: ${BETTERSTACK_SOURCE_TOKEN:?seal the node source token before enabling log shipping} - VECTOR_CONFIG_JSON: "{\"data_dir\":\"/var/lib/vector\",\"sources\":{\"gelf_in\":{\"type\":\"socket\",\"mode\":\"udp\",\"address\":\"0.0.0.0:12201\",\"max_length\":262144,\"receive_buffer_bytes\":8388608,\"framing\":{\"method\":\"chunked_gelf\",\"chunked_gelf\":{\"decompression\":\"Auto\"}},\"decoding\":{\"codec\":\"bytes\"}}},\"transforms\":{\"gelf_envelope\":{\"type\":\"remap\",\"inputs\":[\"gelf_in\"],\"source\":\"packet = string(.message) ?? \\\"\\\"\\nif length(packet) > 262144 {\\n . = {\\\"reason\\\": \\\"oversized\\\"}\\n} else {\\n outer, err = parse_json(packet)\\n if err != null || !is_object(outer) || (outer.version != \\\"1.1\\\" && outer.version != \\\"1.0\\\") {\\n . = {\\\"reason\\\": \\\"malformed_envelope\\\"}\\n } else if exists(outer.partial_message) || exists(outer._partial_message) {\\n . = {\\\"reason\\\": \\\"partial\\\"}\\n } else {\\n label = get(outer, [\\\"_tc.logship\\\"]) ?? null\\n . = {\\\"_tc.logship\\\": label, \\\"message\\\": outer.short_message}\\n }\\n}\",\"drop_on_error\":true,\"drop_on_abort\":true},\"logship_gate\":{\"type\":\"remap\",\"inputs\":[\"gelf_envelope\"],\"source\":\"if exists(.reason) {\\n . = {\\\"reason\\\": .reason}\\n} else {\\nlabel = string(get(., [\\\"_tc.logship\\\"]) ?? null) ?? \\\"\\\"\\nraw = .message\\nreason = \\\"\\\"\\nif label == \\\"\\\" { reason = \\\"unlabelled\\\" }\\nelse if !includes([\\\"tinycloud-node\\\", \\\"tinycloud-ingress\\\"], label) { reason = \\\"unexpected_label\\\" }\\nelse if exists(.partial_message) { reason = \\\"partial\\\" }\\nelse if !is_string(raw) { reason = \\\"malformed_envelope\\\" }\\nelse if length(string!(raw)) > 65536 { reason = \\\"oversized\\\" }\\nif reason != \\\"\\\" {\\n . = {\\\"reason\\\": reason}\\n} else {\\n parsed, err = parse_json(string!(raw))\\n if err != null || !is_object(parsed) { . = {\\\"reason\\\": \\\"non_json\\\"} }\\n else if exists(parsed.partial_message) { . = {\\\"reason\\\": \\\"partial\\\"} }\\n else {\\n target = string(parsed.target) ?? \\\"\\\"\\n level = downcase(string(parsed.level) ?? \\\"\\\")\\n if label == \\\"tinycloud-node\\\" && !includes([\\\"warn\\\", \\\"error\\\"], level) && target != \\\"tinycloud\\\" && !starts_with(target, \\\"tinycloud::\\\") && target != \\\"tinycloud_core\\\" && !starts_with(target, \\\"tinycloud_core::\\\") {\\n . = {\\\"reason\\\": \\\"unknown_target\\\"}\\n } else if label == \\\"tinycloud-node\\\" && !includes([\\\"warn\\\", \\\"error\\\"], level) && (target != \\\"tinycloud::request\\\" || level != \\\"info\\\") {\\n . = {\\\"reason\\\": \\\"filtered_level\\\"}\\n } else { . = {\\\"label\\\": label, \\\"parsed\\\": parsed} }\\n }\\n}\\n}\",\"drop_on_error\":true,\"drop_on_abort\":true},\"gate_route\":{\"type\":\"route\",\"inputs\":[\"logship_gate\"],\"route\":{\"candidate\":\"exists(.parsed)\",\"rejected\":\"exists(.reason)\"}},\"allowlist\":{\"type\":\"remap\",\"inputs\":[\"gate_route.candidate\"],\"source\":\"# Only this fresh object can leave the process boundary. No envelope, span,\\n# message, error, identity, URI or unknown key is copied into it.\\nj = .parsed\\nlabel = .label\\nout = {}\\nts = \\\"\\\"\\nif label == \\\"tinycloud-node\\\" {\\n target = string(j.target) ?? \\\"\\\"\\n level = downcase(string!(j.level))\\n f = object(j.fields) ?? {}\\n msg = string(f.message) ?? \\\"\\\"\\n ts = string!(j.timestamp)\\n if target == \\\"tinycloud::request\\\" && level == \\\"info\\\" && msg == \\\"request\\\" {\\n method = string!(f.method)\\n if includes([\\\"TRACE\\\", \\\"CONNECT\\\"], method) { method = \\\"\\\" }\\n route = string!(f.route)\\n # Literal Rocket template aliases only; never split an arbitrary URI.\\n aliases = {\\\"/attestation?\\\":\\\"/attestation\\\",\\\"/.well-known/encryption/network/?\\\":\\\"/.well-known/encryption/network/\\\",\\\"/hooks/events?\\\":\\\"/hooks/events\\\",\\\"/hooks/webhooks?\\\":\\\"/hooks/webhooks\\\",\\\"/public//kv?\\\":\\\"/public//kv\\\"}\\n canonical_route = get(aliases, [route]) ?? null\\n if is_string(canonical_route) { route = canonical_route }\\n if !includes([\\\"GET\\\",\\\"HEAD\\\",\\\"POST\\\",\\\"PUT\\\",\\\"PATCH\\\",\\\"DELETE\\\",\\\"OPTIONS\\\",\\\"\\\"], method) || !includes([\\\"/healthz\\\",\\\"/info\\\",\\\"/version\\\",\\\"/invoke\\\",\\\"/delegate\\\",\\\"/revoke\\\",\\\"/attestation\\\",\\\"/signed/kv\\\",\\\"/signed/kv/\\\",\\\"/admin/quota\\\",\\\"/admin/quota/\\\",\\\"/admin/usage\\\",\\\"/hooks/events\\\",\\\"/hooks/tickets\\\",\\\"/hooks/webhooks\\\",\\\"/hooks/webhooks/\\\",\\\"/delegation/query\\\",\\\"/delegation/status\\\",\\\"/encryption/networks\\\",\\\"/encryption/networks/\\\",\\\"/encryption/networks//revoke\\\",\\\"/encryption/networks//decrypt\\\",\\\"/policy/v3/status\\\",\\\"/policy/v3/status/\\\",\\\"/policy/v3/policies\\\",\\\"/policy/v3/challenges\\\",\\\"/policy/v3/delegations\\\",\\\"/policy/v3/enforcer-bindings\\\",\\\"/policy/v3/deliveries/authorize\\\",\\\"/.well-known/tinycloud/node-keys\\\",\\\"/.well-known/encryption/network/\\\",\\\"/public//kv\\\",\\\"/public//kv/\\\",\\\"/peer/generate/\\\",\\\"/evidences/\\\",\\\"/share/v2/readiness\\\",\\\"/share/v2/policies\\\",\\\"/share/v2/policy/challenges\\\",\\\"/share/v2/policy/session\\\",\\\"/share/v2/invoke\\\",\\\"/share/v2/deliveries/authorize\\\",\\\"/<_s..>\\\",\\\"/public/<_space_id>/kv/<_key..>\\\",\\\"\\\"], route) { abort }\\n status = f.status\\n latency = f.latency_us\\n if !is_integer(status) || !is_integer(latency) { abort }\\n status = int!(status)\\n latency = int!(latency)\\n if status < 100 || status > 599 || latency < 0 || latency > 9007199254740991 { abort }\\n out = {\\\"event\\\": \\\"node_request\\\", \\\"svc\\\": \\\"api\\\", \\\"level\\\": \\\"info\\\", \\\"method\\\": method, \\\"route\\\": route, \\\"status\\\": status, \\\"latency_us\\\": latency}\\n # N2 correlation fields: copied only when they have exactly the node's emitted shape; anything else is dropped\\n # (the event still ships). The pseudonyms are keyed HMAC-SHA256 digests, never raw identifiers.\\n rid = string(f.request_id) ?? \\\"\\\"\\n if match(rid, r'^[0-9a-f]{8}-[0-9a-f]{4}-[1-8][0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$') { out.request_id = rid }\\n replaced = f.request_id_replaced\\n if is_boolean(replaced) { out.request_id_replaced = replaced }\\n account = string(f.account_hash) ?? \\\"\\\"\\n if match(account, r'^[0-9a-f]{64}$') { out.account_hash = account }\\n space = string(f.space_hash) ?? \\\"\\\"\\n if match(space, r'^[0-9a-f]{64}$') { out.space_hash = space }\\n } else {\\n if !includes([\\\"warn\\\", \\\"error\\\"], level) { abort }\\n code = \\\"unclassified\\\"\\n if target == \\\"tinycloud\\\" || starts_with(target, \\\"tinycloud::\\\") || target == \\\"tinycloud_core\\\" || starts_with(target, \\\"tinycloud_core::\\\") {\\n codes = {\\\"invocation replay insert failed\\\":\\\"invocation_replay_insert_failed\\\",\\\"invocation replay cleanup failed\\\":\\\"invocation_replay_cleanup_failed\\\",\\\"share-v2 local-tee feature active: deriving a deterministic, non-attested TEE identity from node key material\\\":\\\"share_local_tee_identity\\\",\\\"retention: delivered hook delivery prune failed\\\":\\\"retention_hook_delivery_prune_failed\\\",\\\"retention: dead-letter hook delivery prune failed\\\":\\\"retention_dead_letter_prune_failed\\\",\\\"retention: signed KV ticket prune failed\\\":\\\"retention_signed_ticket_prune_failed\\\",\\\"failed to load tunnel state; tunnel not started\\\":\\\"tunnel_state_load_failed\\\",\\\"invalid loopback API address; tunnel not started\\\":\\\"tunnel_address_invalid\\\",\\\"failed to load link state; LAN listener not started\\\":\\\"link_state_load_failed\\\",\\\"invalid link bind address; LAN listener not started\\\":\\\"link_bind_invalid\\\",\\\"invalid loopback API address; LAN listener not started\\\":\\\"link_address_invalid\\\",\\\"failed to bind link LAN listener; LAN listener not started\\\":\\\"link_bind_failed\\\",\\\"failed to build TLS config; LAN listener not started\\\":\\\"link_tls_config_failed\\\",\\\"link LAN listener exited with error\\\":\\\"link_listener_error\\\",\\\"failed to record link listener bind state\\\":\\\"link_listener_state_write_failed\\\",\\\"failed to record link listener bind failure\\\":\\\"link_bind_state_write_failed\\\",\\\"failed to load config for auto-renew\\\":\\\"link_auto_renew_config_failed\\\",\\\"link auto-renew failed\\\":\\\"link_auto_renew_failed\\\",\\\"failed to hot-reload renewed link cert\\\":\\\"link_cert_reload_failed\\\",\\\"link auto-renew succeeded but no state.json found; skipping cert hot-reload\\\":\\\"link_cert_state_missing\\\",\\\"failed to reload TLS material after link auto-renew\\\":\\\"link_listener_cert_reload_failed\\\",\\\"link disable: service delete failed; local state removed anyway\\\":\\\"link_disable_failed\\\",\\\"link connection error\\\":\\\"link_connection_error\\\",\\\"link listener accept error\\\":\\\"link_listener_accept_failed\\\",\\\"webhook delivery attempt failed\\\":\\\"webhook_delivery_failed\\\",\\\"webhook dispatcher loop failed\\\":\\\"webhook_dispatcher_failed\\\",\\\"addressed delegation authorization failed\\\":\\\"share_authorization_failed\\\",\\\"native share authorization denied\\\":\\\"share_native_authorization_denied\\\",\\\"native share KV put failed\\\":\\\"share_native_kv_put_failed\\\",\\\"share v2 readiness probe failed\\\":\\\"share_v2_readiness_failed\\\",\\\"share v2 is enabled but shareEmail.invitationPublicKey is unset\\\":\\\"share_invitation_key_missing\\\",\\\"configured share invitation key does not match the node's derived signing key\\\":\\\"share_invitation_key_mismatch\\\",\\\"share/v2 policy challenge denied\\\":\\\"share_policy_denied\\\",\\\"failed to read committed hook events\\\":\\\"hook_events_read_failed\\\",\\\"failed to load kv write hook rows\\\":\\\"hook_rows_load_failed\\\",\\\"failed to load kv delete hook rows\\\":\\\"hook_rows_load_failed\\\",\\\"missing committed kv hook row for invocation\\\":\\\"missing_committed_hook_row\\\",\\\"database write committed but webhook enqueue failed\\\":\\\"webhook_enqueue_failed\\\",\\\"tunnel: failed to prepare connection attempt\\\":\\\"tunnel_connection_prepare_failed\\\",\\\"tunnel: no frame within idle timeout; treating connection as dead\\\":\\\"tunnel_idle_timeout\\\",\\\"tunnel: read error\\\":\\\"tunnel_read_failed\\\",\\\"tunnel: dropping malformed frame\\\":\\\"tunnel_malformed_frame\\\",\\\"tunnel: relay sent an error frame\\\":\\\"tunnel_relay_error\\\",\\\"tunnel: failed to write frame\\\":\\\"tunnel_write_failed\\\",\\\"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\\\"}\\n known = get(codes, [msg]) ?? null\\n if is_string(known) { code = known }\\n if starts_with(msg, \\\"quota service returned \\\") { code = \\\"quota_fallback\\\" }\\nif starts_with(msg, \\\"Failed to get TDX quote: \\\") { code = \\\"attestation_quote_failed\\\" }\\nif starts_with(msg, \\\"quota service returned an invalid body: \\\") { code = \\\"quota_invalid_body\\\" }\\nif starts_with(msg, \\\"dstack socket available but get_info failed: \\\") { code = \\\"dstack_get_info_failed\\\" }\\n }\\n event = if level == \\\"warn\\\" { \\\"node_warning\\\" } else { \\\"node_error\\\" }\\n out = {\\\"event\\\": event, \\\"svc\\\": \\\"api\\\", \\\"level\\\": level, \\\"event_code\\\": code, \\\"event_count\\\": 1}\\n }\\n} else {\\n ts = string!(j.time)\\n method = string!(j.method)\\n route = string!(j.route)\\n if route == \\\"\\\" { route = \\\"\\\" }\\n if !includes([\\\"GET\\\",\\\"HEAD\\\",\\\"POST\\\",\\\"PUT\\\",\\\"PATCH\\\",\\\"DELETE\\\",\\\"OPTIONS\\\",\\\"\\\"], method) || !includes([\\\"/healthz\\\",\\\"/info\\\",\\\"/version\\\",\\\"/invoke\\\",\\\"/delegate\\\",\\\"/revoke\\\",\\\"/attestation\\\",\\\"/signed/kv\\\",\\\"/signed/kv/\\\",\\\"/admin/quota\\\",\\\"/admin/quota/\\\",\\\"/admin/usage\\\",\\\"/hooks/events\\\",\\\"/hooks/tickets\\\",\\\"/hooks/webhooks\\\",\\\"/hooks/webhooks/\\\",\\\"/delegation/query\\\",\\\"/delegation/status\\\",\\\"/encryption/networks\\\",\\\"/encryption/networks/\\\",\\\"/encryption/networks//revoke\\\",\\\"/encryption/networks//decrypt\\\",\\\"/policy/v3/status\\\",\\\"/policy/v3/status/\\\",\\\"/policy/v3/policies\\\",\\\"/policy/v3/challenges\\\",\\\"/policy/v3/delegations\\\",\\\"/policy/v3/enforcer-bindings\\\",\\\"/policy/v3/deliveries/authorize\\\",\\\"/.well-known/tinycloud/node-keys\\\",\\\"/.well-known/encryption/network/\\\",\\\"/public//kv\\\",\\\"/public//kv/\\\",\\\"/peer/generate/\\\",\\\"/evidences/\\\",\\\"/share/v2/readiness\\\",\\\"/share/v2/policies\\\",\\\"/share/v2/policy/challenges\\\",\\\"/share/v2/policy/session\\\",\\\"/share/v2/invoke\\\",\\\"/share/v2/deliveries/authorize\\\",\\\"/<_s..>\\\",\\\"/public/<_space_id>/kv/<_key..>\\\",\\\"\\\"], route) { abort }\\n status = j.status\\n request_time = j.request_time\\n if !is_integer(status) || !(is_integer(request_time) || is_float(request_time)) { abort }\\n status = int!(status)\\n request_time = to_float!(request_time)\\n if status < 100 || status > 599 || request_time < 0 || request_time > 86400 { abort }\\n out = {\\\"event\\\": \\\"ingress_request\\\", \\\"svc\\\": \\\"ingress\\\", \\\"level\\\": \\\"info\\\", \\\"method\\\": method, \\\"route\\\": route, \\\"status\\\": status, \\\"request_time_seconds\\\": request_time}\\n}\\nif length(ts) > 64 { abort }\\nparsed_ts = parse_timestamp!(ts, format: \\\"%+\\\")\\nout.ts = format_timestamp!(parsed_ts, format: \\\"%Y-%m-%dT%H:%M:%S%.3fZ\\\")\\n. = out\\n\",\"drop_on_error\":true,\"drop_on_abort\":true,\"reroute_dropped\":true},\"gate_counts\":{\"type\":\"remap\",\"inputs\":[\"gate_route.rejected\",\"gate_route._unmatched\",\"allowlist.dropped\",\"event_route._unmatched\"],\"source\":\"reason = .reason\\nif !includes([\\\"malformed_envelope\\\",\\\"unexpected_label\\\",\\\"unlabelled\\\",\\\"non_json\\\",\\\"oversized\\\",\\\"partial\\\",\\\"invalid_fields\\\",\\\"unknown_target\\\",\\\"filtered_level\\\"], reason) { reason = \\\"invalid_fields\\\" }\\n. = {\\\"reason\\\": reason, \\\"count\\\": 1}\",\"drop_on_error\":true,\"drop_on_abort\":true},\"gate_reduce\":{\"type\":\"reduce\",\"inputs\":[\"gate_counts\"],\"group_by\":[\"reason\"],\"end_every_period_ms\":60000,\"expire_after_ms\":75000,\"flush_period_ms\":1000,\"merge_strategies\":{\"count\":\"sum\"}},\"gate_output\":{\"type\":\"remap\",\"inputs\":[\"gate_reduce\"],\"source\":\". = {\\\"ts\\\": format_timestamp!(now(), format: \\\"%Y-%m-%dT%H:%M:%S%.3fZ\\\"), \\\"level\\\": \\\"warn\\\", \\\"event\\\": \\\"logship_gate_summary_total\\\", \\\"svc\\\": \\\"logship\\\", \\\"reason\\\": .reason, \\\"count\\\": .count}\",\"drop_on_error\":true,\"drop_on_abort\":true},\"request_profile\":{\"type\":\"filter\",\"inputs\":[\"allowlist\"],\"condition\":\"\\\"$${TINYCLOUD_LOGSHIP_PROFILE}\\\" == \\\"all_requests\\\" || includes([\\\"node_warning\\\", \\\"node_error\\\"], .event) || (int(.status) ?? 0) >= 400 || (.event == \\\"node_request\\\" && (int(.latency_us) ?? 0) > 1000000) || (.event == \\\"ingress_request\\\" && (to_float(.request_time_seconds) ?? 0.0) > 1.000000)\"},\"event_route\":{\"type\":\"route\",\"inputs\":[\"request_profile\"],\"route\":{\"request\":\".event == \\\"node_request\\\" || .event == \\\"ingress_request\\\"\",\"diagnostic\":\".event == \\\"node_warning\\\" || .event == \\\"node_error\\\"\"}},\"diagnostic_reduce\":{\"type\":\"reduce\",\"inputs\":[\"event_route.diagnostic\"],\"group_by\":[\"event\",\"event_code\",\"level\",\"svc\"],\"end_every_period_ms\":60000,\"expire_after_ms\":75000,\"flush_period_ms\":1000,\"merge_strategies\":{\"event_count\":\"sum\",\"ts\":\"discard\"}},\"diagnostic_output\":{\"type\":\"remap\",\"inputs\":[\"diagnostic_reduce\"],\"source\":\". = {\\\"ts\\\": format_timestamp!(now(), format: \\\"%Y-%m-%dT%H:%M:%S%.3fZ\\\"), \\\"level\\\": .level, \\\"event\\\": .event, \\\"svc\\\": \\\"api\\\", \\\"event_code\\\": .event_code, \\\"event_count\\\": .event_count}\",\"drop_on_error\":true,\"drop_on_abort\":true}},\"sinks\":{\"betterstack\":{\"type\":\"http\",\"inputs\":[\"event_route.request\",\"diagnostic_output\",\"gate_output\"],\"method\":\"post\",\"uri\":\"https://s2795437.us-west-2a.betterstackdata.com/\",\"encoding\":{\"codec\":\"json\"},\"framing\":{\"method\":\"newline_delimited\"},\"compression\":\"gzip\",\"auth\":{\"strategy\":\"bearer\",\"token\":\"SECRET[bs.bs_token]\"},\"batch\":{\"max_bytes\":262144,\"timeout_secs\":1},\"buffer\":{\"type\":\"memory\",\"max_events\":1000,\"when_full\":\"block\"},\"request\":{\"timeout_secs\":10,\"retry_max_duration_secs\":300},\"healthcheck\":{\"enabled\":false}}},\"secret\":{\"bs\":{\"type\":\"directory\",\"path\":\"/var/lib/vector/secrets\",\"remove_trailing_whitespace\":true}}}" + VECTOR_CONFIG_JSON: "{\"data_dir\":\"/var/lib/vector\",\"sources\":{\"gelf_in\":{\"type\":\"socket\",\"mode\":\"udp\",\"address\":\"0.0.0.0:12201\",\"max_length\":262144,\"receive_buffer_bytes\":8388608,\"framing\":{\"method\":\"chunked_gelf\",\"chunked_gelf\":{\"decompression\":\"Auto\"}},\"decoding\":{\"codec\":\"bytes\"}}},\"transforms\":{\"gelf_envelope\":{\"type\":\"remap\",\"inputs\":[\"gelf_in\"],\"source\":\"packet = string(.message) ?? \\\"\\\"\\nif length(packet) > 262144 {\\n . = {\\\"reason\\\": \\\"oversized\\\"}\\n} else {\\n outer, err = parse_json(packet)\\n if err != null || !is_object(outer) || (outer.version != \\\"1.1\\\" && outer.version != \\\"1.0\\\") {\\n . = {\\\"reason\\\": \\\"malformed_envelope\\\"}\\n } else if exists(outer.partial_message) || exists(outer._partial_message) {\\n . = {\\\"reason\\\": \\\"partial\\\"}\\n } else {\\n label = get(outer, [\\\"_tc.logship\\\"]) ?? null\\n . = {\\\"_tc.logship\\\": label, \\\"message\\\": outer.short_message}\\n }\\n}\",\"drop_on_error\":true,\"drop_on_abort\":true},\"logship_gate\":{\"type\":\"remap\",\"inputs\":[\"gelf_envelope\"],\"source\":\"if exists(.reason) {\\n . = {\\\"reason\\\": .reason}\\n} else {\\nlabel = string(get(., [\\\"_tc.logship\\\"]) ?? null) ?? \\\"\\\"\\nraw = .message\\nreason = \\\"\\\"\\nif label == \\\"\\\" { reason = \\\"unlabelled\\\" }\\nelse if !includes([\\\"tinycloud-node\\\", \\\"tinycloud-ingress\\\"], label) { reason = \\\"unexpected_label\\\" }\\nelse if exists(.partial_message) { reason = \\\"partial\\\" }\\nelse if !is_string(raw) { reason = \\\"malformed_envelope\\\" }\\nelse if length(string!(raw)) > 65536 { reason = \\\"oversized\\\" }\\nif reason != \\\"\\\" {\\n . = {\\\"reason\\\": reason}\\n} else {\\n parsed, err = parse_json(string!(raw))\\n if err != null || !is_object(parsed) { . = {\\\"reason\\\": \\\"non_json\\\"} }\\n else if exists(parsed.partial_message) { . = {\\\"reason\\\": \\\"partial\\\"} }\\n else {\\n target = string(parsed.target) ?? \\\"\\\"\\n level = downcase(string(parsed.level) ?? \\\"\\\")\\n if label == \\\"tinycloud-node\\\" && !includes([\\\"warn\\\", \\\"error\\\"], level) && target != \\\"tinycloud\\\" && !starts_with(target, \\\"tinycloud::\\\") && target != \\\"tinycloud_core\\\" && !starts_with(target, \\\"tinycloud_core::\\\") {\\n . = {\\\"reason\\\": \\\"unknown_target\\\"}\\n } else if label == \\\"tinycloud-node\\\" && !includes([\\\"warn\\\", \\\"error\\\"], level) && (target != \\\"tinycloud::request\\\" || level != \\\"info\\\") {\\n . = {\\\"reason\\\": \\\"filtered_level\\\"}\\n } else { . = {\\\"label\\\": label, \\\"parsed\\\": parsed} }\\n }\\n}\\n}\",\"drop_on_error\":true,\"drop_on_abort\":true},\"gate_route\":{\"type\":\"route\",\"inputs\":[\"logship_gate\"],\"route\":{\"candidate\":\"exists(.parsed)\",\"rejected\":\"exists(.reason)\"}},\"allowlist\":{\"type\":\"remap\",\"inputs\":[\"gate_route.candidate\"],\"source\":\"# Only this fresh object can leave the process boundary. No envelope, span,\\n# message, error, identity, URI or unknown key is copied into it.\\nj = .parsed\\nlabel = .label\\nout = {}\\nts = \\\"\\\"\\nif label == \\\"tinycloud-node\\\" {\\n target = string(j.target) ?? \\\"\\\"\\n level = downcase(string!(j.level))\\n f = object(j.fields) ?? {}\\n msg = string(f.message) ?? \\\"\\\"\\n ts = string!(j.timestamp)\\n if target == \\\"tinycloud::request\\\" && level == \\\"info\\\" && msg == \\\"request\\\" {\\n method = string!(f.method)\\n if includes([\\\"TRACE\\\", \\\"CONNECT\\\"], method) { method = \\\"\\\" }\\n route = string!(f.route)\\n # Literal Rocket template aliases only; never split an arbitrary URI.\\n aliases = {\\\"/attestation?\\\":\\\"/attestation\\\",\\\"/.well-known/encryption/network/?\\\":\\\"/.well-known/encryption/network/\\\",\\\"/hooks/events?\\\":\\\"/hooks/events\\\",\\\"/hooks/webhooks?\\\":\\\"/hooks/webhooks\\\",\\\"/public//kv?\\\":\\\"/public//kv\\\"}\\n canonical_route = get(aliases, [route]) ?? null\\n if is_string(canonical_route) { route = canonical_route }\\n if !includes([\\\"GET\\\",\\\"HEAD\\\",\\\"POST\\\",\\\"PUT\\\",\\\"PATCH\\\",\\\"DELETE\\\",\\\"OPTIONS\\\",\\\"\\\"], method) || !includes([\\\"/healthz\\\",\\\"/info\\\",\\\"/version\\\",\\\"/invoke\\\",\\\"/delegate\\\",\\\"/revoke\\\",\\\"/attestation\\\",\\\"/signed/kv\\\",\\\"/signed/kv/\\\",\\\"/admin/quota\\\",\\\"/admin/quota/\\\",\\\"/admin/usage\\\",\\\"/hooks/events\\\",\\\"/hooks/tickets\\\",\\\"/hooks/webhooks\\\",\\\"/hooks/webhooks/\\\",\\\"/delegation/query\\\",\\\"/delegation/status\\\",\\\"/encryption/networks\\\",\\\"/encryption/networks/\\\",\\\"/encryption/networks//revoke\\\",\\\"/encryption/networks//decrypt\\\",\\\"/policy/v3/status\\\",\\\"/policy/v3/status/\\\",\\\"/policy/v3/policies\\\",\\\"/policy/v3/challenges\\\",\\\"/policy/v3/delegations\\\",\\\"/policy/v3/enforcer-bindings\\\",\\\"/policy/v3/deliveries/authorize\\\",\\\"/.well-known/tinycloud/node-keys\\\",\\\"/.well-known/encryption/network/\\\",\\\"/public//kv\\\",\\\"/public//kv/\\\",\\\"/peer/generate/\\\",\\\"/evidences/\\\",\\\"/share/v2/readiness\\\",\\\"/share/v2/policies\\\",\\\"/share/v2/policy/challenges\\\",\\\"/share/v2/policy/session\\\",\\\"/share/v2/invoke\\\",\\\"/share/v2/deliveries/authorize\\\",\\\"/<_s..>\\\",\\\"/public/<_space_id>/kv/<_key..>\\\",\\\"\\\"], route) { abort }\\n status = f.status\\n latency = f.latency_us\\n if !is_integer(status) || !is_integer(latency) { abort }\\n status = int!(status)\\n latency = int!(latency)\\n if status < 100 || status > 599 || latency < 0 || latency > 9007199254740991 { abort }\\n out = {\\\"event\\\": \\\"node_request\\\", \\\"svc\\\": \\\"api\\\", \\\"level\\\": \\\"info\\\", \\\"method\\\": method, \\\"route\\\": route, \\\"status\\\": status, \\\"latency_us\\\": latency}\\n # N2 correlation fields: copied only when they have exactly the node's emitted shape; anything else is dropped\\n # (the event still ships). The pseudonyms are keyed HMAC-SHA256 digests, never raw identifiers.\\n rid = string(f.request_id) ?? \\\"\\\"\\n if match(rid, r'^[0-9a-f]{8}-[0-9a-f]{4}-[1-8][0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$') { out.request_id = rid }\\n replaced = f.request_id_replaced\\n if is_boolean(replaced) { out.request_id_replaced = replaced }\\n account = string(f.account_hash) ?? \\\"\\\"\\n if match(account, r'^[0-9a-f]{64}$') { out.account_hash = account }\\n space = string(f.space_hash) ?? \\\"\\\"\\n if match(space, r'^[0-9a-f]{64}$') { out.space_hash = space }\\n } else {\\n if !includes([\\\"warn\\\", \\\"error\\\"], level) { abort }\\n code = \\\"unclassified\\\"\\n if target == \\\"tinycloud\\\" || starts_with(target, \\\"tinycloud::\\\") || target == \\\"tinycloud_core\\\" || starts_with(target, \\\"tinycloud_core::\\\") {\\n codes = {\\\"invocation replay insert failed\\\":\\\"invocation_replay_insert_failed\\\",\\\"invocation replay cleanup failed\\\":\\\"invocation_replay_cleanup_failed\\\",\\\"share-v2 local-tee feature active: deriving a deterministic, non-attested TEE identity from node key material\\\":\\\"share_local_tee_identity\\\",\\\"retention: delivered hook delivery prune failed\\\":\\\"retention_hook_delivery_prune_failed\\\",\\\"retention: dead-letter hook delivery prune failed\\\":\\\"retention_dead_letter_prune_failed\\\",\\\"retention: signed KV ticket prune failed\\\":\\\"retention_signed_ticket_prune_failed\\\",\\\"failed to load tunnel state; tunnel not started\\\":\\\"tunnel_state_load_failed\\\",\\\"invalid loopback API address; tunnel not started\\\":\\\"tunnel_address_invalid\\\",\\\"failed to load link state; LAN listener not started\\\":\\\"link_state_load_failed\\\",\\\"invalid link bind address; LAN listener not started\\\":\\\"link_bind_invalid\\\",\\\"invalid loopback API address; LAN listener not started\\\":\\\"link_address_invalid\\\",\\\"failed to bind link LAN listener; LAN listener not started\\\":\\\"link_bind_failed\\\",\\\"failed to build TLS config; LAN listener not started\\\":\\\"link_tls_config_failed\\\",\\\"link LAN listener exited with error\\\":\\\"link_listener_error\\\",\\\"failed to record link listener bind state\\\":\\\"link_listener_state_write_failed\\\",\\\"failed to record link listener bind failure\\\":\\\"link_bind_state_write_failed\\\",\\\"failed to load config for auto-renew\\\":\\\"link_auto_renew_config_failed\\\",\\\"link auto-renew failed\\\":\\\"link_auto_renew_failed\\\",\\\"failed to hot-reload renewed link cert\\\":\\\"link_cert_reload_failed\\\",\\\"link auto-renew succeeded but no state.json found; skipping cert hot-reload\\\":\\\"link_cert_state_missing\\\",\\\"failed to reload TLS material after link auto-renew\\\":\\\"link_listener_cert_reload_failed\\\",\\\"link disable: service delete failed; local state removed anyway\\\":\\\"link_disable_failed\\\",\\\"link connection error\\\":\\\"link_connection_error\\\",\\\"link listener accept error\\\":\\\"link_listener_accept_failed\\\",\\\"webhook delivery attempt failed\\\":\\\"webhook_delivery_failed\\\",\\\"webhook dispatcher loop failed\\\":\\\"webhook_dispatcher_failed\\\",\\\"addressed delegation authorization failed\\\":\\\"share_authorization_failed\\\",\\\"native share authorization denied\\\":\\\"share_native_authorization_denied\\\",\\\"native share KV put failed\\\":\\\"share_native_kv_put_failed\\\",\\\"share v2 readiness probe failed\\\":\\\"share_v2_readiness_failed\\\",\\\"share v2 is enabled but shareEmail.invitationPublicKey is unset\\\":\\\"share_invitation_key_missing\\\",\\\"configured share invitation key does not match the node's derived signing key\\\":\\\"share_invitation_key_mismatch\\\",\\\"share/v2 policy challenge denied\\\":\\\"share_policy_denied\\\",\\\"failed to read committed hook events\\\":\\\"hook_events_read_failed\\\",\\\"failed to load kv write hook rows\\\":\\\"hook_rows_load_failed\\\",\\\"failed to load kv delete hook rows\\\":\\\"hook_rows_load_failed\\\",\\\"missing committed kv hook row for invocation\\\":\\\"missing_committed_hook_row\\\",\\\"database write committed but webhook enqueue failed\\\":\\\"webhook_enqueue_failed\\\",\\\"tunnel: failed to prepare connection attempt\\\":\\\"tunnel_connection_prepare_failed\\\",\\\"tunnel: no frame within idle timeout; treating connection as dead\\\":\\\"tunnel_idle_timeout\\\",\\\"tunnel: read error\\\":\\\"tunnel_read_failed\\\",\\\"tunnel: dropping malformed frame\\\":\\\"tunnel_malformed_frame\\\",\\\"tunnel: relay sent an error frame\\\":\\\"tunnel_relay_error\\\",\\\"tunnel: failed to write frame\\\":\\\"tunnel_write_failed\\\",\\\"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\\\",\\\"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\\\"}\\n known = get(codes, [msg]) ?? null\\n if is_string(known) { code = known }\\n if starts_with(msg, \\\"quota service returned \\\") { code = \\\"quota_fallback\\\" }\\nif starts_with(msg, \\\"Failed to get TDX quote: \\\") { code = \\\"attestation_quote_failed\\\" }\\nif starts_with(msg, \\\"quota service returned an invalid body: \\\") { code = \\\"quota_invalid_body\\\" }\\nif starts_with(msg, \\\"dstack socket available but get_info failed: \\\") { code = \\\"dstack_get_info_failed\\\" }\\n }\\n event = if level == \\\"warn\\\" { \\\"node_warning\\\" } else { \\\"node_error\\\" }\\n out = {\\\"event\\\": event, \\\"svc\\\": \\\"api\\\", \\\"level\\\": level, \\\"event_code\\\": code, \\\"event_count\\\": 1}\\n }\\n} else {\\n ts = string!(j.time)\\n method = string!(j.method)\\n route = string!(j.route)\\n if route == \\\"\\\" { route = \\\"\\\" }\\n if !includes([\\\"GET\\\",\\\"HEAD\\\",\\\"POST\\\",\\\"PUT\\\",\\\"PATCH\\\",\\\"DELETE\\\",\\\"OPTIONS\\\",\\\"\\\"], method) || !includes([\\\"/healthz\\\",\\\"/info\\\",\\\"/version\\\",\\\"/invoke\\\",\\\"/delegate\\\",\\\"/revoke\\\",\\\"/attestation\\\",\\\"/signed/kv\\\",\\\"/signed/kv/\\\",\\\"/admin/quota\\\",\\\"/admin/quota/\\\",\\\"/admin/usage\\\",\\\"/hooks/events\\\",\\\"/hooks/tickets\\\",\\\"/hooks/webhooks\\\",\\\"/hooks/webhooks/\\\",\\\"/delegation/query\\\",\\\"/delegation/status\\\",\\\"/encryption/networks\\\",\\\"/encryption/networks/\\\",\\\"/encryption/networks//revoke\\\",\\\"/encryption/networks//decrypt\\\",\\\"/policy/v3/status\\\",\\\"/policy/v3/status/\\\",\\\"/policy/v3/policies\\\",\\\"/policy/v3/challenges\\\",\\\"/policy/v3/delegations\\\",\\\"/policy/v3/enforcer-bindings\\\",\\\"/policy/v3/deliveries/authorize\\\",\\\"/.well-known/tinycloud/node-keys\\\",\\\"/.well-known/encryption/network/\\\",\\\"/public//kv\\\",\\\"/public//kv/\\\",\\\"/peer/generate/\\\",\\\"/evidences/\\\",\\\"/share/v2/readiness\\\",\\\"/share/v2/policies\\\",\\\"/share/v2/policy/challenges\\\",\\\"/share/v2/policy/session\\\",\\\"/share/v2/invoke\\\",\\\"/share/v2/deliveries/authorize\\\",\\\"/<_s..>\\\",\\\"/public/<_space_id>/kv/<_key..>\\\",\\\"\\\"], route) { abort }\\n status = j.status\\n request_time = j.request_time\\n if !is_integer(status) || !(is_integer(request_time) || is_float(request_time)) { abort }\\n status = int!(status)\\n request_time = to_float!(request_time)\\n if status < 100 || status > 599 || request_time < 0 || request_time > 86400 { abort }\\n out = {\\\"event\\\": \\\"ingress_request\\\", \\\"svc\\\": \\\"ingress\\\", \\\"level\\\": \\\"info\\\", \\\"method\\\": method, \\\"route\\\": route, \\\"status\\\": status, \\\"request_time_seconds\\\": request_time}\\n}\\nif length(ts) > 64 { abort }\\nparsed_ts = parse_timestamp!(ts, format: \\\"%+\\\")\\nout.ts = format_timestamp!(parsed_ts, format: \\\"%Y-%m-%dT%H:%M:%S%.3fZ\\\")\\n. = out\\n\",\"drop_on_error\":true,\"drop_on_abort\":true,\"reroute_dropped\":true},\"gate_counts\":{\"type\":\"remap\",\"inputs\":[\"gate_route.rejected\",\"gate_route._unmatched\",\"allowlist.dropped\",\"event_route._unmatched\"],\"source\":\"reason = .reason\\nif !includes([\\\"malformed_envelope\\\",\\\"unexpected_label\\\",\\\"unlabelled\\\",\\\"non_json\\\",\\\"oversized\\\",\\\"partial\\\",\\\"invalid_fields\\\",\\\"unknown_target\\\",\\\"filtered_level\\\"], reason) { reason = \\\"invalid_fields\\\" }\\n. = {\\\"reason\\\": reason, \\\"count\\\": 1}\",\"drop_on_error\":true,\"drop_on_abort\":true},\"gate_reduce\":{\"type\":\"reduce\",\"inputs\":[\"gate_counts\"],\"group_by\":[\"reason\"],\"end_every_period_ms\":60000,\"expire_after_ms\":75000,\"flush_period_ms\":1000,\"merge_strategies\":{\"count\":\"sum\"}},\"gate_output\":{\"type\":\"remap\",\"inputs\":[\"gate_reduce\"],\"source\":\". = {\\\"ts\\\": format_timestamp!(now(), format: \\\"%Y-%m-%dT%H:%M:%S%.3fZ\\\"), \\\"level\\\": \\\"warn\\\", \\\"event\\\": \\\"logship_gate_summary_total\\\", \\\"svc\\\": \\\"logship\\\", \\\"reason\\\": .reason, \\\"count\\\": .count}\",\"drop_on_error\":true,\"drop_on_abort\":true},\"request_profile\":{\"type\":\"filter\",\"inputs\":[\"allowlist\"],\"condition\":\"\\\"$${TINYCLOUD_LOGSHIP_PROFILE}\\\" == \\\"all_requests\\\" || includes([\\\"node_warning\\\", \\\"node_error\\\"], .event) || (int(.status) ?? 0) >= 400 || (.event == \\\"node_request\\\" && (int(.latency_us) ?? 0) > 1000000) || (.event == \\\"ingress_request\\\" && (to_float(.request_time_seconds) ?? 0.0) > 1.000000)\"},\"event_route\":{\"type\":\"route\",\"inputs\":[\"request_profile\"],\"route\":{\"request\":\".event == \\\"node_request\\\" || .event == \\\"ingress_request\\\"\",\"diagnostic\":\".event == \\\"node_warning\\\" || .event == \\\"node_error\\\"\"}},\"diagnostic_reduce\":{\"type\":\"reduce\",\"inputs\":[\"event_route.diagnostic\"],\"group_by\":[\"event\",\"event_code\",\"level\",\"svc\"],\"end_every_period_ms\":60000,\"expire_after_ms\":75000,\"flush_period_ms\":1000,\"merge_strategies\":{\"event_count\":\"sum\",\"ts\":\"discard\"}},\"diagnostic_output\":{\"type\":\"remap\",\"inputs\":[\"diagnostic_reduce\"],\"source\":\". = {\\\"ts\\\": format_timestamp!(now(), format: \\\"%Y-%m-%dT%H:%M:%S%.3fZ\\\"), \\\"level\\\": .level, \\\"event\\\": .event, \\\"svc\\\": \\\"api\\\", \\\"event_code\\\": .event_code, \\\"event_count\\\": .event_count}\",\"drop_on_error\":true,\"drop_on_abort\":true}},\"sinks\":{\"betterstack\":{\"type\":\"http\",\"inputs\":[\"event_route.request\",\"diagnostic_output\",\"gate_output\"],\"method\":\"post\",\"uri\":\"https://s2795437.us-west-2a.betterstackdata.com/\",\"encoding\":{\"codec\":\"json\"},\"framing\":{\"method\":\"newline_delimited\"},\"compression\":\"gzip\",\"auth\":{\"strategy\":\"bearer\",\"token\":\"SECRET[bs.bs_token]\"},\"batch\":{\"max_bytes\":262144,\"timeout_secs\":1},\"buffer\":{\"type\":\"memory\",\"max_events\":1000,\"when_full\":\"block\"},\"request\":{\"timeout_secs\":10,\"retry_max_duration_secs\":300},\"healthcheck\":{\"enabled\":false}}},\"secret\":{\"bs\":{\"type\":\"directory\",\"path\":\"/var/lib/vector/secrets\",\"remove_trailing_whitespace\":true}}}" entrypoint: - /bin/sh - -ec diff --git a/tinycloud-core/Cargo.toml b/tinycloud-core/Cargo.toml index 3328cbc6..70b1a742 100644 --- a/tinycloud-core/Cargo.toml +++ b/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" diff --git a/tinycloud-core/src/db.rs b/tinycloud-core/src/db.rs index 91c32043..54c2083f 100644 --- a/tinycloud-core/src/db.rs +++ b/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( diff --git a/tinycloud-core/src/db_pool.rs b/tinycloud-core/src/db_pool.rs index 127be2aa..700271f3 100644 --- a/tinycloud-core/src/db_pool.rs +++ b/tinycloud-core/src/db_pool.rs @@ -206,6 +206,7 @@ impl RecoveringConnection { { let retry = is_read_only_statement(&stmt.sql).then(|| stmt.clone()); let write = retry.is_none(); + let in_flight = InFlightWrite::arm(write); let started = Instant::now(); let result = match attempt(stmt).await { Err(error) if is_connection_error(&error) => { @@ -218,6 +219,7 @@ impl RecoveringConnection { } result => result, }; + in_flight.disarm(); if write { note_write_outcome(&result); } @@ -238,6 +240,7 @@ impl RecoveringConnection { /// conflict as a replay, so it must not be retried. pub async fn execute_idempotent(&self, stmt: Statement) -> Result { let started = Instant::now(); + let in_flight = InFlightWrite::arm(true); let result = match self.conn.execute(stmt.clone()).await { Err(error) if is_connection_error(&error) && !self.within_retry_window(started) => { self.lost("execute_idempotent", &error, false); @@ -252,6 +255,7 @@ impl RecoveringConnection { } result => result, }; + in_flight.disarm(); note_write_outcome(&result); result } @@ -536,9 +540,11 @@ impl ConnectionTrait for RecoveringConnection { async fn execute_unprepared(&self, sql: &str) -> Result { let read_only = is_read_only_statement(sql); + let in_flight = InFlightWrite::arm(!read_only); let result = self .run("execute", read_only, || self.conn.execute_unprepared(sql)) .await; + in_flight.disarm(); if !read_only { note_write_outcome(&result); } @@ -908,6 +914,37 @@ fn note_write_outcome(result: &Result) { } } +/// A write statement that may already be on the wire (TC-1274). +/// +/// Dropping the statement's future does not cancel it on the server: the +/// released connection is only pinged, which waits for the statement to +/// finish, so an autocommit write dropped by a timeout can still commit. If +/// the future is dropped before its result arrives, the guard notes the write +/// as possibly applied, so [`track_writes`] reports an unknown outcome +/// instead of a safe retry. +struct InFlightWrite { + armed: bool, +} + +impl InFlightWrite { + fn arm(write: bool) -> Self { + Self { armed: write } + } + + /// The result arrived; [`note_write_outcome`] classifies it. + fn disarm(mut self) { + self.armed = false; + } +} + +impl Drop for InFlightWrite { + fn drop(&mut self) { + if self.armed { + note_write_may_have_applied(); + } + } +} + /// How a [transient](is_transient_error) failure of an operation may be /// reported to its client (TC-1054). #[derive(Clone, Copy, Debug, PartialEq, Eq)] diff --git a/tinycloud-core/src/lib.rs b/tinycloud-core/src/lib.rs index db327f91..bceb8b73 100644 --- a/tinycloud-core/src/lib.rs +++ b/tinycloud-core/src/lib.rs @@ -24,6 +24,7 @@ pub mod policy_authority; pub mod policy_capability; mod read_audit; pub mod relationships; +pub mod request_cancel; pub mod request_telemetry; pub mod share_email; pub mod sql; diff --git a/tinycloud-core/src/request_cancel.rs b/tinycloud-core/src/request_cancel.rs new file mode 100644 index 00000000..fa3807d8 --- /dev/null +++ b/tinycloud-core/src/request_cancel.rs @@ -0,0 +1,259 @@ +//! A request's deadline and its commit latch (TC-1274). +//! +//! `/invoke` runs its handler through [`run_with_deadline`]. Until the handler +//! reaches its first data write, the deadline may cut it: the handler future is +//! dropped at whatever `.await` it is parked on, and the request is answered +//! `request_timeout`, which promises the client that nothing was applied. +//! Every wait before that point is drop-safe (tokio guards, reads, read-only +//! transactions that roll back on drop). +//! +//! Each data write first calls [`latch`]. From then on the deadline no longer +//! cuts: the handler runs to completion and reports its true outcome, and a +//! completion past the deadline is logged as an overrun. The latch and the cut +//! are one compare-and-swap on the same state, so a write started on another +//! task (the SQL service's operation task) can never race a timeout answer. +//! +//! The context is task-local and does not cross `tokio::spawn`; code that +//! hands request work to a task carries it with [`current`] and [`within`]. + +use std::{ + future::Future, + sync::{ + atomic::{AtomicU8, Ordering}, + Arc, + }, + time::Duration, +}; + +use tokio::time::Instant; + +const OPEN: u8 = 0; +const LATCHED: u8 = 1; +const CUT: u8 = 2; + +tokio::task_local! { + static CURRENT: Arc; +} + +/// What a request was waiting on when its deadline was reached. Recorded by +/// the bounded waits so a timeout can say where the time went. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +#[repr(u8)] +pub enum Stage { + Other = 0, + LockWait = 1, + Hydration = 2, + ArtifactTransfer = 3, + /// Resolving a SQL or DuckDB database's durable identity. + IdentityResolution = 4, +} + +impl Stage { + pub fn as_str(self) -> &'static str { + match self { + Stage::Other => "other", + Stage::LockWait => "lock_wait", + Stage::Hydration => "hydration", + Stage::ArtifactTransfer => "artifact_transfer", + Stage::IdentityResolution => "identity_resolution", + } + } + + fn from_u8(value: u8) -> Self { + match value { + 1 => Stage::LockWait, + 2 => Stage::Hydration, + 3 => Stage::ArtifactTransfer, + 4 => Stage::IdentityResolution, + _ => Stage::Other, + } + } +} + +/// One request's deadline and latch. +#[derive(Debug)] +pub struct RequestCancel { + deadline: Instant, + budget: Duration, + state: AtomicU8, + stage: AtomicU8, +} + +impl RequestCancel { + pub fn new(budget: Duration) -> Arc { + Arc::new(Self { + deadline: Instant::now() + budget, + budget, + state: AtomicU8::new(OPEN), + stage: AtomicU8::new(Stage::Other as u8), + }) + } + + pub fn deadline(&self) -> Instant { + self.deadline + } + + /// Whether the request may still be cut by its deadline. + pub fn is_open(&self) -> bool { + self.state.load(Ordering::Acquire) == OPEN + } + + pub fn is_latched(&self) -> bool { + self.state.load(Ordering::Acquire) == LATCHED + } + + /// Mark the request as having started a data write. False only if the + /// deadline already cut it, in which case the write must not start. + pub fn latch(&self) -> bool { + match self + .state + .compare_exchange(OPEN, LATCHED, Ordering::AcqRel, Ordering::Acquire) + { + Ok(_) => true, + Err(state) => state == LATCHED, + } + } + + /// Claim the timeout. False if a write has already latched the request. + /// Whoever moves the request from open to cut logs it, exactly once. + pub fn cut(&self) -> bool { + match self + .state + .compare_exchange(OPEN, CUT, Ordering::AcqRel, Ordering::Acquire) + { + Ok(_) => { + tracing::warn!( + error_class = "request_timeout", + stage = self.stage().as_str(), + deadline_ms = self.budget.as_millis() as u64, + "Request deadline exceeded" + ); + true + } + Err(state) => state == CUT, + } + } + + pub fn set_stage(&self, stage: Stage) { + self.stage.store(stage as u8, Ordering::Relaxed); + } + + pub fn stage(&self) -> Stage { + Stage::from_u8(self.stage.load(Ordering::Relaxed)) + } +} + +/// Record what the current request is waiting on, if it has a deadline. +pub fn set_stage(stage: Stage) { + if let Some(context) = current() { + context.set_stage(stage); + } +} + +/// The context installed for the current task, if any. +pub fn current() -> Option> { + CURRENT.try_with(Arc::clone).ok() +} + +/// Latch the current request before a data write; see [`RequestCancel::latch`]. +/// Without a context there is no deadline to race, so this is true. +pub fn latch() -> bool { + current().is_none_or(|context| context.latch()) +} + +/// Run `future` with `context` installed, if there is one. +pub async fn within(context: Option>, future: F) -> F::Output { + match context { + Some(context) => CURRENT.scope(context, future).await, + None => future.await, + } +} + +/// The deadline cut the request before any data write. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub struct DeadlineExceeded; + +/// Run a request handler under `budget` (`None`: no deadline). +/// +/// Before the handler latches, reaching the deadline drops it and returns +/// [`DeadlineExceeded`]. After it latches, the handler completes and its +/// result is returned, with a warning if that was past the deadline. +pub async fn run_with_deadline( + budget: Option, + future: F, +) -> Result { + let Some(budget) = budget else { + return Ok(future.await); + }; + let context = RequestCancel::new(budget); + let started = Instant::now(); + let future = CURRENT.scope(Arc::clone(&context), future); + tokio::pin!(future); + tokio::select! { + biased; + output = &mut future => return Ok(output), + _ = tokio::time::sleep_until(context.deadline()) => {} + } + if context.cut() { + return Err(DeadlineExceeded); + } + let output = future.await; + tracing::warn!( + error_class = "deadline_overrun", + elapsed_ms = started.elapsed().as_millis() as u64, + deadline_ms = budget.as_millis() as u64, + "Request completed after its deadline" + ); + Ok(output) +} + +#[cfg(test)] +mod tests { + use super::*; + + #[tokio::test(start_paused = true)] + async fn an_unlatched_handler_is_cut_at_the_deadline() { + let dropped = Arc::new(AtomicU8::new(0)); + struct OnDrop(Arc); + impl Drop for OnDrop { + fn drop(&mut self) { + self.0.store(1, Ordering::SeqCst); + } + } + let guard = OnDrop(Arc::clone(&dropped)); + let result = run_with_deadline(Some(Duration::from_secs(5)), async move { + let _guard = guard; + std::future::pending::<()>().await + }) + .await; + assert_eq!(result, Err(DeadlineExceeded)); + assert_eq!(dropped.load(Ordering::SeqCst), 1, "the handler was dropped"); + } + + #[tokio::test(start_paused = true)] + async fn a_latched_handler_completes_with_its_result() { + let result = run_with_deadline(Some(Duration::from_secs(5)), async { + assert!(latch()); + tokio::time::sleep(Duration::from_secs(20)).await; + "applied" + }) + .await; + assert_eq!(result, Ok("applied")); + } + + #[tokio::test(start_paused = true)] + async fn a_write_on_another_task_cannot_latch_after_the_cut() { + let (tx, rx) = tokio::sync::oneshot::channel(); + let result = run_with_deadline(Some(Duration::from_secs(5)), async move { + let context = current(); + tokio::spawn(async move { + tokio::time::sleep(Duration::from_secs(6)).await; + let _ = tx.send(context.unwrap().latch()); + }); + std::future::pending::<()>().await + }) + .await; + assert_eq!(result, Err(DeadlineExceeded)); + assert!(!rx.await.unwrap(), "the late write must see the cut"); + } +} diff --git a/tinycloud-core/src/sql/mod.rs b/tinycloud-core/src/sql/mod.rs index 522473fb..7e755e61 100644 --- a/tinycloud-core/src/sql/mod.rs +++ b/tinycloud-core/src/sql/mod.rs @@ -7,10 +7,10 @@ pub mod storage; pub mod types; pub use caveats::SqlCaveats; -pub use service::SqlService; +pub use service::{SqlService, SqlWaitBounds}; pub use types::{ - BatchResponse, ExecuteResponse, QueryResponse, SqlError, SqlExecutionResult, SqlRequest, - SqlResponse, SqlValue, + BatchResponse, ExecuteResponse, QueryResponse, SqlBusyStage, SqlError, SqlExecutionResult, + SqlRequest, SqlResponse, SqlValue, }; pub mod publication; diff --git a/tinycloud-core/src/sql/service.rs b/tinycloud-core/src/sql/service.rs index 86f1bbab..5967ced8 100644 --- a/tinycloud-core/src/sql/service.rs +++ b/tinycloud-core/src/sql/service.rs @@ -1,19 +1,24 @@ use std::{ collections::HashMap, + future::Future, path::{Path, PathBuf}, sync::{ - atomic::{AtomicU64, Ordering}, + atomic::{AtomicU64, AtomicU8, Ordering}, Arc, Weak, }, + time::Duration, }; use dashmap::DashMap; use tinycloud_auth::resource::SpaceId; +use tokio::{sync::OwnedMutexGuard, time::Instant}; +use tracing::Instrument; use crate::database_artifacts::{ - ArtifactExpectation, DatabaseArtifactError, DatabaseArtifactRepository, + ArtifactExpectation, DatabaseArtifact, DatabaseArtifactError, DatabaseArtifactRepository, }; use crate::db_pool::{is_transient_error, track_writes, transient_error_class}; +use crate::{request_cancel, request_telemetry}; use super::{ caveats::SqlCaveats, @@ -29,18 +34,119 @@ const SQLITE_MAGIC: &[u8] = b"SQLite format 3\0"; /// selects the checksum endianness; both values are valid. const SQLITE_WAL_MAGIC: [&[u8]; 2] = [&[0x37, 0x7f, 0x06, 0x82], &[0x37, 0x7f, 0x06, 0x83]]; -/// Per-(space, db) guard over cache hydration; see [`SqlService::handle`]. -type HydrationLock = tokio::sync::Mutex<()>; -type HydrationLockRegistry = - Arc>>>; +/// Per-(space, db) operation lock; see [`SqlService::operation_locks`]. +type OperationLock = tokio::sync::Mutex<()>; +type OperationLockRegistry = + Arc>>>; + +/// How a hydration ended, as every caller that joined it sees it. +#[derive(Clone, Debug)] +enum HydrationOutcome { + Ready, + Unavailable, + Failed(String), + TimedOut, +} + +const PHASE_LOADING: u8 = 0; +const PHASE_WRITING: u8 = 1; + +/// A hydration in progress: what it is doing, and how it ended once it has. +#[derive(Clone)] +struct HydrationFlight { + phase: Arc, + outcome: tokio::sync::watch::Receiver>, +} + +type HydrationRegistry = Arc>>; + +/// Hydrations one [`SqlService::handle`] call may run before it gives up. +const MAX_HYDRATIONS: usize = 2; + +/// Retires a hydration's registry entry and publishes how it ended (TC-1274). +/// +/// Dropped without [`Self::finish`] (the hydration task panicked or its +/// runtime shut down), it still retires the entry and reports a failure, so +/// joiners get an error and the next request starts a fresh hydration instead +/// of joining a dead one. +struct RetireFlight { + service: SqlService, + key: (String, String), + phase: Arc, + sender: Option>>, +} + +impl RetireFlight { + fn finish(mut self, outcome: HydrationOutcome) { + self.retire(outcome); + } + + fn retire(&mut self, outcome: HydrationOutcome) { + let Some(sender) = self.sender.take() else { + return; + }; + let mut flights = self + .service + .hydrations + .lock() + .unwrap_or_else(std::sync::PoisonError::into_inner); + // Only this flight's entry: the key is never re-registered while it + // is present, but compare anyway rather than assume. + if flights + .get(&self.key) + .is_some_and(|flight| Arc::ptr_eq(&flight.phase, &self.phase)) + { + flights.remove(&self.key); + } + drop(flights); + sender.send_replace(Some(outcome)); + } +} + +impl Drop for RetireFlight { + fn drop(&mut self) { + self.retire(HydrationOutcome::Failed( + "database hydration ended abnormally".into(), + )); + } +} + +/// How long a SQL request waits at each stage before it answers +/// [`SqlError::Busy`] (TC-1274). Every wait is also cut short by the request +/// deadline while the request has not started writing. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub struct SqlWaitBounds { + /// The per-(space, db) operation lock. + pub lock_wait: Duration, + /// A caller's wait for the database's local cache to be hydrated. + pub hydration_wait: Duration, + /// A durable artifact load or save that the caller awaits directly. + pub artifact_transfer: Duration, + /// A hydration's own artifact load. It keeps going after its callers + /// give up, so the next request finds the database warm. + pub hydration_max: Duration, +} + +impl Default for SqlWaitBounds { + fn default() -> Self { + Self { + lock_wait: Duration::from_secs(30), + hydration_wait: Duration::from_secs(30), + artifact_transfer: Duration::from_secs(45), + hydration_max: Duration::from_secs(600), + } + } +} #[derive(Clone)] pub struct SqlService { databases: Arc>, - hydration_locks: HydrationLockRegistry, + /// The hydration in progress for each (space, db) with no live actor; see + /// [`SqlService::handle`]. + hydrations: HydrationRegistry, /// Serialize execution through durable persistence, including checkpoint /// replacement, so another request cannot change the snapshot being saved. - operation_locks: HydrationLockRegistry, + operation_locks: OperationLockRegistry, /// What each live actor's local database derives from, carried into every /// durable save so a stale actor is rejected instead of clobbering. Written /// on hydration (the only path that creates an actor) and after each @@ -49,6 +155,7 @@ pub struct SqlService { base_path: String, memory_threshold: u64, artifact_repository: Arc, + bounds: SqlWaitBounds, } impl SqlService { @@ -59,15 +166,21 @@ impl SqlService { ) -> Self { Self { databases: Arc::new(DashMap::new()), - hydration_locks: Arc::new(tokio::sync::Mutex::new(HashMap::new())), + hydrations: Arc::new(std::sync::Mutex::new(HashMap::new())), operation_locks: Arc::new(tokio::sync::Mutex::new(HashMap::new())), lineage: Arc::new(DashMap::new()), base_path, memory_threshold, artifact_repository, + bounds: SqlWaitBounds::default(), } } + pub fn with_wait_bounds(mut self, bounds: SqlWaitBounds) -> Self { + self.bounds = bounds; + self + } + pub async fn execute( &self, space: &SpaceId, @@ -120,9 +233,29 @@ impl SqlService { growth: GrowthPolicy, ) -> Result { crate::request_telemetry::observe_space(space); - let _operation_guard = self.operation_lock(space, db_name).await.lock_owned().await; + let guard = self.acquire_operation(space, db_name).await?; + let (space, db_name) = (space.clone(), db_name.to_string()); + self.run_locked(guard, move |service| async move { + service + .execute_locked(&space, &db_name, request, caveats, ability, growth) + .await + }) + .await + } + + /// The body of an execute, run on the operation task under the lock. + async fn execute_locked( + &self, + space: &SpaceId, + db_name: &str, + request: SqlRequest, + caveats: Option, + ability: String, + growth: GrowthPolicy, + ) -> Result { let key = (space.to_string(), db_name.to_string()); let mut handle = self.handle(space, db_name).await?; + begin_write()?; let result = match handle .execute(request.clone(), caveats.clone(), ability.clone(), growth) @@ -163,11 +296,13 @@ impl SqlService { track_writes(self.persist_write(space, db_name, &handle, growth)).await; if let Err(e) = persisted { self.discard_local_state(&key).await?; - // A lost connection after the artifact write was sent: the - // write may be durable, so a blind retry could apply it - // twice (TC-1054). + // A lost connection or an expired transfer after the artifact + // write was sent: the write may be durable, so a blind retry + // could apply it twice (TC-1054, TC-1274). return Err(match e { - SqlError::Unavailable if write_may_have_applied => SqlError::OutcomeUnknown, + SqlError::Unavailable | SqlError::Busy(_) if write_may_have_applied => { + SqlError::OutcomeUnknown + } e => e, }); } @@ -176,17 +311,111 @@ impl SqlService { Ok(result) } - async fn operation_lock(&self, space: &SpaceId, db_name: &str) -> Arc { + async fn operation_lock(&self, space: &SpaceId, db_name: &str) -> Arc { let key = (space.to_string(), db_name.to_string()); let mut registry = self.operation_locks.lock().await; registry.retain(|_, lock| lock.strong_count() > 0); if let Some(lock) = registry.get(&key).and_then(Weak::upgrade) { return lock; } - let lock = Arc::new(HydrationLock::new(())); + let lock = Arc::new(OperationLock::new(())); registry.insert(key, Arc::downgrade(&lock)); lock } + + /// Take the operation lock for (space, db), waiting at most the lock + /// bound (or the request deadline). + async fn acquire_operation( + &self, + space: &SpaceId, + db_name: &str, + ) -> Result, SqlError> { + let lock = self.operation_lock(space, db_name).await; + self.bounded( + || SqlBusyStage::LockWait, + self.bounds.lock_wait, + lock.lock_owned(), + ) + .await + } + + /// Run `operation` under the operation lock on its own task (TC-1274). + /// + /// The task owns the guard, so a caller that goes away (its future + /// dropped by a deadline, an aborted handler) can never stop the work + /// midway: hydration writes, the actor's statement and the durable save + /// that must follow it all complete, and the lock is released when they + /// have. Before its write starts, the task stops at the request's + /// deadline by itself (see [`begin_write`]). + async fn run_locked( + &self, + guard: OwnedMutexGuard<()>, + operation: F, + ) -> Result + where + T: Send + 'static, + F: FnOnce(SqlService) -> Fut + Send + 'static, + Fut: Future> + Send + 'static, + { + let service = self.clone(); + let task = request_cancel::within(request_cancel::current(), async move { + let _guard = guard; + operation(service).await + }) + .instrument(tracing::Span::current()); + let joined = match request_telemetry::current() { + Some(context) => tokio::spawn(request_telemetry::scope(context, task)).await, + None => tokio::spawn(task).await, + }; + match joined { + Ok(result) => result, + Err(error) if error.is_panic() => std::panic::resume_unwind(error.into_panic()), + Err(error) => Err(SqlError::Internal(format!( + "SQL operation task ended early: {error}" + ))), + } + } + + /// Wait for `future` at most `bound`, or until the request deadline while + /// the request has not started writing (TC-1274). `stage` names what + /// was being waited on when the bound expired. + async fn bounded( + &self, + stage: impl Fn() -> SqlBusyStage, + bound: Duration, + future: impl Future, + ) -> Result { + let started = Instant::now(); + let context = request_cancel::current().filter(|context| context.is_open()); + if let Some(context) = &context { + context.set_stage(stage().into()); + } + let bound_end = started + bound; + let deadline = context + .as_ref() + .map(|context| context.deadline()) + .filter(|deadline| *deadline < bound_end); + let waited = tokio::time::timeout_at(deadline.unwrap_or(bound_end), future).await; + if let Some(context) = &context { + context.set_stage(request_cancel::Stage::Other); + } + match (waited, context) { + (Ok(output), _) => Ok(output), + (Err(_), Some(context)) if deadline.is_some() => { + context.set_stage(stage().into()); + // Logged once, by whichever of this wait and the route's + // deadline claims the cut first. + context.cut(); + Err(SqlError::RequestTimeout) + } + (Err(_), _) => { + let stage = stage(); + log_busy(stage, bound, started.elapsed()); + Err(SqlError::Busy(stage)) + } + } + } + /// Read-only compatibility command; the core actor rejects withdrawn mutations. pub async fn meeting_publication( &self, @@ -194,10 +423,25 @@ impl SqlService { command: serde_json::Value, ) -> Result { crate::request_telemetry::observe_space(space); + let guard = self + .acquire_operation(space, super::publication::DATABASE) + .await?; + let space = space.clone(); + self.run_locked(guard, move |service| async move { + service.meeting_publication_locked(&space, command).await + }) + .await + } + + async fn meeting_publication_locked( + &self, + space: &SpaceId, + command: serde_json::Value, + ) -> Result { let db_name = super::publication::DATABASE; - let _guard = self.operation_lock(space, db_name).await.lock_owned().await; let key = (space.to_string(), db_name.to_string()); let handle = self.handle(space, db_name).await?; + begin_write()?; let result = handle.publication(command).await?; if !result.write_targets.is_empty() { if let Err(error) = self @@ -215,13 +459,17 @@ impl SqlService { /// created by a query or rejected write does not establish its existence. pub async fn export(&self, space: &SpaceId, db_name: &str) -> Result, SqlError> { crate::request_telemetry::observe_space(space); - let _operation_guard = self.operation_lock(space, db_name).await.lock_owned().await; + let _operation_guard = self.acquire_operation(space, db_name).await?; let key = (space.to_string(), db_name.to_string()); if self - .artifact_repository - .load("sql", &space.to_string(), db_name) - .await + .bounded( + || SqlBusyStage::ArtifactTransfer, + self.bounds.artifact_transfer, + self.artifact_repository + .load("sql", &space.to_string(), db_name), + ) + .await? .map_err(artifact_error_to_sql)? .is_none() { @@ -257,32 +505,156 @@ impl SqlService { /// there is none. /// /// Hydration deletes and rewrites the very files a running actor reads BY - /// PATH, and two hydrations of one database interleave their writes, so the - /// miss -> hydrate -> spawn window is serialized per (space, db) and the - /// actor map is re-checked under the guard. Both properties are load-bearing: - /// hydrating concurrently with another hydration, or under a live actor, is - /// how a database silently reverts to an older checkpoint. + /// PATH, and two hydrations of one database interleave their writes, so at + /// most one hydration per (space, db) is in flight, it runs only while there + /// is no actor, and it publishes its actor before it retires. Both + /// properties are load-bearing: hydrating concurrently with another + /// hydration, or under a live actor, is how a database silently reverts to + /// an older checkpoint. + /// + /// The hydration runs on its own task, which no caller can cancel (its + /// cache writes must not be orphaned, TC-1274). Callers join it: each waits + /// at most its hydration bound and then answers busy, while the hydration + /// keeps going under `hydration_max`, so the next request finds the + /// database warm. async fn handle(&self, space: &SpaceId, db_name: &str) -> Result { let key = (space.to_string(), db_name.to_string()); + let started = Instant::now(); + // A hydration that ends `Ready` has published its actor, but an actor + // that cannot open its files deregisters itself at once. Hydrate at + // most twice, as before TC-1274, rather than reload the artifact in a + // loop while holding the operation lock. + for _ in 0..MAX_HYDRATIONS { + if let Some(handle) = self.databases.get(&key).map(|h| h.clone()) { + return Ok(handle); + } + let (flight, start) = { + let mut flights = self + .hydrations + .lock() + .unwrap_or_else(std::sync::PoisonError::into_inner); + // Checked again under the registry: a hydration publishes its + // actor before it leaves the registry. + if let Some(handle) = self.databases.get(&key).map(|h| h.clone()) { + return Ok(handle); + } + match flights.get(&key) { + Some(flight) => (flight.clone(), None), + None => { + let (flight, start) = self.prepare_hydration(space, db_name); + flights.insert(key.clone(), flight.clone()); + (flight, Some(start)) + } + } + }; + // Spawned only after the registry lock is released: if the + // runtime is shutting down, the task is dropped at once and its + // guard takes that lock to retire the entry. + if let Some(start) = start { + start(); + } + match self.join_hydration(flight).await? { + HydrationOutcome::Ready => continue, + HydrationOutcome::Unavailable => return Err(SqlError::Unavailable), + HydrationOutcome::Failed(message) => return Err(SqlError::Internal(message)), + HydrationOutcome::TimedOut => { + log_busy( + SqlBusyStage::ArtifactTransfer, + self.bounds.hydration_max, + started.elapsed(), + ); + return Err(SqlError::Busy(SqlBusyStage::ArtifactTransfer)); + } + } + } if let Some(handle) = self.databases.get(&key).map(|h| h.clone()) { return Ok(handle); } + Err(SqlError::Internal( + "database actor did not start after hydration".into(), + )) + } - let hydration_lock = self.hydration_lock(&key).await; - let _hydrating = hydration_lock.lock().await; + /// Wait for a hydration to end, at most the hydration bound. + async fn join_hydration(&self, flight: HydrationFlight) -> Result { + let HydrationFlight { phase, mut outcome } = flight; + let stage = || match phase.load(Ordering::Acquire) { + PHASE_LOADING => SqlBusyStage::ArtifactTransfer, + _ => SqlBusyStage::Hydration, + }; + let ended = self + .bounded(stage, self.bounds.hydration_wait, async { + outcome + .wait_for(Option::is_some) + .await + .map(|ended| ended.clone()) + }) + .await?; + Ok(match ended { + Ok(Some(outcome)) => outcome, + _ => HydrationOutcome::Failed("database hydration ended without an outcome".into()), + }) + } - // Double-checked: whoever held the guard may have hydrated and spawned - // the actor already, and hydrating under it is exactly what the guard - // exists to prevent. - if let Some(handle) = self.databases.get(&key).map(|h| h.clone()) { - return Ok(handle); + /// Prepare the hydration of (space, db) and the call that spawns it. + /// Prepared under the registry lock; spawn it after releasing the lock. + fn prepare_hydration( + &self, + space: &SpaceId, + db_name: &str, + ) -> (HydrationFlight, impl FnOnce()) { + let (sender, outcome) = tokio::sync::watch::channel(None); + let phase = Arc::new(AtomicU8::new(PHASE_LOADING)); + let retire = RetireFlight { + service: self.clone(), + key: (space.to_string(), db_name.to_string()), + phase: Arc::clone(&phase), + sender: Some(sender), + }; + let service = self.clone(); + let (space, db_name) = (space.clone(), db_name.to_string()); + let task = async move { + let ended = service.hydrate(&space, &db_name, &retire.phase).await; + retire.finish(ended); } + .instrument(tracing::Span::current()); + let telemetry = request_telemetry::current(); + let start = move || match telemetry { + Some(context) => drop(tokio::spawn(request_telemetry::scope(context, task))), + None => drop(tokio::spawn(task)), + }; + (HydrationFlight { phase, outcome }, start) + } - self.hydrate_cache(space, db_name).await?; - - Ok(self - .databases - .entry(key) + /// Load the durable artifact, seed the cache from it and spawn the actor. + /// Only the load is bounded (`hydration_max`): the cache writes after it + /// are local and must finish once begun. + async fn hydrate(&self, space: &SpaceId, db_name: &str, phase: &AtomicU8) -> HydrationOutcome { + let loaded = tokio::time::timeout( + self.bounds.hydration_max, + self.artifact_repository + .load("sql", &space.to_string(), db_name), + ) + .await; + let artifact = match loaded { + Ok(Ok(artifact)) => artifact, + Ok(Err(error)) => return hydration_failure(artifact_error_to_sql(error)), + Err(_) => { + tracing::warn!( + service = "sql", + error_class = "hydration_timeout", + bound_ms = self.bounds.hydration_max.as_millis() as u64, + "Database hydration gave up loading its artifact" + ); + return HydrationOutcome::TimedOut; + } + }; + phase.store(PHASE_WRITING, Ordering::Release); + if let Err(error) = self.seed_cache(space, db_name, artifact).await { + return hydration_failure(error); + } + self.databases + .entry((space.to_string(), db_name.to_string())) .or_insert_with(|| { spawn_actor( space.to_string(), @@ -291,34 +663,19 @@ impl SqlService { self.memory_threshold, self.databases.clone(), ) - }) - .clone()) - } - - /// The hydration guard for `key`, created on first use. - /// - /// The registry holds weak references and is swept on every acquisition, so - /// it cannot outgrow the set of databases currently being hydrated. - async fn hydration_lock(&self, key: &(String, String)) -> Arc { - let mut registry = self.hydration_locks.lock().await; - registry.retain(|_, lock| lock.strong_count() > 0); - if let Some(lock) = registry.get(key).and_then(Weak::upgrade) { - return lock; - } - let lock = Arc::new(HydrationLock::new(())); - registry.insert(key.clone(), Arc::downgrade(&lock)); - lock + }); + HydrationOutcome::Ready } - async fn hydrate_cache(&self, space: &SpaceId, db_name: &str) -> Result<(), SqlError> { + async fn seed_cache( + &self, + space: &SpaceId, + db_name: &str, + artifact: Option, + ) -> Result<(), SqlError> { let cache_path = self.cache_path(space, db_name); let key = (space.to_string(), db_name.to_string()); - match self - .artifact_repository - .load("sql", &space.to_string(), db_name) - .await - .map_err(artifact_error_to_sql)? - { + match artifact { Some(artifact) => { tracing::info!( service = "sql", @@ -431,9 +788,18 @@ impl SqlService { }; if let Some(wal) = wal.filter(|wal| wal.len() < MAX_WAL_DELTA_BYTES) { match self - .artifact_repository - .save_delta("sql", &space.to_string(), db_name, wal, expected.clone()) - .await + .bounded( + || SqlBusyStage::ArtifactTransfer, + self.bounds.artifact_transfer, + self.artifact_repository.save_delta( + "sql", + &space.to_string(), + db_name, + wal, + expected.clone(), + ), + ) + .await? { Ok(saved) => { // The delta rides on the same checkpoint, so only the @@ -462,9 +828,12 @@ impl SqlService { let bytes = payload.len(); if growth == GrowthPolicy::Forbid { let durable_bytes = self - .artifact_repository - .load("sql", &key.0, db_name) - .await + .bounded( + || SqlBusyStage::ArtifactTransfer, + self.bounds.artifact_transfer, + self.artifact_repository.load("sql", &key.0, db_name), + ) + .await? .map_err(artifact_error_to_sql)? .map_or(0, |artifact| artifact.size_bytes.max(0) as u64); if bytes as u64 > durable_bytes { @@ -472,9 +841,18 @@ impl SqlService { } } let saved = self - .artifact_repository - .save("sql", &space.to_string(), db_name, payload, expected) - .await + .bounded( + || SqlBusyStage::ArtifactTransfer, + self.bounds.artifact_transfer, + self.artifact_repository.save( + "sql", + &space.to_string(), + db_name, + payload, + expected, + ), + ) + .await? .map_err(artifact_error_to_sql)?; self.lineage.insert( key, @@ -600,6 +978,76 @@ fn artifact_error_to_sql(err: DatabaseArtifactError) -> SqlError { } } +/// The request's point of no return (TC-1274): the next step hands the +/// statement to the actor, which applies it whether or not anyone is still +/// waiting. Latch the request so its deadline can no longer answer +/// `request_timeout`, unless the deadline has already passed or cut it. +fn begin_write() -> Result<(), SqlError> { + let Some(context) = request_cancel::current() else { + return Ok(()); + }; + if context.is_open() && Instant::now() >= context.deadline() && context.cut() { + return Err(SqlError::RequestTimeout); + } + if context.latch() { + Ok(()) + } else { + Err(SqlError::RequestTimeout) + } +} + +fn hydration_failure(error: SqlError) -> HydrationOutcome { + match error { + SqlError::Unavailable => HydrationOutcome::Unavailable, + SqlError::Internal(message) => HydrationOutcome::Failed(message), + error => HydrationOutcome::Failed(error.to_string()), + } +} + +impl From for request_cancel::Stage { + fn from(stage: SqlBusyStage) -> Self { + match stage { + SqlBusyStage::LockWait => request_cancel::Stage::LockWait, + SqlBusyStage::Hydration => request_cancel::Stage::Hydration, + SqlBusyStage::ArtifactTransfer => request_cancel::Stage::ArtifactTransfer, + } + } +} + +/// The typed busy event; each stage has its own fixed message so the log +/// shipper can map it to a code (`log-shipper/diagnostics.json`). +fn log_busy(stage: SqlBusyStage, bound: Duration, waited: Duration) { + let bound_ms = bound.as_millis() as u64; + let waited_ms = waited.as_millis() as u64; + let stage_name = stage.as_str(); + match stage { + SqlBusyStage::LockWait => tracing::warn!( + service = "sql", + error_class = "sql_busy", + stage = stage_name, + bound_ms, + waited_ms, + "SQL busy: lock wait" + ), + SqlBusyStage::Hydration => tracing::warn!( + service = "sql", + error_class = "sql_busy", + stage = stage_name, + bound_ms, + waited_ms, + "SQL busy: hydration" + ), + SqlBusyStage::ArtifactTransfer => tracing::warn!( + service = "sql", + error_class = "sql_busy", + stage = stage_name, + bound_ms, + waited_ms, + "SQL busy: artifact transfer" + ), + } +} + #[cfg(test)] mod tests { use super::*; @@ -1954,12 +2402,16 @@ mod tests { u64::MAX, repo.clone(), ); + // The bound is above every bounded wait on this path (lock 30 s, + // hydration 30 s, transfer 45 s), so a slow-but-bounded stall + // surfaces as a typed `Busy(stage)` naming the stage; only an + // unbounded wait trips this timeout (TC-1317 review). let run = |db: &'static str, request: SqlRequest, ability: &'static str| { let service = &service; let space = &space; async move { tokio::time::timeout( - std::time::Duration::from_secs(10), + std::time::Duration::from_secs(60), service.execute(space, db, request, None, ability.to_string()), ) .await @@ -2000,7 +2452,7 @@ mod tests { .expect_err("a read whose hydration failed must fail"); assert!(matches!(err, SqlError::Unavailable), "{err:?}"); let served = tokio::time::timeout( - std::time::Duration::from_secs(10), + std::time::Duration::from_secs(60), cold.execute(&space, "a", count(), None, "tinycloud.sql/read".into()), ) .await @@ -2161,4 +2613,655 @@ mod tests { }; assert_eq!(query.rows, vec![vec![SqlValue::Text("Recovered".into())]]); } + + // TC-1274: bounded waits, deadline cuts, and cancel safety. + + /// Holds `load` and the saves until their gate opens; counts loads and + /// saves that have reached the gate. + struct GatedArtifactRepository { + inner: Arc, + loads: std::sync::atomic::AtomicUsize, + saves_waiting: std::sync::atomic::AtomicUsize, + /// Once through the gate, `load` fails as storage being unavailable. + fail_loads: std::sync::atomic::AtomicBool, + load_open: tokio::sync::watch::Sender, + save_open: tokio::sync::watch::Sender, + } + + impl GatedArtifactRepository { + fn new(inner: Arc) -> Arc { + Arc::new(Self { + inner, + loads: Default::default(), + saves_waiting: Default::default(), + fail_loads: Default::default(), + load_open: tokio::sync::watch::channel(true).0, + save_open: tokio::sync::watch::channel(true).0, + }) + } + + fn loads(&self) -> usize { + self.loads.load(Ordering::SeqCst) + } + + async fn pass(gate: &tokio::sync::watch::Sender) { + let mut open = gate.subscribe(); + let _ = open.wait_for(|open| *open).await; + } + } + + #[async_trait] + impl DatabaseArtifactRepository for GatedArtifactRepository { + async fn load( + &self, + service: &str, + space: &str, + name: &str, + ) -> Result, DatabaseArtifactError> { + self.loads.fetch_add(1, Ordering::SeqCst); + Self::pass(&self.load_open).await; + if self.fail_loads.load(Ordering::SeqCst) { + return Err(DatabaseArtifactError::Db(DbErr::ConnectionAcquire( + sea_orm::error::ConnAcquireErr::Timeout, + ))); + } + self.inner.load(service, space, name).await + } + + async fn save( + &self, + service: &str, + space: &str, + name: &str, + payload: Vec, + expected: ArtifactExpectation, + ) -> Result { + self.saves_waiting.fetch_add(1, Ordering::SeqCst); + Self::pass(&self.save_open).await; + self.inner + .save(service, space, name, payload, expected) + .await + } + + async fn save_delta( + &self, + service: &str, + space: &str, + name: &str, + payload: Vec, + expected: ArtifactExpectation, + ) -> Result { + self.saves_waiting.fetch_add(1, Ordering::SeqCst); + Self::pass(&self.save_open).await; + self.inner + .save_delta(service, space, name, payload, expected) + .await + } + } + + fn wait_bounds(millis: u64) -> SqlWaitBounds { + let bound = Duration::from_millis(millis); + SqlWaitBounds { + lock_wait: bound, + hydration_wait: bound, + artifact_transfer: bound, + hydration_max: Duration::from_secs(600), + } + } + + /// A durable database `a` in a fresh space, holding one row. + async fn seeded(name: &str) -> (Arc, SpaceId) { + let repo = artifact_repository().await; + let space = test_space_id(name); + let cache = TempDir::new().unwrap(); + SqlService::new( + cache.path().to_string_lossy().into_owned(), + u64::MAX, + repo.clone(), + ) + .execute( + &space, + "a", + insert("seed"), + None, + "tinycloud.sql/write".into(), + ) + .await + .unwrap(); + (repo, space) + } + + fn rows(result: SqlExecutionResult) -> i64 { + let SqlResponse::Query(query) = result.response else { + panic!("query result required") + }; + match query.rows[..] { + [ref row] => match row[..] { + [SqlValue::Integer(count)] => count, + _ => panic!("one integer column required"), + }, + _ => panic!("one row required"), + } + } + + async fn read(service: &SqlService, space: &SpaceId) -> Result { + service + .execute(space, "a", count(), None, "tinycloud.sql/read".into()) + .await + } + + const PATIENCE: Duration = Duration::from_secs(10); + + #[tokio::test] + async fn tc1274_a_held_operation_lock_answers_sql_busy_lock_wait() { + let (repo, space) = seeded("sql-busy-lock").await; + let cache = TempDir::new().unwrap(); + let service = SqlService::new(cache.path().to_string_lossy().into_owned(), u64::MAX, repo) + .with_wait_bounds(wait_bounds(200)); + let held = service.operation_lock(&space, "a").await.lock_owned().await; + + let err = tokio::time::timeout(PATIENCE, read(&service, &space)) + .await + .expect("the waiter must give up at its bound") + .expect_err("a held lock must answer busy"); + assert!( + matches!(err, SqlError::Busy(SqlBusyStage::LockWait)), + "{err:?}" + ); + assert!(err.to_string().starts_with("sql_busy: lock_wait:"), "{err}"); + + // Another database in the same space is unaffected. + service + .execute(&space, "b", insert("x"), None, "tinycloud.sql/write".into()) + .await + .unwrap(); + drop(held); + assert_eq!(rows(read(&service, &space).await.unwrap()), 1); + } + + #[tokio::test] + async fn tc1274_a_stalled_hydration_answers_busy_and_still_warms_once() { + let (inner, space) = seeded("sql-busy-hydration").await; + let repo = GatedArtifactRepository::new(inner); + repo.load_open.send_replace(false); + let cache = TempDir::new().unwrap(); + let service = SqlService::new( + cache.path().to_string_lossy().into_owned(), + u64::MAX, + repo.clone(), + ) + .with_wait_bounds(wait_bounds(200)); + + for caller in ["first", "second"] { + let err = tokio::time::timeout(PATIENCE, read(&service, &space)) + .await + .unwrap_or_else(|_| panic!("the {caller} caller must give up at its bound")) + .expect_err("a stalled artifact load must answer busy"); + assert!( + matches!(err, SqlError::Busy(SqlBusyStage::ArtifactTransfer)), + "{caller}: {err:?}" + ); + } + assert_eq!(repo.loads(), 1, "the second caller joined the hydration"); + + // The hydration was never abandoned: once its load completes, the + // database is warm and the next request needs no load of its own. + repo.load_open.send_replace(true); + let served = tokio::time::timeout(PATIENCE, async { + loop { + match read(&service, &space).await { + Ok(result) => break result, + Err(SqlError::Busy(_)) => tokio::time::sleep(Duration::from_millis(20)).await, + Err(error) => panic!("{error:?}"), + } + } + }) + .await + .expect("the hydration must complete"); + assert_eq!(rows(served), 1); + assert_eq!(repo.loads(), 1, "exactly one hydration ran"); + } + + #[tokio::test] + async fn tc1274_a_request_cut_by_its_deadline_releases_the_lock() { + let (inner, space) = seeded("sql-deadline-cut").await; + let repo = GatedArtifactRepository::new(inner); + repo.load_open.send_replace(false); + let cache = TempDir::new().unwrap(); + let service = SqlService::new( + cache.path().to_string_lossy().into_owned(), + u64::MAX, + repo.clone(), + ) + .with_wait_bounds(wait_bounds(30_000)); + + let cut = tokio::time::timeout( + PATIENCE, + crate::request_cancel::run_with_deadline( + Some(Duration::from_millis(300)), + read(&service, &space), + ), + ) + .await + .expect("the deadline must cut the request"); + assert!( + matches!(cut, Err(crate::request_cancel::DeadlineExceeded)), + "{cut:?}" + ); + let lock = service.operation_lock(&space, "a").await; + tokio::time::timeout(Duration::from_secs(2), lock.lock_owned()) + .await + .expect("a cut request must release the operation lock"); + + repo.load_open.send_replace(true); + assert_eq!(rows(read(&service, &space).await.unwrap()), 1); + assert_no_temp_files(cache.path()); + } + + #[tokio::test] + async fn tc1274_a_latched_write_reports_its_true_outcome_past_the_deadline() { + let (inner, space) = seeded("sql-deadline-latched").await; + let repo = GatedArtifactRepository::new(inner); + let cache = TempDir::new().unwrap(); + let service = SqlService::new( + cache.path().to_string_lossy().into_owned(), + u64::MAX, + repo.clone(), + ); + read(&service, &space).await.unwrap(); + + repo.save_open.send_replace(false); + let writer = service.clone(); + let write_space = space.clone(); + let request = tokio::spawn(crate::request_cancel::run_with_deadline( + Some(Duration::from_millis(200)), + async move { + writer + .execute( + &write_space, + "a", + insert("late"), + None, + "tinycloud.sql/write".into(), + ) + .await + }, + )); + // The write is latched before it reaches its save; once it waits + // there, run past the deadline before letting it finish. + tokio::time::timeout(PATIENCE, async { + while repo.saves_waiting.load(Ordering::SeqCst) == 0 { + tokio::time::sleep(Duration::from_millis(10)).await; + } + }) + .await + .expect("the write must reach its save"); + tokio::time::sleep(Duration::from_millis(300)).await; + repo.save_open.send_replace(true); + let outcome = tokio::time::timeout(PATIENCE, request) + .await + .expect("the write must finish") + .unwrap(); + assert!(matches!(outcome, Ok(Ok(_))), "{outcome:?}"); + assert_eq!(rows(read(&service, &space).await.unwrap()), 2); + } + + #[tokio::test] + async fn tc1274_a_dropped_caller_never_leaves_a_half_applied_write() { + let (inner, space) = seeded("sql-dropped-writer").await; + let repo = GatedArtifactRepository::new(inner.clone()); + let cache = TempDir::new().unwrap(); + let service = SqlService::new( + cache.path().to_string_lossy().into_owned(), + u64::MAX, + repo.clone(), + ); + read(&service, &space).await.unwrap(); + + repo.save_open.send_replace(false); + let writer = service.clone(); + let write_space = space.clone(); + let caller = tokio::spawn(async move { + writer + .execute( + &write_space, + "a", + insert("second"), + None, + "tinycloud.sql/write".into(), + ) + .await + }); + tokio::time::timeout(PATIENCE, async { + while repo.saves_waiting.load(Ordering::SeqCst) == 0 { + tokio::time::sleep(Duration::from_millis(10)).await; + } + }) + .await + .expect("the write must reach its save"); + caller.abort(); + let _ = caller.await; + repo.save_open.send_replace(true); + + // The write the actor applied is made durable, not left live-only: a + // cold service over the same store sees it once the save lands. + let cold_cache = TempDir::new().unwrap(); + let cold = SqlService::new( + cold_cache.path().to_string_lossy().into_owned(), + u64::MAX, + inner, + ); + tokio::time::timeout(PATIENCE, async { + loop { + let durable = rows(read(&cold, &space).await.unwrap()); + if durable == 2 { + break; + } + assert_eq!(durable, 1, "only the seed row or both rows"); + cold.discard_local_state(&(space.to_string(), "a".to_string())) + .await + .unwrap(); + tokio::time::sleep(Duration::from_millis(20)).await; + } + }) + .await + .expect("the dropped caller's write must still be persisted"); + assert_eq!(rows(read(&service, &space).await.unwrap()), 2); + } + + /// TC-1274 B1: a save whose write statement is already on the wire when + /// its bound expires can still commit (PostgreSQL does not cancel it), so + /// the request must answer `outcome_unknown`, never a `sql_busy` that + /// invites a retry applying the write twice. + #[tokio::test] + async fn postgres_a_save_expiring_after_its_write_was_sent_is_an_unknown_outcome() { + use crate::sea_orm::{ConnectionTrait, TransactionTrait}; + const TEST: &str = + "postgres_a_save_expiring_after_its_write_was_sent_is_an_unknown_outcome"; + let Some(schema) = crate::test_support::PostgresTestSchema::new(TEST).await else { + return; + }; + // One connection, so the delta UPDATE below is already prepared on it + // and the timed-out save's statement is executing, not still parsing. + let repo = Arc::new(SeaOrmDatabaseArtifactRepository::new( + schema.connect(1).await, + )); + let space = test_space_id("sql-save-in-flight"); + let cache = TempDir::new().unwrap(); + let service = SqlService::new( + cache.path().to_string_lossy().into_owned(), + u64::MAX, + repo.clone(), + ) + .with_wait_bounds(SqlWaitBounds { + artifact_transfer: Duration::from_millis(500), + ..SqlWaitBounds::default() + }); + for value in ["seed", "warm"] { + service + .execute( + &space, + "a", + insert(value), + None, + "tinycloud.sql/write".into(), + ) + .await + .unwrap(); + } + + // Readers pass; the save's UPDATE waits on the lock, already sent. + let locker = schema.connect(1).await; + let lock = locker.begin().await.unwrap(); + lock.execute_unprepared("LOCK TABLE database_artifact IN EXCLUSIVE MODE") + .await + .unwrap(); + let outcome = tokio::time::timeout( + PATIENCE, + service.execute( + &space, + "a", + insert("once"), + None, + "tinycloud.sql/write".into(), + ), + ) + .await; + // Release before asserting: a failed assertion must not leave the + // lock held while the schema is dropped. + lock.commit().await.unwrap(); + let err = outcome + .expect("the save's bound must expire") + .expect_err("a save that expired must fail"); + assert!(matches!(err, SqlError::OutcomeUnknown), "{err:?}"); + + // Released, the write that was in flight commits on its own. + let cold_cache = TempDir::new().unwrap(); + let cold = SqlService::new( + cold_cache.path().to_string_lossy().into_owned(), + u64::MAX, + repo, + ); + tokio::time::timeout(PATIENCE, async { + loop { + let durable = rows(read(&cold, &space).await.unwrap()); + if durable == 3 { + break; + } + assert_eq!(durable, 2, "the write commits once or not yet"); + cold.discard_local_state(&(space.to_string(), "a".to_string())) + .await + .unwrap(); + tokio::time::sleep(Duration::from_millis(20)).await; + } + }) + .await + .expect("the in-flight write committed, which is why it is not retryable"); + } + + /// Hydration temp files (`.tmp..`) left anywhere under + /// `dir` would mean a cache write was abandoned midway. + fn assert_no_temp_files(dir: &Path) { + for entry in std::fs::read_dir(dir).unwrap() { + let path = entry.unwrap().path(); + if path.is_dir() { + assert_no_temp_files(&path); + } else { + let name = path.file_name().unwrap().to_string_lossy(); + assert!(!name.contains(".tmp."), "leftover temp file {path:?}"); + } + } + } + + /// A hydration whose own load outlives `hydration_max` ends `TimedOut`: + /// its callers answer busy, its registry entry is retired, and the next + /// request starts a fresh hydration. + #[tokio::test] + async fn tc1274_a_hydration_past_its_own_bound_is_retired() { + let (inner, space) = seeded("sql-hydration-max").await; + let repo = GatedArtifactRepository::new(inner); + repo.load_open.send_replace(false); + let cache = TempDir::new().unwrap(); + let service = SqlService::new( + cache.path().to_string_lossy().into_owned(), + u64::MAX, + repo.clone(), + ) + .with_wait_bounds(SqlWaitBounds { + hydration_max: Duration::from_millis(200), + ..SqlWaitBounds::default() + }); + + let err = tokio::time::timeout(PATIENCE, read(&service, &space)) + .await + .expect("the hydration's own bound must end the wait") + .expect_err("a hydration that timed out must fail"); + assert!( + matches!(err, SqlError::Busy(SqlBusyStage::ArtifactTransfer)), + "{err:?}" + ); + assert!(service.hydrations.lock().unwrap().is_empty()); + + repo.load_open.send_replace(true); + assert_eq!(rows(read(&service, &space).await.unwrap()), 1); + assert_eq!(repo.loads(), 2, "the next request hydrated afresh"); + assert_no_temp_files(cache.path()); + } + + /// Every caller that joined a hydration sees how it failed. + #[tokio::test] + async fn tc1274_every_joiner_sees_a_failed_hydration() { + let (inner, space) = seeded("sql-joiners-fail").await; + let repo = GatedArtifactRepository::new(inner); + repo.load_open.send_replace(false); + repo.fail_loads.store(true, Ordering::SeqCst); + let cache = TempDir::new().unwrap(); + let service = SqlService::new( + cache.path().to_string_lossy().into_owned(), + u64::MAX, + repo.clone(), + ); + + let first = tokio::spawn({ + let (service, space) = (service.clone(), space.clone()); + async move { read(&service, &space).await } + }); + // The second caller queues behind the first on the operation lock + // and then joins the same failed hydration, or finds it retired and + // starts its own; either way it must fail like the first. + tokio::time::timeout(PATIENCE, async { + while repo.loads() == 0 { + tokio::time::sleep(Duration::from_millis(10)).await; + } + }) + .await + .expect("the hydration must start"); + let joiner = tokio::spawn({ + let (service, space) = (service.clone(), space.clone()); + async move { + let flight = service + .hydrations + .lock() + .unwrap() + .get(&(space.to_string(), "a".to_string())) + .cloned() + .expect("the hydration is in flight"); + service.join_hydration(flight).await + } + }); + repo.load_open.send_replace(true); + let first = tokio::time::timeout(PATIENCE, first) + .await + .unwrap() + .unwrap(); + assert!(matches!(first, Err(SqlError::Unavailable)), "{first:?}"); + let joined = tokio::time::timeout(PATIENCE, joiner) + .await + .unwrap() + .unwrap(); + assert!( + matches!(joined, Ok(HydrationOutcome::Unavailable)), + "{joined:?}" + ); + assert_eq!(repo.loads(), 1, "one hydration served both"); + } + + /// Loads its artifact by panicking once, then normally. + struct PanickingArtifactRepository { + inner: Arc, + panicked: std::sync::atomic::AtomicBool, + } + + #[async_trait] + impl DatabaseArtifactRepository for PanickingArtifactRepository { + async fn load( + &self, + service: &str, + space: &str, + name: &str, + ) -> Result, DatabaseArtifactError> { + if !self.panicked.swap(true, Ordering::SeqCst) { + panic!("injected hydration panic"); + } + self.inner.load(service, space, name).await + } + + async fn save( + &self, + service: &str, + space: &str, + name: &str, + payload: Vec, + expected: ArtifactExpectation, + ) -> Result { + self.inner + .save(service, space, name, payload, expected) + .await + } + + async fn save_delta( + &self, + service: &str, + space: &str, + name: &str, + payload: Vec, + expected: ArtifactExpectation, + ) -> Result { + self.inner + .save_delta(service, space, name, payload, expected) + .await + } + } + + /// TC-1274 M3: a hydration task that panics retires its registry entry, + /// so the database is not wedged until the node restarts. + #[tokio::test] + async fn tc1274_a_panicking_hydration_does_not_wedge_the_database() { + let (inner, space) = seeded("sql-hydration-panic").await; + let repo = Arc::new(PanickingArtifactRepository { + inner, + panicked: Default::default(), + }); + let cache = TempDir::new().unwrap(); + let service = SqlService::new(cache.path().to_string_lossy().into_owned(), u64::MAX, repo); + + let err = tokio::time::timeout(PATIENCE, read(&service, &space)) + .await + .expect("a panicked hydration must not hang its caller") + .expect_err("a panicked hydration must fail"); + assert!(matches!(err, SqlError::Internal(_)), "{err:?}"); + assert!(service.hydrations.lock().unwrap().is_empty()); + let served = tokio::time::timeout(PATIENCE, read(&service, &space)) + .await + .expect("the next request must not join the dead hydration") + .unwrap(); + assert_eq!(rows(served), 1); + } + + /// A write whose deadline passed while it waited is refused at its point + /// of no return, and nothing is applied. + #[tokio::test] + async fn tc1274_a_write_past_its_deadline_is_refused_before_it_starts() { + let (repo, space) = seeded("sql-begin-write-cut").await; + let cache = TempDir::new().unwrap(); + let service = SqlService::new(cache.path().to_string_lossy().into_owned(), u64::MAX, repo); + read(&service, &space).await.unwrap(); + + let context = crate::request_cancel::RequestCancel::new(Duration::ZERO); + let err = crate::request_cancel::within( + Some(Arc::clone(&context)), + service.execute( + &space, + "a", + insert("late"), + None, + "tinycloud.sql/write".into(), + ), + ) + .await + .expect_err("a write past its deadline must not start"); + assert!(matches!(err, SqlError::RequestTimeout), "{err:?}"); + assert!(!context.latch(), "the request was cut, not latched"); + assert_eq!(rows(read(&service, &space).await.unwrap()), 1); + } } diff --git a/tinycloud-core/src/sql/types.rs b/tinycloud-core/src/sql/types.rs index 00527851..2d1ac04c 100644 --- a/tinycloud-core/src/sql/types.rs +++ b/tinycloud-core/src/sql/types.rs @@ -278,4 +278,40 @@ pub enum SqlError { "outcome_unknown: the write may have been applied; read the database back before retrying" )] OutcomeUnknown, + /// A bounded wait gave up before the request's write began, so nothing + /// was applied (TC-1274). A retry after `Retry-After` is safe. + #[error("sql_busy: {0}: the database is busy; retry the request")] + Busy(SqlBusyStage), + /// The request deadline was reached before the request's write began, so + /// nothing was applied (TC-1274). + #[error("request_timeout: no change was applied; retry the request")] + RequestTimeout, +} + +/// Where a [`SqlError::Busy`] request was waiting when its bound expired. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum SqlBusyStage { + /// The per-(space, db) operation lock. + LockWait, + /// Joining a hydration of the database's local cache that is still + /// writing its files. + Hydration, + /// Loading or saving the durable database artifact. + ArtifactTransfer, +} + +impl SqlBusyStage { + pub fn as_str(self) -> &'static str { + match self { + SqlBusyStage::LockWait => "lock_wait", + SqlBusyStage::Hydration => "hydration", + SqlBusyStage::ArtifactTransfer => "artifact_transfer", + } + } +} + +impl std::fmt::Display for SqlBusyStage { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.write_str(self.as_str()) + } } diff --git a/tinycloud-node-server/src/config.rs b/tinycloud-node-server/src/config.rs index 464c951b..ca70f76d 100644 --- a/tinycloud-node-server/src/config.rs +++ b/tinycloud-node-server/src/config.rs @@ -1087,17 +1087,66 @@ pub struct SqlStorageConfig { pub path: Option, #[serde(default = "default_sql_memory_threshold")] pub memory_threshold: ByteUnit, + /// How long a SQL request waits for its database's operation lock + /// before answering `503 sql_busy: lock_wait` (TC-1274). + #[serde(default = "default_sql_lock_wait_timeout_ms")] + pub lock_wait_timeout_ms: u64, + /// How long a SQL request waits for its database to be hydrated before + /// answering `503 sql_busy: hydration` or `artifact_transfer`. The + /// hydration itself keeps going (see `hydration_max_ms`). + #[serde(default = "default_sql_hydration_wait_timeout_ms")] + pub hydration_wait_timeout_ms: u64, + /// How long a durable artifact load or save that a request awaits may + /// take before the request answers `sql_busy: artifact_transfer` (or + /// `outcome_unknown` if the save may have been applied). + #[serde(default = "default_sql_artifact_transfer_timeout_ms")] + pub artifact_transfer_timeout_ms: u64, + /// How long a hydration's own artifact load may take. It outlives the + /// callers that gave up on it, so the database still warms. + #[serde(default = "default_sql_hydration_max_ms")] + pub hydration_max_ms: u64, } fn default_sql_memory_threshold() -> ByteUnit { ByteUnit::Mebibyte(10) } +fn default_sql_lock_wait_timeout_ms() -> u64 { + 30_000 +} + +fn default_sql_hydration_wait_timeout_ms() -> u64 { + 30_000 +} + +fn default_sql_artifact_transfer_timeout_ms() -> u64 { + 45_000 +} + +fn default_sql_hydration_max_ms() -> u64 { + 600_000 +} + +impl SqlStorageConfig { + pub fn wait_bounds(&self) -> tinycloud_core::sql::SqlWaitBounds { + tinycloud_core::sql::SqlWaitBounds { + lock_wait: Duration::from_millis(self.lock_wait_timeout_ms), + hydration_wait: Duration::from_millis(self.hydration_wait_timeout_ms), + artifact_transfer: Duration::from_millis(self.artifact_transfer_timeout_ms), + hydration_max: Duration::from_millis(self.hydration_max_ms), + } + } +} + impl Default for SqlStorageConfig { fn default() -> Self { Self { path: None, memory_threshold: default_sql_memory_threshold(), + lock_wait_timeout_ms: default_sql_lock_wait_timeout_ms(), + hydration_wait_timeout_ms: default_sql_hydration_wait_timeout_ms(), + artifact_transfer_timeout_ms: default_sql_artifact_transfer_timeout_ms(), + hydration_max_ms: default_sql_hydration_max_ms(), } } } @@ -1327,7 +1376,8 @@ pub struct DatabaseConfig { /// this window (~40 s) of connection-loss detection rather than two /// detections (~60 s). It is not a request or per-db lock deadline: /// acquisition waits, legitimate transfers and queueing behind the lock - /// add to it (the general deadline is later TC-1054 work). + /// add to it (those are bounded by `invocation.deadline_ms` and the + /// `storage.sql` wait bounds, TC-1274). #[serde(default = "default_database_retry_window_ms")] pub retry_window_ms: u64, } @@ -1447,16 +1497,33 @@ pub struct InvocationConfig { /// rows arbitrarily far into the future. #[serde(default = "default_invocation_max_lifetime_secs")] pub max_lifetime_secs: u64, + /// `/invoke` deadline in milliseconds (TC-1274); zero turns it off. A + /// request that has not begun a write by then is stopped and answered + /// `503 request_timeout`; one that has completes and reports its outcome. + /// The default sits below the ingress's 60 s, so the node answers first. + #[serde(default = "default_invocation_deadline_ms")] + pub deadline_ms: u64, } fn default_invocation_max_lifetime_secs() -> u64 { 300 } +fn default_invocation_deadline_ms() -> u64 { + 55_000 +} + +impl InvocationConfig { + pub fn deadline(&self) -> Option { + (self.deadline_ms > 0).then(|| Duration::from_millis(self.deadline_ms)) + } +} + impl Default for InvocationConfig { fn default() -> Self { Self { max_lifetime_secs: default_invocation_max_lifetime_secs(), + deadline_ms: default_invocation_deadline_ms(), } } } diff --git a/tinycloud-node-server/src/lib.rs b/tinycloud-node-server/src/lib.rs index d9f12c4e..3ebc2575 100644 --- a/tinycloud-node-server/src/lib.rs +++ b/tinycloud-node-server/src/lib.rs @@ -674,7 +674,8 @@ pub async fn app_with_control( tinycloud_config.storage.sql.path.clone().expect("resolved"), tinycloud_config.storage.sql.memory_threshold.as_u64(), database_artifact_repository.clone(), - ); + ) + .with_wait_bounds(tinycloud_config.storage.sql.wait_bounds()); let mut policy_v3_runtime = PolicyV3Runtime::new(seed_conn.clone(), key_setup.node_did(), key_setup.clone()) @@ -948,12 +949,13 @@ pub async fn app_with_control( /// preflight after the policy in [`cors_fairing`] is tightened. const CORS_PREFLIGHT_MAX_AGE_SECS: u32 = 7200; -/// `Retry-After` on a database failure that is safe to retry (TC-1054). +/// `Retry-After` on a failure that is safe to retry (TC-1054, TC-1274). /// -/// Routes report database failures as plain-text `(Status, String)`; a -/// retryable one is a `503` whose body starts with -/// [`routes::UNAVAILABLE_RETRYABLE`]. Other `503`s (cutover fence, missing -/// configuration) and the `500` [`routes::OUTCOME_UNKNOWN`] get no header. +/// Routes report these as plain-text `(Status, String)` `503`s whose body +/// starts with [`routes::UNAVAILABLE_RETRYABLE`] or +/// [`routes::REQUEST_TIMEOUT`] (`Retry-After: 1`), or [`routes::SQL_BUSY`] +/// (`Retry-After: 5`). Other `503`s (cutover fence, missing configuration) +/// and the `500` [`routes::OUTCOME_UNKNOWN`] get no header. fn retry_after_fairing() -> AdHoc { AdHoc::on_response("Retry-After", |_, resp| { Box::pin(async move { @@ -963,11 +965,17 @@ fn retry_after_fairing() -> AdHoc { let Ok(body) = resp.body_mut().to_string().await else { return; }; - if body.starts_with(routes::UNAVAILABLE_RETRYABLE) { - resp.set_header(Header::new( - "Retry-After", - routes::RETRY_AFTER_SECS.to_string(), - )); + let retry_after = if body.starts_with(routes::SQL_BUSY) { + Some(routes::SQL_BUSY_RETRY_AFTER_SECS) + } else if body.starts_with(routes::UNAVAILABLE_RETRYABLE) + || body.starts_with(routes::REQUEST_TIMEOUT) + { + Some(routes::RETRY_AFTER_SECS) + } else { + None + }; + if let Some(secs) = retry_after { + resp.set_header(Header::new("Retry-After", secs.to_string())); } resp.set_sized_body(body.len(), std::io::Cursor::new(body)); }) @@ -1699,6 +1707,21 @@ mod retry_after_fairing_tests { ) } + #[get("/busy")] + fn busy() -> (Status, String) { + let error = + tinycloud_core::sql::SqlError::Busy(tinycloud_core::sql::SqlBusyStage::LockWait); + (Status::ServiceUnavailable, error.to_string()) + } + + #[get("/timeout")] + fn timeout() -> (Status, String) { + ( + Status::ServiceUnavailable, + routes::REQUEST_TIMEOUT_BODY.to_string(), + ) + } + /// TC-1054: clients tell a retryable database failure (503, /// `unavailable_retryable`, `Retry-After`) from one whose write may have /// applied (500, `outcome_unknown`, no `Retry-After`); CORS still applies. @@ -1706,7 +1729,7 @@ mod retry_after_fairing_tests { async fn only_retryable_database_failures_carry_retry_after() { let client = Client::tracked( rocket::build() - .mount("/", routes![retryable, unknown, fenced]) + .mount("/", routes![retryable, unknown, fenced, busy, timeout]) .attach(retry_after_fairing()) .attach(cors_fairing()), ) @@ -1723,6 +1746,23 @@ mod retry_after_fairing_tests { let body = response.into_string().await.unwrap(); assert_eq!(body, "unavailable_retryable: pool exhausted", "body kept"); + // TC-1274: a busy database asks for a longer pause than a request + // that timed out before writing. + for (path, retry_after) in [("/busy", "5"), ("/timeout", "1")] { + let response = client.get(path).dispatch().await; + assert_eq!(response.status(), Status::ServiceUnavailable, "{path}"); + assert_eq!( + response.headers().get_one("Retry-After"), + Some(retry_after), + "{path}" + ); + assert_eq!( + response.headers().get_one("Access-Control-Allow-Origin"), + Some("*"), + "{path}" + ); + } + for path in ["/unknown", "/fenced"] { let response = client.get(path).dispatch().await; assert!( @@ -1737,4 +1777,133 @@ mod retry_after_fairing_tests { assert!(!response.into_string().await.unwrap().is_empty(), "{path}"); } } + + /// An artifact store that never answers, so a cold SQL database never + /// finishes hydrating. + struct StalledArtifacts; + + #[async_trait::async_trait] + impl tinycloud_core::database_artifacts::DatabaseArtifactRepository for StalledArtifacts { + async fn load( + &self, + _: &str, + _: &str, + _: &str, + ) -> Result< + Option, + tinycloud_core::database_artifacts::DatabaseArtifactError, + > { + std::future::pending().await + } + + async fn save( + &self, + _: &str, + _: &str, + _: &str, + _: Vec, + _: tinycloud_core::database_artifacts::ArtifactExpectation, + ) -> Result< + tinycloud_core::database_artifacts::DatabaseArtifact, + tinycloud_core::database_artifacts::DatabaseArtifactError, + > { + std::future::pending().await + } + + async fn save_delta( + &self, + _: &str, + _: &str, + _: &str, + _: Vec, + _: tinycloud_core::database_artifacts::ArtifactExpectation, + ) -> Result< + tinycloud_core::database_artifacts::DeltaSave, + tinycloud_core::database_artifacts::DatabaseArtifactError, + > { + std::future::pending().await + } + } + + /// A SQL read through the `/invoke` deadline wrapper and the real SQL + /// service, as the route runs it. + #[rocket::post("/stalled-sql")] + async fn stalled_sql( + config: &rocket::State, + sql: &rocket::State, + space: &rocket::State, + ) -> Result { + routes::with_invoke_deadline( + config, + Box::pin(async move { + sql.execute( + space, + "a", + tinycloud_core::sql::SqlRequest::Query { + sql: "SELECT 1".into(), + params: Vec::new(), + max_rows: None, + max_bytes: None, + }, + None, + "tinycloud.sql/read".into(), + ) + .await + .map(|_| "served".to_string()) + .map_err(|error| (routes::sql_error_to_status(&error), error.to_string()).into()) + }), + ) + .await + } + + /// TC-1274: over HTTP, a SQL request stalled in hydration is answered at + /// the deadline with `503 request_timeout`, `Retry-After: 1` and CORS. + #[tokio::test] + async fn a_stalled_sql_request_is_answered_at_its_deadline() { + use tinycloud_auth::{ + resolver::DID_METHODS, + ssi::{dids::DIDBuf, jwk::JWK}, + }; + let jwk = JWK::generate_ed25519().unwrap(); + let did: DIDBuf = DID_METHODS.generate(&jwk, "key").unwrap(); + let space = tinycloud_auth::resource::SpaceId::new(did, "default".parse().unwrap()); + let cache = tempfile::TempDir::new().unwrap(); + let sql = tinycloud_core::sql::SqlService::new( + cache.path().to_string_lossy().into_owned(), + u64::MAX, + std::sync::Arc::new(StalledArtifacts), + ); + let mut config = crate::config::Config::default(); + config.invocation.deadline_ms = 300; + let client = Client::tracked( + rocket::build() + .mount("/", rocket::routes![stalled_sql]) + .manage(config) + .manage(sql) + .manage(space) + .attach(retry_after_fairing()) + .attach(cors_fairing()), + ) + .await + .expect("valid Rocket instance"); + + let started = std::time::Instant::now(); + let response = tokio::time::timeout( + std::time::Duration::from_secs(10), + client.post("/stalled-sql").dispatch(), + ) + .await + .expect("the deadline must answer the request"); + assert!(started.elapsed() < std::time::Duration::from_secs(5)); + assert_eq!(response.status(), Status::ServiceUnavailable); + assert_eq!(response.headers().get_one("Retry-After"), Some("1")); + assert_eq!( + response.headers().get_one("Access-Control-Allow-Origin"), + Some("*") + ); + assert_eq!( + response.into_string().await.unwrap(), + routes::REQUEST_TIMEOUT_BODY + ); + } } diff --git a/tinycloud-node-server/src/routes/mod.rs b/tinycloud-node-server/src/routes/mod.rs index 582dadbc..2916a358 100644 --- a/tinycloud-node-server/src/routes/mod.rs +++ b/tinycloud-node-server/src/routes/mod.rs @@ -8,6 +8,7 @@ use serde::{Deserialize, Serialize}; use sha2::{Digest, Sha256}; use std::{ collections::{BTreeMap, HashMap, HashSet}, + future::Future, time::Instant, }; use time::{format_description::well_known::Rfc3339, OffsetDateTime}; @@ -52,6 +53,7 @@ use tinycloud_core::{ models::{ hook_delivery, hook_subscription, invocation as invocation_model, kv_delete, kv_write, }, + request_cancel, sea_orm::{ColumnTrait, DbErr, EntityTrait, QueryFilter, QueryOrder}, sql::{SqlCaveats, SqlError, SqlRequest, SqlService}, storage::{HashBuffer, ImmutableReadStore, ImmutableStaging}, @@ -122,8 +124,21 @@ pub const UNAVAILABLE_RETRYABLE: &str = "unavailable_retryable"; /// Body prefix of a database failure after a write may have been applied; /// the response is a `500` with no `Retry-After` (TC-1054). pub const OUTCOME_UNKNOWN: &str = "outcome_unknown"; -/// `Retry-After` on an [`UNAVAILABLE_RETRYABLE`] response, in seconds. +/// `Retry-After` on an [`UNAVAILABLE_RETRYABLE`] or [`REQUEST_TIMEOUT`] +/// response, in seconds. pub const RETRY_AFTER_SECS: u32 = 1; +/// Body prefix of a `503` whose SQL database stayed busy past a wait bound +/// before the request's write began: `sql_busy: : ...` (TC-1274). +pub const SQL_BUSY: &str = "sql_busy"; +/// `Retry-After` on a [`SQL_BUSY`] response, in seconds. Longer than the +/// retryable one: the request already waited its bound on a database that is +/// still busy, and an immediate retry only lengthens the queue. +pub const SQL_BUSY_RETRY_AFTER_SECS: u32 = 5; +/// Body prefix of a `503` whose `/invoke` deadline was reached before any +/// write began (TC-1274). +pub const REQUEST_TIMEOUT: &str = "request_timeout"; +/// The whole body of a [`REQUEST_TIMEOUT`] response. +pub const REQUEST_TIMEOUT_BODY: &str = "request_timeout: no change was applied; retry the request"; /// The response to a database failure of an operation (TC-1054): /// @@ -732,21 +747,24 @@ pub async fn invoke( duckdb_service: &State, hook_runtime: &State, ) -> Result::Readable>, InvokeError> { - invoke_impl( - i, - req_span, - headers, - data, - staging, - tinycloud, + with_invoke_deadline( config, - quota_cache, - invocation_replay_cache, - policy_v3, - encryption, - sql_service, - duckdb_service, - hook_runtime, + Box::pin(invoke_impl( + i, + req_span, + headers, + data, + staging, + tinycloud, + config, + quota_cache, + invocation_replay_cache, + policy_v3, + encryption, + sql_service, + duckdb_service, + hook_runtime, + )), ) .await } @@ -769,25 +787,48 @@ pub async fn invoke( sql_service: &State, hook_runtime: &State, ) -> Result::Readable>, InvokeError> { - invoke_impl( - i, - req_span, - headers, - data, - staging, - tinycloud, + with_invoke_deadline( config, - quota_cache, - invocation_replay_cache, - policy_v3, - encryption, - sql_service, - (), - hook_runtime, + Box::pin(invoke_impl( + i, + req_span, + headers, + data, + staging, + tinycloud, + config, + quota_cache, + invocation_replay_cache, + policy_v3, + encryption, + sql_service, + (), + hook_runtime, + )), ) .await } +/// Run an `/invoke` handler under the request deadline (TC-1274). Before its +/// first write the deadline drops the handler and answers [`REQUEST_TIMEOUT`]; +/// after it, the handler finishes and its own result is returned. +/// +/// The handler arrives boxed: it is large, and holding it inline in the route +/// future overflows the test threads' stacks in debug builds. +pub(crate) async fn with_invoke_deadline( + config: &Config, + handler: std::pin::Pin>>>, +) -> Result { + request_cancel::run_with_deadline(config.invocation.deadline(), handler) + .await + .unwrap_or_else(|request_cancel::DeadlineExceeded| { + Err(InvokeError::Text( + Status::ServiceUnavailable, + REQUEST_TIMEOUT_BODY.to_string(), + )) + }) +} + #[cfg(feature = "duckdb")] type DuckDbInvokeState<'a> = &'a State; #[cfg(not(feature = "duckdb"))] @@ -1752,6 +1793,10 @@ async fn invoke_impl( .check_and_insert(&admitted, config.invocation.max_lifetime_secs) .await?; } + // TC-1274: the decrypt records its audit and rewraps the key; + // from here the deadline no longer cuts the request. + let latched = request_cancel::latch(); + debug_assert!(latched, "a cut handler is not polled again"); let verified = encryption .decrypt_authorized(&network, &admitted.invocation().0, &body) .await @@ -1811,6 +1856,7 @@ async fn invoke_impl( // Reject quarantined paths and an active cutover fence before // verify_auth_admitted persists invoked_abilities. A rejected // request must never become migration attribution evidence. + request_cancel::set_stage(request_cancel::Stage::IdentityResolution); if tinycloud.effective_database_fence(config.database.write_fence) .await.map_err(identity_resolution_error)? { return Err((Status::ServiceUnavailable, "SQL identity cutover fence is active".into()).into()); @@ -1818,6 +1864,7 @@ async fn invoke_impl( let (space, path, _) = select_database_scope(&sql_caps, "sql")?; database_migration::resolve(tinycloud.connection(), "sql", &space.to_string(), path) .await.map_err(identity_resolution_error)?; + request_cancel::set_stage(request_cancel::Stage::Other); if policy_session_invocation { invocation_replay_cache .check_and_insert_invoker_nonce(admitted.invocation(), 60) @@ -1869,6 +1916,7 @@ async fn invoke_impl( .collect(); if !duckdb_caps.is_empty() { + request_cancel::set_stage(request_cancel::Stage::IdentityResolution); if tinycloud.effective_database_fence(config.database.write_fence) .await.map_err(identity_resolution_error)? { return Err((Status::ServiceUnavailable, "DuckDB identity cutover fence is active".into()).into()); @@ -1876,6 +1924,7 @@ async fn invoke_impl( let (space, path, _) = select_database_scope(&duckdb_caps, "duckdb")?; database_migration::resolve(tinycloud.connection(), "duckdb", &space.to_string(), path) .await.map_err(identity_resolution_error)?; + request_cancel::set_stage(request_cancel::Stage::Other); if policy_session_invocation { invocation_replay_cache .check_and_insert_invoker_nonce(admitted.invocation(), 60) @@ -2516,6 +2565,7 @@ async fn handle_sql_invoke( config: &State, sql_caps: &[(tinycloud_auth::resource::SpaceId, Option, String)], ) -> Result::Readable>, InvokeError> { + request_cancel::set_stage(request_cancel::Stage::IdentityResolution); if tinycloud .effective_database_fence(config.database.write_fence) .await @@ -2527,6 +2577,7 @@ async fn handle_sql_invoke( ) .into()); } + request_cancel::set_stage(request_cancel::Stage::Other); // W1 (D): derive the SQL caveat from the VALIDATED delegation chain, // NOT from the invoker's own invocation facts. The invocation-facts // path is a holdover (and is still consulted as a fallback so the @@ -2570,9 +2621,11 @@ async fn handle_sql_invoke( // N3 will resolve this logical identity through an explicit alias table. // Do not fall back to the legacy final-segment selector here. let space_id = space.to_string(); + request_cancel::set_stage(request_cancel::Stage::IdentityResolution); let db_name = database_migration::resolve(tinycloud.connection(), "sql", &space_id, path) .await .map_err(identity_resolution_error)?; + request_cancel::set_stage(request_cancel::Stage::Other); let sql_request: SqlRequest = serde_json::from_str(&body_str).map_err(|e| (Status::BadRequest, e.to_string()))?; @@ -2639,6 +2692,16 @@ async fn handle_sql_invoke( None }; let execute_start = Instant::now(); + if publication_command + .as_ref() + .is_some_and(|command| command["operation"] == "unfreeze_legacy") + { + // TC-1274: releasing the legacy freeze is publication's only write, + // and it never reaches the SQL service; the read-only commands stay + // cuttable. + let latched = request_cancel::latch(); + debug_assert!(latched, "a cut handler is not polled again"); + } let execute_result = if let Some(command) = publication_command { meeting_publication::execute(tinycloud, sql_service, space, command).await } else if full_space.is_some() { @@ -3041,7 +3104,7 @@ fn json_to_sql_value(v: &serde_json::Value) -> Result Status { +pub(crate) fn sql_error_to_status(err: &SqlError) -> Status { match err { SqlError::Sqlite(_) => Status::BadRequest, SqlError::PermissionDenied(_) => Status::Forbidden, @@ -3056,6 +3119,7 @@ fn sql_error_to_status(err: &SqlError) -> Status { SqlError::Internal(_) => Status::InternalServerError, SqlError::Unavailable => Status::ServiceUnavailable, SqlError::OutcomeUnknown => Status::InternalServerError, + SqlError::Busy(_) | SqlError::RequestTimeout => Status::ServiceUnavailable, } } @@ -3109,6 +3173,7 @@ async fn handle_duckdb_invoke( duckdb_caps: &[(tinycloud_auth::resource::SpaceId, Option, String)], arrow_format: bool, ) -> Result::Readable>, InvokeError> { + request_cancel::set_stage(request_cancel::Stage::IdentityResolution); if tinycloud .effective_database_fence(config.database.write_fence) .await @@ -3120,6 +3185,7 @@ async fn handle_duckdb_invoke( ) .into()); } + request_cancel::set_stage(request_cancel::Stage::Other); let caveats: Option = admitted .invocation() .0 @@ -3145,9 +3211,11 @@ async fn handle_duckdb_invoke( let (space, path, ability) = select_database_scope(duckdb_caps, "duckdb")?; // Keep the logical path separate from any legacy physical artifact name. let space_id = space.to_string(); + request_cancel::set_stage(request_cancel::Stage::IdentityResolution); let db_name = database_migration::resolve(tinycloud.connection(), "duckdb", &space_id, path) .await .map_err(identity_resolution_error)?; + request_cancel::set_stage(request_cancel::Stage::Other); if ability == "tinycloud.duckdb/import" { // Import always grows the database artifact — gate before reading @@ -3176,6 +3244,9 @@ async fn handle_duckdb_invoke( } }; + // TC-1274: the import writes the live cache and the artifact. + let latched = request_cancel::latch(); + debug_assert!(latched, "a cut handler is not polled again"); let import_start = Instant::now(); let import_result = duckdb_service.import_db(space, &db_name, &body_bytes).await; crate::prometheus::observe_span( @@ -3228,6 +3299,11 @@ async fn handle_duckdb_invoke( None }; + // TC-1274: DuckDB's service has no write latch of its own; its + // hydration and statement must not be cut once started. Its waits are + // not bounded either (TC-1274 follow-up). + let latched = request_cancel::latch(); + debug_assert!(latched, "a cut handler is not polled again"); let execute_start = Instant::now(); let execute_result = if full_space.is_some() { duckdb_service @@ -4005,6 +4081,59 @@ mod tests { sql_error_to_status(&SqlError::Internal("x".into())), Status::InternalServerError ); + for error in [ + SqlError::Busy(tinycloud_core::sql::SqlBusyStage::Hydration), + SqlError::RequestTimeout, + ] { + assert_eq!(sql_error_to_status(&error), Status::ServiceUnavailable); + } + assert!(SqlError::Busy(tinycloud_core::sql::SqlBusyStage::Hydration) + .to_string() + .starts_with(&format!("{SQL_BUSY}: hydration:"))); + // The SQL service's own timeout answer is the route's, word for word. + assert_eq!(SqlError::RequestTimeout.to_string(), REQUEST_TIMEOUT_BODY); + } + + /// TC-1274: an `/invoke` that has not begun a write is answered + /// `request_timeout` at its deadline; one that has reports its outcome. + #[tokio::test] + async fn invoke_deadline_cuts_only_before_the_first_write() { + let mut config = Config::default(); + config.invocation.deadline_ms = 50; + let cut = with_invoke_deadline( + &config, + Box::pin(std::future::pending::>()), + ) + .await; + match cut { + Err(InvokeError::Text(status, body)) => { + assert_eq!(status, Status::ServiceUnavailable); + assert_eq!(body, REQUEST_TIMEOUT_BODY); + } + other => panic!("expected request_timeout, got {other:?}"), + } + + let latched = with_invoke_deadline( + &config, + Box::pin(async { + request_cancel::latch(); + tokio::time::sleep(std::time::Duration::from_millis(200)).await; + Ok::<_, InvokeError>("applied") + }), + ) + .await; + assert!(matches!(latched, Ok("applied")), "{latched:?}"); + + config.invocation.deadline_ms = 0; + let unbounded = with_invoke_deadline( + &config, + Box::pin(async { + tokio::time::sleep(std::time::Duration::from_millis(100)).await; + Ok::<_, InvokeError>("served") + }), + ) + .await; + assert!(matches!(unbounded, Ok("served")), "{unbounded:?}"); } fn test_space_id(name: &str) -> SpaceId { diff --git a/tinycloud.toml b/tinycloud.toml index a0325900..6e12edc2 100644 --- a/tinycloud.toml +++ b/tinycloud.toml @@ -20,6 +20,12 @@ cors = true # database = "sqlite:./data/caps.db" # [global.storage.sql] # path = "./data/sql" + ## Wait bounds before a SQL request answers 503 sql_busy (TC-1274). + ## Env: TINYCLOUD_STORAGE__SQL__, e.g. TINYCLOUD_STORAGE__SQL__LOCK_WAIT_TIMEOUT_MS + # lock_wait_timeout_ms = 30000 + # hydration_wait_timeout_ms = 30000 + # artifact_transfer_timeout_ms = 45000 + # hydration_max_ms = 600000 # a hydration keeps warming after its callers give up # [global.storage.duckdb] # path = "./data/duckdb" @@ -43,6 +49,12 @@ cors = true # bulk_statement_timeout_ms = 120000 # retry_window_ms = 10000 +[global.invocation] + ## /invoke deadline (TC-1274): before any write, the request is stopped and + ## answered 503 request_timeout. Keep it below the ingress timeout (60 s). 0 = off. + ## Env: TINYCLOUD_INVOCATION__DEADLINE_MS + # deadline_ms = 55000 + [global.keys] # Provision a unique, persistent root before starting this node. # TINYCLOUD_KEYS__SECRET supplies it; Dstack deployments explicitly