SSS: improve tracing

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<sync_events::v5::Request>,
 ) -> Result<Ra<sync_events::v5::Response>, Ra<UiaaResponse>> {
+    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<OwnedRoomId, TodoRoom> = 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 (
+    for (room_id, todo_room) in &todo_rooms {
-        room_id,
+        trace!(
-        TodoRoom {
+            room_id = room_id.as_str(),
-            required_state_request,
+            ?todo_room,
-            timeline_limit,
+            "Processing matched room"
-            roomsince,
+        );
-        },
+        let roomsincecount = PduCount::Normal(todo_room.roomsince);
-    ) in &todo_rooms
-    {
-        let roomsincecount = PduCount::Normal(*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,44 +475,30 @@ pub(crate) async fn sync_events_v5_route(
             .collect::<Vec<_>>();
         let name = match &*heroes {
             [] => None,
-            [only] => Some(only.0.clone()),
+            [(only, _)] => Some(only.clone()),
-            [firsts @ .., last] => Some({
+            [firsts @ .., (last, _)] => Some({
                 let firsts = firsts
                     .iter()
-                    .map(|h| h.0.clone())
+                    .map(|(name, _)| name.clone())
                     .collect::<Vec<_>>()
                     .join(", ");
 
-                format!("{firsts} and {}", last.0)
+                format!("{firsts} and {last}")
             }),
         };
 
-        let avatar = if let [only] = &*heroes {
+        let room = sync_events::v5::response::Room {
-            only.1.clone()
+            name: services().rooms.state_accessor.get_name(room_id)?.or(name),
-        } else {
+            avatar: if let [(_name, Some(avatar))] = &*heroes {
-            None
+                JsOption::Some(avatar.clone())
-        };
-
-        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::Some(avatar) => JsOption::from_option(avatar.url),
-                            JsOption::from_option(avatar.url)
-                        }
                     JsOption::Null => JsOption::Null,
                     JsOption::Undefined => JsOption::Undefined,
                 }
             },
-                initial: Some(roomsince == &0),
+            initial: Some(todo_room.roomsince == 0),
             is_dm: None,
             invite_state: None,
             unread_notifications: UnreadNotificationsCount {
@@ -541,8 +545,10 @@ pub(crate) async fn sync_events_v5_route(
             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