Files
buzz/crates/buzz-db/src/error.rs
Will Pfleger 0a06c0b3cb 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

| 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>
2026-11-03 17:48:59 -05:00

204 lines
7.5 KiB
Rust
Raw Blame History

This file contains ambiguous Unicode characters

This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.

//! Database error types.
use thiserror::Error;
/// Errors produced by database operations.
#[derive(Debug, Error)]
pub enum DbError {
/// A SQLx driver-level error.
#[error("database error: {0}")]
Sqlx(#[from] sqlx::Error),
/// A SQLx migration error.
#[error("migration error: {0}")]
Migrate(#[from] sqlx::migrate::MigrateError),
/// Attempted to store an AUTH event (kind 22242), which is forbidden.
#[error("AUTH events (kind 22242) must not be stored")]
AuthEventRejected,
/// Attempted to store an ephemeral event (kinds 20000–29999), which is forbidden.
#[error("ephemeral events (kind {0}) must not be stored")]
EphemeralEventRejected(u16),
/// The requested channel does not exist.
#[error("channel not found: {0}")]
ChannelNotFound(uuid::Uuid),
/// Another listed open channel in the community already has this name
/// (see `channel::ensure_listed_channel_name_unique`).
#[error("an open channel named \"{0}\" already exists")]
ChannelNameTaken(String),
/// The requested member is not in the channel.
#[error("member not found in channel {0}")]
MemberNotFound(uuid::Uuid),
/// A generic not-found error.
#[error("not found: {0}")]
NotFound(String),
/// The caller lacks permission for the requested operation.
#[error("access denied: {0}")]
AccessDenied(String),
/// Invitation admission or minting was denied by authoritative restrictions.
#[error("invitation principal is restricted")]
InviteRestricted,
/// A verified invitation owner conflicts with the recorded owner.
#[error("invitation owner does not match the recorded owner")]
InviteOwnerMismatch,
/// JSON serialization or deserialization failed.
#[error("serialization error: {0}")]
Serde(#[from] serde_json::Error),
/// A value in the database is malformed or unexpected.
#[error("invalid data: {0}")]
InvalidData(String),
/// A partition the catalog audit had already listed was dropped before the
/// audit finished. A fresh snapshot sees a consistent catalog.
#[error("partition catalog changed mid-audit: {0}")]
PartitionDroppedMidAudit(String),
/// A serving write admitted before the lifecycle transition is still live.
/// This is an ordinary retryable drain condition, not a safety violation.
#[error(
"community {community_id} still has {active_count} active serving write lease(s): {operations:?}"
)]
ServingWritesNotDrained {
/// Community whose lifecycle transition must retry.
community_id: uuid::Uuid,
/// Number of currently unexpired serving-write leases.
active_count: i64,
/// Distinct operation categories holding those leases.
operations: Vec<String>,
},
/// A deletion safety invariant is structurally violated and requires
/// operator/code remediation rather than blind retry.
#[error("deletion safety error: {0}")]
DeletionSafety(String),
/// An artifact sync page exceeds its resource limit.
#[error("artifact sync limit exceeded")]
ArtifactSyncLimit,
/// A complete read-state snapshot exceeds its bounded resource budget.
#[error("read-state snapshot exceeds event or byte limit")]
ReadStateSnapshotTooLarge,
/// A complete thread window exceeds its request-wide work allowance.
#[error("thread window exceeds {0} budget")]
ThreadWindowBudgetExceeded(&'static str),
/// A stored timestamp value could not be interpreted.
#[error("invalid timestamp: {0}")]
InvalidTimestamp(i64),
/// A roster mutation would remove the last effective relay Operator,
/// leaving no one able to administer the deployment through the API.
/// The transaction is rolled back and the caller must add a replacement
/// Operator before demoting or deleting the current one.
#[error("operation would remove the last relay operator")]
LastOperator,
}
impl DbError {
/// Whether Postgres cancelled the statement (SQLSTATE 57014:
/// `statement_timeout` or an explicit cancel).
///
/// Replica-routed reads surface a cancel instead of re-running on the
/// writer. Usually the cancel means expensive work that the writer would
/// only repeat at the primary's cost. It can also mean the replica waited
/// on a lock that only it holds (a replayed `ACCESS EXCLUSIVE` from
/// primary DDL), when the writer would have answered quickly. That miss is
/// the accepted price of keeping runaway reads off the primary. Per-call
/// routed reads record it as the `statement_cancelled` route reason;
/// `ReadSession` reads return it to the relay, which logs the failed read.
pub fn is_statement_cancelled(&self) -> bool {
matches!(
self,
DbError::Sqlx(sqlx::Error::Database(db)) if db.code().as_deref() == Some("57014")
)
}
/// Whether the failure is about reaching the database at all (pool
/// acquire timeout, closed pool, or socket I/O) rather than about the
/// statement or its tenant. Every later query on the pool is expected to
/// fail the same way.
pub fn is_connection_unavailable(&self) -> bool {
matches!(
self,
DbError::Sqlx(sqlx::Error::PoolTimedOut | sqlx::Error::PoolClosed | sqlx::Error::Io(_))
)
}
}
/// Convenience alias for `Result<T, DbError>`.
pub type Result<T> = std::result::Result<T, DbError>;
/// A fixed description of a driver error for log lines. Postgres primary
/// messages can repeat a bound value (`invalid input syntax for type uuid:
/// "<value>"`), so only the SQLSTATE code is kept.
pub fn sqlx_error_kind(e: &sqlx::Error) -> String {
let kind = match e {
sqlx::Error::Database(db) => {
return format!("database:{}", db.code().as_deref().unwrap_or("unknown"))
}
sqlx::Error::RowNotFound => "row_not_found",
sqlx::Error::PoolTimedOut => "pool_timed_out",
sqlx::Error::PoolClosed => "pool_closed",
sqlx::Error::Io(_) => "io",
sqlx::Error::Tls(_) => "tls",
sqlx::Error::Protocol(_) => "protocol",
sqlx::Error::ColumnDecode { .. } | sqlx::Error::Decode(_) => "decode",
sqlx::Error::Encode(_) => "encode",
_ => "other",
};
kind.to_owned()
}
impl DbError {
/// A fixed description of this error for log lines: never the
/// message, which can repeat bound values.
pub fn kind(&self) -> String {
use DbError as E;
let kind = match self {
E::Sqlx(e) => return sqlx_error_kind(e),
E::Serde(_) => "serde",
E::InvalidData(_) => "invalid_data",
E::NotFound(_) | E::ChannelNotFound(_) | E::MemberNotFound(_) => "not_found",
E::AccessDenied(_) => "access_denied",
_ => "other",
};
kind.to_owned()
}
}
#[cfg(test)]
mod tests {
use super::DbError;
#[test]
fn connection_unavailable_covers_only_pool_and_io_failures() {
for error in [
sqlx::Error::PoolTimedOut,
sqlx::Error::PoolClosed,
sqlx::Error::Io(std::io::Error::from(std::io::ErrorKind::ConnectionReset)),
] {
assert!(DbError::Sqlx(error).is_connection_unavailable());
}
for error in [
DbError::Sqlx(sqlx::Error::RowNotFound),
DbError::Sqlx(sqlx::Error::Protocol("bad frame".into())),
DbError::AccessDenied("write-fenced".into()),
DbError::InvalidData("bad row".into()),
] {
assert!(!error.is_connection_unavailable(), "{error:?}");
}
}
}