From e16a62e1eda124b1aa8a4aa35a3504d453defafc Mon Sep 17 00:00:00 2001 From: timedout Date: Sat, 11 Jul 2026 02:27:48 +0100 Subject: [PATCH] feat: Add more debug logging to PDU handle funcs Tracking down weird soft-fails --- src/core/error/err.rs | 8 +++++ src/service/rooms/event_handler/acl_check.rs | 1 + .../event_handler/handle_incoming_pdu.rs | 11 ++++--- .../rooms/event_handler/handle_outlier_pdu.rs | 18 +++++------- src/service/rooms/event_handler/pdu_checks.rs | 7 +++-- .../event_handler/upgrade_outlier_pdu.rs | 29 ++++++++++++++----- 6 files changed, 51 insertions(+), 23 deletions(-) diff --git a/src/core/error/err.rs b/src/core/error/err.rs index 131eea2ef..c1ae95654 100644 --- a/src/core/error/err.rs +++ b/src/core/error/err.rs @@ -149,6 +149,14 @@ macro_rules! err_log { #[macro_export] #[collapse_debuginfo(yes)] macro_rules! err_lev { + (debug_info) => { + if $crate::debug::logging() { + $crate::tracing::Level::INFO + } else { + $crate::tracing::Level::DEBUG + } + }; + (debug_warn) => { if $crate::debug::logging() { $crate::tracing::Level::WARN diff --git a/src/service/rooms/event_handler/acl_check.rs b/src/service/rooms/event_handler/acl_check.rs index c3fcfea1c..5492c9ba1 100644 --- a/src/service/rooms/event_handler/acl_check.rs +++ b/src/service/rooms/event_handler/acl_check.rs @@ -14,6 +14,7 @@ pub async fn acl_check(&self, server_name: &ServerName, room_id: &RoomId) -> Res .await .map(|c: RoomServerAclEventContent| c) else { + trace!("Room has no ACL, allowing"); return Ok(()); }; diff --git a/src/service/rooms/event_handler/handle_incoming_pdu.rs b/src/service/rooms/event_handler/handle_incoming_pdu.rs index e8da06bd6..1d3cb355d 100644 --- a/src/service/rooms/event_handler/handle_incoming_pdu.rs +++ b/src/service/rooms/event_handler/handle_incoming_pdu.rs @@ -4,8 +4,8 @@ }; use conduwuit::{ - Err, Event, Result, debug, debug_error, debug_warn, defer, error, matrix::PartialPdu, - result::DebugInspect, trace, utils::time::jitter, + Err, Event, Result, debug, debug_error, debug_warn, defer, matrix::PartialPdu, trace, + utils::time::jitter, }; use futures::{FutureExt, StreamExt, future::try_join3}; use ruma::{CanonicalJsonValue, EventId, RoomId, ServerName, UserId}; @@ -31,6 +31,7 @@ pub async fn handle_incoming_pdu<'a>( // Skip the PDU if we already have it as a timeline event. We still re-process // outliers in this scenario. if let Ok(pdu_id) = self.services.timeline.get_pdu_id(event_id).await { + debug!("Database hit for incoming PDU, skipping processing"); return Ok(Some(pdu_id)); } trace!( @@ -96,6 +97,7 @@ pub async fn handle_incoming_pdu<'a>( // If this is not a timeline event, stop now, as we don't want to de-outlier it. if !is_timeline_event { + debug!("Not promoting incoming event as it is not a timeline event"); return Ok(None); } @@ -108,6 +110,7 @@ pub async fn handle_incoming_pdu<'a>( .await? .origin_server_ts(); if incoming_pdu.origin_server_ts() < first_ts_in_room { + debug!("Not promoting incoming event as it is sent before we joined the room"); return Ok(None); } @@ -124,8 +127,8 @@ pub async fn handle_incoming_pdu<'a>( first_ts_in_room, )) .await - .debug_inspect_err(|e| { - error!("Failed to fetch and persist incoming event's prev_events: {e:?}"); + .inspect_err(|e| { + debug_error!("Failed to fetch and persist incoming event's prev_events: {e:?}"); })?; let is_dummy_event = incoming_pdu.event_type().to_string() == "org.matrix.dummy_event" diff --git a/src/service/rooms/event_handler/handle_outlier_pdu.rs b/src/service/rooms/event_handler/handle_outlier_pdu.rs index af53043f9..3763f02d1 100644 --- a/src/service/rooms/event_handler/handle_outlier_pdu.rs +++ b/src/service/rooms/event_handler/handle_outlier_pdu.rs @@ -32,8 +32,8 @@ pub(super) async fn handle_outlier_pdu<'a, Pdu>( // outlier PDU. if let Ok(pdu_event) = self.services.timeline.get_pdu(event_id).await { debug!( - "Already have event {event_id} as an outlier or timeline event, not \ - re-processing" + "Database hit for {event_id} (event is either an outlier or already promoted), \ + skipping outlier handling" ); value.insert( "event_id".to_owned(), @@ -46,7 +46,7 @@ pub(super) async fn handle_outlier_pdu<'a, Pdu>( // (in this case, just size check) if !Self::pdu_format_check_1(&value) { warn!( - "dropping incoming PDU {event_id} in room {room_id} from {origin} because it \ + "Dropping incoming PDU {event_id} in room {room_id} from {origin} because it \ exceeds 65535 bytes or is otherwise too large." ); return Err!(Request(TooLarge("PDU is too large"))); @@ -180,12 +180,12 @@ pub(super) async fn handle_outlier_pdu<'a, Pdu>( }, | hash_map::Entry::Occupied(_) => { self.reject_and_persist(event_id, &incoming_pdu); - return Err!(Request(Forbidden( + return Err!(Request(Forbidden(debug_warn!( "Auth event's type and state_key combination exists multiple times: {}, \ {}", auth_event.kind, auth_event.state_key().unwrap_or("") - ))); + )))); }, } } @@ -200,19 +200,17 @@ pub(super) async fn handle_outlier_pdu<'a, Pdu>( .await? { self.reject_and_persist(event_id, &incoming_pdu); - return Err!(Request(Forbidden( + return Err!(Request(Forbidden(debug_warn!( "Event authorisation fails based on event's claimed auth events" - ))); + )))); } - trace!("Validation successful."); - // 7. Persist the event as an outlier. self.services .outlier .add_pdu_outlier(pdu_event.event_id(), &incoming_pdu); - trace!("Added pdu as outlier."); + debug!("PDU passed checks and has been persisted as an outlier"); Ok((pdu_event, incoming_pdu)) } diff --git a/src/service/rooms/event_handler/pdu_checks.rs b/src/service/rooms/event_handler/pdu_checks.rs index 60991b799..71ed6234c 100644 --- a/src/service/rooms/event_handler/pdu_checks.rs +++ b/src/service/rooms/event_handler/pdu_checks.rs @@ -37,7 +37,10 @@ pub(super) async fn signature_hash_check_2_3( .verify_event(&pdu_json, room_version_rules) .await { - | Ok(ruma::signatures::Verified::All) => Ok(pdu_json), + | Ok(ruma::signatures::Verified::All) => { + trace!("Signatures and hashes verified successfully"); + Ok(pdu_json) + }, | Ok(ruma::signatures::Verified::Signatures) => { debug_info!("Content hash mismatch, redacting event and continuing"); let redacted = redact(pdu_json, &room_version_rules.redaction, None) @@ -114,7 +117,7 @@ pub(super) async fn state_before_check_5( trace!("Could not calculate incoming state, asking remote {origin} for it"); self.fetch_state(origin, create_event, &room_id, incoming_pdu.event_id()) .await - .debug_inspect_err(|e| { + .inspect_err(|e| { debug_error!("Could not fetch state from {origin}: {e}"); })? }, diff --git a/src/service/rooms/event_handler/upgrade_outlier_pdu.rs b/src/service/rooms/event_handler/upgrade_outlier_pdu.rs index 37c00c1fc..a892f8fb1 100644 --- a/src/service/rooms/event_handler/upgrade_outlier_pdu.rs +++ b/src/service/rooms/event_handler/upgrade_outlier_pdu.rs @@ -1,7 +1,7 @@ use std::{borrow::Borrow, collections::HashMap, sync::Arc, time::Instant}; use conduwuit::{ - Err, Result, debug, debug_info, is_equal_to, is_true, + Err, Result, debug, debug_info, debug_warn, is_equal_to, is_true, matrix::{Event, PduEvent}, trace, utils::{ @@ -46,10 +46,10 @@ pub(super) async fn upgrade_outlier_to_timeline_pdu( trace!(event_id=%incoming_pdu.event_id(), "Skipping upgrade of already upgraded PDU"); return Ok(Some(id)); } else if rejected { - return Err!(Request(Forbidden("Event has been rejected"))); + return Err!(Request(Forbidden(debug_info!("Event has been rejected")))); } else if soft_failed { // Soft-failed events cannot be promoted. - return Err!(Request(Forbidden("Event has been soft-failed"))); + return Err!(Request(Forbidden(debug_info!("Event has been soft-failed")))); } // These should never happen, but they're good last-minute sanity checks to @@ -83,9 +83,9 @@ pub(super) async fn upgrade_outlier_to_timeline_pdu( if !passes_state_before { self.reject_and_persist(incoming_pdu.event_id(), &val); - return Err!(Request(Forbidden( + return Err!(Request(Forbidden(debug_warn!( "Event authorisation fails based on the state before the event" - ))); + )))); } // Now that we know the event passes both self-authentication, and @@ -103,7 +103,15 @@ pub(super) async fn upgrade_outlier_to_timeline_pdu( let state_lock = self.services.state.mutex.lock(room_id).await; let passes_current_state = self .current_state_check_6(&incoming_pdu, &room_version_rules, create_event) - .await?; + .await + .inspect(|passes| { + if !*passes { + debug_warn!( + "Event authorisation fails based on the current room state - will be \ + soft-failed" + ); + } + })?; // Determine whether this PDU should be soft-failed. // If the auth check failed, invariably yes. Otherwise, only if the user isn't @@ -128,7 +136,14 @@ pub(super) async fn upgrade_outlier_to_timeline_pdu( debug!(event_id = %incoming_pdu.event_id, "Checking policy server for event"); should_soft_fail = self .policy_server_check_7(&incoming_pdu, &mut val, &room_version_rules) - .await?; + .await + .inspect(|passes| { + if !*passes { + debug_warn!( + "Event did not pass the policy server check and will be soft-failed" + ); + } + })?; // TODO: this is supposed to hide redactions from policy servers and janitorial // bots, however, for full efficacy it also needs to hide redactions for