mirror of
https://github.com/block/buzz.git
synced 2026-11-04 16:31:38 +00:00
0a06c0b3cb
🤖 Adds an access log for relay reads, logins, connections and HTTP requests on the dedicated `buzz_relay::access` target. It writes to stdout, not `audit_log`, so reads never take the audit advisory lock. The log is shaped for volume: one line per HTTP request, one line per WebSocket read, and one line per WebSocket connection. ## Lines per operation | Operation | Lines | |---|---| | HTTP request on a matched route | 1 (`http`), except the skip list below | | HTTP request matching no route | 1 (`http`, `route="<unmatched>"`) at status 400 and above, otherwise none | | WebSocket connection | 1 (`close`, carrying the login) | | WebSocket `REQ` / `COUNT` / NIP-AR sync | 1 each (`req` / `count` / `sync`), plus the `buzz_ws_reads_total` counter | | WebSocket NIP-42 login | 1 (`auth`) per decided or cut-off attempt, capped after the decision as below | | Audio login | 1 (`auth`, at its final admission check) | | WebSocket `EVENT` | 1 (`Event ingested`, not on the access target) | ## HTTP requests One middleware, `http_access_log`, writes every HTTP line. It sits between `track_metrics` and `http_trace_layer`, so rebuilt errors, body-limit refusals and localhost refusals all reach it. It writes the line when the response is ready, which is not proof the body was delivered. A request dropped before then logs `request=aborted` at WARN with no `status`. - Every line carries `route` (the matched route template, never the raw path), `peer_addr` when the listener has one, `status`, `time_to_response_ms` and `http_method` (the HTTP verb). The verb stays on the line itself because the `http.request` span is absent under an access-only filter and when a pending request is dropped. - Handlers record what they learn on the request's `AccessSlot`: the login (`method`, `pubkey`, `pubkey_verified`, `community`), the decision, the filter summary, and the route's own fields. The decision is `outcome` (`success` / `denied` / `failed` / `challenged`) with a fixed `reason`, or `undecided` when the route recorded none. A refusal is final: a later admission doesn't replace it, so a replayed NIP-98 proof that verifies and is then refused logs `failed` / `nip98_replay`. - `outcome` describes the login. What the route did is in `status` and the route's fields: a rejected `/events` write logs `outcome=success` with `status=400`, `accepted=false` and its `reject_reason`. - Route fields: - `/query` and `/count`: the filter summary and `result_count`. An incremental `/query` response (`{changes:[...]}`) counts its changes, removals included. Artifact reads record their summary before the query runs, so a read dropped mid-query keeps it. - `/events`: `accepted`, `kind`, `event_id`, and on a refused write the parse `category` / `line` / `column` or a fixed `reject_reason` (such as `invalid` or `restricted`), never the ingest message. - Invite mint: `invite_id`, `expires_at` and `max_uses`. Invite claim: `joined`. - Admin feedback attachment reads: `feedback_id` and `attachment_sha256`. With `BUZZ_ADMIN_AUTH=disabled` they log `method=network_trusted` with no key, and Host or Origin refusals log their fixed reason. - Every other route logs only the login fields. - No field can hold an invite code, a token, or a Blossom read hash. Media routes log the `/media/{sha256_ext}` template. - Skip list: NIP-11 and other non-upgrade requests on `/`, `/info`, `/.well-known/nostr.json`, `/health`, `/_liveness`, `/_readiness`, and the SPA and static files the relay serves when enabled (web assets, invite landing pages, git web pages, the admin bundle) at any status. Successful WebSocket upgrades (101) log no `http` line. Refusals before the upgrade on `/` and the audio path log one, with the status actually sent. - Routes that aren't Nostr-key logins (the command-token disconnect endpoint, the workflow webhook, the git server's internal callback) log `outcome=undecided` with no key. - Dev-mode `X-Pubkey` requests log `method=x_pubkey`, `pubkey_verified=false`. - A successful `/query` or `/count` that returned nothing (`result_count=0`) logs at DEBUG: on staging, 93% of `/query` lines were empty polls. Denied, failed, aborted and error reads, reads with no `result_count`, writes and logins keep their levels. - Other successful lines and git's credential-less first request (`challenged`, with its 401) are INFO. Refusals, statuses of 400 and above, and aborted requests are WARN. In Enforce mode the line records the remapped status (for example 403). Denial bodies and headers are unchanged. ## WebSocket reads - `REQ` / `COUNT` / `sync` lines carry `pubkey`, `conn_id`, `sub_id`, the filter summary, the outcome (`served` / `denied` / `aborted` / `error` plus a fixed reason), and `events_queued` (REQ and sync) or `count` (a COUNT that counted). A `REQ` is `served` only once its EOSE is queued to the client. A read logs WARN only when it ends in `error`. `served`, `denied` and `aborted` are INFO, since `aborted` means the read ended before completing: the client disconnected or sent CLOSE, a same-ID `REQ` replaced it, or the session was cancelled. - A NIP-AR sync subscription writes its `sync` line when its initial set completes, not when live delivery ends. Its summary is the registered live filter (kinds and channels, never artifact predicates), and `events_queued` counts the initial set. - `REQ` lines stay at INFO even when empty at EOSE, because the subscription can still deliver live events later. - Filter summary, shared with HTTP `/query` and `/count`: `kinds`, channel ids, authors and `p` values each list the first 10 distinct values. The exact `kind_count` / `channel_count` / `author_count` / `p_count` (summed per filter) appears only when the list is `*` or shows fewer values than the filters held. A dimension that any filter leaves open logs `*`. `since` / `until` / `limit` take the widest bound and are absent when any filter leaves them open, so no field understates what the read covered. `ids` is a count only. NIP-50 search logs `search: true`, never the text. Only well-formed channel ids and pubkeys are listed. An artifact read's summary uses only the standard dimensions of each raw filter, so artifact predicates and client-defined tags (such as `#1`) are never logged. The summary is skipped when the access target is off. Under `=warn`, every WARN line, HTTP or WebSocket, still carries it. - Per connection, only the first 16 reads that are refused before they run (`auth_required`, quota, concurrency, overload) or denied are logged. The rest are counted as `reads_suppressed` on the close line. A refusal that arrives after the close line has been written, from a read still running when the client left, logs its own line, so every refusal is either logged or counted, never both. Served reads are never capped. ## WebSocket read counter `buzz_ws_reads_total{type="req"|"count"|"sync"}` counts every parsed `REQ`, `COUNT` and NIP-AR sync frame before admission, exported at zero from startup. It is a metric, so it counts at any `RUST_LOG`, including production's current `error`. ## WebSocket logins A NIP-42 login writes one `auth` line when it is decided. A successful login logs INFO `outcome=success` at its commit point, decided under the connection's close-reason lock, so a disconnect racing the login (session expiry, admin disconnect, revocation, ban or roster removal) either wins, and the login logs no success, or loses and closes the connection right after the success line. A refused or failed login writes one WARN `auth` line with `outcome`, a fixed `reason` from the shared `AuthReason` code set, `pubkey` and `pubkey_verified`. Root WebSocket `auth` lines carry `peer_addr`. AUTH frames after the login is decided are capped at 16 per connection, and the rest are counted as `auth_suppressed`. An attempt cut off by close or session expiry logs `aborted`. Audio logins log one `auth` line at their final admission check. ## Connections The close line is the connection's only line. It is owned by the upgraded socket, so it is written exactly once however the connection ends: a normal close, a refusal while checking the community is active (`refused=not_admitted`), the connection limit (`refused=connection_limit`), or the handler being dropped. It carries `conn_id`, `community`, `peer_addr`, `duration_ms`, the login, `events_queued` / `bytes_queued` (frames the writer accepted and flushed, not client delivery), and the two suppression counters. ## Error text - Database errors log as `DbError::kind()` (SQLSTATE or variant), including the command-executor event insert. Search errors, on both read paths and in the search-cancel task, log as `SearchError::kind()` / the same SQLx classifier. Workflow database and webhook errors log as their codes, since webhook URLs can be secrets. - Git NIP-98 failures log a fixed code. Git subprocess stderr moved to DEBUG because hook output can contain message text. ## Operator notes `.env.example` documents the target, its `event` values (`http`, `auth`, `req`, `count`, `sync`, `close`), the skip list, the levels, and how to turn it down: `buzz_relay::access=warn` keeps refusals, errors and aborted HTTP requests, and of WebSocket reads only those that end in `error`, and `=off` drops everything. It also lists the removed lines: `NIP-42 auth successful/failed`, `WebSocket connection established/closed`, `event=connect`, `HTTP bridge request`, `Event ingested via pipeline`, `relay invite minted`, `relay member added via invite`, `admin feedback attachment read`, and `addr` (now `peer_addr`). JSON lines no longer repeat the current span as `span`, since `spans` already ends with it. A line logged under an explicit `parent:` span loses that parent's fields. The default OTel export filter sets `buzz_relay::access=off`, so access lines aren't exported a second time as span events. `peer_addr` is the TCP peer. `BUZZ_CLIENT_IP_HEADER` optionally names a request header (for example `cf-connecting-ip` behind Cloudflare or `x-real-ip` behind nginx, matched case-insensitively). When set, `http`, `auth` (root and audio), `close` and connection-limit lines also log `client_ip`: the rightmost comma-separated entry of the header's last field, only if it parses as an IP address. It never replaces `peer_addr`, and it is only trustworthy when every request arrives through a proxy that overwrites the header. --------- Signed-off-by: Duncan <dcfd242e557282d7a1e2cf2e6877522682f1e5c6156dc92ca7d90eaedd3b0f95@buzz.block.builderlab.xyz> Signed-off-by: Will Pfleger <pfleger.will@gmail.com> Signed-off-by: Will Pfleger <wpfleger@block.xyz> Co-authored-by: Duncan <dcfd242e557282d7a1e2cf2e6877522682f1e5c6156dc92ca7d90eaedd3b0f95@buzz.block.builderlab.xyz>