Sometimes `Timeline::paginate_backward()` returns `true` when it is not at the start of the timeline

[zecakeh]

This seems to occur reliably with the live timeline when we received only a handful of new messages in a room via Client::sync() since the last time that the client was used.

This does not happen if there are no new messages in the room, or if there are more than a handful new messages in the room, so closing the app and relaunching it makes the issue go away. So it seems like it happens when we receive a timeline for the room that is not limited in the first sync since the client was created.

These are the logs with an account with a single room, and a single new message received via sync, with RUST_LOG=matrix_sdk::event_cache=trace,matrix_sdk::sync=trace,matrix_sdk_base::event_cache=trace,matrix_sdk_sqlite::event_cache_store=trace,matrix_sdk_ui=trace,warn:

Logs

2025-01-09T16:15:27.969965Z TRACE listen_task: matrix_sdk::event_cache: Spawning the listen task
2025-01-09T16:15:27.974414Z TRACE build{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org" track_read_receipts=true}:set_fully_read_event: matrix_sdk_ui::timeline::controller::state: Updating read marker fully_read_event="$FkaI5ODAPrgJvTOGFhoXToS980hyQqkaPBvPS4PRyIk"
2025-01-09T16:15:27.975741Z TRACE live_update_handler{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org" focus="live"}: matrix_sdk_ui::timeline::builder: Spawned the event subscriber task.
2025-01-09T16:15:27.975892Z TRACE live_update_handler{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org" focus="live"}: matrix_sdk_ui::timeline::builder: Waiting for an event.
2025-01-09T16:15:27.976871Z  INFO local_echo_handler{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org" focus="live"}: matrix_sdk_ui::timeline::builder: spawned the local echo handler!
2025-01-09T16:15:27.977783Z TRACE matrix_sdk_ui::timeline::controller: Creating timeline items signal
2025-01-09T16:15:28.136411Z DEBUG call_sync_response_handlers: matrix_sdk::sync: Ran event handlers in 3.389072ms
2025-01-09T16:15:28.136904Z DEBUG call_sync_response_handlers: matrix_sdk::sync: Ran notification handlers in 187.705µs
2025-01-09T16:15:28.137713Z TRACE listen_task:handle_room_updates: matrix_sdk::event_cache::room: adding new events
2025-01-09T16:15:28.139980Z TRACE live_update_handler{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org" focus="live"}: matrix_sdk_ui::timeline::builder: Received new ephemeral events from sync.
2025-01-09T16:15:28.140164Z TRACE live_update_handler{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org" focus="live"}:handle_ephemeral_events: matrix_sdk_ui::timeline::controller::state: Handling ephemeral room events
2025-01-09T16:15:28.140404Z TRACE live_update_handler{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org" focus="live"}: matrix_sdk_ui::timeline::builder: Waiting for an event.
2025-01-09T16:15:28.202833Z DEBUG call_sync_response_handlers: matrix_sdk::sync: Ran event handlers in 495.547µs
2025-01-09T16:15:28.202861Z DEBUG call_sync_response_handlers: matrix_sdk::sync: Ran notification handlers in 5.366µs
2025-01-09T16:15:28.202948Z TRACE listen_task:handle_room_updates: matrix_sdk::event_cache::room: adding new events
2025-01-09T16:15:28.205620Z TRACE listen_task:handle_room_updates: matrix_sdk::event_cache::room: Handling account data
2025-01-09T16:15:28.205962Z TRACE live_update_handler{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org" focus="live"}: matrix_sdk_ui::timeline::builder: Received new timeline events diffs
2025-01-09T16:15:28.210216Z TRACE live_update_handler{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org" focus="live"}:handle_event{event_id="$ty1lzRvKOcOGyYes797OVOKR8eBB_K9ILPKH_zFnYzg" position=End { origin: Sync }}: matrix_sdk_ui::timeline::event_handler: Handling remote event
2025-01-09T16:15:28.211088Z TRACE live_update_handler{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org" focus="live"}:handle_event{event_id="$ty1lzRvKOcOGyYes797OVOKR8eBB_K9ILPKH_zFnYzg" position=End { origin: Sync }}:handle_room_message: matrix_sdk_ui::timeline::event_handler: Adding new remote timeline item at the back
2025-01-09T16:15:28.211277Z TRACE live_update_handler{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org" focus="live"}:handle_event{event_id="$ty1lzRvKOcOGyYes797OVOKR8eBB_K9ILPKH_zFnYzg" position=End { origin: Sync }}:handle_room_message: matrix_sdk_ui::timeline::controller::state: Updating read marker fully_read_event="$FkaI5ODAPrgJvTOGFhoXToS980hyQqkaPBvPS4PRyIk"
2025-01-09T16:15:28.211576Z TRACE live_update_handler{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org" focus="live"}:run: matrix_sdk_ui::timeline::date_dividers: inserting the first date divider @ 0
2025-01-09T16:15:28.212340Z TRACE live_update_handler{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org" focus="live"}: matrix_sdk_ui::timeline::builder: Waiting for an event.
2025-01-09T16:15:28.212368Z TRACE live_update_handler{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org" focus="live"}: matrix_sdk_ui::timeline::builder: Received new ephemeral events from sync.
2025-01-09T16:15:28.212395Z TRACE live_update_handler{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org" focus="live"}:handle_ephemeral_events: matrix_sdk_ui::timeline::controller::state: Handling ephemeral room events
2025-01-09T16:15:28.212447Z TRACE live_update_handler{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org" focus="live"}: matrix_sdk_ui::timeline::builder: Waiting for an event.
2025-01-09T16:15:28.212505Z TRACE live_update_handler{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org" focus="live"}: matrix_sdk_ui::timeline::builder: Handling fully read marker. target=$ty1lzRvKOcOGyYes797OVOKR8eBB_K9ILPKH_zFnYzg
2025-01-09T16:15:28.212567Z TRACE live_update_handler{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org" focus="live"}:set_fully_read_event: matrix_sdk_ui::timeline::controller::state: Updating read marker fully_read_event="$ty1lzRvKOcOGyYes797OVOKR8eBB_K9ILPKH_zFnYzg"
2025-01-09T16:15:28.212581Z TRACE live_update_handler{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org" focus="live"}: matrix_sdk_ui::timeline::builder: Waiting for an event.
2025-01-09T16:15:31.541087Z DEBUG paginate_backwards{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org"}:live_paginate_backwards{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org"}:run_backwards{batch_size=20}: matrix_sdk::event_cache::pagination: Not back-paginating since we've reached the start of the timeline.
2025-01-09T16:15:31.541143Z TRACE paginate_backwards{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org"}:live_paginate_backwards{room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org"}:run_backwards{batch_size=20}: matrix_sdk_ui::timeline::pagination: Back-pagination succeeded with 0 events
2025-01-09T16:15:32.028158Z TRACE mark_as_read{receipt_type="m.read" room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org"}:send_single_receipt{receipt_type="m.read" thread=Unthreaded event_id="$ty1lzRvKOcOGyYes797OVOKR8eBB_K9ILPKH_zFnYzg" room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org"}: matrix_sdk_ui::timeline::controller: found a previous public receipt old_pub_read=$ty1lzRvKOcOGyYes797OVOKR8eBB_K9ILPKH_zFnYzg
2025-01-09T16:15:32.028478Z TRACE mark_as_read{receipt_type="m.read" room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org"}:send_single_receipt{receipt_type="m.read" thread=Unthreaded event_id="$ty1lzRvKOcOGyYes797OVOKR8eBB_K9ILPKH_zFnYzg" room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org"}: matrix_sdk_ui::timeline::controller: event referred to new receipt is Same the previous receipt
2025-01-09T16:15:32.028595Z TRACE mark_as_read{receipt_type="m.read" room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org"}:send_single_receipt{receipt_type="m.read" thread=Unthreaded event_id="$ty1lzRvKOcOGyYes797OVOKR8eBB_K9ILPKH_zFnYzg" room_id="!BbvbHeskfeWkHQsbJJ:beta.matrix.org"}: matrix_sdk_ui::timeline: not sending receipt, because we already cover the event with a previous receipt

[bnjbvr]

Thanks for opening the issue. We've done quite a few fixes related to that problem (#4495, #4733, #4779 to name a few), and we're now much more confident in the implementation, but let us know / open a new issue with new logs if you run into this again. Thanks!