When in doubt, log all the things

src/api/client/membership.rs

@@ -1249,6 +1249,7 @@ async fn join_room_by_id_helper_remote(
 		services.rooms.timeline.get_pdu(event_id).await.ok()
 	};
 
+	debug!("running stateres check on send_join parsed PDU");
 	let auth_check = state_res::event_auth::auth_check(
 		&state_res::RoomVersion::new(&room_version_id)?,
 		&parsed_join_pdu,

src/core/matrix/state_res/mod.rs

@@ -609,7 +609,7 @@ where
 		let fetch_state = |ty: &StateEventType, key: &str| {
 			future::ready(auth_state.get(&ty.with_state_key(key)))
 		};
-
+		debug!("running auth check on {:?}", event.event_id());
 		let auth_result =
 			auth_check(room_version, &event, current_third_party.as_ref(), fetch_state).await;
 

src/service/rooms/event_handler/handle_outlier_pdu.rs

@@ -76,7 +76,7 @@ pub(super) async fn handle_outlier_pdu<'a>(
 		// 5. Reject "due to auth events" if can't get all the auth events or some of
 		//    the auth events are also rejected "due to auth events"
 		// NOTE: Step 5 is not applied anymore because it failed too often
-		debug!("Fetching auth events");
+		debug!("Fetching auth events for {}", incoming_pdu.event_id);
 		Box::pin(self.fetch_and_handle_outliers(
 			origin,
 			&incoming_pdu.auth_events,
@@ -88,12 +88,12 @@ pub(super) async fn handle_outlier_pdu<'a>(
 
 	// 6. Reject "due to auth events" if the event doesn't pass auth based on the
 	//    auth events
-	debug!("Checking based on auth events");
+	debug!("Checking {} based on auth events", incoming_pdu.event_id);
 	// Build map of auth events
 	let mut auth_events = HashMap::with_capacity(incoming_pdu.auth_events.len());
 	for id in &incoming_pdu.auth_events {
 		let Ok(auth_event) = self.services.timeline.get_pdu(id).await else {
-			warn!("Could not find auth event {id}");
+			warn!("Could not find auth event {id} for {}", incoming_pdu.event_id);
 			continue;
 		};
 
@@ -128,6 +128,7 @@ pub(super) async fn handle_outlier_pdu<'a>(
 		ready(auth_events.get(&key))
 	};
 
+	debug!("running auth check to handle outlier pdu {:?}", incoming_pdu.event_id);
 	let auth_check = state_res::event_auth::auth_check(
 		&to_room_version(&room_version_id),
 		&incoming_pdu,

src/service/rooms/event_handler/upgrade_outlier_pdu.rs

@@ -1,12 +1,6 @@
 use std::{borrow::Borrow, collections::BTreeMap, iter::once, sync::Arc, time::Instant};
 
-use conduwuit::{
-	Err, Result, debug, debug_info, err, implement,
-	matrix::{EventTypeExt, PduEvent, StateKey, state_res},
-	trace,
-	utils::stream::{BroadbandExt, ReadyExt},
-	warn,
-};
+use conduwuit::{Err, Result, debug, debug_info, err, implement, matrix::{EventTypeExt, PduEvent, StateKey, state_res}, trace, utils::stream::{BroadbandExt, ReadyExt}, warn, info};
 use futures::{FutureExt, StreamExt, future::ready};
 use ruma::{CanonicalJsonValue, RoomId, ServerName, events::StateEventType};
 
@@ -44,7 +38,7 @@ pub(super) async fn upgrade_outlier_to_timeline_pdu(
 		return Err!(Request(InvalidParam("Event has been soft failed")));
 	}
 
-	debug!("Upgrading to timeline pdu");
+	debug!("Upgrading pdu {} from outlier to timeline pdu", incoming_pdu.event_id);
 	let timer = Instant::now();
 	let room_version_id = get_room_version_id(create_event)?;
 
@@ -52,7 +46,7 @@ pub(super) async fn upgrade_outlier_to_timeline_pdu(
 	//     backwards extremities doing all the checks in this list starting at 1.
 	//     These are not timeline events.
 
-	debug!("Resolving state at event");
+	debug!("Resolving state at event {}", incoming_pdu.event_id);
 	let mut state_at_incoming_event = if incoming_pdu.prev_events.len() == 1 {
 		self.state_at_incoming_degree_one(&incoming_pdu).await?
 	} else {
@@ -70,7 +64,7 @@ pub(super) async fn upgrade_outlier_to_timeline_pdu(
 		state_at_incoming_event.expect("we always set this to some above");
 	let room_version = to_room_version(&room_version_id);
 
-	debug!("Performing auth check");
+	debug!("Performing auth check to upgrade {}", incoming_pdu.event_id);
 	// 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 {
@@ -80,6 +74,7 @@ pub(super) async fn upgrade_outlier_to_timeline_pdu(
 		self.services.timeline.get_pdu(event_id).await.ok()
 	};
 
+	debug!("running auth check on {}", incoming_pdu.event_id);
 	let auth_check = state_res::event_auth::auth_check(
 		&room_version,
 		&incoming_pdu,
@@ -93,7 +88,7 @@ pub(super) async fn upgrade_outlier_to_timeline_pdu(
 		return Err!(Request(Forbidden("Event has failed auth check with state at the event.")));
 	}
 
-	debug!("Gathering auth events");
+	debug!("Gathering auth events for {}", incoming_pdu.event_id);
 	let auth_events = self
 		.services
 		.state
@@ -111,6 +106,7 @@ pub(super) async fn upgrade_outlier_to_timeline_pdu(
 		ready(auth_events.get(&key).cloned())
 	};
 
+	debug!("running auth check on {} with claimed state auth", incoming_pdu.event_id);
 	let auth_check = state_res::event_auth::auth_check(
 		&room_version,
 		&incoming_pdu,
@@ -121,7 +117,7 @@ pub(super) async fn upgrade_outlier_to_timeline_pdu(
 	.map_err(|e| err!(Request(Forbidden("Auth check failed: {e:?}"))))?;
 
 	// Soft fail check before doing state res
-	debug!("Performing soft-fail check");
+	debug!("Performing soft-fail check on {}", incoming_pdu.event_id);
 	let soft_fail = match (auth_check, incoming_pdu.redacts_id(&room_version_id)) {
 		| (false, _) => true,
 		| (true, None) => false,
@@ -218,7 +214,7 @@ pub(super) async fn upgrade_outlier_to_timeline_pdu(
 	// 14. Check if the event passes auth based on the "current state" of the room,
 	//     if not soft fail it
 	if soft_fail {
-		debug!("Soft failing event");
+		info!("Soft failing event {}", incoming_pdu.event_id);
 		let extremities = extremities.iter().map(Borrow::borrow);
 
 		self.services

src/service/rooms/timeline/mod.rs

@@ -771,6 +771,7 @@ impl Service {
 			ready(auth_events.get(&key))
 		};
 
+		debug!("running auth check on new {} event by {} in {}", pdu.kind, pdu.sender, pdu.room_id);
 		let auth_check = state_res::auth_check(
 			&room_version,
 			&pdu,