feat: Add more debug logging to PDU handle funcs

Tracking down weird soft-fails

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

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(());
 		};
 

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"

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))
 	}

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}");
 					})?
 			},

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