feat(relay): log WebSocket EVENT writes on the access target (#9154)

Logs every WebSocket `EVENT` on the access target
(`buzz_relay::access`). Before this, accepted writes logged only `Event
ingested` on the handler target, and refused or ephemeral writes logged
nothing.

### What's logged
Each `EVENT` frame writes one `event=write` line when its handler
finishes. The line has `conn_id`, `community`, `pubkey` (the
authenticated login, if any), `kind`, `event_id`, and
`outcome`/`reason`, taken from the OK the relay sent:
- `accepted`
- `rejected` (INFO), with `reason` set to the OK's NIP-01 prefix
(`invalid`, `restricted`, `auth-required`, `duplicate`, `rate-limited`,
…). Any other message is logged as `other`.
- `error` (WARN), when the OK starts with `error`
- `aborted`, when the handler ended before deciding an OK

`outcome` is always the relay's decision. If the OK couldn't be queued
because the outbound channel was full or closed, the line adds
`ok_queued=false`; the field is left off otherwise.

`EVENT`s refused before the handler runs are logged too, where their OK
is sent: admission rate limits, with admission's reason, and a full
handler pool, as `rate-limited`.

The OK text after the prefix, the event's content and its tag values are
never logged. Lines join to `auth`/`close` lines (and so to `peer_addr`)
through `conn_id`, the same way `req` lines do.

Rejected writes are capped per connection by the same refusal-budget
mechanism as refused reads, on their own counter: the first 16
rejections are logged and the rest are only counted, in a new
`writes_suppressed` field on the `close` line. Accepted writes are never
capped.

### How
`access::WriteLog` sends the OK and records it in one call
(`write.ok(...)`). That call replaces every
`conn.send(RelayMessage::ok(...))` in `handle_event` and the
observer-frame handler, so the line always shows what the client was
told.

### Tests
- `access::tests`: the reason comes from the OK prefix only; each
outcome logs at the right level and without content; rejected lines are
capped by the budget and accepted ones are not (draining the channel so
every OK is queued); an OK refused by a full or a closed outbound
channel keeps its outcome and adds `ok_queued=false`.
- `handlers::event::tests::fanout_access`: an unauthenticated `EVENT`
going through `handle_event` writes one `rejected`/`auth-required` line,
with no content or tag values.

---------

Signed-off-by: Will Pfleger <wpfleger@block.xyz>
Co-authored-by: Duncan <dcfd242e557282d7a1e2cf2e6877522682f1e5c6156dc92ca7d90eaedd3b0f95@buzz.block.builderlab.xyz>
This commit is contained in:
Will Pfleger
2026-11-05 19:46:24 -05:00
committed by GitHub
parent bd1b17dee8
commit fba8a7a94f
7 changed files with 470 additions and 65 deletions

File diff suppressed because one or more lines are too long

View File

@@ -13,6 +13,8 @@
//! except public documents and probes; a request that matched no route is
//! logged only at status 400 or above, as `route="<unmatched>"`. `route` is the
//! matched template, never the raw path.
//! `event=write` lines cover WebSocket EVENT: one per frame, with the OK the
//! relay answered (see [`WriteLog`]).
//! A successful bridge read that returned nothing (`result_count=0`) logs at
//! DEBUG: polling clients make most of them. WebSocket `req` lines stay at
//! INFO, because an empty subscription can still deliver live events.
@@ -188,12 +190,13 @@ impl<T: PartialEq> Listed<T> {
const REFUSAL_LINES: u64 = 16;
/// Per-connection bound on the access lines a client can trigger without
/// being served: reads refused or denied, and AUTH frames after the login was
/// decided. The first [`REFUSAL_LINES`] of each are logged; the rest are
/// being served: reads refused or denied, EVENTs rejected, and AUTH frames
/// after the login was decided. Each kind has its own counter. The first [`REFUSAL_LINES`] of each are logged; the rest are
/// counted and reported on the close line. Served reads are never capped.
#[derive(Debug, Default)]
pub(crate) struct RefusalBudget {
reads: AtomicU64,
writes: AtomicU64,
auths: AtomicU64,
}
@@ -203,6 +206,11 @@ impl RefusalBudget {
Self::charge(&self.reads)
}
/// Whether this rejected EVENT may write its line.
pub(crate) fn write(&self) -> bool {
Self::charge(&self.writes)
}
/// Whether this post-decision AUTH frame may write its line.
pub(crate) fn auth(&self) -> bool {
Self::charge(&self.auths)
@@ -477,6 +485,126 @@ impl Drop for ReadLog {
}
}
/// The NIP-01 OK prefixes a write's `reason` may take; any other message
/// logs `other`, so the text after the prefix never reaches the log.
const OK_PREFIXES: [&str; 9] = [
"duplicate",
"pow",
"blocked",
"rate-limited",
"invalid",
"restricted",
"mute",
"error",
"auth-required",
];
/// The fixed reason for a refused write: its OK message's NIP-01 prefix.
fn ok_reason(message: &str) -> &'static str {
let prefix = message.split_once(':').map_or(message, |(p, _)| p);
OK_PREFIXES
.into_iter()
.find(|p| *p == prefix)
.unwrap_or("other")
}
/// One access line per WebSocket EVENT, written when its handler ends and
/// recording the OK the relay answered: `accepted`, `rejected` or `error`
/// (WARN) with the OK prefix as `reason`, or `aborted` if the handler ended
/// before deciding one. `outcome` is the relay's decision; an OK that could not
/// be queued (outbound channel full or closed) adds `ok_queued=false`.
/// Only the event's `kind` and id are logged, never its content or tags.
/// Rejected lines are capped per connection by [`RefusalBudget`], on their own
/// counter, separate from refused reads'.
pub(crate) struct WriteLog {
conn_id: Uuid,
community: CommunityId,
pubkey: Option<String>,
kind: u32,
event_id: String,
/// The OK decided, as (accepted, reason, queued); `None` until one is.
answer: Option<(bool, &'static str, bool)>,
budget: Arc<RefusalBudget>,
}
impl WriteLog {
pub(crate) fn new(conn: &crate::connection::ConnectionState, event: &nostr::Event) -> Self {
let pubkey = match conn.auth_state_snapshot() {
crate::connection::AuthState::Authenticated(ctx) => Some(ctx.pubkey.to_hex()),
_ => None,
};
Self {
conn_id: conn.conn_id,
community: conn.tenant.community(),
pubkey,
kind: buzz_core::kind::event_kind_u32(event),
event_id: event.id.to_hex(),
answer: None,
budget: Arc::clone(&conn.refusal_budget),
}
}
/// Log an EVENT refused before its handler ran, under a fixed `reason`;
/// `queued` is whether its OK was queued.
pub(crate) fn refused(
conn: &crate::connection::ConnectionState,
event: &nostr::Event,
reason: &'static str,
queued: bool,
) {
Self::new(conn, event).answer = Some((false, reason, queued));
}
/// Send the EVENT's OK and record it for the line.
pub(crate) fn ok(
&mut self,
conn: &crate::connection::ConnectionState,
event_id: &str,
accepted: bool,
message: &str,
) {
let queued = conn.send(crate::protocol::RelayMessage::ok(
event_id, accepted, message,
));
let reason = if accepted { "" } else { ok_reason(message) };
self.answer = Some((accepted, reason, queued));
}
}
impl Drop for WriteLog {
fn drop(&mut self) {
let (outcome, reason) = match self.answer {
None => ("aborted", None),
Some((true, ..)) => ("accepted", None),
Some((false, "error", _)) => ("error", Some("error")),
Some((false, reason, _)) => ("rejected", Some(reason)),
};
// Present only when an OK was decided but could not be queued.
let ok_queued = matches!(self.answer, Some((.., false))).then_some(false);
if outcome == "rejected" && !self.budget.write() {
return;
}
let level = if outcome == "error" {
Level::WARN
} else {
Level::INFO
};
emit!(
level,
event = "write",
conn_id = %self.conn_id,
community = %self.community,
pubkey = self.pubkey.as_deref(),
kind = self.kind,
event_id = self.event_id.as_str(),
outcome,
reason,
ok_queued,
"access"
);
}
}
/// Which credential an auth attempt presented.
#[derive(Clone, Copy, Debug, PartialEq, Eq)]
pub(crate) enum AuthMethod {
@@ -999,6 +1127,7 @@ impl Drop for CloseLine {
events_queued = self.queued.events(),
bytes_queued = self.queued.bytes(),
reads_suppressed = RefusalBudget::close(&self.refusals.reads),
writes_suppressed = RefusalBudget::close(&self.refusals.writes),
auth_suppressed = RefusalBudget::close(&self.refusals.auths),
"access"
);
@@ -1781,6 +1910,125 @@ pub(crate) mod tests {
assert!(line.get("pubkey").is_none());
}
/// A rejected write's reason is only its OK message's NIP-01 prefix.
#[test]
fn write_reason_is_the_ok_prefix_only() {
assert_eq!(ok_reason("invalid: bad signature"), "invalid");
assert_eq!(
ok_reason("auth-required: not authenticated"),
"auth-required"
);
assert_eq!(ok_reason("rate-limited"), "rate-limited");
assert_eq!(ok_reason("something: secret"), "other");
assert_eq!(ok_reason(""), "other");
}
/// Each answer logs its outcome and level; no OK logs `aborted`.
#[test]
fn write_lines_record_the_ok_answered() {
let (conn, _rx) =
crate::connection::tests::test_conn_with_auth(crate::connection::AuthState::Failed);
let event = nostr::EventBuilder::new(nostr::Kind::Custom(9), "secret words")
.sign_with_keys(&nostr::Keys::generate())
.unwrap();
let id = event.id.to_hex();
let (_, out) = capture(|| {
WriteLog::new(&conn, &event).ok(&conn, &id, true, "");
WriteLog::new(&conn, &event).ok(&conn, &id, false, "duplicate: already have it");
WriteLog::new(&conn, &event).ok(&conn, &id, false, "error: internal error");
drop(WriteLog::new(&conn, &event));
WriteLog::refused(&conn, &event, "messages", true);
});
assert!(!out.raw().contains("secret"), "{}", out.raw());
let got: Vec<String> = out
.lines()
.iter()
.map(|l| {
assert_eq!(l["event"], "write", "{l}");
assert_eq!(l["kind"], 9, "{l}");
assert_eq!(l["event_id"], id.as_str(), "{l}");
assert!(l.get("ok_queued").is_none(), "{l}");
format!("{}/{}/{}", l["outcome"], l["reason"], l["level"])
})
.collect();
assert_eq!(
got,
[
r#""accepted"/null/"INFO""#,
r#""rejected"/"duplicate"/"INFO""#,
r#""error"/"error"/"WARN""#,
r#""aborted"/null/"INFO""#,
r#""rejected"/"messages"/"INFO""#,
]
);
}
/// Rejected writes past the refusal budget are only counted; accepted
/// writes are never capped.
#[test]
fn rejected_writes_have_a_refusal_budget() {
let (conn, mut rx) =
crate::connection::tests::test_conn_with_auth(crate::connection::AuthState::Failed);
let event = nostr::EventBuilder::new(nostr::Kind::Custom(9), "")
.sign_with_keys(&nostr::Keys::generate())
.unwrap();
let (_, out) = capture(|| {
for _ in 0..REFUSAL_LINES + 3 {
WriteLog::refused(&conn, &event, "messages", true);
WriteLog::new(&conn, &event).ok(&conn, "x", true, "");
// Drain, so every OK is queued and only the cap is under test.
rx.try_recv().expect("OK queued");
}
});
let lines = out.lines();
assert!(
lines.iter().all(|l| l.get("ok_queued").is_none()),
"{lines:?}"
);
let count = |o: &str| lines.iter().filter(|l| l["outcome"] == o).count();
assert_eq!(count("rejected"), REFUSAL_LINES as usize);
assert_eq!(count("accepted"), REFUSAL_LINES as usize + 3);
assert_eq!(RefusalBudget::close(&conn.refusal_budget.writes), 3);
}
/// An OK the outbound channel could not take (full or closed) keeps the
/// relay's decision as `outcome` and adds `ok_queued=false`.
#[test]
fn write_lines_mark_an_ok_that_could_not_be_queued() {
let event = nostr::EventBuilder::new(nostr::Kind::Custom(9), "")
.sign_with_keys(&nostr::Keys::generate())
.unwrap();
let id = event.id.to_hex();
// Full: the test channel holds 4 frames and nothing drains it.
let (full, _rx) =
crate::connection::tests::test_conn_with_auth(crate::connection::AuthState::Failed);
while full.send(String::new()) {}
// Closed: the receiver is gone.
let (closed, rx) =
crate::connection::tests::test_conn_with_auth(crate::connection::AuthState::Failed);
drop(rx);
let (_, out) = capture(|| {
WriteLog::new(&full, &event).ok(&full, &id, true, "");
WriteLog::new(&closed, &event).ok(&closed, &id, false, "invalid: bad");
WriteLog::refused(&closed, &event, "rate-limited", false);
});
let got: Vec<String> = out
.lines()
.iter()
.map(|l| format!("{}/{}/{}", l["outcome"], l["reason"], l["ok_queued"]))
.collect();
assert_eq!(
got,
[
r#""accepted"/null/false"#,
r#""rejected"/"invalid"/false"#,
r#""rejected"/"rate-limited"/false"#,
]
);
}
/// Every read is measured under its type, outcome and reason, including
/// the refusals whose lines the budget suppresses.
/// Mutation: record after the budget check in `Drop`, or drop the

View File

@@ -1372,6 +1372,7 @@ async fn handle_text_message(text: String, conn: Arc<ConnectionState>, state: Ar
}
if let Err(reason) = enforce_ws_admission(&msg, &conn, &state).await {
// An EVENT's write line is written where its OK is sent.
crate::access::ReadLog::refused(&msg, &conn, reason);
return;
}
@@ -1391,10 +1392,11 @@ async fn handle_text_message(text: String, conn: Arc<ConnectionState>, state: Ar
Err(_) => {
// Correlate to the event id: a bare NOTICE here strands the
// client's pending publish exactly as an over-quota one did.
conn.send(request_rejection_message(
let queued = conn.send(request_rejection_message(
RejectionTarget::Event(event.id),
"rate-limited: too many concurrent requests",
));
crate::access::WriteLog::refused(&conn, &event, "rate-limited", queued);
return;
}
};
@@ -2426,6 +2428,58 @@ pub(crate) mod tests {
assert_eq!(frame[3], "rate-limited: too many concurrent requests");
}
/// The saturation refusal's write line records whether its OK was queued,
/// with the outbound channel open, full or closed. Mutation: pass `true`
/// instead of the send result at the refusal site → RED.
#[tokio::test]
async fn saturated_handler_write_line_records_whether_its_ok_was_queued() {
let state = crate::state::tests::test_state().await;
let permits = state.handler_semaphore.available_permits();
let _held = Arc::clone(&state.handler_semaphore)
.acquire_many_owned(permits as u32)
.await
.expect("hold every handler permit");
let mut got = Vec::new();
for channel in ["open", "full", "closed"] {
let (conn, rx) = test_conn_with_auth(AuthState::Failed);
let _rx = match channel {
"full" => {
while conn.send(String::new()) {}
Some(rx)
}
"closed" => {
drop(rx);
None
}
_ => Some(rx),
};
let event = EventBuilder::new(Kind::TextNote, "hello")
.sign_with_keys(&Keys::generate())
.expect("sign event");
let raw = serde_json::json!(["EVENT", event]).to_string();
let (guard, out) = crate::access::tests::capture_access_only(tracing::Level::INFO);
handle_text_message(raw, Arc::clone(&conn), Arc::clone(&state)).await;
drop(guard);
let line = out
.lines()
.into_iter()
.find(|l| l["event"] == "write")
.expect("write line");
got.push(format!(
"{channel}:{}/{}/{}",
line["outcome"], line["reason"], line["ok_queued"]
));
}
assert_eq!(
got,
[
r#"open:"rejected"/"rate-limited"/null"#,
r#"full:"rejected"/"rate-limited"/false"#,
r#"closed:"rejected"/"rate-limited"/false"#,
]
);
}
/// The REQ arm of the same branch still settles on CLOSED.
#[tokio::test]
async fn saturated_handler_rejects_a_req_on_the_closed_channel() {

View File

@@ -21,7 +21,6 @@ use buzz_pubsub::EventTopic;
use nostr::{Event, PublicKey};
use crate::connection::{AuthState, ConnectionState};
use crate::protocol::RelayMessage;
use crate::state::AppState;
use super::ingest::{reject_with_transport, IngestAuth, IngestError};
@@ -656,6 +655,7 @@ pub async fn handle_event(event: Event, conn: Arc<ConnectionState>, state: Arc<A
let start = std::time::Instant::now();
let event_id_hex = event.id.to_hex();
let kind_u32 = event_kind_u32(&event);
let mut write = crate::access::WriteLog::new(&conn, &event);
let kind_str = bounded_kind_label(kind_u32);
// Record the declared span fields now that we have the values.
@@ -689,11 +689,12 @@ pub async fn handle_event(event: Event, conn: Arc<ConnectionState>, state: Arc<A
),
_ => {
reject("auth");
conn.send(RelayMessage::ok(
write.ok(
&conn,
&event_id_hex,
false,
"auth-required: not authenticated",
));
);
return;
}
}
@@ -705,21 +706,23 @@ pub async fn handle_event(event: Event, conn: Arc<ConnectionState>, state: Arc<A
let is_gift_wrap = kind_u32 == KIND_GIFT_WRAP;
if event.pubkey != auth_pubkey && !is_gift_wrap {
reject("invalid");
conn.send(RelayMessage::ok(
write.ok(
&conn,
&event_id_hex,
false,
"invalid: event pubkey does not match authenticated identity",
));
);
return;
}
if kind_u32 == buzz_core::kind::KIND_AUTH {
reject("invalid");
conn.send(RelayMessage::ok(
write.ok(
&conn,
&event_id_hex,
false,
"invalid: AUTH events cannot be submitted via EVENT",
));
);
return;
}
@@ -745,7 +748,7 @@ pub async fn handle_event(event: Event, conn: Arc<ConnectionState>, state: Arc<A
| IngestError::CanvasConflict(m) => (m, "auth"),
};
reject(reason);
conn.send(RelayMessage::ok(&event_id_hex, false, &message));
write.ok(&conn, &event_id_hex, false, &message);
return;
}
}
@@ -753,11 +756,12 @@ pub async fn handle_event(event: Event, conn: Arc<ConnectionState>, state: Arc<A
if kind_u32 == KIND_AGENT_OBSERVER_FRAME {
if !scopes.is_empty() && !scopes.contains(&buzz_auth::Scope::MessagesWrite) {
reject("scope");
conn.send(RelayMessage::ok(
write.ok(
&conn,
&event_id_hex,
false,
"restricted: insufficient scope for agent observer frames",
));
);
return;
}
// P1-b: acquire an effect permit before the observer handler's
@@ -777,15 +781,16 @@ pub async fn handle_event(event: Event, conn: Arc<ConnectionState>, state: Arc<A
// an FI assertion is present. Gate is off_mode when no assertion
// exists, so SessionExpired here always implies an active FI session.
// [FI-TRACE-DENIAL-ORACLE, NIP-FI §authorization_denied]
conn.send(RelayMessage::ok(
write.ok(
&conn,
&event_id_hex,
false,
"restricted: authorization denied",
));
);
return;
}
};
handle_agent_observer_event(event, conn_id, &event_id_hex, conn, state).await;
handle_agent_observer_event(event, conn_id, &event_id_hex, conn, state, &mut write).await;
return;
}
@@ -800,11 +805,12 @@ pub async fn handle_event(event: Event, conn: Arc<ConnectionState>, state: Arc<A
if is_ephemeral(kind_u32) && kind_u32 != buzz_core::kind::KIND_NIP43_LEAVE_REQUEST {
if !scopes.is_empty() && !scopes.contains(&buzz_auth::Scope::MessagesWrite) {
reject("scope");
conn.send(RelayMessage::ok(
write.ok(
&conn,
&event_id_hex,
false,
"restricted: insufficient scope for ephemeral events",
));
);
return;
}
// Cached: this runs per ephemeral event. Persistent ingest keeps the
@@ -816,21 +822,18 @@ pub async fn handle_event(event: Event, conn: Arc<ConnectionState>, state: Arc<A
Ok(true) => {}
Ok(false) => {
reject("restricted");
conn.send(RelayMessage::ok(
write.ok(
&conn,
&event_id_hex,
false,
"restricted: community writes are fenced",
));
);
return;
}
Err(error) => {
reject("error");
tracing::warn!(%error, event_id = %event_id_hex, "failed to check ephemeral-event community lifecycle");
conn.send(RelayMessage::ok(
&event_id_hex,
false,
"error: internal server error",
));
write.ok(&conn, &event_id_hex, false, "error: internal server error");
return;
}
}
@@ -841,11 +844,12 @@ pub async fn handle_event(event: Event, conn: Arc<ConnectionState>, state: Arc<A
Ok(permit) => permit,
Err(crate::nip_fi_gate::SessionExpired) => {
// Fix 4: [FI-TRACE-DENIAL-ORACLE]
conn.send(RelayMessage::ok(
write.ok(
&conn,
&event_id_hex,
false,
"restricted: authorization denied",
));
);
return;
}
};
@@ -860,7 +864,7 @@ pub async fn handle_event(event: Event, conn: Arc<ConnectionState>, state: Arc<A
.await
{
Ok(()) => {
conn.send(RelayMessage::ok(&event_id_hex, true, ""));
write.ok(&conn, &event_id_hex, true, "");
}
Err(e) => {
// Rejections carry the ingest taxonomy so backend failures
@@ -882,7 +886,7 @@ pub async fn handle_event(event: Event, conn: Arc<ConnectionState>, state: Arc<A
}
};
reject(reason);
conn.send(RelayMessage::ok(&event_id_hex, false, &message));
write.ok(&conn, &event_id_hex, false, &message);
}
}
return;
@@ -909,11 +913,12 @@ pub async fn handle_event(event: Event, conn: Arc<ConnectionState>, state: Arc<A
Ok(permit) => permit,
Err(crate::nip_fi_gate::SessionExpired) => {
// Fix 4: [FI-TRACE-DENIAL-ORACLE]
conn.send(RelayMessage::ok(
write.ok(
&conn,
&event_id_hex,
false,
"restricted: authorization denied",
));
);
return;
}
};
@@ -938,11 +943,7 @@ pub async fn handle_event(event: Event, conn: Arc<ConnectionState>, state: Arc<A
"not_accepted"
},
);
conn.send(RelayMessage::ok(
&result.event_id,
result.accepted,
&result.message,
));
write.ok(&conn, &result.event_id, result.accepted, &result.message);
}
Err(e) => {
let e = e.into_legacy();
@@ -958,7 +959,7 @@ pub async fn handle_event(event: Event, conn: Arc<ConnectionState>, state: Arc<A
};
record_event_processing(start, reason);
reject(reason);
conn.send(RelayMessage::ok(&event_id_hex, false, &msg));
write.ok(&conn, &event_id_hex, false, &msg);
}
}
}
@@ -1322,25 +1323,18 @@ async fn handle_agent_observer_event(
event_id_hex: &str,
conn: Arc<ConnectionState>,
state: Arc<AppState>,
write: &mut crate::access::WriteLog,
) {
let event_clone = event.clone();
let verify_result = tokio::task::spawn_blocking(move || verify_event(&event_clone)).await;
match verify_result {
Ok(Ok(())) => {}
Ok(Err(e)) => {
conn.send(RelayMessage::ok(
event_id_hex,
false,
&format!("invalid: {e}"),
));
write.ok(&conn, event_id_hex, false, &format!("invalid: {e}"));
return;
}
Err(_) => {
conn.send(RelayMessage::ok(
event_id_hex,
false,
"error: internal error",
));
write.ok(&conn, event_id_hex, false, "error: internal error");
return;
}
}
@@ -1349,11 +1343,12 @@ async fn handle_agent_observer_event(
let now = chrono::Utc::now().timestamp();
let event_ts = event.created_at.as_secs() as i64;
if (event_ts - now).unsigned_abs() > 300 {
conn.send(RelayMessage::ok(
write.ok(
&conn,
event_id_hex,
false,
"invalid: observer frame timestamp outside ±5 minute freshness window",
));
);
return;
}
@@ -1361,12 +1356,12 @@ async fn handle_agent_observer_event(
Ok(Some(route)) => route,
Ok(None) => {
// Unknown frame value — silently drop, no error to publisher.
conn.send(RelayMessage::ok(event_id_hex, true, ""));
write.ok(&conn, event_id_hex, true, "");
return;
}
Err(message) => {
reject("invalid");
conn.send(RelayMessage::ok(event_id_hex, false, &message));
write.ok(&conn, event_id_hex, false, &message);
return;
}
};
@@ -1405,11 +1400,7 @@ async fn handle_agent_observer_event(
}
Err(e) => {
warn!(conn_id = %conn_id, event_id = %event_id_hex, "agent observer owner check failed: {e}");
conn.send(RelayMessage::ok(
event_id_hex,
false,
"error: internal server error",
));
write.ok(&conn, event_id_hex, false, "error: internal server error");
return;
}
}
@@ -1418,11 +1409,12 @@ async fn handle_agent_observer_event(
};
if !is_owner {
reject("auth");
conn.send(RelayMessage::ok(
write.ok(
&conn,
event_id_hex,
false,
"restricted: observer frame is not authorized for this agent owner",
));
);
return;
}
@@ -1432,11 +1424,12 @@ async fn handle_agent_observer_event(
if matches!(route.direction, AgentObserverDirection::Telemetry) {
let agent_key: [u8; 32] = agent_bytes.as_slice().try_into().unwrap_or([0u8; 32]);
if observer_frame_rate_limited(&state, conn.tenant.community(), agent_key) {
conn.send(RelayMessage::ok(
write.ok(
&conn,
event_id_hex,
false,
"rate-limited: observer frame rate exceeded (100/sec per agent)",
));
);
return;
}
}
@@ -1463,7 +1456,7 @@ async fn handle_agent_observer_event(
);
fan_out_event_to_local_subscribers(&state, conn.tenant.community(), &stored_event).await;
conn.send(RelayMessage::ok(event_id_hex, true, ""));
write.ok(&conn, event_id_hex, true, "");
}
fn agent_observer_route(event: &Event) -> Result<Option<AgentObserverRoute>, String> {
@@ -1831,12 +1824,14 @@ mod tests {
),
});
let mut write = crate::access::WriteLog::new(&conn, &event);
super::handle_agent_observer_event(
event.clone(),
conn.conn_id,
&event.id.to_hex(),
conn,
state,
&mut write,
)
.await;
@@ -3486,6 +3481,38 @@ mod tests {
"membership lookup"
);
}
/// A refused WebSocket EVENT writes one `write` access line with the
/// OK's fixed prefix as its reason, and never the event's content or
/// tag values.
#[tokio::test]
async fn refused_ws_event_writes_one_access_line_without_its_content() {
let state = test_state().await;
let (conn, mut send_rx) =
crate::connection::tests::test_conn_with_auth(crate::connection::AuthState::Failed);
let event = EventBuilder::new(Kind::Custom(9), "secret words")
.tag(nostr::Tag::parse(["h", "secret-channel"]).unwrap())
.sign_with_keys(&Keys::generate())
.unwrap();
let (guard, out) = crate::access::tests::capture_scoped();
super::super::handle_event(event.clone(), conn, state).await;
drop(guard);
let axum::extract::ws::Message::Text(ack) = send_rx.try_recv().expect("OK") else {
panic!("expected text OK");
};
assert!(ack.contains("auth-required"), "{ack}");
assert!(!out.raw().contains("secret"), "{}", out.raw());
let lines = out.lines();
assert_eq!(lines.len(), 1, "{lines:?}");
let line = &lines[0];
assert_eq!(line["event"], "write", "{line}");
assert_eq!(line["outcome"], "rejected", "{line}");
assert_eq!(line["reason"], "auth-required", "{line}");
assert_eq!(line["kind"], 9, "{line}");
assert_eq!(line["event_id"], event.id.to_hex(), "{line}");
assert!(line.get("pubkey").is_none(), "{line}");
}
}
// ---------------------------------------------------------------------

View File

@@ -145,10 +145,13 @@ async fn send_admission_result(
crate::handlers::close::refuse(sub_id, &reason, conn, state).await;
}
_ => {
conn.send(request_rejection_message(
let queued = conn.send(request_rejection_message(
rejection_target_for(msg),
&reason,
));
if let ClientMessage::Event(event) = msg {
crate::access::WriteLog::refused(conn, event, logged, queued);
}
}
}
Err(logged)
@@ -263,6 +266,58 @@ mod tests {
assert_eq!(frame[2], false);
}
/// The write line's `ok_queued` for an over-quota EVENT, with the outbound
/// channel `open`, full or closed: absent when the OK was queued, `false`
/// when it was not. Mutation: pass `true` instead of the send result at
/// the refusal site → RED.
#[tokio::test]
async fn admission_write_line_records_whether_its_ok_was_queued() {
let state = crate::state::tests::test_state().await;
let mut got = Vec::new();
for channel in ["open", "full", "closed"] {
let (conn, rx) = test_conn();
let _rx = match channel {
"full" => {
while conn.send(String::new()) {}
Some(rx)
}
"closed" => {
drop(rx);
None
}
_ => Some(rx),
};
let (msg, _) = parsed_event_message();
let (guard, out) = crate::access::tests::capture_access_only(tracing::Level::INFO);
let _ = send_admission_result(
&conn,
&state,
Err(AdmissionError::Unavailable),
&msg,
"ws_operations",
)
.await;
drop(guard);
let line = out
.lines()
.into_iter()
.find(|l| l["event"] == "write")
.expect("write line");
got.push(format!(
"{channel}:{}/{}",
line["outcome"], line["ok_queued"]
));
}
assert_eq!(
got,
[
r#"open:"rejected"/null"#,
r#"full:"rejected"/false"#,
r#"closed:"rejected"/false"#
]
);
}
/// A REQ still settles on CLOSED, which carries the subscription id. This
/// pins the pre-existing behavior the fix must not disturb.
#[tokio::test]

View File

@@ -1240,6 +1240,7 @@ dependencies = [
"tracing",
"ulid",
"uuid",
"webp",
]
[[package]]
@@ -2396,7 +2397,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "ccc2776f0c61eca1ca32528f85548abd1a4be8fb53d1b21c013e4f18da1e7090"
dependencies = [
"data-encoding",
"syn 1.0.109",
"syn 2.0.118",
]
[[package]]
@@ -4978,6 +4979,16 @@ dependencies = [
"vcpkg",
]
[[package]]
name = "libwebp-sys"
version = "0.9.6"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "54cd30df7c7165ce74a456e4ca9732c603e8dc5e60784558c1c6dc047f876733"
dependencies = [
"cc",
"glob",
]
[[package]]
name = "line-clipping"
version = "0.3.7"
@@ -11132,7 +11143,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "32497e9a4c7b38532efcdebeef879707aa9f794296a4f0244f6f69e9bc8574bd"
dependencies = [
"fastrand",
"getrandom 0.3.4",
"getrandom 0.4.3",
"once_cell",
"rustix",
"windows-sys 0.61.2",
@@ -12632,6 +12643,15 @@ dependencies = [
"system-deps",
]
[[package]]
name = "webp"
version = "0.3.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "c071456adef4aca59bf6a583c46b90ff5eb0b4f758fc347cea81290288f37ce1"
dependencies = [
"libwebp-sys",
]
[[package]]
name = "webpki-root-certs"
version = "1.0.10"

View File

@@ -333,6 +333,7 @@ run_unit_tests() {
connection::tests::dispatcher_counts_each_req_and_count_frame_once \
connection::tests::read_before_login_logs_one_denial_from_the_handler \
connection::tests::read_refused_by_a_full_handler_semaphore_logs_one_denial \
connection::tests::saturated_handler_write_line_records_whether_its_ok_was_queued \
connection::tests::read_refused_by_unavailable_admission_logs_one_denial \
handlers::auth::tests::repeat_auth_after_a_terminal_logs_one_denial \
nip_fi_upgrade::tests::deny_protected_logs_one_denied_auth_line \