From 9405e5f16c149c2a5e55155072062955c4cc46de Mon Sep 17 00:00:00 2001 From: Lambda Date: Sat, 31 May 2025 19:12:36 +0000 Subject: [PATCH] SSS: improve tracing --- src/api/client_server/sync/msc4186.rs | 192 +++++++++++++------------- 1 file changed, 99 insertions(+), 93 deletions(-) diff --git a/src/api/client_server/sync/msc4186.rs b/src/api/client_server/sync/msc4186.rs index 01a3fe31..41785beb 100644 --- a/src/api/client_server/sync/msc4186.rs +++ b/src/api/client_server/sync/msc4186.rs @@ -19,7 +19,7 @@ use ruma::{ }, uint, JsOption, OwnedRoomId, RoomId, UInt, UserId, }; -use tracing::{debug, error}; +use tracing::{debug, error, field, trace, warn}; use super::{load_timeline, share_encrypted_room}; use crate::{ @@ -27,6 +27,7 @@ use crate::{ services, Ar, Error, Ra, Result, }; +#[derive(Debug)] struct TodoRoom { required_state_request: BTreeSet<(StateEventType, String)>, timeline_limit: u64, @@ -59,9 +60,16 @@ impl Default for TodoRoom { } #[allow(clippy::too_many_lines)] +#[tracing::instrument(skip_all, fields( + pos, + next_batch, + connection_id = ?body.conn_id, +))] pub(crate) async fn sync_events_v5_route( body: Ar, ) -> Result, Ra> { + let current_span = tracing::Span::current(); + let sender_user = body.sender_user.expect("user is authenticated"); let sender_device = body.sender_device.expect("user is authenticated"); let body = body.body; @@ -69,7 +77,9 @@ pub(crate) async fn sync_events_v5_route( let watcher = services().globals.watch(&sender_user, &sender_device); let next_batch = services().globals.next_count()?; + current_span.record("next_batch", field::display(&next_batch)); + current_span.record("pos", field::debug(&body.pos)); let globalsince = body.pos.as_ref().and_then(|string| string.parse().ok()).unwrap_or(0); @@ -324,6 +334,8 @@ pub(crate) async fn sync_events_v5_route( let mut todo_rooms: BTreeMap = BTreeMap::new(); for (list_id, list) in body.lists { + trace!(list_id, ?list, "Collecting rooms in list"); + if list.filters.and_then(|f| f.is_invite).unwrap_or(false) { continue; } @@ -352,16 +364,20 @@ pub(crate) async fn sync_events_v5_route( room_id, ); } + let num_rooms = list_room_ids.len(); + trace!(list_id, num_rooms, "Done collecting rooms"); + lists.insert( list_id.clone(), sync_events::v5::response::List { - count: UInt::try_from(list_room_ids.len()).unwrap_or(UInt::MAX), + count: UInt::try_from(num_rooms).unwrap_or(UInt::MAX), }, ); } for (room_id, room) in &body.room_subscriptions { if !services().rooms.metadata.exists(room_id)? { + warn!(room_id = room_id.as_str(), "Subscribed room does not exist"); continue; } todo_rooms.entry(room_id.clone()).or_default().update( @@ -379,25 +395,23 @@ pub(crate) async fn sync_events_v5_route( ); let mut rooms = BTreeMap::new(); - for ( - room_id, - TodoRoom { - required_state_request, - timeline_limit, - roomsince, - }, - ) in &todo_rooms - { - let roomsincecount = PduCount::Normal(*roomsince); + for (room_id, todo_room) in &todo_rooms { + trace!( + room_id = room_id.as_str(), + ?todo_room, + "Processing matched room" + ); + let roomsincecount = PduCount::Normal(todo_room.roomsince); let (timeline_pdus, limited) = load_timeline( &sender_user, room_id, roomsincecount, - *timeline_limit, + todo_room.timeline_limit, )?; - if roomsince != &0 && timeline_pdus.is_empty() { + if todo_room.roomsince != 0 && timeline_pdus.is_empty() { + trace!("No new timeline events, skipping"); continue; } @@ -410,14 +424,18 @@ pub(crate) async fn sync_events_v5_route( } PduCount::Normal(c) => c.to_string(), }) - .or_else(|| (roomsince != &0).then(|| roomsince.to_string())); + .or_else(|| { + (todo_room.roomsince != 0) + .then(|| todo_room.roomsince.to_string()) + }); let room_events: Vec<_> = timeline_pdus .iter() .map(|(_, pdu)| pdu.to_sync_room_event()) .collect(); - let required_state = required_state_request + let required_state = todo_room + .required_state_request .iter() .filter_map(|state| { services() @@ -457,92 +475,80 @@ pub(crate) async fn sync_events_v5_route( .collect::>(); let name = match &*heroes { [] => None, - [only] => Some(only.0.clone()), - [firsts @ .., last] => Some({ + [(only, _)] => Some(only.clone()), + [firsts @ .., (last, _)] => Some({ let firsts = firsts .iter() - .map(|h| h.0.clone()) + .map(|(name, _)| name.clone()) .collect::>() .join(", "); - format!("{firsts} and {}", last.0) + format!("{firsts} and {last}") }), }; - let avatar = if let [only] = &*heroes { - only.1.clone() - } else { - None - }; - - rooms.insert( - room_id.clone(), - sync_events::v5::response::Room { - name: services() - .rooms - .state_accessor - .get_name(room_id)? - .or(name), - avatar: if let Some(avatar) = avatar { - JsOption::Some(avatar) - } else { - match services().rooms.state_accessor.get_avatar(room_id)? { - JsOption::Some(avatar) => { - JsOption::from_option(avatar.url) - } - JsOption::Null => JsOption::Null, - JsOption::Undefined => JsOption::Undefined, - } - }, - initial: Some(roomsince == &0), - is_dm: None, - invite_state: None, - unread_notifications: UnreadNotificationsCount { - highlight_count: Some( - services() - .rooms - .user - .highlight_count(&sender_user, room_id)? - .try_into() - .expect("notification count can't go that high"), - ), - notification_count: Some( - services() - .rooms - .user - .notification_count(&sender_user, room_id)? - .try_into() - .expect("notification count can't go that high"), - ), - }, - timeline: room_events, - required_state, - prev_batch, - limited, - joined_count: Some( - services() - .rooms - .state_cache - .room_joined_count(room_id)? - .map(UInt::new_saturating) - .unwrap_or(uint!(0)), - ), - invited_count: Some( - services() - .rooms - .state_cache - .room_invited_count(room_id)? - .map(UInt::new_saturating) - .unwrap_or(uint!(0)), - ), - // Count events in timeline greater than global sync counter - num_live: None, - // TODO - bump_stamp: None, - // TODO - heroes: None, + let room = sync_events::v5::response::Room { + name: services().rooms.state_accessor.get_name(room_id)?.or(name), + avatar: if let [(_name, Some(avatar))] = &*heroes { + JsOption::Some(avatar.clone()) + } else { + match services().rooms.state_accessor.get_avatar(room_id)? { + JsOption::Some(avatar) => JsOption::from_option(avatar.url), + JsOption::Null => JsOption::Null, + JsOption::Undefined => JsOption::Undefined, + } }, - ); + initial: Some(todo_room.roomsince == 0), + is_dm: None, + invite_state: None, + unread_notifications: UnreadNotificationsCount { + highlight_count: Some( + services() + .rooms + .user + .highlight_count(&sender_user, room_id)? + .try_into() + .expect("notification count can't go that high"), + ), + notification_count: Some( + services() + .rooms + .user + .notification_count(&sender_user, room_id)? + .try_into() + .expect("notification count can't go that high"), + ), + }, + timeline: room_events, + required_state, + prev_batch, + limited, + joined_count: Some( + services() + .rooms + .state_cache + .room_joined_count(room_id)? + .map(UInt::new_saturating) + .unwrap_or(uint!(0)), + ), + invited_count: Some( + services() + .rooms + .state_cache + .room_invited_count(room_id)? + .map(UInt::new_saturating) + .unwrap_or(uint!(0)), + ), + // Count events in timeline greater than global sync counter + num_live: None, + // TODO + bump_stamp: None, + // TODO + heroes: None, + }; + trace!(room_id = room_id.as_str(), ?room, "Built room data"); + + rooms.insert(room_id.clone(), room); } if rooms