From 25e4c8d722b29e5a2cedad4871b2bf769bd1c4c8 Mon Sep 17 00:00:00 2001 From: Benjamin Bouvier Date: Thu, 25 Jan 2024 13:47:46 +0100 Subject: [PATCH] read receipts: add lots of tracing logs for easier remote debugging --- crates/matrix-sdk-base/src/read_receipts.rs | 23 +++++++++++-------- .../matrix-sdk-ui/src/timeline/inner/mod.rs | 4 ++++ crates/matrix-sdk-ui/src/timeline/mod.rs | 6 ++++- 3 files changed, 23 insertions(+), 10 deletions(-) diff --git a/crates/matrix-sdk-base/src/read_receipts.rs b/crates/matrix-sdk-base/src/read_receipts.rs index 0bb8dea8e..8cb5e2356 100644 --- a/crates/matrix-sdk-base/src/read_receipts.rs +++ b/crates/matrix-sdk-base/src/read_receipts.rs @@ -136,7 +136,7 @@ use ruma::{ EventId, OwnedEventId, OwnedUserId, RoomId, UserId, }; use serde::{Deserialize, Serialize}; -use tracing::{debug, instrument, trace}; +use tracing::{debug, instrument, trace, warn}; #[derive(Clone, Debug, Serialize, Deserialize, PartialEq)] struct LatestReadReceipt { @@ -332,24 +332,27 @@ impl ReceiptSelector { if event_pos >= *best_pos { *best_pos = event_pos; self.latest_event_with_receipt = Some(event_id.to_owned()); - trace!("saving better"); + debug!("saving better"); + } else { + trace!("not better, keeping previous"); } } else { // We didn't have a previous receipt, this is the first one we // store: remember it. self.latest_event_pos = Some(event_pos); self.latest_event_with_receipt = Some(event_id.to_owned()); - trace!("saving for the first time"); + debug!("saving for the first time"); } } /// Try to match pending receipts against new events. + #[instrument(skip_all)] fn handle_pending_receipts(&mut self, pending: &mut RingBuffer) { // Try to match stashed receipts against the new events. - trace!("handle_pending_receipts"); pending.retain(|event_id| { if let Some(event_pos) = self.event_id_to_pos.get(event_id) { // Maybe select this read receipt as it might be better than the ones we had. + trace!(%event_id, "matching event against its stashed receipt"); self.try_select_later(event_id, *event_pos); // Remove this stashed read receipt from the pending list, as it's been @@ -371,12 +374,12 @@ impl ReceiptSelector { /// /// Returns any receipts (for the current user) that we could not match /// against any event - these are "pending". + #[instrument(skip_all)] fn handle_new_receipt( &mut self, user_id: &UserId, receipt_event: &ReceiptEventContent, ) -> Vec { - trace!("handle_new_receipt"); let mut pending = Vec::new(); // Now consider new receipts. for (event_id, receipts) in &receipt_event.0 { @@ -384,10 +387,12 @@ impl ReceiptSelector { if let Some(receipt) = receipts.get(&ty).and_then(|receipts| receipts.get(user_id)) { if matches!(receipt.thread, ReceiptThread::Main | ReceiptThread::Unthreaded) { + trace!(%event_id, "found new candidate"); if let Some(event_pos) = self.event_id_to_pos.get(event_id) { self.try_select_later(event_id, *event_pos); } else { // It's a new pending receipt. + trace!(%event_id, "stashed as pending"); pending.push(event_id.clone()); } } @@ -502,7 +507,7 @@ pub(crate) fn compute_unread_counts( // safely from here. read_receipts.find_and_process_events(&event_id, user_id, all_events.iter()); - trace!(?read_receipts, "after finding a better receipt"); + debug!(?read_receipts, "after finding a better receipt"); return; } @@ -517,7 +522,7 @@ pub(crate) fn compute_unread_counts( read_receipts.process_event(event, user_id); } - trace!(?read_receipts, "no better receipt, {} new events", new_events.len()); + debug!(?read_receipts, "no better receipt, {} new events", new_events.len()); } /// Is the event worth marking a room as unread? @@ -525,7 +530,7 @@ fn marks_as_unread(event: &Raw, user_id: &UserId) -> bool let event = match event.deserialize() { Ok(event) => event, Err(err) => { - debug!( + warn!( "couldn't deserialize event {:?}: {err}", event.get_field::("event_id").ok().flatten() ); @@ -601,7 +606,7 @@ fn marks_as_unread(event: &Raw, user_id: &UserId) -> bool _ => { // What I don't know about, I don't care about. - debug!("unhandled timeline event type: {}", event.event_type()); + warn!("unhandled timeline event type: {}", event.event_type()); false } } diff --git a/crates/matrix-sdk-ui/src/timeline/inner/mod.rs b/crates/matrix-sdk-ui/src/timeline/inner/mod.rs index fbdf560c1..aa41233cc 100644 --- a/crates/matrix-sdk-ui/src/timeline/inner/mod.rs +++ b/crates/matrix-sdk-ui/src/timeline/inner/mod.rs @@ -1066,9 +1066,11 @@ impl TimelineInner { if let Some((old_pub_read, _)) = state.user_receipt(own_user_id, ReceiptType::Read, room).await { + trace!(%old_pub_read, "found a previous public receipt"); if let Some(relative_pos) = state.meta.compare_events_positions(&old_pub_read, event_id) { + trace!("event referred to new receipt is {relative_pos:?} the previous receipt"); return relative_pos == RelativePosition::After; } } @@ -1079,9 +1081,11 @@ impl TimelineInner { if let Some((old_priv_read, _)) = state.latest_user_read_receipt(own_user_id, room).await { + trace!(%old_priv_read, "found a previous private receipt"); if let Some(relative_pos) = state.meta.compare_events_positions(&old_priv_read, event_id) { + trace!("event referred to new receipt is {relative_pos:?} the previous receipt"); return relative_pos == RelativePosition::After; } } diff --git a/crates/matrix-sdk-ui/src/timeline/mod.rs b/crates/matrix-sdk-ui/src/timeline/mod.rs index ee3cf4229..ff5d9c2b5 100644 --- a/crates/matrix-sdk-ui/src/timeline/mod.rs +++ b/crates/matrix-sdk-ui/src/timeline/mod.rs @@ -56,7 +56,7 @@ use ruma::{ }; use thiserror::Error; use tokio::sync::{mpsc::Sender, Mutex, Notify}; -use tracing::{debug, error, info, instrument, warn}; +use tracing::{debug, error, info, instrument, trace, warn}; use self::futures::SendAttachment; @@ -708,9 +708,13 @@ impl Timeline { event_id: OwnedEventId, ) -> Result { if !self.inner.should_send_receipt(&receipt_type, &thread, &event_id).await { + trace!( + "not sending receipt, because we already cover the event with a previous receipt" + ); return Ok(false); } + trace!("sending receipt"); self.room().send_single_receipt(receipt_type, thread, event_id).await?; Ok(true) }