Additional logging/tracing tweaks around sliding-sync.

Additional spans around receipt service interface.

Signed-off-by: Jason Volk <jason@zemos.net>

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!(
+		debug!(
-			conn.globalsince,
+			?timeout,
-			last_batch = ?conn.next_batch,
+			last_since = conn.globalsince,
-			count = ?services.globals.pending_count(),
+			last_batch = conn.next_batch,
-			stop_at = ?stop_at,
+			pend_count = ?services.globals.pending_count(),
 			"notified by watcher"
 		);
 

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,

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,

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,

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,

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,

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,