feat(relay): log reads, logins and connections on access target - #8376

🤖 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

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.