From 9cd175b1252f828ea9a1a561b54ae44da17c9467 Mon Sep 17 00:00:00 2001 From: Jason Volk Date: Wed, 22 Oct 2025 20:30:43 +0000 Subject: [PATCH] Additional logging/tracing tweaks around sliding-sync. Additional spans around receipt service interface. Signed-off-by: Jason Volk --- src/api/client/sync/v5.rs | 23 ++++++++--------------- src/api/client/sync/v5/e2ee.rs | 2 +- src/api/client/sync/v5/receipts.rs | 2 +- src/api/client/sync/v5/selector.rs | 10 +++++++--- src/api/client/sync/v5/to_device.rs | 2 +- src/api/client/sync/v5/typing.rs | 2 +- src/service/rooms/read_receipt/mod.rs | 8 ++++++-- 7 files changed, 25 insertions(+), 24 deletions(-) diff --git a/src/api/client/sync/v5.rs b/src/api/client/sync/v5.rs index 2619b6c4..dbd0b3af 100644 --- a/src/api/client/sync/v5.rs +++ b/src/api/client/sync/v5.rs @@ -23,7 +23,7 @@ use ruma::{ }; use tokio::time::{Instant, timeout_at}; use tuwunel_core::{ - Err, Result, apply, at, + Err, Result, apply, at, debug, debug::INFO_SPAN_LEVEL, err, error::inspect_log, @@ -53,7 +53,6 @@ struct SyncInfo<'a> { services: &'a Services, sender_user: &'a UserId, sender_device: &'a DeviceId, - request: &'a Request, } #[derive(Clone, Debug)] @@ -152,13 +151,6 @@ pub(crate) async fn sync_events_v5_route( conn.update_cache(request); conn.update_rooms_prologue(advancing); - let sync_info = SyncInfo { - services, - sender_user, - sender_device, - request, - }; - let mut response = Response { txn_id: request.txn_id.clone(), lists: Default::default(), @@ -167,6 +159,7 @@ pub(crate) async fn sync_events_v5_route( extensions: Default::default(), }; + let sync_info = SyncInfo { services, sender_user, sender_device }; loop { debug_assert!( conn.globalsince <= conn.next_batch, @@ -203,15 +196,15 @@ pub(crate) async fn sync_events_v5_route( if timeout_at(stop_at, watchers).await.is_err() || services.server.is_stopping() { response.pos = conn.next_batch.to_string().into(); - trace!(conn.globalsince, conn.next_batch, "timeout; empty response"); + trace!(conn.globalsince, conn.next_batch, "timeout; empty response {response:?}"); return Ok(response); } - trace!( - conn.globalsince, - last_batch = ?conn.next_batch, - count = ?services.globals.pending_count(), - stop_at = ?stop_at, + debug!( + ?timeout, + last_since = conn.globalsince, + last_batch = conn.next_batch, + pend_count = ?services.globals.pending_count(), "notified by watcher" ); diff --git a/src/api/client/sync/v5/e2ee.rs b/src/api/client/sync/v5/e2ee.rs index 9cd88896..84a3c1d6 100644 --- a/src/api/client/sync/v5/e2ee.rs +++ b/src/api/client/sync/v5/e2ee.rs @@ -94,7 +94,7 @@ pub(super) async fn collect( }) } -#[tracing::instrument(level = "trace", skip_all, fields(room_id))] +#[tracing::instrument(level = "trace", skip_all, fields(room_id), ret)] async fn collect_room( SyncInfo { services, sender_user, .. }: SyncInfo<'_>, conn: &Connection, diff --git a/src/api/client/sync/v5/receipts.rs b/src/api/client/sync/v5/receipts.rs index 7e64952a..51c1162b 100644 --- a/src/api/client/sync/v5/receipts.rs +++ b/src/api/client/sync/v5/receipts.rs @@ -44,7 +44,7 @@ pub(super) async fn collect( Ok(response::Receipts { rooms }) } -#[tracing::instrument(level = "trace", skip_all, fields(room_id))] +#[tracing::instrument(level = "trace", skip_all, fields(room_id), ret)] async fn collect_room( SyncInfo { services, sender_user, .. }: SyncInfo<'_>, conn: &Connection, diff --git a/src/api/client/sync/v5/selector.rs b/src/api/client/sync/v5/selector.rs index 7e43bc43..ecc132cb 100644 --- a/src/api/client/sync/v5/selector.rs +++ b/src/api/client/sync/v5/selector.rs @@ -29,9 +29,8 @@ pub(super) async fn selector( ) -> (Window, ResponseLists) { use MembershipState::*; - let SyncInfo { services, sender_user, request, .. } = sync_info; + let SyncInfo { services, sender_user, .. } = sync_info; - trace!(?request); let mut rooms = services .state_cache .user_memberships(sender_user, Some(&[Join, Invite, Knock])) @@ -64,7 +63,12 @@ pub(super) async fn selector( (window, lists) } -#[tracing::instrument(name = "window", level = "debug", skip_all)] +#[tracing::instrument( + name = "window", + level = "debug", + skip_all, + fields(rooms = rooms.clone().count()) +)] async fn select_window<'a, Rooms>( sync_info: SyncInfo<'_>, conn: &Connection, diff --git a/src/api/client/sync/v5/to_device.rs b/src/api/client/sync/v5/to_device.rs index 7de338ff..a87e275a 100644 --- a/src/api/client/sync/v5/to_device.rs +++ b/src/api/client/sync/v5/to_device.rs @@ -4,7 +4,7 @@ use tuwunel_core::{self, Result}; use super::{Connection, SyncInfo}; -#[tracing::instrument(name = "to_device", level = "trace", skip_all)] +#[tracing::instrument(name = "to_device", level = "trace", skip_all, ret)] pub(super) async fn collect( SyncInfo { services, sender_user, sender_device, .. }: SyncInfo<'_>, conn: &Connection, diff --git a/src/api/client/sync/v5/typing.rs b/src/api/client/sync/v5/typing.rs index aa52df4b..47d55463 100644 --- a/src/api/client/sync/v5/typing.rs +++ b/src/api/client/sync/v5/typing.rs @@ -13,7 +13,7 @@ use tuwunel_core::{ use super::{Connection, SyncInfo, Window, extension_rooms_selector}; -#[tracing::instrument(name = "typing", level = "trace", skip_all)] +#[tracing::instrument(name = "typing", level = "trace", skip_all, ret)] pub(super) async fn collect( sync_info: SyncInfo<'_>, conn: &Connection, diff --git a/src/service/rooms/read_receipt/mod.rs b/src/service/rooms/read_receipt/mod.rs index 90771f8b..d67bfa61 100644 --- a/src/service/rooms/read_receipt/mod.rs +++ b/src/service/rooms/read_receipt/mod.rs @@ -40,6 +40,7 @@ impl crate::Service for Service { impl Service { /// Replaces the previous read receipt. + #[tracing::instrument(skip(self), level = "debug", name = "set_receipt")] pub async fn readreceipt_update( &self, user_id: &UserId, @@ -58,6 +59,7 @@ impl Service { } /// Gets the latest private read receipt from the user in the room + #[tracing::instrument(skip(self), level = "debug", name = "get_private")] pub async fn private_read_get( &self, room_id: &RoomId, @@ -122,13 +124,13 @@ impl Service { } /// Sets a private read marker at PDU `count`. - #[tracing::instrument(skip(self), level = "debug")] + #[tracing::instrument(skip(self), level = "debug", name = "set_private")] pub fn private_read_set(&self, room_id: &RoomId, user_id: &UserId, count: u64) { self.db.private_read_set(room_id, user_id, count); } /// Returns the private read marker PDU count. - #[tracing::instrument(skip(self), level = "debug")] + #[tracing::instrument(skip(self), level = "debug", name = "get_private_count", ret)] pub async fn private_read_get_count( &self, room_id: &RoomId, @@ -140,12 +142,14 @@ impl Service { } /// Returns the PDU count of the last typing update in this room. + #[tracing::instrument(skip(self), level = "debug", name = "get_private_last", ret)] pub async fn last_privateread_update(&self, user_id: &UserId, room_id: &RoomId) -> u64 { self.db .last_privateread_update(user_id, room_id) .await } + #[tracing::instrument(skip(self), level = "debug", name = "get_receipt_last", ret)] pub async fn last_receipt_count( &self, room_id: &RoomId,