5 Commits

Author	SHA1	Message	Date
Will Pfleger	5b433d9292	feat(relay): resolve NIP-FI issuer bindings from the database (#8377) ... Stack: #8372 (merged) → this PR → #8399 → #8401 Makes relay login checks read the per-community NIP-FI issuer bindings that #8372 stores. Without this, the relay can't keep up with bb-public, where new communities are created at every signup and a static `BUZZ_NIP_FI_COMMUNITIES` list won't do. **Source switch.** `BUZZ_NIP_FI_COMMUNITY_SOURCE=database` resolves each community's trusted issuers from `community_nip_fi_issuers`, filtered by the issuer registry, instead of the static list. Each community gets its own policy ID: the base ID no longer hashes every community audience, and the final ID hashes the base plus this community's audience, so policy IDs change once (see `docs/operator-nip-fi-bindings.md`). `Config::from_env` refuses to start, in every mode, on an unknown source, on `database` together with `BUZZ_NIP_FI_COMMUNITIES`, and on `database` without `BUZZ_NIP_FI_PROVISION_BINDING`. `BUZZ_NIP_FI_RESOLVER_*` and `BUZZ_NIP_FI_SNAPSHOT_*` are validated in every mode, so a bad value fails the deploy that sets it. In `off` mode no resolver is built and no snapshot is loaded. **Resolver (`nip_fi_resolver.rs`).** - **Snapshot:** each pod loads every binding into memory, capped at `BUZZ_NIP_FI_SNAPSHOT_MAX_ROWS` (going over is a failed load). It refreshes every 30 s, start to start, with jitter that only shortens the delay and backoff after failures. Each attempt is limited by `BUZZ_NIP_FI_SNAPSHOT_REFRESH_TIMEOUT_MS`, which must be shorter than the interval. A refresh whose deadline passes before it publishes publishes nothing. The old snapshot is dropped off the runtime. - **Freshness:** a host in a snapshot loaded under two minutes ago is answered from memory. Any other host, and every host once the snapshot is stale, goes to a live lookup. Every answer carries a deadline two minutes after the read behind it started, and WS, HTTP and audio recheck it just before admitting. - **Live lookups:** bounded and single-flight. In-flight lookups are capped by `BUZZ_NIP_FI_RESOLVER_MAX_INFLIGHT` (default 8, clamped below the database pool size), and the pending hosts and their waiters have fixed caps. Positive answers are used for that admission only. A "not found" is cached for 5 s, up to `BUZZ_NIP_FI_RESOLVER_NEGATIVE_CACHE_MAX` hosts, and only when no snapshot was published and no binding was created while it ran. A lookup that panics still leaves the pending map. - **Removal:** a removed binding stops admitting new connections within 30 s plus the refresh timeout (40 s by default) while refreshes succeed, and within two minutes of the last good load while they fail. Open WebSocket sessions are not rechecked when a binding is removed; they end at their own session deadline. **Shadow mode** resolves through the same path as enforce, including the database lookup and the freshness rules. It keeps the resolved binding's deadline and checks it at the same point as enforce; a binding that goes stale during the tenant lookup is recorded as `stage=deadline, outcome=unavailable`, without changing the legacy response or closing the socket. With `source=database` its `community` metric label is only `bound` or `unmapped`; with `source=env` it keeps the existing per-community audience label, so current shadow dashboards are unchanged. Each request resolves its Host once: the router guard's resolution, failures included, is reused by shadow recording and admission. **Provisioning.** Both operator provisioning paths drop this pod's cached "not found" for the new host after a commit that bound issuers, so the creator's first login looks it up. **Startup and readiness.** With `source=database` and a mode other than `off`, the first snapshot loads before any listener binds, under its own startup phase `nip_fi_snapshot_load`. A failed load exits non-zero, so a pod is never ready without a snapshot. **Operational consequence:** boot already fails when the database is unreachable; what is new is that a snapshot over `BUZZ_NIP_FI_SNAPSHOT_MAX_ROWS` or a load past its timeout also crash-loops new pods. After two minutes the old pods' snapshots go stale and most logins fall through to the 8-slot live lookup, which sheds the rest with 503. The way out is raising the cap or timeout, or `mode=off`. **Metrics.** `buzz_nip_fi_binding_snapshot_*` covers loads, failures, rows and freshness. `buzz_nip_fi_binding_snapshot_loaded_timestamp_seconds` is written on every refresh attempt, so alert on `time() - x > 120` together with `absent(x)`. `buzz_nip_fi_binding_snapshot_rows` against `buzz_nip_fi_binding_snapshot_max_rows` gives the headroom to the row cap. `buzz_nip_fi_resolver_*` covers live lookups and the negative cache. The env vars and alerts are documented in `.env.example`, the chart README and `docs/operator-nip-fi-bindings.md`, which also has the staged off → shadow → enforce rollout for `source=database` with go/no-go signals at each step, and the over-cap and load-timeout failure modes with their ways out. **Regression coverage.** Router-level tests run the database resolver through the real `build_router` for root WS, audio and protected HTTP, in enforce and shadow mode. Over PostgreSQL and Redis, two pods using the env community source (two exact bindings) replay assertions retained from before a disconnect through a real root NIP-42 session, the audio deny-set check and signed NIP-98 requests: they are denied on both pods, and a root session upgraded before the disconnect is refused by the post-registration deny-set check. Postgres tests in `buzz-db` check that archived and quiescing communities, and issuers missing from the registry, never reach the snapshot or the live lookup. Process-level `boot_lifecycle` tests spawn the real relay with `source=database`: an over-cap or timed-out startup load exits non-zero with no health listener bound, and a loadable snapshot lets readiness turn ready. --------- Signed-off-by: Will Pfleger <pfleger.will@gmail.com> Co-authored-by: Hayt <211b96e6a2b7f45fd4047988976c7bbbeeda0c15f3ae7b32eec20834b5a55118@buzz.block.builderlab.xyz> Co-authored-by: Duncan <dcfd242e557282d7a1e2cf2e6877522682f1e5c6156dc92ca7d90eaedd3b0f95@buzz.block.builderlab.xyz>	2026-10-19 10:32:18 -04:00
Luke Tornquist	e097c42996	feat(relay): time post-metrics-bind startup steps (#8132) ... ## Summary Relay pods on large deployments can take over 5 minutes to open their health port, and right now nothing shows which startup step is slow. Startup timing ends at `metrics_bind`, and the slow work all happens after it. This PR times every startup step from Postgres connect through public listener bind. It does not change startup behavior. - Each step logs `Startup phase started` and `Startup phase finished`, with `phase`, `elapsed_ms`, and `status` (`succeeded` / `degraded` / `failed`, the same values `buzz_process_lifecycle` records use). - Gauge `buzz_startup_phase_current{phase}` is `1` while a step runs and `0` after it ends. A pod that is still starting shows exactly which step it is on. - Gauge `buzz_startup_phase_seconds{phase}` records each finished step's duration. - The startup NIP-43 membership reconcile logs `NIP-43 startup reconciliation progress` every 5,000 communities, with `done`, `total`, `republished`, `failed`, and `elapsed_ms`. These are gauges rather than counters on purpose. Each value is written once per boot, and a monotonic-counter scrape drops a series' first sample, so a one-shot counter never shows up. ## Contract change `deploy/charts/buzz/README.md` ("Early-startup telemetry contract") said the early lifecycle phases are log-only. That still holds: `crypto_init` through `metrics_bind` are unchanged and emit no metrics. The README now also documents the post-bind steps. The guard in `boot_lifecycle.rs` now allows exactly the two `buzz_startup_phase_*` families. It still rejects any other startup, boot, or lifecycle family, and it also rejects any exported label value that names an early phase. ## Design - `crates/buzz-relay/src/startup_steps.rs` adds a closed `StartupStep` vocabulary (18 steps) and a `StepTimer` guard. - A step ends exactly once: - `finish()` → `succeeded` - `degrade()` then `finish()` → `degraded` (a non-fatal error branch) - dropped without finishing → `failed` (covers `?` early returns and panics) - The NIP-43 and large-roster reconciles now return `ReconcileSummary { repaired, failed }`. A sweep where any item fails ends its step `degraded`, and the final log line includes the `failed` count. NIP-FI warm ends `degraded` when any issuer did not warm. The deprecated `reconcile_nip43_membership_snapshots` wrapper still returns `repaired`. - Steps that are disabled by config (migrate, audit connect, NIP-FI warm, git probe, NIP-43 reconcile) are not timed, so their series never appear. - The gauges are set once, so they age out after the existing gauge idle timeout (2700 s with default intervals; logged as `idle_timeout_secs`). A step that runs longer than that loses its `_current` series. The README says so. - Progress logging runs only for the `Bootstrap` reconcile. The 60 s maintenance sweep stays quiet. ## What got simpler Little got simpler in the code: this mostly adds instrumentation. One CI gap closed along the way: the 54 `config` tests and the 9 non-ignored `boot_lifecycle` tests, which ran in no CI lane, now run in `test-unit`. The instrumentation is scoped as small as I could make it, and it is the evidence needed for the follow-up that should delete code: moving the per-community NIP-43 reconcile off the pre-bind path, after which the 900 s startup-probe override can go back to the chart default. ## Testing - `startup_steps` unit tests (`DebuggingRecorder`): - a running step is current and has no duration - a finished step clears current and records its elapsed time - dropped and degraded steps clear current and record a duration - log capture: `finish`, `degrade`+`finish`, drop, and panic each emit exactly one `Startup phase finished` record with the right `status`. Mutating `degrade()` to a no-op and removing the ends-once guard makes these tests fail. - the vocabulary is unique and shares no names with the early lifecycle phases - Tests that capture logs or check callsite interest now share `test_support::tracing_dispatch_lock()`. These are the `startup_steps` helpers, two `telemetry` tests, and the `config` and `bridge` log-capture helpers. tracing-core caches each callsite's interest across the whole process. Without the lock, the new panic test lost its record in 60 of 150 parallel runs of `telemetry:: startup_steps:: config::`. With the lock it failed 0 of 300. Removing the lock from `gauges()` brings the failures back (53 of 100 runs). - `nip43_progress_logs_every_interval_inside_the_startup_sweep_only` checks the cadence at 79,942 communities (15 progress lines, none at the start or end) and table-tests that the maintenance sweep never logs progress. - `boot_lifecycle::successful_main_emits_complete_lifecycle_and_reports_current_startup_step` boots the real relay binary against a TCP peer that never speaks Postgres. It asserts that `/metrics` shows `buzz_startup_phase_current{phase="db_connect"} 1` and no finished-step durations, and that no early phase leaks into metrics. - **CI routing.** `just test-unit` picks relay tests by hand-maintained filter. Before this PR, CI's filters selected none of the `startup_steps`, `telemetry`, `config` or non-ignored `boot_lifecycle` tests above; the NIP-43 cadence test is picked up by the existing `handlers::side_effects::tests::` clause. Its infra-free relay stanza now selects `startup_steps::tests::`, `telemetry::tests::` and `config::tests::` (anchored so `nip_fi_config` is not selected twice), and a new `cargo nextest run -p buzz-relay --test boot_lifecycle` line runs the non-ignored `boot_lifecycle` tests (they spawn the real binary and need no Postgres or Redis; the Postgres cases stay `#[ignore]`d). `scripts/run-tests.sh` mirrors both, running `telemetry` and `config` single-threaded because they mutate process env. ### Manual check 1. `just relay` (or run `buzz-relay` against local Postgres and Redis). 2. Once the relay is up: `curl -s localhost:9102/metrics | grep buzz_startup_phase`. Every step that ran has a `_seconds` value, and every `_current` value is 0. 3. In the relay logs, `"Startup phase finished"` lines show each step's `elapsed_ms`. --------- Signed-off-by: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz> Co-authored-by: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz>	2026-10-07 10:15:43 -04:00
Luke Tornquist	b37e477211	Make relay readiness process-local (#7341) ... ## Summary Make Kubernetes readiness depend only on the relay process lifecycle, so a shared Postgres or Redis slowdown cannot withdraw every pod at once. Move dependency checks to one fixed-cadence loop per pod. The loop permits only one evaluation at a time, emits metrics after each sample, and caches a timestamped report. `/_status` reads that cache without calling Postgres, Redis, or the deletion catalog. It reports `not_yet_sampled`, `fresh`, or `stale`. Each completed sample also writes a Unix timestamp gauge, so Datadog can compute sample age at query time. Fail closed when the community lifecycle lookup errors. An inconclusive tenant-state lookup no longer admits a socket to AUTH or REQ handling. ### Related issue None found. This addresses the elevated relay HTTP 500 and reconnect incident investigated on 2026-09-03. ### Tradeoff The readiness gauge now reports the latest private-probe observation, not the shutdown transition itself. After shutdown starts, a scrape can still see `1` until the next readiness probe refreshes the gauge to `0`. Kubernetes routing is unaffected because it uses the readiness response from the authoritative process state. A terminal `0` was never guaranteed: even a transition-owned gauge could update in process and then exit before Prometheus scraped it. If no scrape occurs before exit, both designs miss the terminal sample. The new design adds at most the interval until the next readiness probe when a scrape occurs during shutdown. Dependency status is now sampled every 30 seconds rather than on demand. A slow evaluation delays the next sample instead of stacking more work. The status payload exposes the cached report age. The completion timestamp stays unchanged when sampling stops, so `time() - timestamp` crosses the stale threshold without a server aging loop. Outcome counters and duration histograms remain cumulative and cannot provide no-data detection. ### Testing Gimli exercised exact SHA `edff1ec4a5362e132e367bf7449d2b0a68f1e9a9` on an isolated Blox stack. Repeated `/_status` bursts caused no dependency calls, metrics advanced without status traffic, stale status remained visible, and lifecycle lookup failures admitted no AUTH or REQ handling. Follow-up verification at `fdbb394ed598c94cde85ed01cb11e9de0ee8f00d` confirmed sampler-owned outcome and duration emission without status traffic and bound the real startup seam. The final timestamp-gauge change is covered by targeted red/green tests and the same boot regression at `c0f36e22b527c2fd6a63a548d036d006ffa17171`. ### Complexity Readiness remains one process-local sample per probe. Dependency I/O now has one owner and one execution path; request volume cannot increase dependency-check load. One completion timestamp replaces the prior server-side age update path; Datadog computes age without another loop. Community admission also returns to one fail-closed rule for inactive and unknown tenant state. Generated with [Claude Code](https://claude.ai/code) --------- Signed-off-by: tornquist <tornquist@squareup.com> Signed-off-by: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz> Co-authored-by: Codex <noreply@openai.com> Co-authored-by: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz> Co-authored-by: Claude Opus 5 <noreply@anthropic.com> Co-authored-by: Amp <amp@ampcode.com>	2026-09-28 14:02:12 -04:00
ravarora2	891208914e	Add authenticated WebSocket recovery telemetry (#7546) ... ## Summary Argo rollout recovery needs to distinguish an open WebSocket from a connection that completed NIP-42 authentication and is usable. The relay currently exposes total WebSocket connections, but it cannot answer whether authenticated clients recovered after a pod drain or why authentication failed. This change adds a bounded recovery contract: - `buzz_auth_attempts_total{method="nip42"}` - `buzz_auth_outcomes_total{method="nip42",outcome}` - `buzz_auth_duration_seconds{method="nip42",outcome}` - `buzz_ws_authenticated_connections_active` - `buzz_auth_post_terminal_frames_total{state}` `buzz_auth_attempts_total` now has one consistent recovery-oriented unit: a challenge lifecycle successfully queued to the connection writer. This intentionally replaces the historical unit of AUTH frames that reached the pending handler. AUTH frames received after a lifecycle is already authenticated or failed are protocol noise; they use the separate bounded post-terminal counter and cannot inflate rollout-gating attempts or outcomes. Each issued challenge reaches exactly one terminal outcome. Authentication transitions and active-gauge changes share one short synchronous state lock, cancellation can claim a pending database-backed AUTH before a late handler result, and a drop guard reconciles aborted or panicked connection futures. Accounting is terminalized before writer joins, while terminal socket delivery has a one-second best-effort bound so a stalled sink cannot retain the authenticated gauge or connection permit indefinitely. Dependency failures are distinct from policy verdicts: allowlist and relay-membership lookup errors now emit `allowlist_check_error` and `relay_membership_check_error`, never `allowlist_denied` or `not_relay_member`. The fail-closed allow/deny policy is unchanged. All rollout-facing labels come from fixed enums; identities, challenges, URLs, and raw error strings are never exported. All fixed counter and histogram label sets, including zero histogram buckets, counts, and sums, are present on the first real exporter scrape. This is the first implementation slice of the rollout-reliability plan. A later PR will consume these metrics from opt-in Argo Rollout analysis; merging this PR alone does not change deployment behavior. ### Related issue None found. ### Testing Validated at final head `f9992cac835284c25ee0f99e17ddba0b932d7c69`, which contains current `origin/main`: - `cargo fmt --all -- --check` - `cargo clippy -p buzz-relay --all-targets -- -D warnings` - compiled every `buzz-relay` test target - release builds for `buzz-relay`, `buzz`, `buzz-admin`, and `buzz-test-cli` - 16/16 connection lifecycle/writer/production-dispatch tests - 7/7 AUTH handler tests - bounded metric-contract exporter test - 13/13 relay main-target tests (1 PostgreSQL-only test ignored) - 9/9 real boot-lifecycle tests, including a production install and first Prometheus scrape Mutation checks proved that the production regressions fail when any of these are removed or reintroduced: - challenge attempt start in `handle_active_connection` - authentication series initialization in the real metric installer - separation of post-terminal AUTH floods from authoritative attempts The exact-head release binaries were also exercised against the isolated review database: 1. Started the release relay and verified health/readiness. 2. Created a channel with the regular CLI. 3. Held one authenticated WebSocket subscription open and authenticated a second WebSocket publisher. 4. Published a message and read it back through the regular CLI. 5. Observed `attempt_delta=2`, `success_delta=2`, `active_while_subscribed=1`, and `active_after_disconnect=0`. 6. Sent SIGTERM and waited for graceful relay shutdown. ### Local caveat The full relay library target consistently reached 1,049 passes with 89 intentionally ignored tests, but the untouched `api::mesh_demo::tests::demo_join_forwarded_arm_round_trips_echo` intermittently returned HTTP 504 instead of 200. One isolated rerun passed; later isolated and full reruns reproduced the 504. No mesh files are changed by this PR, and all changed-path, main-target, boot-lifecycle, lint, build, mutation, and live-local checks above passed at the final head. Generated with Codex --------- Signed-off-by: Ravneet Arora <rarora@squareup.com>	2026-09-16 16:06:33 -04:00
ravarora2	88687876f7	feat(relay): add early startup lifecycle logs (#7258) ... ## Why Early relay failures can currently appear as a container restart without a trustworthy in-process account of whether crypto, structured logging, configuration, relay identity, or the metrics listener failed. Most of those steps happen before the Prometheus exporter exists, so their chronology belongs in logs rather than metrics. Implements the logs-only early-startup slice of #7238. Post-bind Prometheus exporter supervision is tracked separately in #7284. ## What changed - create a process lifecycle recorder before the Tokio runtime and emit a fixed, versioned JSON schema directly to stderr; - record started and exactly one terminal event for `crypto_init`, `tracing_init`, `config_load`, `key_load`, `metrics_bind`, and the aggregate `process_telemetry` phase; - keep every status and reason bounded and suppress raw errors that could contain credentials, keys, URLs, or other secrets; - return typed metrics-install errors so `metrics_bind` can be classified without logging raw values, while preserving the existing public `metrics::install` API; - document the logs-only evidence contract and add real child-process regressions for success and failure paths. This PR adds **no startup metric families** and no dashboard contract. Existing application metrics remain unchanged. ## Verification Exact head: `8faf7526822a119efa035e58b2b3c59aa67fc81d` - `cargo fmt --all -- --check` - `cargo clippy -p buzz-relay --all-targets -- -D warnings` - relay binary target: 13 passed, 1 PostgreSQL-only test ignored - real relay child-process lifecycle target: 9 passed - full relay package library target: 1,023 passed, 89 ignored; the same six media tests failed at `crates/buzz-relay/src/api/media.rs:1145` with `Sqlx(PoolTimedOut)` because local PostgreSQL is unavailable - three independent exact-head reviews found no correctness, security, compatibility, lifecycle-accounting, logs-only-scope, or test-adequacy finding All exact-head GitHub CI gates are green, including lint, unit tests, PostgreSQL, relay/backend/desktop integration, both Linux server cross-compiles, Windows/macOS builds, and security checks. ## Staging verification - exact multi-architecture image: `dev-sha-8faf7526822a119efa035e58b2b3c59aa67fc81d-run-33708188952-1` - immutable manifest: `sha256:26cad28266a6bb0b0e7081eb6091d374e5489f8bb78c475a4a65737dee86cc67` - image workflow: https://github.com/block/buzz/actions/runs/33708188952 - focused staging deployment: https://github.com/squareup/builderbot-platform-core-infrastructure/pull/314 - replacement ReplicaSet `buzz-d68764bc7` has two Ready pods with zero restarts - Datadog received one complete, contiguous sequence 1-12 from each pod; both end with `process_telemetry/terminal/succeeded` at 3 ms - queries scoped to the replacement ReplicaSet return no data for the removed `buzz_startup_phase_terminal` or `buzz_startup_phase_duration_seconds` families The experimental Row 7 was removed from the Buzz Startup & Rollout Safety dashboard. This logs-only PR deliberately adds no replacement dashboard row. --- **Update Sep 3, 12:26 ET:** Clarified the review boundary: this PR does not close the broader #7238. Later exporter-task termination is pre-existing runtime behavior and is now explicitly tracked in #7284; no production code or staged image changed in this update. Generated with Codex Signed-off-by: Ravneet Arora <rarora@squareup.com>	2026-09-03 13:37:51 -04:00