From 4617ee2b6b763f66bfc6a018471dfdb2170db5da Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Timo=20K=C3=B6sters?= Date: Wed, 22 Feb 2023 21:07:47 +0100 Subject: [PATCH] More logging for remote joins --- src/api/client_server/membership.rs | 31 ++++++++++++++++++++++---- src/service/rooms/event_handler/mod.rs | 8 +++++-- 2 files changed, 33 insertions(+), 6 deletions(-) diff --git a/src/api/client_server/membership.rs b/src/api/client_server/membership.rs index cd0cc7a7..965c618d 100644 --- a/src/api/client_server/membership.rs +++ b/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( diff --git a/src/service/rooms/event_handler/mod.rs b/src/service/rooms/event_handler/mod.rs index 66c6394d..63301b81 100644 --- a/src/service/rooms/event_handler/mod.rs +++ b/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(()) }