diff --git a/.github/workflows/docker.yml b/.github/workflows/docker.yml index 9cbf6335..67e6ae58 100644 --- a/.github/workflows/docker.yml +++ b/.github/workflows/docker.yml @@ -666,9 +666,9 @@ jobs: native = 'ghcr.io/tinycloudlabs/tinycloud-node' reviewed = native + '@sha256:4bdae4fc232d886bb56bfbce4ec62ed4b8fb4e1369a01f6afb73d06dd68c188f' # TC-959: main's N0 compose (#349 c33c2302…) with the 95m ingress body - # cap (raw d95bfb70…) and TC-1274's Vector config (raw b25b8414…), - # its single node digest normalized to 64 zeros. - n0_template_hash = '009382266172b76ae1858aa79060da5f58ece66a758dd8fd876b96367d96e1db' + # cap (raw d95bfb70…) and the TC-1274 + TC-1317 Vector config + # (raw 1228d819…), its single node digest normalized to 64 zeros. + n0_template_hash = '7fabba70e71423faa2c8b61981d4a7c95ac7c2552074af81c0877af774d6b383' node_pin = re.compile(rb'(?m)^ image: ghcr\.io/tinycloudlabs/tinycloud-node@sha256:([0-9a-f]{64})$') def n0_template(raw): pins = list(node_pin.finditer(raw)) diff --git a/CHANGELOG.md b/CHANGELOG.md index 046c264e..015cde80 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,6 +2,14 @@ ## [Unreleased] +- Authorized reads no longer wait without limit for their audit record (TC-1317). Every read (KV get/list/metadata/sync, capabilities read, and the authorization step of SQL, DuckDB, space info, `/signed/kv` and `/encryption/networks`) waits for its invocation record to commit before its data is returned. That wait used to have no bound, and one serial queue served every account. + - **Bounded wait.** A read waits at most `database.read_audit_wait_ms` (20 s) and is then answered `503 read_audit_busy: the read audit is backlogged; retry the request` with `Retry-After: 5`, without its data. The node refuses to start with `read_audit_wait_ms = 0`, which would answer every read busy. A batch that fails with a transient database error is now `503 unavailable_retryable` instead of 500; other batch failures stay 500, and none of them is reported as 401 any more. + - **The invariant is unchanged and tested:** no read's data is returned unless its audit record has committed. + - **Abandoned records are skipped.** When a batch forms, records whose reader already gave up or was cut are dropped and counted instead of committed. Their data was never returned. This lets a backlog drain on its own instead of needing a restart, and keeps cut SQL requests out of the database-migration attribution evidence. + - **Panic isolation.** A panic while committing one batch fails only that batch; the queue keeps working. + - **Visibility.** New Prometheus metrics: `tinycloud_read_audit_failed_batches_total`, `tinycloud_read_audit_abandoned_total`, `tinycloud_read_audit_busy_total`, and the gauges `tinycloud_read_audit_queue_depth` and `tinycloud_read_audit_in_flight_batch_age_ms`. A watchdog logs `Read audit wait expired`, `Read audit batch slow` (over 5 s), `Read audit batch failed` and `Read audit drain stalled` (a batch in flight over 30 s, including a SQLite writer-lock wait; queued records with no progress for 10 s; or a dead drain, whose reads fail as stopped), each at most once a minute, with counts and durations only. The log shipper maps them to `read_audit_busy`, `read_audit_batch_slow`, `read_audit_batch_failed` and `read_audit_drain_stalled`. A request cut by the `/invoke` deadline while it waits on its audit now logs `stage="read_audit"`. + - **N0 compose.** The embedded Vector configuration is regenerated for these codes, so the reviewed N0 compose template changes to `7fabba70…` (raw `1228d819…`; `docs/releasing.md`). + - **Not covered.** An overall request deadline for `/signed/kv` and `/encryption/networks` is TC-1418; the audit queue's throughput is TC-321. - SQL requests no longer wait without limit, and `/invoke` has a deadline (TC-1274). The cause of the original stall is still unknown; this change bounds the waits and reports them. - **Bounded waits.** A SQL request waits at most `storage.sql.lock_wait_timeout_ms` (30 s) for its database's operation lock, `hydration_wait_timeout_ms` (30 s) for the database to be loaded into the node's cache, and `artifact_transfer_timeout_ms` (45 s) for a durable artifact load or save. It then answers `503 sql_busy: : …` 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. diff --git a/docker-compose.dstack-postgres.yaml b/docker-compose.dstack-postgres.yaml index 7041d572..8ded4d66 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\\\",\\\"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}}}" + 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\\\",\\\"Read audit wait expired\\\":\\\"read_audit_busy\\\",\\\"Read audit batch slow\\\":\\\"read_audit_batch_slow\\\",\\\"Read audit batch failed\\\":\\\"read_audit_batch_failed\\\",\\\"Read audit drain stalled\\\":\\\"read_audit_drain_stalled\\\"}\\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 8e496571..3cf390bb 100644 --- a/docs/releasing.md +++ b/docs/releasing.md @@ -309,11 +309,12 @@ Before any CVM mutation the workflow requires: - the main compose, with its one node digest replaced by 64 zeros, to hash to the reviewed N0 template - **`009382266172b76ae1858aa79060da5f58ece66a758dd8fd876b96367d96e1db`** - (raw `b25b8414c784ee7d66d6e3a507d3dba29818aca5cbf339e85bcb667e2316e20d` normalized: the 1.21.0 compose + **`7fabba70e71423faa2c8b61981d4a7c95ac7c2552074af81c0877af774d6b383`** + (raw `1228d81927fc0a3fbba85745103e77b3112606f5d314d15974d400b222409350` normalized: the 1.21.0 compose `d95bfb707871c1d626c4a8f2b8d32d354103edbb5077847c6a21fe5f7f6cfa50`, template `51f8e9e9…`, with only the embedded Vector config regenerated for TC-1274's - warning codes. That compose is the #349 compose + and TC-1317's warning codes; TC-1274 alone was template `00938226…`, raw + `b25b8414…`. That compose is the #349 compose `c33c23021589163b62a71ef245b7194717711922027629f155bdd5cff806b8c7`, which keeps `TINYCLOUD_EPOCH_HEAD_BACKFILL__ENABLED: "false"`, with only `CLIENT_MAX_BODY_SIZE=32m` → `95m`). Ingress, socat, Vector and the log @@ -378,8 +379,8 @@ gh workflow run docker.yml -R TinyCloudLabs/tinycloud-node --ref main \ The served/OCI identity remains **1.20.6-dstack / e18578ff9162986ddd813259c60f73866e3e60d1**. With the template lock on main this redeploys exactly main's raw compose -`b25b8414c784ee7d66d6e3a507d3dba29818aca5cbf339e85bcb667e2316e20d` -(the 1.21.0 compose `d95bfb70…` with TC-1274's Vector config), whatever digest +`1228d81927fc0a3fbba85745103e77b3112606f5d314d15974d400b222409350` +(the 1.21.0 compose `d95bfb70…` with the TC-1274 and TC-1317 Vector config), whatever digest main's template currently pins. It is not a rollback of a later release across a schema migration. Current pre-N0 tag/pinned equivalents are separately hash-checked; arbitrary same-image config diff --git a/docs/runbooks/tc-959-n0-log-shipping.md b/docs/runbooks/tc-959-n0-log-shipping.md index b9ee8997..b3b1f204 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 | `b25b8414c784ee7d66d6e3a507d3dba29818aca5cbf339e85bcb667e2316e20d` (the 1.21.0 compose `d95bfb70…`, template `51f8e9e9…`, with TC-1274's regenerated Vector config); node digest normalized, template `009382266172b76ae1858aa79060da5f58ece66a758dd8fd876b96367d96e1db`. See [`docs/releasing.md`](../releasing.md#main-release-with-n0-log-shipping-one-dispatch) | +| After the main release: template-locked raw compose | `1228d81927fc0a3fbba85745103e77b3112606f5d314d15974d400b222409350` (the 1.21.0 compose `d95bfb70…`, template `51f8e9e9…`, with the TC-1274 and TC-1317 regenerated Vector config); node digest normalized, template `7fabba70e71423faa2c8b61981d4a7c95ac7c2552074af81c0877af774d6b383`. See [`docs/releasing.md`](../releasing.md#main-release-with-n0-log-shipping-one-dispatch) | The raw after hash identifies the profile-enabled compose, not deployment approval. Record its final reviewed PR head and required CI evidence in the officer handoff. Do not infer a raw-file hash from the distinct application-reported compose hash. diff --git a/log-shipper/canonical.json b/log-shipper/canonical.json index 0a0cfd6c..df1c9c38 100644 --- a/log-shipper/canonical.json +++ b/log-shipper/canonical.json @@ -1,6 +1,6 @@ { "repo": "samgbafa/tinycloud-dev", - "revision": "5a8280c65c6417c02edb4ea7025d5593c65585f8", + "revision": "4adaf13b33c85d0a18f63126fc877776c4ee3dbb", "path": "ops/logging/fields.json", - "sha256": "ac5e127a5a223ea32fa9cb1644b60315ff5c79abcf2f677a14fef7cb0c416437" + "sha256": "02463b9370d88eff282d9c3f5b738f18a169ad6276bacdb9c3d4e60264fb062a" } diff --git a/log-shipper/cases.mjs b/log-shipper/cases.mjs index e53a95da..34559b0b 100644 --- a/log-shipper/cases.mjs +++ b/log-shipper/cases.mjs @@ -43,6 +43,7 @@ export const vectorTests = [ ...[['SQL busy: lock wait', 'sql_busy_lock_wait'], ['SQL busy: hydration', 'sql_busy_hydration'], ['SQL busy: artifact transfer', 'sql_busy_artifact_transfer']].map(([message, code]) => check(`SQL busy warning maps to ${code} without its fields`, envelope({ timestamp, level: 'WARN', target: 'tinycloud_core::sql::service', fields: { message, service: 'sql', error_class: 'sql_busy', stage: canary, bound_ms: 30000, waited_ms: 30001 } }), `.event == "node_warning" && .event_code == "${code}" && .event_count == 1`)), ...[['Request deadline exceeded', 'request_timeout'], ['Request completed after its deadline', 'deadline_overrun']].map(([message, code]) => check(`request deadline warning maps to ${code} without its fields`, envelope({ timestamp, level: 'WARN', target: 'tinycloud_core::request_cancel', fields: { message, error_class: canary, stage: canary, deadline_ms: 55000 } }), `.event == "node_warning" && .event_code == "${code}" && .event_count == 1`)), check('hydration timeout warning maps to sql_hydration_timeout without its fields', envelope({ timestamp, level: 'WARN', target: 'tinycloud_core::sql::service', fields: { message: 'Database hydration gave up loading its artifact', service: 'sql', error_class: canary, bound_ms: 600000 } }), '.event == "node_warning" && .event_code == "sql_hydration_timeout" && .event_count == 1'), + ...[['Read audit wait expired', 'read_audit_busy'], ['Read audit batch slow', 'read_audit_batch_slow'], ['Read audit batch failed', 'read_audit_batch_failed'], ['Read audit drain stalled', 'read_audit_drain_stalled']].map(([message, code]) => check(`read-audit warning maps to ${code} without its fields`, envelope({ timestamp, level: 'WARN', target: 'tinycloud_core::read_audit', fields: { message, error_class: canary, count: 3, queue_depth: 1024, in_flight_batch_age_ms: 30001, abandoned: 7 } }), `.event == "node_warning" && .event_code == "${code}" && .event_count == 1`)), check('dependency warning is a fixed unclassified diagnostic', envelope({ timestamp, level: 'WARN', target: 'hyper::proto', fields: { message: canary, error: canary } }), '.event == "node_warning" && .event_code == "unclassified" && .event_count == 1'), check('dependency error without a message still counts', envelope({ timestamp, level: 'ERROR', target: 'sqlx::pool', fields: { error: canary } }), '.event == "node_error" && .event_code == "unclassified" && .event_count == 1'), check('warning without a target or fields still counts', envelope({ timestamp, level: 'WARN' }), '.event == "node_warning" && .event_code == "unclassified" && .event_count == 1'), diff --git a/log-shipper/diagnostics.json b/log-shipper/diagnostics.json index faa08ef7..42290771 100644 --- a/log-shipper/diagnostics.json +++ b/log-shipper/diagnostics.json @@ -53,7 +53,11 @@ "SQL busy: artifact transfer": "sql_busy_artifact_transfer", "Request deadline exceeded": "request_timeout", "Request completed after its deadline": "deadline_overrun", - "Database hydration gave up loading its artifact": "sql_hydration_timeout" + "Database hydration gave up loading its artifact": "sql_hydration_timeout", + "Read audit wait expired": "read_audit_busy", + "Read audit batch slow": "read_audit_batch_slow", + "Read audit batch failed": "read_audit_batch_failed", + "Read audit drain stalled": "read_audit_drain_stalled" }, "prefix": { "dstack socket available but get_info failed: ": "dstack_get_info_failed", diff --git a/log-shipper/fields.json b/log-shipper/fields.json index 32e30759..3e787966 100644 --- a/log-shipper/fields.json +++ b/log-shipper/fields.json @@ -78,7 +78,7 @@ "status": { "type": "integer", "min": 100, "max": 599 }, "latency_us": { "type": "integer", "min": 0, "max": 9007199254740991 }, "request_time_seconds": { "type": "number", "min": 0, "max": 86400 }, - "event_code": { "type": "enum", "values": ["invocation_replay_insert_failed", "invocation_replay_cleanup_failed", "dstack_get_info_failed", "share_local_tee_identity", "retention_hook_delivery_prune_failed", "retention_dead_letter_prune_failed", "retention_signed_ticket_prune_failed", "quota_invalid_body", "quota_fallback", "tunnel_state_load_failed", "tunnel_address_invalid", "link_state_load_failed", "link_bind_invalid", "link_address_invalid", "link_bind_failed", "link_bind_state_write_failed", "link_tls_config_failed", "link_listener_error", "link_listener_state_write_failed", "link_auto_renew_config_failed", "link_auto_renew_failed", "link_cert_reload_failed", "link_cert_state_missing", "link_listener_cert_reload_failed", "link_disable_failed", "link_connection_error", "link_listener_accept_failed", "webhook_delivery_failed", "webhook_dispatcher_failed", "share_authorization_failed", "share_native_authorization_denied", "share_native_kv_put_failed", "share_v2_readiness_failed", "share_invitation_key_missing", "share_invitation_key_mismatch", "share_policy_denied", "attestation_quote_failed", "hook_events_read_failed", "hook_rows_load_failed", "missing_committed_hook_row", "webhook_enqueue_failed", "tunnel_connection_prepare_failed", "tunnel_idle_timeout", "tunnel_read_failed", "tunnel_malformed_frame", "tunnel_relay_error", "tunnel_write_failed", "tunnel_state_record_failed", "tunnel_state_clear_failed", "tunnel_auth_rejected", "network_did_resolution_enabled", "unclassified", "sql_busy_lock_wait", "sql_busy_hydration", "sql_busy_artifact_transfer", "request_timeout", "deadline_overrun", "sql_hydration_timeout"] }, + "event_code": { "type": "enum", "values": ["invocation_replay_insert_failed", "invocation_replay_cleanup_failed", "dstack_get_info_failed", "share_local_tee_identity", "retention_hook_delivery_prune_failed", "retention_dead_letter_prune_failed", "retention_signed_ticket_prune_failed", "quota_invalid_body", "quota_fallback", "tunnel_state_load_failed", "tunnel_address_invalid", "link_state_load_failed", "link_bind_invalid", "link_address_invalid", "link_bind_failed", "link_bind_state_write_failed", "link_tls_config_failed", "link_listener_error", "link_listener_state_write_failed", "link_auto_renew_config_failed", "link_auto_renew_failed", "link_cert_reload_failed", "link_cert_state_missing", "link_listener_cert_reload_failed", "link_disable_failed", "link_connection_error", "link_listener_accept_failed", "webhook_delivery_failed", "webhook_dispatcher_failed", "share_authorization_failed", "share_native_authorization_denied", "share_native_kv_put_failed", "share_v2_readiness_failed", "share_invitation_key_missing", "share_invitation_key_mismatch", "share_policy_denied", "attestation_quote_failed", "hook_events_read_failed", "hook_rows_load_failed", "missing_committed_hook_row", "webhook_enqueue_failed", "tunnel_connection_prepare_failed", "tunnel_idle_timeout", "tunnel_read_failed", "tunnel_malformed_frame", "tunnel_relay_error", "tunnel_write_failed", "tunnel_state_record_failed", "tunnel_state_clear_failed", "tunnel_auth_rejected", "network_did_resolution_enabled", "unclassified", "sql_busy_lock_wait", "sql_busy_hydration", "sql_busy_artifact_transfer", "request_timeout", "deadline_overrun", "sql_hydration_timeout", "read_audit_busy", "read_audit_batch_slow", "read_audit_batch_failed", "read_audit_drain_stalled"] }, "event_count": { "type": "integer", "min": 1, "max": 9007199254740991 }, "reason": { "type": "enum", "values": ["malformed_envelope", "unexpected_label", "unlabelled", "non_json", "oversized", "partial", "invalid_fields", "unknown_target", "filtered_level"] }, "count": { "type": "integer", "min": 1, "max": 9007199254740991 }, diff --git a/scripts/ci/fixtures/tc959-n0-compose.yaml b/scripts/ci/fixtures/tc959-n0-compose.yaml index 7041d572..8ded4d66 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\\\",\\\"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}}}" + 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\\\",\\\"Read audit wait expired\\\":\\\"read_audit_busy\\\",\\\"Read audit batch slow\\\":\\\"read_audit_batch_slow\\\",\\\"Read audit batch failed\\\":\\\"read_audit_batch_failed\\\",\\\"Read audit drain stalled\\\":\\\"read_audit_drain_stalled\\\"}\\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/src/db.rs b/tinycloud-core/src/db.rs index 54c2083f..ab0ac2c4 100644 --- a/tinycloud-core/src/db.rs +++ b/tinycloud-core/src/db.rs @@ -258,6 +258,10 @@ pub enum TxError { Encryption(#[from] crate::encryption::EncryptionError), #[error("delegation-chain-traversal-limit-exceeded")] ChainTraversalLimitExceeded, + /// The read's audit record was not confirmed; its data was not returned + /// (TC-1317). + #[error(transparent)] + ReadAudit(#[from] crate::read_audit::ReadAuditError), } #[non_exhaustive] @@ -456,9 +460,20 @@ impl SpaceDatabase where K: Secrets, { - /// Number of durable read-audit records and group commits completed. - pub fn read_audit_commit_stats(&self) -> (u64, u64) { - self.read_audit.stats() + /// Counts and ages of the read-audit pipeline, for metrics and logs. + pub fn read_audit_health(&self) -> crate::read_audit::ReadAuditHealth { + self.read_audit.health() + } + + /// Bound how long a read waits for its audit record (TC-1317). Takes + /// effect for waits that start afterwards. + pub fn set_read_audit_wait(&self, wait: std::time::Duration) { + self.read_audit.set_wait(wait); + } + + #[cfg(test)] + pub(crate) fn read_audit_pipeline(&self) -> &crate::read_audit::ReadAuditPipeline { + &self.read_audit } pub async fn stage_key(&self, space_id: &SpaceId) -> Result { @@ -2702,7 +2717,7 @@ where crate::telemetry::StageOutcome::from(record_result.is_ok()), read_audit_start.elapsed(), ); - record_result?; + record_result.map_err(TxError::::from)?; Ok(( TransactResult { commits: HashMap::new(), diff --git a/tinycloud-core/src/kv_sync.rs b/tinycloud-core/src/kv_sync.rs index 76da742f..78afdbaf 100644 --- a/tinycloud-core/src/kv_sync.rs +++ b/tinycloud-core/src/kv_sync.rs @@ -927,6 +927,8 @@ pub(crate) mod tests { Put(&'a str, &'a [u8]), PutMeta(&'a str, &'a [u8], &'a [(&'a str, &'a str)]), Del(&'a str), + /// A read: it goes through the read-audit pipeline (TC-1317). + Get(&'a str), } impl Owner { @@ -956,6 +958,7 @@ pub(crate) mod tests { let (key, ability) = match op { Op::Put(key, _) | Op::PutMeta(key, _, _) => (key, "tinycloud.kv/put"), Op::Del(key) => (key, "tinycloud.kv/del"), + Op::Get(key) => (key, "tinycloud.kv/get"), }; let resource = (*space).clone().to_resource( "kv".parse::().unwrap(), @@ -1043,7 +1046,7 @@ pub(crate) mod tests { let (key, value, metadata) = match op { Op::Put(key, value) => (key, value, &[][..]), Op::PutMeta(key, value, metadata) => (key, value, *metadata), - Op::Del(_) => continue, + Op::Del(_) | Op::Get(_) => continue, }; let mut stage = HashBuffer::new(Vec::new()); stage.write_all(value).await.unwrap(); @@ -1077,6 +1080,46 @@ pub(crate) mod tests { .unwrap() } + /// TC-1317: with the read-audit drain held, a KV read answers busy at + /// its bound without returning data, while KV writes, which are not + /// audited reads, are unaffected. + #[tokio::test] + async fn tc1317_a_held_read_audit_bounds_reads_and_spares_writes() { + let db = sqlite_db().await; + db.set_read_audit_wait(std::time::Duration::from_millis(200)); + let owner = Owner::generate(); + host(&db, &owner).await; + run(&db, &owner, &[Op::Put("notes/a", b"a")]).await; + + let held = db.read_audit_pipeline().hold_drain().await; + let read = tokio::time::timeout( + std::time::Duration::from_secs(10), + invoke( + &db, + &owner, + &[Op::Get("notes/a")], + KvInvokeOptions::default(), + ), + ) + .await + .expect("a read must not wait past its bound"); + let error = read.expect_err("a read whose audit is not confirmed must fail"); + assert!(error.starts_with("read_audit_busy:"), "{error}"); + tokio::time::timeout( + std::time::Duration::from_secs(10), + invoke( + &db, + &owner, + &[Op::Put("notes/b", b"b")], + KvInvokeOptions::default(), + ), + ) + .await + .expect("a write does not wait on the read audit") + .unwrap(); + drop(held); + } + /// A delivered change: the key and its etag, `None` for a tombstone. pub(crate) type Delivered = (String, Option); diff --git a/tinycloud-core/src/lib.rs b/tinycloud-core/src/lib.rs index bceb8b73..beedf46c 100644 --- a/tinycloud-core/src/lib.rs +++ b/tinycloud-core/src/lib.rs @@ -45,6 +45,7 @@ pub use db::{ pub use db_pool::RecoveringConnection; pub use encryption::ColumnEncryption; pub use libp2p; +pub use read_audit::{ReadAuditError, ReadAuditHealth, DEFAULT_READ_AUDIT_WAIT}; pub use sea_orm; pub use sea_orm_migration; pub use sql_sizes::{SizeTrackingArtifactRepository, SqlSizes}; diff --git a/tinycloud-core/src/read_audit.rs b/tinycloud-core/src/read_audit.rs index c57ee337..3af145ab 100644 --- a/tinycloud-core/src/read_audit.rs +++ b/tinycloud-core/src/read_audit.rs @@ -7,7 +7,7 @@ //! one transaction. Mutations and audit batches share the same writer lock. use crate::{ - db_pool::RecoveringConnection, + db_pool::{is_transient_error, transient_error_class, RecoveringConnection}, encryption::{maybe_encrypt, ColumnEncryption}, events::Invocation, hash::Hash, @@ -27,6 +27,7 @@ use std::sync::{ atomic::{AtomicU64, Ordering}, Arc, }; +use std::time::{Duration, Instant}; use time::OffsetDateTime; use tokio::sync::{mpsc, oneshot, Mutex}; @@ -67,22 +68,144 @@ impl ReadAuditRecord { } } +/// Why a read's audit record was not confirmed (TC-1317). The read's data is +/// never returned without a confirmed record. +#[derive(Debug, Clone, PartialEq, Eq, thiserror::Error)] +pub enum ReadAuditError { + /// The record was not confirmed within the read-audit wait bound. + #[error("read_audit_busy: the read audit is backlogged; retry the request")] + Busy, + /// The record's batch failed with a transient database error; nothing + /// of the read was returned, so a fresh request is safe. + #[error( + "unavailable_retryable: read audit storage temporarily unavailable; retry the request" + )] + Unavailable, + /// The record's batch failed otherwise. + #[error("read audit failed: {0}")] + Failed(String), + /// The pipeline is gone. + #[error("read audit pipeline stopped")] + Stopped, +} + struct Command { record: ReadAuditRecord, - committed: oneshot::Sender>, + committed: oneshot::Sender>, context: Option>, + enqueued: Instant, } -#[derive(Debug, Default)] +#[derive(Debug)] struct PipelineStats { records: AtomicU64, batches: AtomicU64, + failed_batches: AtomicU64, + abandoned: AtomicU64, + busy: AtomicU64, + /// Batches whose commit took longer than [`SLOW_BATCH`], and the longest. + slow_batches: AtomicU64, + max_commit_ms: AtomicU64, + /// When the batch now being committed started, in ms since `epoch` plus + /// one; 0 when none is in flight. + in_flight_since: AtomicU64, + /// The longest queue wait of the last formed batch's records. + last_queue_wait_ms: AtomicU64, + /// The class of the latest failed batch (a fixed string). + last_failure_class: std::sync::Mutex<&'static str>, + /// Reads whose pipeline was gone when they queued or waited. + stopped: AtomicU64, + epoch: Instant, + /// Test-only fault: this pipeline's next batch commit panics. + #[cfg(test)] + panic_next_batch: std::sync::atomic::AtomicBool, +} + +impl Default for PipelineStats { + fn default() -> Self { + Self { + records: AtomicU64::new(0), + batches: AtomicU64::new(0), + failed_batches: AtomicU64::new(0), + abandoned: AtomicU64::new(0), + busy: AtomicU64::new(0), + slow_batches: AtomicU64::new(0), + max_commit_ms: AtomicU64::new(0), + in_flight_since: AtomicU64::new(0), + last_queue_wait_ms: AtomicU64::new(0), + last_failure_class: std::sync::Mutex::new("other"), + stopped: AtomicU64::new(0), + epoch: Instant::now(), + #[cfg(test)] + panic_next_batch: std::sync::atomic::AtomicBool::new(false), + } + } } +impl PipelineStats { + fn in_flight_age(&self) -> Duration { + match self.in_flight_since.load(Ordering::Acquire) { + 0 => Duration::ZERO, + since => self + .epoch + .elapsed() + .saturating_sub(Duration::from_millis(since - 1)), + } + } + + fn failure_class(&self) -> &'static str { + *self + .last_failure_class + .lock() + .unwrap_or_else(std::sync::PoisonError::into_inner) + } +} + +/// A point-in-time view of the pipeline: counts and durations only. +#[derive(Clone, Copy, Debug, Default, PartialEq, Eq)] +pub struct ReadAuditHealth { + /// Records committed. + pub records: u64, + /// Batches committed. + pub batches: u64, + /// Batches that failed. + pub failed_batches: u64, + /// Records skipped because their waiter was gone when the batch formed. + pub abandoned: u64, + /// Waits that gave up at the bound. + pub busy: u64, + /// Records waiting in the queue. + pub queue_depth: u64, + /// How long the batch being committed has been in flight (0 if none). + pub in_flight_batch_age_ms: u64, + /// The longest queue wait among the records of the last formed batch. + pub last_queue_wait_ms: u64, + /// Reads answered `Stopped` because the pipeline was gone. + pub stopped: u64, + /// The drain is gone: nothing will ever commit a record again. + pub drain_stopped: bool, +} + +/// A batch commit slower than this is reported (TC-1317). +const SLOW_BATCH: Duration = Duration::from_secs(5); +/// A batch in flight longer than this, or a queue that waited longer than +/// [`STALLED_QUEUE_WAIT`] with no batch completing, is a stalled drain. +const STALLED_BATCH: Duration = Duration::from_secs(30); +const STALLED_QUEUE_WAIT: Duration = Duration::from_secs(10); +/// How often the watchdog looks, and how often each warning may repeat. +const WATCHDOG_TICK: Duration = Duration::from_secs(10); +const WARNING_INTERVAL: Duration = Duration::from_secs(60); + +/// Default bound on a read's wait for its audit record (TC-1317). +pub const DEFAULT_READ_AUDIT_WAIT: Duration = Duration::from_secs(20); + #[derive(Clone, Debug)] pub(crate) struct ReadAuditPipeline { sender: mpsc::Sender, stats: Arc, + wait_ms: Arc, + #[cfg(test)] + gate: Arc>, } impl ReadAuditPipeline { @@ -93,41 +216,216 @@ impl ReadAuditPipeline { let conn = conn.into(); let (sender, receiver) = mpsc::channel(CHANNEL_CAPACITY); let stats = Arc::new(PipelineStats::default()); - tokio::spawn(run_pipeline(conn, writer_lock, receiver, stats.clone())); - Self { sender, stats } + #[cfg(test)] + let gate = Arc::new(Mutex::new(())); + tokio::spawn(run_pipeline( + conn, + writer_lock, + receiver, + stats.clone(), + #[cfg(test)] + gate.clone(), + )); + tokio::spawn(run_watchdog(sender.downgrade(), stats.clone())); + Self { + sender, + stats, + wait_ms: Arc::new(AtomicU64::new(DEFAULT_READ_AUDIT_WAIT.as_millis() as u64)), + #[cfg(test)] + gate, + } + } + + /// Bound a read's wait for its audit record. + pub(crate) fn set_wait(&self, wait: Duration) { + self.wait_ms + .store(wait.as_millis() as u64, Ordering::Relaxed); + } + + /// Hold every batch before it is committed until the guard drops. + #[cfg(test)] + pub(crate) async fn hold_drain(&self) -> tokio::sync::OwnedMutexGuard<()> { + self.gate.clone().lock_owned().await } pub(crate) async fn record( &self, invocation: &Invocation, encryption: Option<&ColumnEncryption>, - ) -> Result<(), DbErr> { + ) -> Result<(), ReadAuditError> { self.enqueue(ReadAuditRecord::from_invocation(invocation, encryption)) .await } - async fn enqueue(&self, record: ReadAuditRecord) -> Result<(), DbErr> { - let (committed, receipt) = oneshot::channel(); - self.sender - .send(Command { - record, - committed, - context: request_telemetry::current(), - }) - .await - .map_err(|_| DbErr::Custom("read audit pipeline stopped".to_string()))?; - receipt - .await - .map_err(|_| DbErr::Custom("read audit pipeline dropped commit receipt".to_string()))? - .map_err(DbErr::Custom) + /// Queue `record` and wait for its commit, at most the wait bound. + /// + /// Giving up drops the receipt. The drain then skips the record if its + /// batch has not formed yet, and commits it otherwise; either way nothing + /// is confirmed to a caller whose record is not committed. + async fn enqueue(&self, record: ReadAuditRecord) -> Result<(), ReadAuditError> { + let bound = Duration::from_millis(self.wait_ms.load(Ordering::Relaxed)); + crate::request_cancel::set_stage(crate::request_cancel::Stage::ReadAudit); + let waited = tokio::time::timeout(bound, async { + let (committed, receipt) = oneshot::channel(); + self.sender + .send(Command { + record, + committed, + context: request_telemetry::current(), + enqueued: Instant::now(), + }) + .await + .map_err(|_| ReadAuditError::Stopped)?; + receipt.await.map_err(|_| ReadAuditError::Stopped)? + }) + .await; + crate::request_cancel::set_stage(crate::request_cancel::Stage::Other); + match waited { + Ok(Err(ReadAuditError::Stopped)) => { + self.stats.stopped.fetch_add(1, Ordering::Relaxed); + Err(ReadAuditError::Stopped) + } + Ok(outcome) => outcome, + Err(_) => { + self.stats.busy.fetch_add(1, Ordering::Relaxed); + Err(ReadAuditError::Busy) + } + } } + #[cfg(test)] pub(crate) fn stats(&self) -> (u64, u64) { ( self.stats.records.load(Ordering::Relaxed), self.stats.batches.load(Ordering::Relaxed), ) } + + pub(crate) fn health(&self) -> ReadAuditHealth { + health(&self.stats, &self.sender) + } +} + +fn health(stats: &PipelineStats, sender: &mpsc::Sender) -> ReadAuditHealth { + ReadAuditHealth { + records: stats.records.load(Ordering::Relaxed), + batches: stats.batches.load(Ordering::Relaxed), + failed_batches: stats.failed_batches.load(Ordering::Relaxed), + abandoned: stats.abandoned.load(Ordering::Relaxed), + busy: stats.busy.load(Ordering::Relaxed), + queue_depth: (sender.max_capacity() - sender.capacity()) as u64, + in_flight_batch_age_ms: stats.in_flight_age().as_millis() as u64, + last_queue_wait_ms: stats.last_queue_wait_ms.load(Ordering::Relaxed), + stopped: stats.stopped.load(Ordering::Relaxed), + drain_stopped: sender.is_closed(), + } +} + +/// What the waiters of a failed batch are told: a transient database error +/// is retryable (nothing of the read was returned), anything else is not. +fn batch_error(error: DbErr) -> ReadAuditError { + if is_transient_error(&error) { + ReadAuditError::Unavailable + } else { + ReadAuditError::Failed(error.to_string()) + } +} + +/// The warnings the watchdog has emitted, and what it last reported. +#[derive(Default)] +struct WatchdogState { + reported: ReadAuditHealth, + reported_slow: u64, + last: [Option; 4], + /// Batches committed, failed or skipped at the last look that moved. + progress: u64, + progress_at: Option, +} + +/// A drain that is stuck cannot report itself, so a separate task watches +/// it (TC-1317). Every warning carries counts and durations only, and each +/// repeats at most once per [`WARNING_INTERVAL`]. +async fn run_watchdog(sender: mpsc::WeakSender, stats: Arc) { + let mut state = WatchdogState::default(); + let mut tick = tokio::time::interval(WATCHDOG_TICK); + tick.set_missed_tick_behavior(tokio::time::MissedTickBehavior::Delay); + loop { + tick.tick().await; + // The pipeline is gone once every sender has been dropped. + let Some(sender) = sender.upgrade() else { + return; + }; + let now = health(&stats, &sender); + drop(sender); + watch(&stats, &mut state, now, Instant::now()); + } +} + +fn watch(stats: &PipelineStats, state: &mut WatchdogState, now: ReadAuditHealth, at: Instant) { + let mut due = |kind: usize| { + let due = state.last[kind].is_none_or(|last| at.duration_since(last) >= WARNING_INTERVAL); + if due { + state.last[kind] = Some(at); + } + due + }; + let busy = now.busy - state.reported.busy; + if busy > 0 && due(0) { + tracing::warn!( + error_class = "read_audit_busy", + count = busy, + queue_depth = now.queue_depth, + last_queue_wait_ms = now.last_queue_wait_ms, + "Read audit wait expired" + ); + state.reported.busy = now.busy; + } + let slow = stats.slow_batches.load(Ordering::Relaxed); + if slow > state.reported_slow && due(1) { + tracing::warn!( + error_class = "read_audit_batch_slow", + count = slow - state.reported_slow, + max_commit_ms = stats.max_commit_ms.swap(0, Ordering::Relaxed), + "Read audit batch slow" + ); + state.reported_slow = slow; + } + let failed = now.failed_batches - state.reported.failed_batches; + if failed > 0 && due(2) { + tracing::warn!( + error_class = stats.failure_class(), + count = failed, + "Read audit batch failed" + ); + state.reported.failed_batches = now.failed_batches; + } + // A queue that has not moved since the last look: nothing committed, + // failed or skipped while records waited. + let progress = now.batches + now.failed_batches + now.abandoned; + if progress != state.progress || now.queue_depth == 0 || state.progress_at.is_none() { + state.progress = progress; + state.progress_at = Some(at); + } + let idle_for = state + .progress_at + .map_or(Duration::ZERO, |since| at.duration_since(since)); + let stuck_batch = Duration::from_millis(now.in_flight_batch_age_ms) >= STALLED_BATCH; + let stuck_queue = now.queue_depth > 0 && idle_for >= STALLED_QUEUE_WAIT; + // A dead drain: reads fail as `Stopped` and nothing will ever commit. + let dead = now.drain_stopped || now.stopped > state.reported.stopped; + if (stuck_batch || stuck_queue || dead) && due(3) { + tracing::warn!( + error_class = "read_audit_drain_stalled", + in_flight_batch_age_ms = now.in_flight_batch_age_ms, + queue_depth = now.queue_depth, + queue_idle_ms = idle_for.as_millis() as u64, + abandoned = now.abandoned, + drain_stopped = now.drain_stopped, + stopped = now.stopped, + "Read audit drain stalled" + ); + state.reported.stopped = now.stopped; + } } async fn run_pipeline( @@ -135,6 +433,7 @@ async fn run_pipeline( writer_lock: Option>>, mut receiver: mpsc::Receiver, stats: Arc, + #[cfg(test)] gate: Arc>, ) { while let Some(first) = receiver.recv().await { let mut batch = vec![first]; @@ -145,14 +444,52 @@ async fn run_pipeline( Err(_) => break, } } + let formed = Instant::now(); + let queue_wait = batch + .iter() + .map(|command| formed.duration_since(command.enqueued)) + .max() + .unwrap_or_default(); + stats + .last_queue_wait_ms + .store(queue_wait.as_millis() as u64, Ordering::Relaxed); + // A waiter that is already gone gave up or was cut: its read was not + // and can never be confirmed, since its receipt is closed for good. + // Committing its record would only spend drain time on a read nobody + // received. A waiter that leaves after this point is still committed. + let before = batch.len(); + batch.retain(|command| !command.committed.is_closed()); + stats + .abandoned + .fetch_add((before - batch.len()) as u64, Ordering::Relaxed); + if batch.is_empty() { + continue; + } + // In flight from here, including the SQLite writer-lock wait, so a + // batch stuck on that lock shows as a stalled drain. + let started = stats.epoch.elapsed(); + stats + .in_flight_since + .store(started.as_millis() as u64 + 1, Ordering::Release); + #[cfg(test)] + drop(gate.lock().await); let _writer = match &writer_lock { Some(lock) => Some(lock.lock().await), None => None, }; commit_batch(&conn, batch, &stats).await; + stats.in_flight_since.store(0, Ordering::Release); + let took = stats.epoch.elapsed().saturating_sub(started); + if took >= SLOW_BATCH { + stats.slow_batches.fetch_add(1, Ordering::Relaxed); + stats + .max_commit_ms + .fetch_max(took.as_millis() as u64, Ordering::Relaxed); + } } } + /// Charge each waiting request the full physical batch, not a share of a /// process-wide delta. These totals are non-additive across requests. /// Queue/writer-lock waits and detached driver rollback cleanup are excluded. @@ -162,9 +499,35 @@ async fn commit_batch( stats: &PipelineStats, ) -> Snapshot { let metrics = Arc::new(Metrics::default()); - let result = sqlx_core::request_telemetry::scope(metrics.clone(), persist_batch(conn, &batch)) - .await - .map_err(|error| error.to_string()); + let persisted = std::panic::AssertUnwindSafe(sqlx_core::request_telemetry::scope( + metrics.clone(), + async { + #[cfg(test)] + if stats.panic_next_batch.swap(false, Ordering::SeqCst) { + panic!("injected read-audit batch panic"); + } + persist_batch(conn, &batch).await + }, + )); + // A panic fails this batch's waiters; the drain goes on (TC-1317). + let result = match futures::FutureExt::catch_unwind(persisted).await { + Ok(Ok(())) => Ok(()), + Ok(Err(error)) => { + let class = transient_error_class(&error).unwrap_or("other"); + *stats + .last_failure_class + .lock() + .unwrap_or_else(std::sync::PoisonError::into_inner) = class; + Err(batch_error(error)) + } + Err(_) => { + *stats + .last_failure_class + .lock() + .unwrap_or_else(std::sync::PoisonError::into_inner) = "panic"; + Err(ReadAuditError::Failed("read audit batch panicked".into())) + } + }; let snapshot = metrics.snapshot(); // At most 64 commands: scanning prior entries avoids a recipient allocation // and deduplicates by context identity, never by account or request UUID. @@ -185,6 +548,8 @@ async fn commit_batch( .records .fetch_add(batch.len() as u64, Ordering::Relaxed); stats.batches.fetch_add(1, Ordering::Relaxed); + } else { + stats.failed_batches.fetch_add(1, Ordering::Relaxed); } for command in batch { let _ = command.committed.send(result.clone()); @@ -491,6 +856,7 @@ mod tests { record: record(index), committed, context: Some(context), + enqueued: Instant::now(), }); receipts.push(receipt); } @@ -540,6 +906,7 @@ mod tests { ); let conn = database(url.clone(), 8).await; let pipeline = ReadAuditPipeline::start(conn.clone(), Some(Arc::new(Mutex::new(())))); + pipeline.set_wait(COMMIT_TEST_WAIT); let requests = (0..32) .map(|index| { @@ -586,6 +953,7 @@ mod tests { Migrator::up(&conn, None).await.unwrap(); let writer_lock = Arc::new(Mutex::new(())); let pipeline = ReadAuditPipeline::start(conn.clone(), Some(writer_lock.clone())); + pipeline.set_wait(COMMIT_TEST_WAIT); let writer = writer_lock.lock().await; let audit = tokio::spawn(async move { pipeline.enqueue(record(0)).await }); @@ -634,6 +1002,7 @@ mod tests { record, committed, context: None, + enqueued: Instant::now(), } } @@ -969,6 +1338,7 @@ mod tests { // The pipeline itself, without a writer lock as on PostgreSQL in // production: concurrent reads group commit and are durable. let pipeline = ReadAuditPipeline::start(single.conn.clone(), None); + pipeline.set_wait(COMMIT_TEST_WAIT); let before = invocation::Entity::find() .count(&single.conn) .await @@ -1255,7 +1625,7 @@ mod tests { /// following batches are exactly consecutive runs of `MAX_BATCH_SIZE`. struct Stall { lock: RowLock, - gate: tokio::task::JoinHandle>, + gate: tokio::task::JoinHandle>, } fn gate_read(name: &str) -> ReadAuditRecord { @@ -1289,7 +1659,7 @@ mod tests { async fn enqueue_in_order( pipeline: &ReadAuditPipeline, reads: Vec, - ) -> Vec>> { + ) -> Vec>> { let queued = || CHANNEL_CAPACITY - pipeline.sender.capacity(); let already = queued(); let mut receipts = Vec::new(); @@ -1384,6 +1754,7 @@ mod tests { }; let pipeline = ReadAuditPipeline::start(schema_pool(TEST, &pipelined.conn, 4).await, None); + pipeline.set_wait(COMMIT_TEST_WAIT); let locks = schema_pool(TEST, &pipelined.conn, 1).await; let stalled = stall(&pipeline, &locks, &pipelined.conn, "overlap-gate").await; let receipts = enqueue_in_order(&pipeline, reads(0..SATURATED)).await; @@ -1468,6 +1839,15 @@ mod tests { } } + /// What a waiter of the failed batch is told (TC-1317): a terminated + /// connection is a retryable failure, a constraint is not. + fn waiter_error(self) -> &'static str { + match self { + Failure::MissingParent => "foreign key constraint", + Failure::Terminated => "unavailable_retryable", + } + } + fn held_invocation(self) -> Hash { crate::hash::hash(format!("{}-held", self.name()).as_bytes()) } @@ -1604,6 +1984,7 @@ mod tests { .await .unwrap(); let pipeline = ReadAuditPipeline::start(schema_pool(TEST, conn, 4).await, None); + pipeline.set_wait(COMMIT_TEST_WAIT); let locks = schema_pool(TEST, conn, 2).await; for failure in [Failure::Terminated, Failure::MissingParent] { @@ -1644,7 +2025,7 @@ mod tests { .unwrap() .expect_err("a read of a failed batch is not acknowledged"); assert!( - error.to_string().contains(failure.error()), + error.to_string().contains(failure.waiter_error()), "{failure:?}: {error}" ); failed += 1; @@ -1744,4 +2125,228 @@ mod tests { } assert_eq!(outcomes[0], outcomes[1]); } + + // TC-1317: a bounded wait, abandoned records skipped, and the invariant + // that no read is confirmed without its committed record. + + const PATIENCE: Duration = Duration::from_secs(10); + /// Tests of commit semantics, not of the bound: a loaded host must not + /// turn their waits into `Busy` (TC-1317 review). + const COMMIT_TEST_WAIT: Duration = Duration::from_secs(600); + + async fn file_pipeline() -> (tempfile::TempDir, DatabaseConnection, ReadAuditPipeline) { + let directory = tempfile::tempdir().unwrap(); + let url = format!( + "sqlite:{}?mode=rwc", + directory.path().join("bounded.db").display() + ); + let conn = database(url, 4).await; + let pipeline = ReadAuditPipeline::start(conn.clone(), Some(Arc::new(Mutex::new(())))); + (directory, conn, pipeline) + } + + async fn committed(conn: &DatabaseConnection, index: usize) -> bool { + invocation::Entity::find_by_id(record(index).id) + .one(conn) + .await + .unwrap() + .is_some() + } + + async fn until(mut done: impl FnMut() -> bool) { + tokio::time::timeout(PATIENCE, async { + while !done() { + tokio::time::sleep(Duration::from_millis(5)).await; + } + }) + .await + .expect("condition must hold in time"); + } + + /// `enqueue`, failing the test rather than hanging if it never returns. + async fn bounded(pipeline: &ReadAuditPipeline, index: usize) -> Result<(), ReadAuditError> { + tokio::time::timeout(PATIENCE, pipeline.enqueue(record(index))) + .await + .expect("enqueue must return within its bound") + } + + /// The watchdog reports a drain that stopped moving, once per interval, + /// and stays quiet while it progresses. + #[test] + fn tc1317_the_watchdog_reports_a_stalled_drain_once_per_interval() { + let stats = PipelineStats::default(); + let mut state = WatchdogState::default(); + let start = Instant::now(); + let waiting = ReadAuditHealth { + queue_depth: 3, + ..Default::default() + }; + let stalled = |state: &WatchdogState| state.last[3]; + + watch(&stats, &mut state, waiting, start); + assert_eq!(stalled(&state), None, "just started waiting"); + watch(&stats, &mut state, waiting, start + STALLED_QUEUE_WAIT); + assert_eq!(stalled(&state), Some(start + STALLED_QUEUE_WAIT)); + watch(&stats, &mut state, waiting, start + STALLED_QUEUE_WAIT * 2); + assert_eq!( + stalled(&state), + Some(start + STALLED_QUEUE_WAIT), + "rate-limited" + ); + + // A batch completes: no longer stalled, even with records queued. + let moved = ReadAuditHealth { + batches: 1, + ..waiting + }; + let later = start + STALLED_QUEUE_WAIT + WARNING_INTERVAL; + watch(&stats, &mut state, moved, later); + assert_eq!(stalled(&state), Some(start + STALLED_QUEUE_WAIT)); + + // A batch in flight too long is stalled whatever the queue does. + let hung = ReadAuditHealth { + batches: 1, + in_flight_batch_age_ms: STALLED_BATCH.as_millis() as u64, + ..Default::default() + }; + watch(&stats, &mut state, hung, later + Duration::from_secs(1)); + assert_eq!(stalled(&state), Some(later + Duration::from_secs(1))); + } + + #[tokio::test] + async fn tc1317_a_held_drain_answers_busy_within_the_bound() { + let (_directory, _conn, pipeline) = file_pipeline().await; + pipeline.set_wait(Duration::from_millis(200)); + let held = pipeline.hold_drain().await; + let started = std::time::Instant::now(); + let outcome = tokio::time::timeout(PATIENCE, pipeline.enqueue(record(0))) + .await + .expect("the wait must end at its bound"); + assert_eq!(outcome, Err(ReadAuditError::Busy)); + assert!(started.elapsed() < Duration::from_secs(5)); + assert_eq!(pipeline.health().busy, 1); + drop(held); + } + + /// Records whose waiters were gone when their batch formed are skipped + /// and counted; a waiter still waiting is always committed. + #[tokio::test] + async fn tc1317_abandoned_records_are_skipped_and_the_drain_recovers() { + let (_directory, conn, pipeline) = file_pipeline().await; + pipeline.set_wait(Duration::from_millis(100)); + let held = pipeline.hold_drain().await; + + // Record 0 is taken into a batch, which then waits at the gate. + assert_eq!(bounded(&pipeline, 0).await, Err(ReadAuditError::Busy)); + until(|| pipeline.health().queue_depth == 0).await; + // Records 1-5 queue behind it, and their waiters give up. + for index in 1..=5 { + assert_eq!(bounded(&pipeline, index).await, Err(ReadAuditError::Busy)); + } + assert_eq!(pipeline.health().queue_depth, 5); + + drop(held); + until(|| pipeline.health().abandoned == 5).await; + // The batch formed before its waiter left is committed (harmless: + // nothing was returned); the abandoned ones never reach the DB. + until(|| pipeline.health().records == 1).await; + assert!(committed(&conn, 0).await); + for index in 1..=5 { + assert!(!committed(&conn, index).await, "record {index}"); + } + + pipeline.set_wait(DEFAULT_READ_AUDIT_WAIT); + tokio::time::timeout(PATIENCE, pipeline.enqueue(record(6))) + .await + .expect("a recovered drain answers at once") + .unwrap(); + assert!(committed(&conn, 6).await); + } + + /// The invariant: whenever `enqueue` confirms, the record is committed, + /// including when waiters around it are cut at random points. + #[tokio::test] + async fn tc1317_no_read_is_confirmed_without_its_committed_record() { + let (_directory, conn, pipeline) = file_pipeline().await; + let held = pipeline.hold_drain().await; + let waiters = (0..48) + .map(|index| { + let pipeline = pipeline.clone(); + tokio::spawn(async move { + // Every third waiter is cut while it waits. + let cut = Duration::from_millis(if index % 3 == 0 { 20 } else { 5_000 }); + ( + index, + tokio::time::timeout(cut, pipeline.enqueue(record(index))).await, + ) + }) + }) + .collect::>(); + // Every cut waiter has gone before the drain is released. + let (cut, staying): (Vec<_>, Vec<_>) = waiters + .into_iter() + .enumerate() + .partition(|(index, _)| index % 3 == 0); + for (_, waiter) in cut { + let (_, outcome) = waiter.await.unwrap(); + assert!(outcome.is_err(), "a cut waiter is never confirmed"); + } + drop(held); + let mut confirmed = 0; + for (_, waiter) in staying { + let (index, outcome) = waiter.await.unwrap(); + if matches!(outcome, Ok(Ok(()))) { + confirmed += 1; + assert!( + committed(&conn, index).await, + "confirmed {index} uncommitted" + ); + } + } + assert_eq!(confirmed, 32, "every waiter that stayed was confirmed"); + let health = pipeline.health(); + assert_eq!( + health.records + health.abandoned, + 48, + "each record is either committed or counted as abandoned" + ); + } + + #[tokio::test] + async fn tc1317_a_transient_batch_failure_is_retryable() { + assert_eq!( + batch_error(DbErr::ConnectionAcquire( + sea_orm::error::ConnAcquireErr::Timeout + )), + ReadAuditError::Unavailable + ); + assert!(matches!( + batch_error(DbErr::Custom("constraint".into())), + ReadAuditError::Failed(_) + )); + } + + /// A panic while committing one batch fails only that batch's waiters; + /// the drain keeps serving. + #[tokio::test] + async fn tc1317_a_panicking_batch_does_not_stop_the_drain() { + let (_directory, conn, pipeline) = file_pipeline().await; + pipeline + .stats + .panic_next_batch + .store(true, Ordering::SeqCst); + let outcome = tokio::time::timeout(PATIENCE, pipeline.enqueue(record(0))) + .await + .expect("the panicking batch's waiter must be answered"); + assert!( + matches!(outcome, Err(ReadAuditError::Failed(_))), + "{outcome:?}" + ); + assert_eq!(pipeline.health().failed_batches, 1); + tokio::time::timeout(PATIENCE, pipeline.enqueue(record(1))) + .await + .expect("the drain survives") + .unwrap(); + assert!(committed(&conn, 1).await); + } } diff --git a/tinycloud-core/src/request_cancel.rs b/tinycloud-core/src/request_cancel.rs index fa3807d8..d858bc8f 100644 --- a/tinycloud-core/src/request_cancel.rs +++ b/tinycloud-core/src/request_cancel.rs @@ -46,6 +46,8 @@ pub enum Stage { ArtifactTransfer = 3, /// Resolving a SQL or DuckDB database's durable identity. IdentityResolution = 4, + /// Waiting for a read's audit record to commit (TC-1317). + ReadAudit = 5, } impl Stage { @@ -56,6 +58,7 @@ impl Stage { Stage::Hydration => "hydration", Stage::ArtifactTransfer => "artifact_transfer", Stage::IdentityResolution => "identity_resolution", + Stage::ReadAudit => "read_audit", } } @@ -65,6 +68,7 @@ impl Stage { 2 => Stage::Hydration, 3 => Stage::ArtifactTransfer, 4 => Stage::IdentityResolution, + 5 => Stage::ReadAudit, _ => Stage::Other, } } diff --git a/tinycloud-node-server/src/config.rs b/tinycloud-node-server/src/config.rs index ca70f76d..ec03704e 100644 --- a/tinycloud-node-server/src/config.rs +++ b/tinycloud-node-server/src/config.rs @@ -1380,6 +1380,12 @@ pub struct DatabaseConfig { /// `storage.sql` wait bounds, TC-1274). #[serde(default = "default_database_retry_window_ms")] pub retry_window_ms: u64, + /// How long an authorized read waits for its audit record to commit + /// before it is answered `503 read_audit_busy` (TC-1317). Its data is + /// never returned without the record. Kept below `storage.sql`'s lock wait + /// and the `/invoke` deadline, so the typed answer comes first. + #[serde(default = "default_database_read_audit_wait_ms")] + pub read_audit_wait_ms: u64, } fn default_database_max_connections() -> u32 { @@ -1426,6 +1432,10 @@ fn default_database_retry_window_ms() -> u64 { 10_000 } +fn default_database_read_audit_wait_ms() -> u64 { + tinycloud_core::DEFAULT_READ_AUDIT_WAIT.as_millis() as u64 +} + impl Default for DatabaseConfig { fn default() -> Self { Self { @@ -1442,6 +1452,7 @@ impl Default for DatabaseConfig { tcp_keepalive_retries: default_database_tcp_keepalive_retries(), tcp_user_timeout_ms: default_database_tcp_user_timeout_ms(), retry_window_ms: default_database_retry_window_ms(), + read_audit_wait_ms: default_database_read_audit_wait_ms(), } } } @@ -1457,6 +1468,15 @@ pub struct DidResolutionConfig { } impl DatabaseConfig { + /// Reject settings that would make the node unusable (TC-1317): a zero + /// read-audit wait would answer every authorized read `read_audit_busy`. + pub fn validate(&self) -> Result<(), &'static str> { + if self.read_audit_wait_ms == 0 { + return Err("database.read_audit_wait_ms must be greater than zero"); + } + Ok(()) + } + /// The pool's PostgreSQL `statement_timeout` policy. pub fn statement_timeouts(&self) -> StatementTimeouts { StatementTimeouts { @@ -1583,6 +1603,21 @@ mod tests { } } + /// TC-1317: a zero read-audit wait would answer every read busy, so the + /// node refuses to start with it. + #[test] + fn tc1317_startup_rejects_a_zero_read_audit_wait() { + for (wait_ms, ok) in [(0, false), (1, true), (20_000, true)] { + let mut config = Config::default(); + config.database.read_audit_wait_ms = wait_ms; + assert_eq!( + crate::resolve_runtime_config(&config).is_ok(), + ok, + "{wait_ms}" + ); + } + } + /// TC-1274: a running backfill needs a positive rate and progress /// interval; a disabled one boots whatever its pacing says. #[test] diff --git a/tinycloud-node-server/src/lib.rs b/tinycloud-node-server/src/lib.rs index 3ebc2575..16fbdbd6 100644 --- a/tinycloud-node-server/src/lib.rs +++ b/tinycloud-node-server/src/lib.rs @@ -425,6 +425,7 @@ pub async fn app(config: &Figment) -> Result> { pub fn resolve_runtime_config(tinycloud_config: &Config) -> Result { let mut resolved = tinycloud_config.clone(); resolved.hooks.validate().map_err(anyhow::Error::msg)?; + resolved.database.validate().map_err(anyhow::Error::msg)?; resolved .epoch_head_backfill .validate() @@ -646,6 +647,9 @@ pub async fn app_with_control( ) .await? .with_sql_sizes(sql_sizes.clone()); + tinycloud.set_read_audit_wait(Duration::from_millis( + tinycloud_config.database.read_audit_wait_ms, + )); let encryption_service = encryption_service.with_sqlite_writer_lock(tinycloud.sqlite_writer_lock()); let database_artifact_repository: Arc = @@ -877,7 +881,7 @@ pub async fn app_with_control( let shutdown = rocket.shutdown(); Box::pin(async move { tokio::spawn(async move { - let mut last_read_audit = (0u64, 0u64); + let mut last_read_audit = tinycloud_core::ReadAuditHealth::default(); let period = std::time::Duration::from_secs(5); let mut interval = tokio::time::interval_at(tokio::time::Instant::now() + period, period); @@ -965,7 +969,9 @@ fn retry_after_fairing() -> AdHoc { let Ok(body) = resp.body_mut().to_string().await else { return; }; - let retry_after = if body.starts_with(routes::SQL_BUSY) { + let retry_after = if body.starts_with(routes::SQL_BUSY) + || body.starts_with(routes::READ_AUDIT_BUSY) + { Some(routes::SQL_BUSY_RETRY_AFTER_SECS) } else if body.starts_with(routes::UNAVAILABLE_RETRYABLE) || body.starts_with(routes::REQUEST_TIMEOUT) @@ -1092,9 +1098,9 @@ mod production_route_tests { } /// One telemetry sample tick: update the DB pool gauges, probe pool-acquire -/// latency (the `DbPoolAcquire` span), and advance the cumulative read-audit -/// counters. `last_read_audit` carries the previous cumulative -/// `(records, batches)` so the monotonic counters advance by deltas. +/// latency (the `DbPoolAcquire` span), and update the read-audit metrics. +/// `last_read_audit` carries the previous cumulative counts so the monotonic +/// counters advance by deltas. /// /// sea-orm couples pool acquisition with `BEGIN` on the generic connection, so /// the request-path `DbTxBegin` span cannot separate the two. This sampler is @@ -1103,7 +1109,7 @@ mod production_route_tests { async fn sample_db_telemetry( conn: &RecoveringConnection, tinycloud: &TinyCloud, - last_read_audit: &mut (u64, u64), + last_read_audit: &mut tinycloud_core::ReadAuditHealth, ) { use tinycloud_core::sea_orm::{ConnectionTrait, DatabaseBackend}; @@ -1128,12 +1134,9 @@ async fn sample_db_telemetry( DatabaseBackend::MySql => sample_pool!(pool.get_mysql_connection_pool()), } - let (records, batches) = tinycloud.read_audit_commit_stats(); - crate::prometheus::add_read_audit_stats( - records.saturating_sub(last_read_audit.0), - batches.saturating_sub(last_read_audit.1), - ); - *last_read_audit = (records, batches); + let read_audit = tinycloud.read_audit_health(); + crate::prometheus::observe_read_audit(last_read_audit, &read_audit); + *last_read_audit = read_audit; } /// Run one retention sweep: prune terminal hook deliveries and expired signed @@ -1722,6 +1725,14 @@ mod retry_after_fairing_tests { ) } + #[get("/read-audit-busy")] + fn read_audit_busy() -> (Status, String) { + ( + Status::ServiceUnavailable, + tinycloud_core::ReadAuditError::Busy.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. @@ -1729,7 +1740,10 @@ 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, busy, timeout]) + .mount( + "/", + routes![retryable, unknown, fenced, busy, timeout, read_audit_busy], + ) .attach(retry_after_fairing()) .attach(cors_fairing()), ) @@ -1746,9 +1760,9 @@ 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")] { + // TC-1274, TC-1317: a busy database or a backlogged read audit asks + // for a longer pause than a request that timed out before writing. + for (path, retry_after) in [("/busy", "5"), ("/read-audit-busy", "5"), ("/timeout", "1")] { let response = client.get(path).dispatch().await; assert_eq!(response.status(), Status::ServiceUnavailable, "{path}"); assert_eq!( diff --git a/tinycloud-node-server/src/prometheus.rs b/tinycloud-node-server/src/prometheus.rs index 5686f848..b16c7c67 100644 --- a/tinycloud-node-server/src/prometheus.rs +++ b/tinycloud-node-server/src/prometheus.rs @@ -105,6 +105,36 @@ lazy_static! { "Cumulative durable read-audit commit batches." ) .unwrap(); + /// Read-audit batches that failed (TC-1317). + pub static ref READ_AUDIT_FAILED_BATCHES: IntCounter = register_int_counter!( + "tinycloud_read_audit_failed_batches_total", + "Read-audit commit batches that failed." + ) + .unwrap(); + /// Read-audit records skipped because their waiter was gone (TC-1317). + pub static ref READ_AUDIT_ABANDONED: IntCounter = register_int_counter!( + "tinycloud_read_audit_abandoned_total", + "Read-audit records skipped because their waiter was gone when the batch formed." + ) + .unwrap(); + /// Reads that gave up waiting for their audit record (TC-1317). + pub static ref READ_AUDIT_BUSY: IntCounter = register_int_counter!( + "tinycloud_read_audit_busy_total", + "Reads answered read_audit_busy because their audit record was not committed in time." + ) + .unwrap(); + /// Read-audit records waiting in the queue (TC-1317). + pub static ref READ_AUDIT_QUEUE_DEPTH: IntGauge = register_int_gauge!( + "tinycloud_read_audit_queue_depth", + "Read-audit records waiting in the queue." + ) + .unwrap(); + /// How long the read-audit batch being committed has been in flight. + pub static ref READ_AUDIT_IN_FLIGHT_MS: IntGauge = register_int_gauge!( + "tinycloud_read_audit_in_flight_batch_age_ms", + "Milliseconds the read-audit batch being committed has been in flight (0 if none)." + ) + .unwrap(); /// Invocation replay-cache rows inserted (first sighting of an invocation). pub static ref REPLAY_ROWS_INSERTED: IntCounter = register_int_counter!( "tinycloud_replay_rows_inserted_total", @@ -182,13 +212,23 @@ pub fn set_db_pool_gauges(size: i64, idle: i64) { } } -/// Advance the cumulative read-audit counters by the deltas observed since the -/// previous sampler tick. Read-audit stats are process-cumulative and -/// monotonic, so the sampler feeds monotonic increments here. -pub fn add_read_audit_stats(records_delta: u64, batches_delta: u64) { +/// Advance the cumulative read-audit counters by the deltas since the +/// previous sampler tick, and set the read-audit gauges. The pipeline's +/// counts are process-cumulative and monotonic, so the counters advance by +/// monotonic increments. +pub fn observe_read_audit( + previous: &tinycloud_core::ReadAuditHealth, + now: &tinycloud_core::ReadAuditHealth, +) { if enabled() { - READ_AUDIT_RECORDS.inc_by(records_delta); - READ_AUDIT_BATCHES.inc_by(batches_delta); + READ_AUDIT_RECORDS.inc_by(now.records.saturating_sub(previous.records)); + READ_AUDIT_BATCHES.inc_by(now.batches.saturating_sub(previous.batches)); + READ_AUDIT_FAILED_BATCHES + .inc_by(now.failed_batches.saturating_sub(previous.failed_batches)); + READ_AUDIT_ABANDONED.inc_by(now.abandoned.saturating_sub(previous.abandoned)); + READ_AUDIT_BUSY.inc_by(now.busy.saturating_sub(previous.busy)); + READ_AUDIT_QUEUE_DEPTH.set(now.queue_depth as i64); + READ_AUDIT_IN_FLIGHT_MS.set(now.in_flight_batch_age_ms as i64); } } diff --git a/tinycloud-node-server/src/routes/encryption.rs b/tinycloud-node-server/src/routes/encryption.rs index d25cf4a1..7c6ea5b5 100644 --- a/tinycloud-node-server/src/routes/encryption.rs +++ b/tinycloud-node-server/src/routes/encryption.rs @@ -17,7 +17,7 @@ use tinycloud_core::encryption_network::{ NetworkDescriptor, NetworkId, Threshold, WellKnownRecord, NETWORK_CREATE_ACTION, NETWORK_REVOKE_ACTION, }; -use tinycloud_core::{events::Invocation, util::InvocationInfo}; +use tinycloud_core::{events::Invocation, util::InvocationInfo, TxError, TxStoreError}; #[derive(Debug, Deserialize)] pub struct CreateNetworkBody { @@ -257,7 +257,16 @@ async fn verify_auth( .invoke::(invocation, HashMap::new()) .await .map(|_| ()) - .map_err(|err| (Status::Unauthorized, err.to_string())); + // Infrastructure failures are not authorization failures (TC-1317): + // a read-audit or transient database failure is retryable, and must + // not tell the client its credentials were refused. + .map_err(|err| match &err { + TxStoreError::Tx(TxError::ReadAudit(error)) => super::read_audit_failure(error), + TxStoreError::Tx(TxError::Db(error) | TxError::EpochInsert(error)) => { + super::database_failure(error, false, err.to_string()) + } + _ => (Status::Unauthorized, err.to_string()), + }); crate::prometheus::observe_span( span, if result.is_ok() { "ok" } else { "error" }, diff --git a/tinycloud-node-server/src/routes/mod.rs b/tinycloud-node-server/src/routes/mod.rs index 2916a358..3851a8d6 100644 --- a/tinycloud-node-server/src/routes/mod.rs +++ b/tinycloud-node-server/src/routes/mod.rs @@ -139,6 +139,22 @@ pub const SQL_BUSY_RETRY_AFTER_SECS: u32 = 5; 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"; +/// Body prefix of a `503` whose read's audit record was not committed within +/// the read-audit wait bound (TC-1317); `Retry-After` is +/// [`SQL_BUSY_RETRY_AFTER_SECS`], since the audit queue is backlogged. +pub const READ_AUDIT_BUSY: &str = "read_audit_busy"; + +/// The response to a read whose audit record was not confirmed (TC-1317). +/// Its data was not returned, so retrying with a fresh request is safe +/// whenever the failure was transient. +fn read_audit_failure(error: &tinycloud_core::ReadAuditError) -> (Status, String) { + use tinycloud_core::ReadAuditError; + let status = match error { + ReadAuditError::Busy | ReadAuditError::Unavailable => Status::ServiceUnavailable, + ReadAuditError::Failed(_) | ReadAuditError::Stopped => Status::InternalServerError, + }; + (status, error.to_string()) +} /// The response to a database failure of an operation (TC-1054): /// @@ -2274,6 +2290,9 @@ async fn invoke_impl( if let TxStoreError::KvTooManyMutations { .. } = &e { return Err(too_many_mutations().into()); } + if let TxStoreError::Tx(TxError::ReadAudit(error)) = &e { + return Err(read_audit_failure(error).into()); + } if let TxStoreError::Tx(TxError::Db(error) | TxError::EpochInsert(error)) = &e { return Err( database_failure(error, write_may_have_applied, e.to_string()).into() @@ -3725,6 +3744,7 @@ async fn verify_auth( TxStoreError::Tx(TxError::Db(error) | TxError::EpochInsert(error)) => { database_failure(error, false, e.to_string()) } + TxStoreError::Tx(TxError::ReadAudit(error)) => read_audit_failure(error), TxStoreError::Tx(TxError::SpaceNotFound) => (Status::NotFound, e.to_string()), _ => (Status::Unauthorized, e.to_string()), }) @@ -3756,6 +3776,7 @@ async fn verify_auth_admitted( TxStoreError::Tx(TxError::Db(error) | TxError::EpochInsert(error)) => { database_failure(error, false, e.to_string()) } + TxStoreError::Tx(TxError::ReadAudit(error)) => read_audit_failure(error), TxStoreError::Tx(TxError::SpaceNotFound) => (Status::NotFound, e.to_string()), _ => (Status::Unauthorized, e.to_string()), }) @@ -8405,6 +8426,17 @@ mod tests { ) -> Result<( rocket::Rocket, tinycloud_core::sea_orm::DatabaseConnection, + )> { + tc409_invoke_rocket_with(space, Config::default()).await + } + + /// [`tc409_invoke_rocket`] with `config` managed instead of the default. + async fn tc409_invoke_rocket_with( + space: &SpaceId, + config: Config, + ) -> Result<( + rocket::Rocket, + tinycloud_core::sea_orm::DatabaseConnection, )> { use tinycloud_core::models::space as space_model; use tinycloud_core::sea_orm::ActiveModelTrait; @@ -8463,7 +8495,7 @@ mod tests { .manage(tinycloud) .manage(sql_service) .manage(None::) - .manage(Config::default()) + .manage(config) .manage(QuotaCache::new(None, None)) .manage(InvocationReplayCache::new(replay_db)) .manage(hook_runtime) @@ -8915,6 +8947,14 @@ mod tests { /// [`Self::new`] with extra routes or managed state on the same rocket. async fn new_with( extend: impl FnOnce(rocket::Rocket) -> rocket::Rocket, + ) -> Result { + Self::new_configured(Config::default(), extend).await + } + + /// [`Self::new_with`] with `config` instead of the default. + async fn new_configured( + config: Config, + extend: impl FnOnce(rocket::Rocket) -> rocket::Rocket, ) -> Result { use tinycloud_core::models::actor; use tinycloud_core::sea_orm::ActiveModelTrait; @@ -8930,7 +8970,7 @@ mod tests { Some("probe"), "urn:uuid:tc732-probe", )?; - let (rocket, conn) = tc409_invoke_rocket(&space).await?; + let (rocket, conn) = tc409_invoke_rocket_with(&space, config).await?; let rocket = extend(rocket); let sync_cursor_key = rocket .state::() @@ -9215,6 +9255,11 @@ mod tests { /// An owner-root invocation of `caps` (resource URI, action). fn owner_invocation(&self, caps: &[(String, &str)]) -> Result { + self.owner_invocation_to(&self.space.did().to_string(), caps) + } + + /// [`Self::owner_invocation`] addressed to `audience`. + fn owner_invocation_to(&self, audience: &str, caps: &[(String, &str)]) -> Result { use tinycloud_auth::ssi::{dids::DIDURLBuf, ucan::Payload}; use tinycloud_auth::ucan_capabilities_object::Capabilities; let mut capabilities = Capabilities::new(); @@ -9227,7 +9272,7 @@ mod tests { } Ok(Payload { issuer: self.owner_vm.parse::()?, - audience: self.space.did().to_string().parse::()?, + audience: audience.parse::()?, not_before: None, expiration: test_invocation_expiration(), nonce: Some(self.next_nonce()), @@ -9515,6 +9560,235 @@ mod tests { Ok(()) } + /// TC-1317: an `/invoke` KV read whose audit record cannot commit is + /// answered `503 read_audit_busy` at the read-audit bound, without its + /// data; once the drain frees up the same read is served. + #[tokio::test] + async fn a_kv_read_with_a_stalled_read_audit_is_answered_busy() -> Result<()> { + use rocket::http::Status; + + let fixture = KvSyncFixture::new().await?; + fixture.owner_write("notes/a", Some(b"secret")).await?; + let tinycloud = fixture + .client + .rocket() + .state::() + .expect("TinyCloud is managed"); + tinycloud.set_read_audit_wait(std::time::Duration::from_millis(200)); + let get = || { + fixture.owner_invocation(&[( + fixture.kv_resource("notes/a").unwrap().as_uri().to_string(), + "tinycloud.kv/get", + )]) + }; + + // The SQLite writer lock is what every audit batch takes to commit. + let writer = tinycloud + .sqlite_writer_lock() + .expect("the fixture runs on SQLite"); + let held = writer.lock().await; + let reply = tokio::time::timeout( + std::time::Duration::from_secs(10), + fixture.dispatch(get()?, &[]), + ) + .await + .expect("the read must be answered at its bound"); + drop(held); + assert_eq!(reply.status, Status::ServiceUnavailable); + assert!(reply.body.starts_with(READ_AUDIT_BUSY), "{}", reply.body); + assert!(!reply.body.contains("secret"), "no data without its audit"); + + let reply = fixture.dispatch(get()?, &[]).await; + assert_eq!(reply.status, Status::Ok); + assert_eq!(reply.body, "secret"); + Ok(()) + } + + /// TC-1317 review R2: with the read audit stalled, every reclassified + /// auth route answers `503 read_audit_busy` instead of 401, a SQL request + /// never executes, and a real authorization denial is still 401/403. + #[tokio::test] + async fn reclassified_auth_routes_answer_busy_and_denials_stay_denials() -> Result<()> { + use rocket::http::{ContentType, Header, Status}; + use tinycloud_auth::ssi::{dids::DIDURLBuf, ucan::Payload}; + use tinycloud_auth::ucan_capabilities_object::Capabilities; + + let fixture = KvSyncFixture::new_with(|rocket| { + rocket + .mount( + "/", + rocket::routes![ + create_signed_kv_url, + crate::routes::encryption::create_network + ], + ) + .manage(crate::signed_urls::SignedUrlRuntime::new([33; 32])) + }) + .await?; + fixture.owner_write("notes/a", Some(b"secret")).await?; + let tinycloud = fixture + .client + .rocket() + .state::() + .expect("TinyCloud is managed"); + tinycloud.set_read_audit_wait(std::time::Duration::from_millis(200)); + let kv_get = || -> Result<(String, &str)> { + Ok(( + fixture.kv_resource("notes/a")?.as_uri().to_string(), + "tinycloud.kv/get", + )) + }; + let busy = |status: Status, body: &str, route: &str| { + assert_eq!(status, Status::ServiceUnavailable, "{route}: {body}"); + assert!(body.starts_with(READ_AUDIT_BUSY), "{route}: {body}"); + }; + + let writer = tinycloud + .sqlite_writer_lock() + .expect("the fixture runs on SQLite"); + let held = writer.lock().await; + async fn within(future: F) -> Result { + tokio::time::timeout(std::time::Duration::from_secs(10), future).await + } + + // `/signed/kv` (`verify_auth`). + let response = within( + fixture + .client + .post("/signed/kv") + .header(Header::new( + "Authorization", + fixture.owner_invocation(&[kv_get()?])?, + )) + .header(ContentType::JSON) + .body( + serde_json::json!({ "space": fixture.space.to_string(), "path": "notes/a" }) + .to_string(), + ) + .dispatch(), + ) + .await?; + let status = response.status(); + busy( + status, + &response.into_string().await.unwrap_or_default(), + "/signed/kv", + ); + + // `/encryption/networks` (its own `verify_auth`): no longer a 401. + let response = within( + fixture + .client + .post("/encryption/networks") + .header(Header::new( + "Authorization", + fixture.owner_invocation_to(&fixture.node_did, &[kv_get()?])?, + )) + .header(ContentType::JSON) + .body("{}") + .dispatch(), + ) + .await?; + let status = response.status(); + busy( + status, + &response.into_string().await.unwrap_or_default(), + "/encryption/networks", + ); + + // SQL (`verify_auth_admitted`): busy, and the statement never runs. + let reply = within(fixture.owner_sql( + "db", + SqlRequest::Execute { + sql: "CREATE TABLE never_created (id INTEGER)".into(), + params: Vec::new(), + schema: None, + }, + )) + .await??; + busy(reply.status, &reply.body, "sql"); + + // A real denial is still a denial: a stranger reading the space. + let stranger = JWK::generate_ed25519()?; + let stranger_vm = tc341_verification_method(&stranger)?; + let mut capabilities = Capabilities::new(); + let (uri, action) = kv_get()?; + capabilities.with_action( + uri.parse()?, + action.parse::()?, + [std::collections::BTreeMap::::new()], + ); + let denied = Payload { + issuer: stranger_vm.parse::()?, + audience: fixture.space.did().to_string().parse::()?, + not_before: None, + expiration: test_invocation_expiration(), + nonce: Some(fixture.next_nonce()), + facts: Some(Vec::::new()), + proof: vec![], + attenuation: capabilities, + } + .sign(stranger.get_algorithm().unwrap_or_default(), &stranger)? + .encode()?; + let reply = within(fixture.dispatch(denied, &[])).await?; + assert!( + [Status::Unauthorized, Status::Forbidden].contains(&reply.status), + "a denial must not turn into busy: {} {}", + reply.status, + reply.body + ); + drop(held); + + let reply = fixture + .owner_sql( + "db", + SqlRequest::Query { + sql: "SELECT name FROM sqlite_master WHERE name = 'never_created'".into(), + params: Vec::new(), + max_rows: None, + max_bytes: None, + }, + ) + .await?; + assert_eq!(reply.status, Status::Ok, "{}", reply.body); + assert_eq!(reply.json["rows"], serde_json::json!([]), "{}", reply.body); + Ok(()) + } + + /// TC-1317 review R2: a deadline shorter than the read-audit wait cuts a + /// read waiting on its audit with `503 request_timeout`, no data. + #[tokio::test] + async fn a_deadline_before_the_audit_wait_answers_request_timeout() -> Result<()> { + use rocket::http::Status; + + let mut config = Config::default(); + config.invocation.deadline_ms = 300; + let fixture = KvSyncFixture::new_configured(config, |rocket| rocket).await?; + fixture.owner_write("notes/a", Some(b"secret")).await?; + let tinycloud = fixture + .client + .rocket() + .state::() + .expect("TinyCloud is managed"); + let get = fixture.owner_invocation(&[( + fixture.kv_resource("notes/a")?.as_uri().to_string(), + "tinycloud.kv/get", + )])?; + let writer = tinycloud + .sqlite_writer_lock() + .expect("the fixture runs on SQLite"); + let held = writer.lock().await; + let reply = tokio::time::timeout( + std::time::Duration::from_secs(10), + fixture.dispatch(get, &[]), + ) + .await?; + drop(held); + assert_eq!(reply.status, Status::ServiceUnavailable, "{}", reply.body); + assert_eq!(reply.body, REQUEST_TIMEOUT_BODY); + Ok(()) + } + #[tokio::test] async fn kv_sync_root_feed_pages_and_requires_root_authority() -> Result<()> { use rocket::http::Status; diff --git a/tinycloud.toml b/tinycloud.toml index 6e12edc2..7f646f00 100644 --- a/tinycloud.toml +++ b/tinycloud.toml @@ -48,6 +48,9 @@ cors = true # statement_timeout_ms = 30000 # bulk_statement_timeout_ms = 120000 # retry_window_ms = 10000 + ## How long an authorized read waits for its audit record before 503 + ## read_audit_busy (TC-1317). Its data is never returned without the record. + # read_audit_wait_ms = 20000 [global.invocation] ## /invoke deadline (TC-1274): before any write, the request is stopped and