From 9465c5df1ff3ba10149d2a0e2580a91b6be0a687 Mon Sep 17 00:00:00 2001 From: Jade Ellis Date: Sun, 20 Jul 2025 01:03:18 +0100 Subject: [PATCH] style: Improve logging and comments --- src/core/matrix/state_res/event_auth.rs | 4 +- .../rooms/event_handler/call_policyserv.rs | 26 ++++++- .../event_handler/upgrade_outlier_pdu.rs | 73 +++++++++++++++---- 3 files changed, 82 insertions(+), 21 deletions(-) diff --git a/src/core/matrix/state_res/event_auth.rs b/src/core/matrix/state_res/event_auth.rs index 81c83431..77a4a95c 100644 --- a/src/core/matrix/state_res/event_auth.rs +++ b/src/core/matrix/state_res/event_auth.rs @@ -149,8 +149,8 @@ where for<'a> &'a E: Event + Send, { debug!( - event_id = format!("{}", incoming_event.event_id()), - event_type = format!("{}", incoming_event.event_type()), + event_id = %incoming_event.event_id(), + event_type = ?incoming_event.event_type(), "auth_check beginning" ); diff --git a/src/service/rooms/event_handler/call_policyserv.rs b/src/service/rooms/event_handler/call_policyserv.rs index 96e3f7cc..aef99dba 100644 --- a/src/service/rooms/event_handler/call_policyserv.rs +++ b/src/service/rooms/event_handler/call_policyserv.rs @@ -1,3 +1,8 @@ +//! Policy server integration for event spam checking in Matrix rooms. +//! +//! This module implements a check against a room-specific policy server, as +//! described in the relevant Matrix spec proposal (see: https://github.com/matrix-org/matrix-spec-proposals/pull/4284). + use std::time::Duration; use conduwuit::{Err, Event, PduEvent, Result, debug, implement, warn}; @@ -12,7 +17,11 @@ use ruma::{ #[tracing::instrument(skip_all, level = "debug")] pub async fn policyserv_check(&self, pdu: &PduEvent, room_id: &RoomId) -> Result { if *pdu.event_type() == StateEventType::RoomPolicy.into() { - debug!("Skipping spam check for policy server meta-event in room {room_id}"); + debug!( + room_id = %room_id, + event_type = ?pdu.event_type(), + "Skipping spam check for policy server meta-event" + ); return Ok(()); } let Ok(policyserver) = self @@ -37,7 +46,11 @@ pub async fn policyserv_check(&self, pdu: &PduEvent, room_id: &RoomId) -> Result return Ok(()); } if !self.services.state_cache.server_in_room(via, room_id).await { - debug!("Policy server {via} is not in the room {room_id}, skipping spam check"); + debug!( + room_id = %room_id, + via = %via, + "Policy server is not in the room, skipping spam check" + ); return Ok(()); } let outgoing = self @@ -45,7 +58,12 @@ pub async fn policyserv_check(&self, pdu: &PduEvent, room_id: &RoomId) -> Result .sending .convert_to_outgoing_federation_event(pdu.to_canonical_object()) .await; - debug!("Checking pdu {outgoing:?} for spam with policy server {via} for room {room_id}"); + debug!( + room_id = %room_id, + via = %via, + outgoing = ?outgoing, + "Checking event for spam with policy server" + ); let response = tokio::time::timeout( Duration::from_secs(10), self.services @@ -65,6 +83,8 @@ pub async fn policyserv_check(&self, pdu: &PduEvent, room_id: &RoomId) -> Result room_id = %room_id, "Failed to contact policy server: {e}" ); + // Network or policy server errors are treated as non-fatal: event is allowed by + // default. return Ok(()); }, | Err(_) => { diff --git a/src/service/rooms/event_handler/upgrade_outlier_pdu.rs b/src/service/rooms/event_handler/upgrade_outlier_pdu.rs index e8e22fe9..d3dc32fb 100644 --- a/src/service/rooms/event_handler/upgrade_outlier_pdu.rs +++ b/src/service/rooms/event_handler/upgrade_outlier_pdu.rs @@ -47,7 +47,10 @@ where return Err!(Request(InvalidParam("Event has been soft failed"))); } - debug!("Upgrading pdu {} from outlier to timeline pdu", incoming_pdu.event_id); + debug!( + event_id = %incoming_pdu.event_id, + "Upgrading PDU from outlier to timeline" + ); let timer = Instant::now(); let room_version_id = get_room_version_id(create_event)?; @@ -55,7 +58,10 @@ where // backwards extremities doing all the checks in this list starting at 1. // These are not timeline events. - debug!("Resolving state at event {}", incoming_pdu.event_id); + debug!( + event_id = %incoming_pdu.event_id, + "Resolving state at event" + ); let mut state_at_incoming_event = if incoming_pdu.prev_events().count() == 1 { self.state_at_incoming_degree_one(&incoming_pdu).await? } else { @@ -74,7 +80,10 @@ where let room_version = to_room_version(&room_version_id); - debug!("Performing auth check to upgrade {}", incoming_pdu.event_id); + debug!( + event_id = %incoming_pdu.event_id, + "Performing auth check to upgrade" + ); // 11. Check the auth of the event passes based on the state of the event let state_fetch_state = &state_at_incoming_event; let state_fetch = |k: StateEventType, s: StateKey| async move { @@ -84,7 +93,10 @@ where self.services.timeline.get_pdu(event_id).await.ok() }; - debug!("running auth check on {}", incoming_pdu.event_id); + debug!( + event_id = %incoming_pdu.event_id, + "Running initial auth check" + ); let auth_check = state_res::event_auth::auth_check( &room_version, &incoming_pdu, @@ -98,7 +110,10 @@ where return Err!(Request(Forbidden("Event has failed auth check with state at the event."))); } - debug!("Gathering auth events for {}", incoming_pdu.event_id); + debug!( + event_id = %incoming_pdu.event_id, + "Gathering auth events" + ); let auth_events = self .services .state @@ -116,7 +131,10 @@ where ready(auth_events.get(&key).map(ToOwned::to_owned)) }; - debug!("running auth check on {} with claimed state auth", incoming_pdu.event_id); + debug!( + event_id = %incoming_pdu.event_id, + "Running auth check with claimed state auth" + ); let auth_check = state_res::event_auth::auth_check( &room_version, &incoming_pdu, @@ -127,7 +145,10 @@ where .map_err(|e| err!(Request(Forbidden("Auth check failed: {e:?}"))))?; // Soft fail check before doing state res - debug!("Performing soft-fail check on {}", incoming_pdu.event_id); + debug!( + event_id = %incoming_pdu.event_id, + "Performing soft-fail check" + ); let mut soft_fail = match (auth_check, incoming_pdu.redacts_id(&room_version_id)) { | (false, _) => true, | (true, None) => false, @@ -142,7 +163,10 @@ where // 13. Use state resolution to find new room state // We start looking at current room state now, so lets lock the room - trace!("Locking the room"); + trace!( + room_id = %room_id, + "Locking the room" + ); let state_lock = self.services.state.mutex.lock(room_id).await; // Now we calculate the set of extremities this room has after the incoming @@ -223,21 +247,32 @@ where // 14-pre. If the event is not a state event, ask the policy server about it if incoming_pdu.state_key.is_none() { - debug!("Checking policy server for event {}", incoming_pdu.event_id); + debug!( + event_id = %incoming_pdu.event_id,"Checking policy server for event"); let policy = self.policyserv_check(&incoming_pdu, room_id); if let Err(e) = policy.await { - warn!("Policy server check failed for event {}: {e}", incoming_pdu.event_id); + warn!( + event_id = %incoming_pdu.event_id, + error = ?e, + "Policy server check failed for event" + ); if !soft_fail { soft_fail = true; } } - debug!("Policy server check passed for event {}", incoming_pdu.event_id); + debug!( + event_id = %incoming_pdu.event_id, + "Policy server check passed for event" + ); } // Additionally, if this is a redaction for a soft-failed event, we soft-fail it // also if let Some(redact_id) = incoming_pdu.redacts_id(&room_version_id) { - debug!("Checking if redaction {} is for a soft-failed event", redact_id); + debug!( + redact_id = %redact_id, + "Checking if redaction is for a soft-failed event" + ); if self .services .pdu_metadata @@ -245,8 +280,8 @@ where .await { warn!( - "Redaction {} is for a soft-failed event, soft failing the redaction", - redact_id + redact_id = %redact_id, + "Redaction is for a soft-failed event, soft failing the redaction" ); soft_fail = true; } @@ -255,7 +290,10 @@ where // 14. Check if the event passes auth based on the "current state" of the room, // if not soft fail it if soft_fail { - info!("Soft failing event {}", incoming_pdu.event_id); + info!( + event_id = %incoming_pdu.event_id, + "Soft failing event" + ); // assert!(extremities.is_empty(), "soft_fail extremities empty"); let extremities = extremities.iter().map(Borrow::borrow); @@ -276,7 +314,10 @@ where .pdu_metadata .mark_event_soft_failed(incoming_pdu.event_id()); - warn!("Event was soft failed: {:?}", incoming_pdu.event_id()); + warn!( + event_id = %incoming_pdu.event_id, + "Event was soft failed" + ); return Err!(Request(InvalidParam("Event has been soft failed"))); }