atagen

matrix-rust-sdk

public
Star0
Watch0

Commit 2eb08d9cad52

tarball

atagen <boss@atagen.co>2026-10-26 09:19 UTC

4 files changed+28-3
timeline: log each step of a timeline build and history operation

A device trace showed build() never returning on the first launch after an upgrade, with nothing saying whether it waited on the room caches lock, the history coordinator, the event cache subscribe or the encryption state.
Modified file: crates/matrix-sdk-ui/src/timeline/builder.rs+7 additions−1 deletions
@@ -18,7 +18,7 @@ use matrix_sdk::Room;
1818 use matrix_sdk_base::{SendOutsideWasm, SyncOutsideWasm};
1919 use ruma::{events::AnySyncTimelineEvent, room_version_rules::RoomVersionRules};
2020 use tokio::sync::mpsc;
21-use tracing::{Instrument, Span, info_span};
21+use tracing::{Instrument, Span, debug, info_span};
2222
2323 use super::{
2424 DateDividerMode, Error, Timeline, TimelineDropHandle, TimelineFocus,
@@ -162,13 +162,17 @@ impl TimelineBuilder {
162162 // Subscribe the event cache to sync responses, in case we hadn't done it yet.
163163 room.client().event_cache().subscribe()?;
164164
165+ debug!("timeline build: getting the room event cache");
165166 let (room_event_cache, event_cache_drop) = room.event_cache().await?;
166167 if matches!(focus, TimelineFocus::Live { .. }) {
168+ debug!("timeline build: loading retained history");
167169 room_event_cache.load_retained_history().await?;
168170 }
171+ debug!("timeline build: subscribing to the event cache");
169172 let (initial_events, initial_gaps, event_subscriber) =
170173 room_event_cache.subscribe_with_history().await?;
171174
175+ debug!("timeline build: reading the encryption state");
172176 let is_room_encrypted = room
173177 .latest_encryption_state()
174178 .await
@@ -185,6 +189,7 @@ impl TimelineBuilder {
185189 settings,
186190 );
187191
192+ debug!("timeline build: initialising the focus");
188193 let InitFocusResult { focus_task, has_events } = controller
189194 .init_focus(&focus, &room_event_cache, (initial_events, initial_gaps))
190195 .await?;
@@ -223,6 +228,7 @@ impl TimelineBuilder {
223228
224229 let local_echo_listener_handle = {
225230 let timeline_controller = controller.clone();
231+ debug!("timeline build: subscribing to the send queue");
226232 let (local_echoes, send_queue_stream) = room.send_queue().subscribe().await?;
227233
228234 room.client()
Modified file: crates/matrix-sdk-ui/tests/integration/timeline/mod.rs+1 additions−1 deletions
@@ -56,8 +56,8 @@ mod queue;
5656 mod reactions;
5757 mod read_receipts;
5858 mod redecryption;
59-mod segmented_history;
6059 mod replies;
60+mod segmented_history;
6161 mod subscribe;
6262 mod thread;
6363
Modified file: crates/matrix-sdk/src/event_cache/caches/room/history.rs+16 additions
@@ -104,6 +104,19 @@ enum HistoryOperation {
104104 Barrier,
105105 }
106106
107+impl HistoryOperation {
108+ fn name(&self) -> &'static str {
109+ match self {
110+ Self::Recent => "recent",
111+ Self::Fill(_) => "fill",
112+ Self::SpendBudget(_) => "spend budget",
113+ Self::Append(..) => "append",
114+ Self::Restore => "restore",
115+ Self::Barrier => "barrier",
116+ }
117+ }
118+}
119+
107120 #[derive(Clone)]
108121 enum HistoryResponse {
109122 Recent(RecentHistoryOutcome),
@@ -134,6 +147,8 @@ async fn coordinate_history(
134147 };
135148 let cache = RoomEventCache { inner };
136149 let recent = matches!(operation, HistoryOperation::Recent);
150+ let name = operation.name();
151+ tracing::debug!(room_id = %cache.room_id(), operation = name, "history operation started");
137152 let mut waiters = vec![reply];
138153 let (cancel, cancellation) = watch::channel(false);
139154 let operation = async {
@@ -174,6 +189,7 @@ async fn coordinate_history(
174189 };
175190 match action {
176191 Action::Complete(result) => {
192+ tracing::debug!(room_id = %cache.room_id(), operation = name, ok = result.is_ok(), "history operation finished");
177193 for reply in waiters {
178194 let _ = reply.send(result.clone());
179195 }
Modified file: crates/matrix-sdk/src/event_cache/mod.rs+4 additions−1 deletions
@@ -48,7 +48,7 @@ use tokio::sync::{
4848 broadcast::{Receiver, Sender, channel},
4949 mpsc,
5050 };
51-use tracing::{error, instrument, trace};
51+use tracing::{debug, error, instrument, trace};
5252
5353 use crate::{
5454 Client,
@@ -673,6 +673,7 @@ impl EventCacheInner {
673673 Err(by_room_guard) => {
674674 // Slow-path: the entry doesn't exist; let's acquire a write lock.
675675 drop(by_room_guard);
676+ debug!(%room_id, "waiting for the room caches lock to create a room's caches");
676677 let by_room_guard = self.by_room.clone().write_owned().await;
677678
678679 // In the meanwhile, some other caller might have obtained write access and done
@@ -685,6 +686,7 @@ impl EventCacheInner {
685686 Err(by_room_guard) => by_room_guard,
686687 };
687688
689+ debug!(%room_id, "creating a room's caches");
688690 let caches = Caches::new(
689691 &self.client,
690692 room_id,
@@ -699,6 +701,7 @@ impl EventCacheInner {
699701 self.automatic_pagination.get().cloned(),
700702 )
701703 .await?;
704+ debug!(%room_id, "created a room's caches");
702705
703706 by_room_guard.insert(room_id.to_owned(), caches);