More logging for remote joins

src/api/client_server/membership.rs

@@ -29,7 +29,7 @@ use std::{
     sync::{Arc, RwLock},
     time::{Duration, Instant},
 };
-use tracing::{debug, error, warn};
+use tracing::{debug, error, info, warn};
 
 use crate::{
     service::pdu::{gen_event_id_canonical_json, PduBuilder},
@@ -491,9 +491,13 @@ async fn join_room_by_id_helper(
         .state_cache
         .server_in_room(services().globals.server_name(), room_id)?
     {
+        info!("Joining {room_id} over federation.");
+
         let (make_join_response, remote_server) =
             make_join_request(sender_user, room_id, servers).await?;
 
+        info!("make_join finished");
+
         let room_version_id = match make_join_response.room_version {
             Some(room_version)
                 if services()
@@ -578,6 +582,7 @@ async fn join_room_by_id_helper(
         // It has enough fields to be called a proper event now
         let mut join_event = join_event_stub;
 
+        info!("Asking {remote_server} for send_join");
         let send_join_response = services()
             .sending
             .send_federation_request(
@@ -590,7 +595,10 @@ async fn join_room_by_id_helper(
             )
             .await?;
 
+        info!("send_join finished");
+
         if let Some(signed_raw) = &send_join_response.room_state.event {
+            info!("There is a signed event. This room is probably using restricted joins");
             let (signed_event_id, signed_value) =
                 match gen_event_id_canonical_json(signed_raw, &room_version_id) {
                     Ok(t) => t,
@@ -630,24 +638,29 @@ async fn join_room_by_id_helper(
                     .expect("we created a valid pdu")
                     .insert(remote_server.to_string(), signature.clone());
             } else {
-                warn!("Server {} sent invalid sendjoin event", remote_server);
+                warn!(
+                    "Server {remote_server} sent invalid signature in sendjoin signatures for event {signed_value:?}",
+                );
             }
         }
 
         services().rooms.short.get_or_create_shortroomid(room_id)?;
 
+        info!("Parsing join event");
         let parsed_join_pdu = PduEvent::from_id_val(event_id, join_event.clone())
             .map_err(|_| Error::BadServerResponse("Invalid join event PDU."))?;
 
         let mut state = HashMap::new();
         let pub_key_map = RwLock::new(BTreeMap::new());
 
+        info!("Fetching join signing keys");
         services()
             .rooms
             .event_handler
             .fetch_join_signing_keys(&send_join_response, &room_version_id, &pub_key_map)
             .await?;
 
+        info!("Going through send_join response room_state");
         for result in send_join_response
             .room_state
             .state
@@ -677,6 +690,7 @@ async fn join_room_by_id_helper(
             }
         }
 
+        info!("Going through send_join response auth_chain");
         for result in send_join_response
             .room_state
             .auth_chain
@@ -694,6 +708,7 @@ async fn join_room_by_id_helper(
                 .add_pdu_outlier(&event_id, &value)?;
         }
 
+        info!("Running send_join auth check");
         if !state_res::event_auth::auth_check(
             &state_res::RoomVersion::new(&room_version_id).expect("room version is supported"),
             &parsed_join_pdu,
@@ -724,6 +739,7 @@ async fn join_room_by_id_helper(
             ));
         }
 
+        info!("Saving state from send_join");
         let (statehash_before_join, new, removed) = services().rooms.state_compressor.save_state(
             room_id,
             state
@@ -743,12 +759,14 @@ async fn join_room_by_id_helper(
             .force_state(room_id, statehash_before_join, new, removed, &state_lock)
             .await?;
 
+        info!("Updating joined counts for new room");
         services().rooms.state_cache.update_joined_count(room_id)?;
 
         // We append to state before appending the pdu, so we don't have a moment in time with the
         // pdu without it's state. This is okay because append_pdu can't fail.
         let statehash_after_join = services().rooms.state.append_to_state(&parsed_join_pdu)?;
 
+        info!("Appending new room join event");
         services().rooms.timeline.append_pdu(
             &parsed_join_pdu,
             join_event,
@@ -756,6 +774,7 @@ async fn join_room_by_id_helper(
             &state_lock,
         )?;
 
+        info!("Setting final room state for new room");
         // We set the room state after inserting the pdu, so that we never have a moment in time
         // where events in the current room state do not exist
         services()
@@ -763,6 +782,8 @@ async fn join_room_by_id_helper(
             .state
             .set_room_state(room_id, statehash_after_join, &state_lock)?;
     } else {
+        info!("We can join locally");
+
         let join_rules_event = services().rooms.state_accessor.room_state_get(
             room_id,
             &StateEventType::RoomJoinRules,
@@ -881,8 +902,9 @@ async fn join_room_by_id_helper(
         };
 
         if !restriction_rooms.is_empty() {
-            // We couldn't do the join locally, maybe federation can help to satisfy the restricted
-            // join requirements
+            info!(
+                "We couldn't do the join locally, maybe federation can help to satisfy the restricted join requirements"
+            );
             let (make_join_response, remote_server) =
                 make_join_request(sender_user, room_id, servers).await?;
 
@@ -1040,6 +1062,7 @@ async fn make_join_request(
         if remote_server == services().globals.server_name() {
             continue;
         }
+        info!("Asking {remote_server} for make_join");
         let make_join_response = services()
             .sending
             .send_federation_request(

src/service/rooms/event_handler/mod.rs

@@ -1460,12 +1460,12 @@ impl Service {
         }
 
         if servers.is_empty() {
-            // We had all keys locally
+            info!("We had all keys locally");
             return Ok(());
         }
 
         for server in services().globals.trusted_servers() {
-            trace!("Asking batch signing keys from trusted server {}", server);
+            info!("Asking batch signing keys from trusted server {}", server);
             if let Ok(keys) = services()
                 .sending
                 .send_federation_request(
@@ -1508,10 +1508,12 @@ impl Service {
             }
 
             if servers.is_empty() {
+                info!("Trusted server supplied all signing keys");
                 return Ok(());
             }
         }
 
+        info!("Asking individual servers for signing keys");
         let mut futures: FuturesUnordered<_> = servers
             .into_keys()
             .map(|server| async move {
@@ -1541,6 +1543,8 @@ impl Service {
             }
         }
 
+        info!("Search for signing keys done");
+
         Ok(())
     }