room list previews and ordering can get minutes behind

[ara4n]

Steps to reproduce

1. Send a msg in a room, or receive a push
2. Go to room list
3. Observe the room list preview shows an older message from a few minutes ago
4. Eventually it updates, but can often take 30-90s

Outcome

What did you expect?

if i see msgs in the room timeline, i expect the roomlist to know about then too and show them in the room preview and order the list correctly

What happened instead?

much lag.

Your phone model

No response

Operating system version

No response

Application version

254

Homeserver

No response

Will you send logs?

Yes

[ara4n]

^ example of this happening earlier; 42 minute lag on room list contents (after the app was backgrounded for a bit, but after giving it adequate time to catch up). have rageshaked logs.

[Hywan]

Based on the logs here, https://github.com/vector-im/element-x-ios-rageshakes/issues/507. I've used the console_0.log.gz file.

Here is the SlidingSync requests:

08:10:30, pos = 1, all_rooms = 0..=49, visible_rooms = 0..=19, invites = 0..=99
08:10:31, pos = 2, all_rooms = 0..=99, visible_rooms = 0..=19, invites = 0..=169
08:10:31, pos = 3, all_rooms = 0..=149, visible_rooms = 0..=19, invites = 0..=169
08:10:32, pos = 3, all_rooms = 0..=149, visible_rooms = 0..=14, invites = 0..=169
08:10:32, pos = 4, all_rooms = 0..=199, visible_rooms = 0..=14, invites = 0..=169
08:10:32, pos = 5, all_rooms = 0..=249, visible_rooms = 0..=14, invites = 0..=169
08:10:33, pos = 6, all_rooms = 0..=299, visible_rooms = 0..=14, invites = 0..=169
08:10:33, pos = 7, all_rooms = 0..=349, visible_rooms = 0..=14, invites = 0..=169
08:10:34, pos = 8, all_rooms = 0..=399, visible_rooms = 0..=14, invites = 0..=169
08:10:34, pos = 9, all_rooms = 0..=449, visible_rooms = 0..=14, invites = 0..=169
08:10:34, pos = 9, all_rooms = 0..=449, visible_rooms = 0..=14, invites = 0..=169
08:10:34, pos = 10, all_rooms = 0..=499, visible_rooms = 0..=14, invites = 0..=169
08:10:35, pos = 11, all_rooms = 0..=549, visible_rooms = 0..=14, invites = 0..=169
08:10:35, pos = 12, all_rooms = 0..=599, visible_rooms = 0..=14, invites = 0..=169
08:10:35, pos = 13, all_rooms = 0..=649, visible_rooms = 0..=14, invites = 0..=169
08:10:36, pos = 14, all_rooms = 0..=699, visible_rooms = 0..=14, invites = 0..=169
08:10:36, pos = 15, all_rooms = 0..=749, visible_rooms = 0..=14, invites = 0..=169
08:10:37, pos = 16, all_rooms = 0..=799, visible_rooms = 0..=14, invites = 0..=169
08:10:37, pos = 17, all_rooms = 0..=849, visible_rooms = 0..=14, invites = 0..=169
08:10:37, pos = 18, all_rooms = 0..=899, visible_rooms = 0..=14, invites = 0..=169
08:10:38, pos = 19, all_rooms = 0..=949, visible_rooms = 0..=14, invites = 0..=169
08:10:38, pos = 20, all_rooms = 0..=999, visible_rooms = 0..=14, invites = 0..=169
08:10:39, pos = 21, all_rooms = 0..=1049, visible_rooms = 0..=14, invites = 0..=169
08:10:39, pos = 22, all_rooms = 0..=1099, visible_rooms = 0..=14, invites = 0..=169
08:10:39, pos = 23, all_rooms = 0..=1149, visible_rooms = 0..=14, invites = 0..=169
08:10:40, pos = 24, all_rooms = 0..=1199, visible_rooms = 0..=14, invites = 0..=169
08:10:40, pos = 25, all_rooms = 0..=1249, visible_rooms = 0..=14, invites = 0..=169
08:10:40, pos = 26, all_rooms = 0..=1299, visible_rooms = 0..=14, invites = 0..=169
08:10:41, pos = 27, all_rooms = 0..=1349, visible_rooms = 0..=14, invites = 0..=169
08:10:41, pos = 28, all_rooms = 0..=1399, visible_rooms = 0..=14, invites = 0..=169
08:10:42, pos = 29, all_rooms = 0..=1449, visible_rooms = 0..=14, invites = 0..=169
08:10:42, pos = 30, all_rooms = 0..=1499, visible_rooms = 0..=14, invites = 0..=169
08:10:45, pos = 31, all_rooms = 0..=1549, visible_rooms = 0..=14, invites = 0..=169
08:10:46, pos = 32, all_rooms = 0..=1599, visible_rooms = 0..=14, invites = 0..=169
08:10:46, pos = 33, all_rooms = 0..=1649, visible_rooms = 0..=14, invites = 0..=169
08:10:46, pos = 34, all_rooms = 0..=1699, visible_rooms = 0..=14, invites = 0..=169
08:10:47, pos = 35, all_rooms = 0..=1749, visible_rooms = 0..=14, invites = 0..=169
08:10:47, pos = 36, all_rooms = 0..=1799, visible_rooms = 0..=14, invites = 0..=169
08:10:48, pos = 37, all_rooms = 0..=1849, visible_rooms = 0..=14, invites = 0..=169
08:10:48, pos = 38, all_rooms = 0..=1899, visible_rooms = 0..=14, invites = 0..=169
08:10:48, pos = 39, all_rooms = 0..=1949, visible_rooms = 0..=14, invites = 0..=169
08:10:49, pos = 40, all_rooms = 0..=1999, visible_rooms = 0..=14, invites = 0..=169
08:10:49, pos = 41, all_rooms = 0..=2049, visible_rooms = 0..=14, invites = 0..=169
08:10:49, pos = 42, all_rooms = 0..=2099, visible_rooms = 0..=14, invites = 0..=169
08:10:50, pos = 43, all_rooms = 0..=2149, visible_rooms = 0..=14, invites = 0..=169
08:10:51, pos = 44, all_rooms = 0..=2199, visible_rooms = 0..=14, invites = 0..=169
08:10:51, pos = 45, all_rooms = 0..=2249, visible_rooms = 0..=14, invites = 0..=169
08:10:54, pos = 46, all_rooms = 0..=2299, visible_rooms = 0..=14, invites = 0..=169
08:10:56, pos = 47, all_rooms = 0..=2349, visible_rooms = 0..=14, invites = 0..=169
08:10:56, pos = 48, all_rooms = 0..=2399, visible_rooms = 0..=14, invites = 0..=169
08:10:57, pos = 49, all_rooms = 0..=2449, visible_rooms = 0..=14, invites = 0..=169
08:10:58, pos = 50, all_rooms = 0..=2499, visible_rooms = 0..=14, invites = 0..=169
08:10:58, pos = 51, all_rooms = 0..=2549, visible_rooms = 0..=14, invites = 0..=169
08:10:59, pos = 52, all_rooms = 0..=2599, visible_rooms = 0..=14, invites = 0..=169
08:10:59, pos = 53, all_rooms = 0..=2649, visible_rooms = 0..=14, invites = 0..=169
08:11:00, pos = 54, all_rooms = 0..=2699, visible_rooms = 0..=14, invites = 0..=169
08:11:01, pos = 55, all_rooms = 0..=2749, visible_rooms = 0..=14, invites = 0..=169
08:11:01, pos = 56, all_rooms = 0..=2799, visible_rooms = 0..=14, invites = 0..=169
08:11:02, pos = 57, all_rooms = 0..=2849, visible_rooms = 0..=14, invites = 0..=169
08:11:02, pos = 58, all_rooms = 0..=2899, visible_rooms = 0..=14, invites = 0..=169
08:11:03, pos = 59, all_rooms = 0..=2949, visible_rooms = 0..=14, invites = 0..=169
08:11:03, pos = 60, all_rooms = 0..=2999, visible_rooms = 0..=14, invites = 0..=169
08:11:04, pos = 61, all_rooms = 0..=3049, visible_rooms = 0..=14, invites = 0..=169
08:11:05, pos = 62, all_rooms = 0..=3099, visible_rooms = 0..=14, invites = 0..=169
08:11:05, pos = 63, all_rooms = 0..=3149, visible_rooms = 0..=14, invites = 0..=169
08:11:06, pos = 64, all_rooms = 0..=3199, visible_rooms = 0..=14, invites = 0..=169
08:11:06, pos = 65, all_rooms = 0..=3249, visible_rooms = 0..=14, invites = 0..=169
08:11:07, pos = 66, all_rooms = 0..=3299, visible_rooms = 0..=14, invites = 0..=169
08:11:09, pos = 67, all_rooms = 0..=3349, visible_rooms = 0..=14, invites = 0..=169
08:11:11, pos = 68, all_rooms = 0..=3399, visible_rooms = 0..=14, invites = 0..=169
08:11:12, pos = 69, all_rooms = 0..=3449, visible_rooms = 0..=14, invites = 0..=169
08:11:12, pos = 70, all_rooms = 0..=3499, visible_rooms = 0..=14, invites = 0..=169
08:11:13, pos = 71, all_rooms = 0..=3549, visible_rooms = 0..=14, invites = 0..=169
08:11:14, pos = 72, all_rooms = 0..=3599, visible_rooms = 0..=14, invites = 0..=169
08:11:14, pos = 73, all_rooms = 0..=3649, visible_rooms = 0..=14, invites = 0..=169
08:11:15, pos = 74, all_rooms = 0..=3699, visible_rooms = 0..=14, invites = 0..=169
08:11:15, pos = 75, all_rooms = 0..=3749, visible_rooms = 0..=14, invites = 0..=169
11:16:42, pos = 75, all_rooms = 0..=49, visible_rooms = 0..=14, invites = 0..=169
11:16:43, pos = , all_rooms = 0..=49, visible_rooms = 0..=14, invites = 0..=169
11:16:45, pos = , all_rooms = 0..=49, visible_rooms = 0..=14, invites = 0..=169
11:16:47, pos = 1, all_rooms = 0..=99, visible_rooms = 0..=14, invites = 0..=169
11:16:48, pos = 2, all_rooms = 0..=149, visible_rooms = 0..=14, invites = 0..=169
11:16:48, pos = 3, all_rooms = 0..=199, visible_rooms = 0..=14, invites = 0..=169
11:16:48, pos = 4, all_rooms = 0..=249, visible_rooms = 0..=14, invites = 0..=169
11:16:49, pos = 5, all_rooms = 0..=299, visible_rooms = 0..=14, invites = 0..=169
11:16:49, pos = 6, all_rooms = 0..=349, visible_rooms = 0..=14, invites = 0..=169
11:16:49, pos = 7, all_rooms = 0..=399, visible_rooms = 0..=14, invites = 0..=169
11:16:50, pos = 8, all_rooms = 0..=449, visible_rooms = 0..=14, invites = 0..=169
11:16:50, pos = 9, all_rooms = 0..=499, visible_rooms = 0..=14, invites = 0..=169
11:16:50, pos = 10, all_rooms = 0..=549, visible_rooms = 0..=14, invites = 0..=169
11:16:50, pos = 11, all_rooms = 0..=599, visible_rooms = 0..=14, invites = 0..=169
11:16:51, pos = 12, all_rooms = 0..=649, visible_rooms = 0..=14, invites = 0..=169
11:16:51, pos = 13, all_rooms = 0..=699, visible_rooms = 0..=14, invites = 0..=169
11:16:52, pos = 14, all_rooms = 0..=749, visible_rooms = 0..=14, invites = 0..=169
11:16:53, pos = 15, all_rooms = 0..=799, visible_rooms = 0..=14, invites = 0..=169
11:16:53, pos = 16, all_rooms = 0..=849, visible_rooms = 0..=14, invites = 0..=169
11:16:54, pos = 17, all_rooms = 0..=899, visible_rooms = 0..=14, invites = 0..=169
11:16:54, pos = 18, all_rooms = 0..=949, visible_rooms = 0..=14, invites = 0..=169
11:16:54, pos = 19, all_rooms = 0..=999, visible_rooms = 0..=14, invites = 0..=169
11:16:54, pos = 20, all_rooms = 0..=1049, visible_rooms = 0..=14, invites = 0..=169
11:16:55, pos = 21, all_rooms = 0..=1099, visible_rooms = 0..=14, invites = 0..=169
11:16:55, pos = 22, all_rooms = 0..=1149, visible_rooms = 0..=14, invites = 0..=169
11:16:55, pos = 23, all_rooms = 0..=1199, visible_rooms = 0..=14, invites = 0..=169
11:16:55, pos = 24, all_rooms = 0..=1249, visible_rooms = 0..=14, invites = 0..=169
11:16:56, pos = 25, all_rooms = 0..=1299, visible_rooms = 0..=14, invites = 0..=169
11:16:56, pos = 26, all_rooms = 0..=1349, visible_rooms = 0..=14, invites = 0..=169
11:16:56, pos = 27, all_rooms = 0..=1399, visible_rooms = 0..=14, invites = 0..=169
11:16:57, pos = 28, all_rooms = 0..=1449, visible_rooms = 0..=14, invites = 0..=169
11:16:57, pos = 29, all_rooms = 0..=1499, visible_rooms = 0..=14, invites = 0..=169
11:16:58, pos = 30, all_rooms = 0..=1549, visible_rooms = 0..=14, invites = 0..=169
11:16:58, pos = 31, all_rooms = 0..=1599, visible_rooms = 0..=14, invites = 0..=169
11:16:58, pos = 32, all_rooms = 0..=1649, visible_rooms = 0..=14, invites = 0..=169
11:16:58, pos = 33, all_rooms = 0..=1699, visible_rooms = 0..=14, invites = 0..=169
11:16:59, pos = 34, all_rooms = 0..=1749, visible_rooms = 0..=14, invites = 0..=169
11:16:59, pos = 35, all_rooms = 0..=1799, visible_rooms = 0..=14, invites = 0..=169
11:16:59, pos = 36, all_rooms = 0..=1849, visible_rooms = 0..=14, invites = 0..=169
11:16:59, pos = 37, all_rooms = 0..=1899, visible_rooms = 0..=14, invites = 0..=169
11:17:00, pos = 38, all_rooms = 0..=1949, visible_rooms = 0..=14, invites = 0..=169
11:17:00, pos = 39, all_rooms = 0..=1999, visible_rooms = 0..=14, invites = 0..=169
11:17:00, pos = 40, all_rooms = 0..=2049, visible_rooms = 0..=14, invites = 0..=169
11:17:01, pos = 41, all_rooms = 0..=2099, visible_rooms = 0..=14, invites = 0..=169
11:17:01, pos = 42, all_rooms = 0..=2149, visible_rooms = 0..=14, invites = 0..=169
11:17:02, pos = 43, all_rooms = 0..=2199, visible_rooms = 0..=14, invites = 0..=169

At 8:58, your app wasn't running. If we check the logs:

2023-06-27T08:11:16.489947Z  INFO root: elementx: HomeScreenViewModel.swift:215: Updating rooms
2023-06-27T08:11:16.492324Z  INFO root: elementx: HomeScreenViewModel.swift:234: Finished updating rooms
2023-06-27T11:16:42.363635Z  INFO root: elementx: AppCoordinator.swift:608: Application did become active
2023-06-27T11:16:42.367018Z  INFO root: elementx: ClientProxy.swift:119: Starting sync

At 08:11, the app has emitted its last log, and at 11:16, the app became active, and has started syncing again. If you were checking at 8:58, it means the app wasn't detected as active. cc @stefanceriu

[bnjbvr]

@ara4n have you enabled the notifications feature flag, in the app? A few things hint that it could be the lock timing out, again (which ought to be solved with this PR, until we get a different locking system).

[stefanceriu]

I believe you are looking for 7:58 UTC which would be here https://rageshakes.element.io/api/listing/2023-06-27/111722-MA7WLIGO/console.1_7.log.gz

2023-06-27T07:58:39.536145Z  INFO root: elementx: AppCoordinator.swift:608: Application did become active

[ara4n]

@ara4n have you enabled the notifications feature flag, in the app? A few things hint that it could be the lock timing out, again (which ought to be solved with this PR, until we get a different locking system).

no, i turned off the notifs feature flag again. (and we should be logging labs flags in rageshake content, like EW does, otherwise we're shooting in the dark).

Amandine is also suffering from this (and spotted it within a few mins of using today's build), and won't have turned on the feature flag.

Something else is causing roomlist updates to seriously lag.

I believe you are looking for 7:58 UTC

yup, i'm in Europe/London (UTC+1) but logs are in UTC.

[Hywan]

OK, let's use my magic command line to get a summary of the logs. What we can see is this.

[summary]
07:00:54, pos = 201, all_rooms = 0..=4007, visible_rooms = 15..=35, invites = 0..=169
07:02:17, pos = 201, all_rooms = 0..=49, visible_rooms = 15..=35, invites = 0..=169
07:02:17, pos = 202, all_rooms = 0..=99, visible_rooms = 15..=35, invites = 0..=169

At 07:00:54 (UTC), you've probably backgrounded the app. At 07:02:17 (UTC), you've foregrounded the app. The SlidingSync session didn't expire, but all_rooms has been refreshed expectedly. We get pos = 201 twice because maybe you've scrolled immediately (edit: it's not the case because visible_rooms didn't change but something has…), thus cancelling the in-flight request. Let's check the logs to be sure:

[logs]
2023-06-27T07:02:17.711849Z  INFO root: elementx: AppCoordinator.swift:608: Application did become active
2023-06-27T07:02:17.712113Z  INFO root: elementx: ClientProxy.swift:119: Starting sync
…
2023-06-27T07:02:17.719176Z DEBUG root:sync_stream: matrix_sdk::sliding_sync: crates/matrix-sdk/src/sliding_sync/mod.rs:584: Sync-loop has received an internal message internal_message=Ok(SyncLoopSkipOverCurrentIteration)
…
2023-06-27T07:02:17.941125Z DEBUG root:sync_stream:sync_once{pos="201"}:handle_response: matrix_sdk::sliding_sync: crates/matrix-sdk/src/sliding_sync/mod.rs:280: Update position markers` pos="202" delta_token=None

OK, so the session didn't expire. Great. It's confirmed. And you've indeed scrolled immediately, thus cancelling the in-flight request.

Then, continuing reading my summary:

[summary]
07:12:09, pos = 638, all_rooms = 0..=4007, visible_rooms = 0..=13, invites = 0..=169
07:22:54, pos = 814, all_rooms = 0..=1149, visible_rooms = 0..=20, invites = 0..=169

This is disturbing. During 07:12 and 07:22, nothing happened:

[logs]
2023-06-27T07:12:21.893072Z  INFO root:send_queued_messages{room_id="!jtXonBVaPHPTzuleUn:matrix.org"}: matrix_sdk_ui::timeline::queue: crates/matrix-sdk-ui/src/timeline/queue.rs:86: Message receiver closed
2023-06-27T07:22:54.260662Z  WARN root:sync_stream:sync_once{pos="813"}:handle_response:process_sliding_sync:process_sliding_sync:handle_timeline{room_id="!svmqfTNNFVJDXeugra:matrix.org"}:decrypt_room_event{room_id="!svmqfTNNFVJDXeugra:matrix.org" sender="@matthew:cpf-demo.s.modular.im" event_id="$1fCnxaSyRC0bsytcxonSrjbb9rX9F0KV_EaUR_a0rlw" algorithm="m.megolm.v1.aes-sha2" sender_key="curve25519:QHvARLRW/n/JGn2ipIJlduN1kvykF4aKLGl1vGkv/HU" session_id="1pCJYzFvRVZL1y+i4ML1an5yHMNBPFM72Vi/mLSC2j0"}: matrix_sdk_crypto::machine: crates/matrix-sdk-crypto/src/machine.rs:1363: Failed to decrypt a room event: Can't find the room key to decrypt the event, withheld code: None

We also jump from position 638 to 814. I may have missed some logs here. What I don't get is why all_rooms reduces to 0..=1149. Oh ok, if we have missing logs, we can assume the app was backgrounded and foregrounded, and all_rooms has been refreshed and is catching up. OK, all good.

Let's assume logs are missing. After that, everything looks good.

[summary]
07:22:54, pos = 814, all_rooms = 0..=1149, visible_rooms = 0..=20, invites = 0..=169
07:22:55, pos = 815, all_rooms = 0..=1199, visible_rooms = 0..=20, invites = 0..=169
07:22:55, pos = 816, all_rooms = 0..=1249, visible_rooms = 0..=20, invites = 0..=169
07:22:56, pos = 817, all_rooms = 0..=1299, visible_rooms = 0..=20, invites = 0..=169
07:22:56, pos = 818, all_rooms = 0..=1349, visible_rooms = 0..=20, invites = 0..=169
07:22:57, pos = 819, all_rooms = 0..=1399, visible_rooms = 0..=20, invites = 0..=169
07:22:57, pos = 820, all_rooms = 0..=1449, visible_rooms = 0..=20, invites = 0..=169

Let's jump to 07:24:23:

[summary]
07:24:23, pos = 899, all_rooms = 0..=4007, visible_rooms = 0..=20, invites = 0..=169
07:24:29, pos = 900, all_rooms = 0..=4007, visible_rooms = 0..=20, invites = 0..=169
07:31:45, pos = 900, all_rooms = 0..=49, visible_rooms = 0..=20, invites = 0..=169
07:31:45, pos = 900, all_rooms = 0..=49, visible_rooms = 0..=20, invites = 0..=169
07:31:45, pos = 900, all_rooms = 0..=49, visible_rooms = 0..=20, invites = 0..=169
07:31:46, pos = 901, all_rooms = 0..=99, visible_rooms = 0..=20, invites = 0..=169
07:31:46, pos = 902, all_rooms = 0..=149, visible_rooms = 0..=20, invites = 0..=169
07:31:47, pos = 903, all_rooms = 0..=199, visible_rooms = 0..=20, invites = 0..=169

At 07:24:29 (still UTC), I assume you've backgrounded the app, and foregrounded it at 07:31:45. Why? Because we have the same pos and because all_rooms has been refreshed.

Let's see the logs:

[logs]
2023-06-27T07:31:45.151419Z  INFO root: elementx: AppCoordinator.swift:150: [AppCoordinator] tappedNotification
…
2023-06-27T07:31:45.321809Z  INFO root: elementx: AppCoordinator.swift:608: Application did become active
2023-06-27T07:31:45.321973Z  INFO root: elementx: ClientProxy.swift:119: Starting sync

OK, good. You've received a notification, you've tapped on it, and the app was active again, thus re-doing its dance.

Looking at the log, I notice that:

[logs]
2023-06-27T07:31:45.480443Z DEBUG root:sync_stream: matrix_sdk::sliding_sync: crates/matrix-sdk/src/sliding_sync/mod.rs:584: Sync-loop has received an internal message internal_message=Ok(SyncLoopSkipOverCurrentIteration)

is happening 3 or 4 times. Maybe you've scrolled down and scrolled back to your initial position, be the top of the room list (0..=20). So vislble_rooms doesn't change, but it has stopped syncing. That's a potential optimisation we can add. When the viewport “changes” to its current value (so it doesn't really change), we must not refresh visible_rooms, so that the in-flight sync iteration is not cancelled.

But anyway, the thing goes on and on.

[summary]
07:31:49, pos = 907, all_rooms = 0..=399, visible_rooms = 0..=20, invites = 0..=169
07:31:50, pos = 908, all_rooms = 0..=449, visible_rooms = 0..=20, invites = 0..=169
07:31:50, pos = 909, all_rooms = 0..=499, visible_rooms = 0..=20, invites = 0..=169
07:31:51, pos = 910, all_rooms = 0..=549, visible_rooms = 0..=20, invites = 0..=169
07:31:51, pos = 911, all_rooms = 0..=599, visible_rooms = 0..=20, invites = 0..=169
07:31:51, pos = 912, all_rooms = 0..=649, visible_rooms = 0..=20, invites = 0..=169
07:31:52, pos = 913, all_rooms = 0..=699, visible_rooms = 0..=20, invites = 0..=169
07:31:52, pos = 914, all_rooms = 0..=749, visible_rooms = 0..=20, invites = 0..=169
07:31:53, pos = 915, all_rooms = 0..=799, visible_rooms = 0..=20, invites = 0..=169
07:31:53, pos = 916, all_rooms = 0..=849, visible_rooms = 0..=20, invites = 0..=169
07:31:53, pos = 917, all_rooms = 0..=899, visible_rooms = 0..=20, invites = 0..=169
07:31:54, pos = 918, all_rooms = 0..=949, visible_rooms = 0..=20, invites = 0..=169
07:31:55, pos = 919, all_rooms = 0..=999, visible_rooms = 0..=20, invites = 0..=169
07:31:55, pos = 920, all_rooms = 0..=1049, visible_rooms = 0..=20, invites = 0..=169
07:31:56, pos = 921, all_rooms = 0..=1099, visible_rooms = 0..=20, invites = 0..=169
07:31:57, pos = 922, all_rooms = 0..=1149, visible_rooms = 0..=20, invites = 0..=169
07:31:58, pos = 923, all_rooms = 0..=1199, visible_rooms = 0..=20, invites = 0..=169
07:31:58, pos = 924, all_rooms = 0..=1249, visible_rooms = 0..=20, invites = 0..=169
07:31:59, pos = 925, all_rooms = 0..=1299, visible_rooms = 0..=20, invites = 0..=169
07:31:59, pos = 926, all_rooms = 0..=1349, visible_rooms = 0..=20, invites = 0..=169
07:31:59, pos = 927, all_rooms = 0..=1399, visible_rooms = 0..=20, invites = 0..=169
07:32:00, pos = 928, all_rooms = 0..=1449, visible_rooms = 0..=20, invites = 0..=169
07:32:01, pos = 929, all_rooms = 0..=1499, visible_rooms = 0..=20, invites = 0..=169
07:32:01, pos = 930, all_rooms = 0..=1549, visible_rooms = 0..=20, invites = 0..=169
07:32:02, pos = 931, all_rooms = 0..=1599, visible_rooms = 0..=20, invites = 0..=169
07:32:02, pos = 932, all_rooms = 0..=1649, visible_rooms = 0..=20, invites = 0..=169
07:32:03, pos = 933, all_rooms = 0..=1699, visible_rooms = 0..=20, invites = 0..=169
07:32:04, pos = 934, all_rooms = 0..=1749, visible_rooms = 0..=20, invites = 0..=169
07:32:04, pos = 935, all_rooms = 0..=1799, visible_rooms = 0..=20, invites = 0..=169
07:32:05, pos = 936, all_rooms = 0..=1849, visible_rooms = 0..=20, invites = 0..=169
07:32:05, pos = 937, all_rooms = 0..=1899, visible_rooms = 0..=20, invites = 0..=169
07:32:06, pos = 938, all_rooms = 0..=1949, visible_rooms = 0..=20, invites = 0..=169
07:32:07, pos = 939, all_rooms = 0..=1999, visible_rooms = 0..=20, invites = 0..=169
07:32:08, pos = 940, all_rooms = 0..=2049, visible_rooms = 0..=20, invites = 0..=169
07:32:08, pos = 941, all_rooms = 0..=2099, visible_rooms = 0..=20, invites = 0..=169
07:32:09, pos = 942, all_rooms = 0..=2149, visible_rooms = 0..=20, invites = 0..=169
07:32:09, pos = 943, all_rooms = 0..=2199, visible_rooms = 0..=20, invites = 0..=169
07:32:10, pos = 944, all_rooms = 0..=2249, visible_rooms = 0..=20, invites = 0..=169
07:32:11, pos = 945, all_rooms = 0..=2299, visible_rooms = 0..=20, invites = 0..=169
07:32:11, pos = 946, all_rooms = 0..=2349, visible_rooms = 0..=20, invites = 0..=169
07:32:12, pos = 947, all_rooms = 0..=2399, visible_rooms = 0..=20, invites = 0..=169
07:32:12, pos = 948, all_rooms = 0..=2449, visible_rooms = 0..=20, invites = 0..=169
07:32:13, pos = 949, all_rooms = 0..=2499, visible_rooms = 0..=20, invites = 0..=169
07:32:14, pos = 950, all_rooms = 0..=2549, visible_rooms = 0..=20, invites = 0..=169
07:32:14, pos = 951, all_rooms = 0..=2599, visible_rooms = 0..=20, invites = 0..=169
07:32:15, pos = 952, all_rooms = 0..=2649, visible_rooms = 0..=20, invites = 0..=169
07:32:15, pos = 953, all_rooms = 0..=2699, visible_rooms = 0..=20, invites = 0..=169
07:32:15, pos = 954, all_rooms = 0..=2749, visible_rooms = 0..=20, invites = 0..=169
07:32:16, pos = 955, all_rooms = 0..=2799, visible_rooms = 0..=20, invites = 0..=169
07:32:16, pos = 956, all_rooms = 0..=2849, visible_rooms = 0..=20, invites = 0..=169
07:32:16, pos = 957, all_rooms = 0..=2899, visible_rooms = 0..=20, invites = 0..=169
07:32:17, pos = 958, all_rooms = 0..=2949, visible_rooms = 0..=20, invites = 0..=169
07:32:17, pos = 959, all_rooms = 0..=2999, visible_rooms = 0..=20, invites = 0..=169
07:32:17, pos = 960, all_rooms = 0..=3049, visible_rooms = 0..=20, invites = 0..=169
07:32:18, pos = 961, all_rooms = 0..=3099, visible_rooms = 0..=20, invites = 0..=169
07:32:18, pos = 962, all_rooms = 0..=3149, visible_rooms = 0..=20, invites = 0..=169
07:32:18, pos = 963, all_rooms = 0..=3199, visible_rooms = 0..=20, invites = 0..=169
07:32:19, pos = 964, all_rooms = 0..=3249, visible_rooms = 0..=20, invites = 0..=169
07:32:19, pos = 965, all_rooms = 0..=3299, visible_rooms = 0..=20, invites = 0..=169
07:32:19, pos = 966, all_rooms = 0..=3349, visible_rooms = 0..=20, invites = 0..=169
07:32:20, pos = 967, all_rooms = 0..=3399, visible_rooms = 0..=20, invites = 0..=169
07:32:20, pos = 968, all_rooms = 0..=3449, visible_rooms = 0..=20, invites = 0..=169
07:32:20, pos = 969, all_rooms = 0..=3499, visible_rooms = 0..=20, invites = 0..=169
07:32:21, pos = 970, all_rooms = 0..=3549, visible_rooms = 0..=20, invites = 0..=169
07:32:21, pos = 971, all_rooms = 0..=3599, visible_rooms = 0..=20, invites = 0..=169
07:32:21, pos = 972, all_rooms = 0..=3649, visible_rooms = 0..=20, invites = 0..=169
07:32:22, pos = 973, all_rooms = 0..=3699, visible_rooms = 0..=20, invites = 0..=169
07:32:22, pos = 974, all_rooms = 0..=3749, visible_rooms = 0..=20, invites = 0..=169
07:32:22, pos = 975, all_rooms = 0..=3799, visible_rooms = 0..=20, invites = 0..=169
07:32:23, pos = 976, all_rooms = 0..=3849, visible_rooms = 0..=20, invites = 0..=169
07:32:23, pos = 977, all_rooms = 0..=3899, visible_rooms = 0..=20, invites = 0..=169
07:32:24, pos = 978, all_rooms = 0..=3949, visible_rooms = 0..=20, invites = 0..=169
07:32:24, pos = 979, all_rooms = 0..=3999, visible_rooms = 0..=20, invites = 0..=169
07:32:24, pos = 980, all_rooms = 0..=4007, visible_rooms = 0..=20, invites = 0..=169
07:32:25, pos = 981, all_rooms = 0..=4007, visible_rooms = 0..=20, invites = 0..=169
07:32:25, pos = 982, all_rooms = 0..=4007, visible_rooms = 0..=20, invites = 0..=169
07:32:25, pos = 983, all_rooms = 0..=4007, visible_rooms = 0..=20, invites = 0..=169
07:32:26, pos = 984, all_rooms = 0..=4007, visible_rooms = 0..=20, invites = 0..=169
07:32:30, pos = 985, all_rooms = 0..=4007, visible_rooms = 0..=20, invites = 0..=169
07:32:31, pos = 986, all_rooms = 0..=4007, visible_rooms = 0..=20, invites = 0..=169
07:32:33, pos = 987, all_rooms = 0..=4007, visible_rooms = 0..=20, invites = 0..=169
07:32:42, pos = 987, all_rooms = 0..=4007, visible_rooms = 0..=20, invites = 0..=169
07:32:42, pos = 988, all_rooms = 0..=4007, visible_rooms = 0..=20, invites = 0..=169
07:32:42, pos = 989, all_rooms = 0..=4007, visible_rooms = 0..=20, invites = 0..=169
07:32:42, pos = 990, all_rooms = 0..=4007, visible_rooms = 0..=20, invites = 0..=169
07:32:43, pos = 991, all_rooms = 0..=4007, visible_rooms = 0..=20, invites = 0..=169
07:32:44, pos = 992, all_rooms = 0..=4007, visible_rooms = 0..=20, invites = 0..=169
07:33:07, pos = 993, all_rooms = 0..=4007, visible_rooms = 0..=20, invites = 0..=169
07:33:07, pos = 994, all_rooms = 0..=4007, visible_rooms = 0..=20, invites = 0..=169
07:41:27, pos = 994, all_rooms = 0..=49, visible_rooms = 0..=20, invites = 0..=169
07:41:27, pos = 995, all_rooms = 0..=99, visible_rooms = 0..=20, invites = 0..=169
07:41:28, pos = 996, all_rooms = 0..=149, visible_rooms = 0..=20, invites = 0..=169
07:41:31, pos = 997, all_rooms = 0..=199, visible_rooms = 0..=20, invites = 0..=169
07:41:32, pos = 998, all_rooms = 0..=249, visible_rooms = 0..=20, invites = 0..=169
07:41:32, pos = 999, all_rooms = 0..=299, visible_rooms = 0..=20, invites = 0..=169
07:41:33, pos = 1000, all_rooms = 0..=349, visible_rooms = 0..=20, invites = 0..=169
07:41:34, pos = 1001, all_rooms = 0..=399, visible_rooms = 0..=20, invites = 0..=169
07:41:34, pos = 1002, all_rooms = 0..=449, visible_rooms = 0..=20, invites = 0..=169
07:41:35, pos = 1003, all_rooms = 0..=499, visible_rooms = 0..=20, invites = 0..=169
07:41:36, pos = 1004, all_rooms = 0..=549, visible_rooms = 0..=20, invites = 0..=169
07:41:36, pos = 1005, all_rooms = 0..=599, visible_rooms = 0..=20, invites = 0..=169
07:41:37, pos = 1006, all_rooms = 0..=649, visible_rooms = 0..=20, invites = 0..=169
07:41:37, pos = 1007, all_rooms = 0..=699, visible_rooms = 0..=20, invites = 0..=169
07:41:38, pos = 1008, all_rooms = 0..=749, visible_rooms = 0..=20, invites = 0..=169
07:41:39, pos = 1009, all_rooms = 0..=799, visible_rooms = 0..=20, invites = 0..=169
07:41:40, pos = 1010, all_rooms = 0..=849, visible_rooms = 0..=20, invites = 0..=169
07:41:41, pos = 1011, all_rooms = 0..=899, visible_rooms = 0..=20, invites = 0..=169
07:41:41, pos = 1012, all_rooms = 0..=949, visible_rooms = 0..=20, invites = 0..=169
07:41:42, pos = 1013, all_rooms = 0..=999, visible_rooms = 0..=20, invites = 0..=169
07:41:42, pos = 1014, all_rooms = 0..=1049, visible_rooms = 0..=20, invites = 0..=169
07:41:42, pos = 1015, all_rooms = 0..=1099, visible_rooms = 0..=20, invites = 0..=169
07:41:43, pos = 1016, all_rooms = 0..=1149, visible_rooms = 0..=20, invites = 0..=169
07:41:43, pos = 1017, all_rooms = 0..=1199, visible_rooms = 0..=20, invites = 0..=169
07:41:44, pos = 1018, all_rooms = 0..=1249, visible_rooms = 0..=20, invites = 0..=169
07:41:44, pos = 1019, all_rooms = 0..=1299, visible_rooms = 0..=20, invites = 0..=169
07:41:45, pos = 1020, all_rooms = 0..=1349, visible_rooms = 0..=20, invites = 0..=169
07:41:45, pos = 1021, all_rooms = 0..=1399, visible_rooms = 0..=20, invites = 0..=169
07:41:46, pos = 1022, all_rooms = 0..=1449, visible_rooms = 0..=20, invites = 0..=169
07:41:46, pos = 1023, all_rooms = 0..=1499, visible_rooms = 0..=20, invites = 0..=169
07:41:47, pos = 1024, all_rooms = 0..=1549, visible_rooms = 0..=20, invites = 0..=169
07:41:48, pos = 1025, all_rooms = 0..=1599, visible_rooms = 0..=20, invites = 0..=169
07:41:48, pos = 1026, all_rooms = 0..=1649, visible_rooms = 0..=20, invites = 0..=169
07:41:49, pos = 1027, all_rooms = 0..=1699, visible_rooms = 0..=20, invites = 0..=169
07:41:50, pos = 1028, all_rooms = 0..=1749, visible_rooms = 0..=20, invites = 0..=169
07:41:50, pos = 1029, all_rooms = 0..=1799, visible_rooms = 0..=20, invites = 0..=169
07:41:51, pos = 1030, all_rooms = 0..=1849, visible_rooms = 0..=20, invites = 0..=169
07:41:51, pos = 1031, all_rooms = 0..=1899, visible_rooms = 0..=20, invites = 0..=169
07:41:52, pos = 1032, all_rooms = 0..=1949, visible_rooms = 0..=20, invites = 0..=169
07:41:52, pos = 1033, all_rooms = 0..=1999, visible_rooms = 0..=20, invites = 0..=169
07:41:53, pos = 1034, all_rooms = 0..=2049, visible_rooms = 0..=20, invites = 0..=169
07:41:54, pos = 1035, all_rooms = 0..=2099, visible_rooms = 0..=20, invites = 0..=169
07:55:58, pos = 1035, all_rooms = 0..=49, visible_rooms = 0..=20, invites = 0..=169
07:55:58, pos = 1036, all_rooms = 0..=99, visible_rooms = 0..=20, invites = 0..=169
07:55:59, pos = 1037, all_rooms = 0..=149, visible_rooms = 0..=20, invites = 0..=169
07:56:01, pos = 1038, all_rooms = 0..=199, visible_rooms = 0..=20, invites = 0..=169
07:56:01, pos = 1039, all_rooms = 0..=249, visible_rooms = 0..=20, invites = 0..=169
07:56:02, pos = 1040, all_rooms = 0..=299, visible_rooms = 0..=20, invites = 0..=169
07:56:02, pos = 1041, all_rooms = 0..=349, visible_rooms = 0..=20, invites = 0..=169
07:56:03, pos = 1042, all_rooms = 0..=399, visible_rooms = 0..=20, invites = 0..=169
07:56:03, pos = 1043, all_rooms = 0..=449, visible_rooms = 0..=20, invites = 0..=169
07:56:03, pos = 1043, all_rooms = 0..=449, visible_rooms = 0..=20, invites = 0..=169
07:56:04, pos = 1044, all_rooms = 0..=499, visible_rooms = 0..=20, invites = 0..=169
07:56:05, pos = 1045, all_rooms = 0..=549, visible_rooms = 0..=20, invites = 0..=169
07:56:05, pos = 1046, all_rooms = 0..=599, visible_rooms = 0..=20, invites = 0..=169
07:56:05, pos = 1047, all_rooms = 0..=649, visible_rooms = 0..=20, invites = 0..=169
07:56:06, pos = 1048, all_rooms = 0..=699, visible_rooms = 0..=20, invites = 0..=169
07:56:06, pos = 1049, all_rooms = 0..=749, visible_rooms = 0..=20, invites = 0..=169
07:56:06, pos = 1050, all_rooms = 0..=799, visible_rooms = 0..=20, invites = 0..=169
07:56:07, pos = 1051, all_rooms = 0..=849, visible_rooms = 0..=20, invites = 0..=169
07:56:07, pos = 1052, all_rooms = 0..=899, visible_rooms = 0..=20, invites = 0..=169
07:56:07, pos = 1053, all_rooms = 0..=949, visible_rooms = 0..=20, invites = 0..=169
07:56:08, pos = 1054, all_rooms = 0..=999, visible_rooms = 0..=20, invites = 0..=169
07:56:08, pos = 1055, all_rooms = 0..=1049, visible_rooms = 0..=20, invites = 0..=169
07:56:08, pos = 1056, all_rooms = 0..=1099, visible_rooms = 0..=20, invites = 0..=169
07:56:09, pos = 1057, all_rooms = 0..=1149, visible_rooms = 0..=20, invites = 0..=169
07:56:09, pos = 1058, all_rooms = 0..=1199, visible_rooms = 0..=20, invites = 0..=169
07:56:09, pos = 1059, all_rooms = 0..=1249, visible_rooms = 0..=20, invites = 0..=169
07:56:10, pos = 1060, all_rooms = 0..=1299, visible_rooms = 0..=20, invites = 0..=169
07:56:10, pos = 1061, all_rooms = 0..=1349, visible_rooms = 0..=20, invites = 0..=169
07:56:10, pos = 1062, all_rooms = 0..=1399, visible_rooms = 0..=20, invites = 0..=169
07:56:11, pos = 1063, all_rooms = 0..=1449, visible_rooms = 0..=20, invites = 0..=169
07:56:11, pos = 1064, all_rooms = 0..=1499, visible_rooms = 0..=20, invites = 0..=169
07:56:11, pos = 1065, all_rooms = 0..=1549, visible_rooms = 0..=20, invites = 0..=169
07:56:12, pos = 1066, all_rooms = 0..=1599, visible_rooms = 0..=20, invites = 0..=169
07:56:14, pos = 1067, all_rooms = 0..=1649, visible_rooms = 0..=20, invites = 0..=169
07:56:15, pos = 1068, all_rooms = 0..=1699, visible_rooms = 0..=20, invites = 0..=169
07:56:15, pos = 1069, all_rooms = 0..=1749, visible_rooms = 0..=20, invites = 0..=169
07:56:16, pos = 1070, all_rooms = 0..=1799, visible_rooms = 0..=20, invites = 0..=169
07:56:16, pos = 1071, all_rooms = 0..=1849, visible_rooms = 0..=20, invites = 0..=169
07:56:17, pos = 1072, all_rooms = 0..=1899, visible_rooms = 0..=20, invites = 0..=169
07:56:17, pos = 1073, all_rooms = 0..=1949, visible_rooms = 0..=20, invites = 0..=169
07:56:18, pos = 1074, all_rooms = 0..=1999, visible_rooms = 0..=20, invites = 0..=169
07:56:18, pos = 1075, all_rooms = 0..=2049, visible_rooms = 0..=20, invites = 0..=169
07:56:19, pos = 1076, all_rooms = 0..=2099, visible_rooms = 0..=20, invites = 0..=169
07:56:19, pos = 1077, all_rooms = 0..=2149, visible_rooms = 0..=20, invites = 0..=169
07:56:20, pos = 1078, all_rooms = 0..=2199, visible_rooms = 0..=20, invites = 0..=169
07:56:20, pos = 1079, all_rooms = 0..=2249, visible_rooms = 0..=20, invites = 0..=169
07:56:21, pos = 1080, all_rooms = 0..=2299, visible_rooms = 0..=20, invites = 0..=169
07:56:21, pos = 1081, all_rooms = 0..=2349, visible_rooms = 0..=20, invites = 0..=169
07:56:21, pos = 1082, all_rooms = 0..=2399, visible_rooms = 0..=20, invites = 0..=169
07:56:22, pos = 1083, all_rooms = 0..=2449, visible_rooms = 0..=20, invites = 0..=169
07:56:22, pos = 1084, all_rooms = 0..=2499, visible_rooms = 0..=20, invites = 0..=169
07:56:23, pos = 1085, all_rooms = 0..=2549, visible_rooms = 0..=20, invites = 0..=169
07:56:23, pos = 1086, all_rooms = 0..=2599, visible_rooms = 0..=20, invites = 0..=169
07:56:24, pos = 1087, all_rooms = 0..=2649, visible_rooms = 0..=20, invites = 0..=169
07:56:24, pos = 1088, all_rooms = 0..=2699, visible_rooms = 0..=20, invites = 0..=169
07:56:25, pos = 1089, all_rooms = 0..=2749, visible_rooms = 0..=20, invites = 0..=169
07:56:25, pos = 1090, all_rooms = 0..=2799, visible_rooms = 0..=20, invites = 0..=169
07:56:25, pos = 1091, all_rooms = 0..=2849, visible_rooms = 0..=20, invites = 0..=169
07:56:26, pos = 1092, all_rooms = 0..=2899, visible_rooms = 0..=20, invites = 0..=169
07:56:26, pos = 1093, all_rooms = 0..=2949, visible_rooms = 0..=20, invites = 0..=169
07:56:27, pos = 1094, all_rooms = 0..=2999, visible_rooms = 0..=20, invites = 0..=169
07:56:28, pos = 1095, all_rooms = 0..=3049, visible_rooms = 0..=20, invites = 0..=169
07:56:28, pos = 1096, all_rooms = 0..=3099, visible_rooms = 0..=20, invites = 0..=169
07:56:29, pos = 1097, all_rooms = 0..=3149, visible_rooms = 0..=20, invites = 0..=169
07:56:29, pos = 1098, all_rooms = 0..=3199, visible_rooms = 0..=20, invites = 0..=169
07:56:30, pos = 1099, all_rooms = 0..=3249, visible_rooms = 0..=20, invites = 0..=169
07:56:30, pos = 1100, all_rooms = 0..=3299, visible_rooms = 0..=20, invites = 0..=169
07:56:31, pos = 1101, all_rooms = 0..=3349, visible_rooms = 0..=20, invites = 0..=169
07:56:31, pos = 1102, all_rooms = 0..=3399, visible_rooms = 0..=20, invites = 0..=169
07:56:31, pos = 1103, all_rooms = 0..=3449, visible_rooms = 0..=20, invites = 0..=169
07:56:32, pos = 1104, all_rooms = 0..=3499, visible_rooms = 0..=20, invites = 0..=169
07:56:33, pos = 1105, all_rooms = 0..=3549, visible_rooms = 0..=20, invites = 0..=169
07:56:33, pos = 1106, all_rooms = 0..=3599, visible_rooms = 0..=20, invites = 0..=169
07:56:34, pos = 1107, all_rooms = 0..=3649, visible_rooms = 0..=20, invites = 0..=169
07:56:34, pos = 1108, all_rooms = 0..=3699, visible_rooms = 0..=20, invites = 0..=169
07:56:35, pos = 1109, all_rooms = 0..=3749, visible_rooms = 0..=20, invites = 0..=169
07:56:35, pos = 1110, all_rooms = 0..=3799, visible_rooms = 0..=20, invites = 0..=169
07:56:36, pos = 1111, all_rooms = 0..=3849, visible_rooms = 0..=20, invites = 0..=169
07:56:37, pos = 1112, all_rooms = 0..=3899, visible_rooms = 0..=20, invites = 0..=169
07:56:37, pos = 1113, all_rooms = 0..=3949, visible_rooms = 0..=20, invites = 0..=169
07:56:38, pos = 1114, all_rooms = 0..=3999, visible_rooms = 0..=20, invites = 0..=169
07:58:39, pos = 1115, all_rooms = 0..=49, visible_rooms = 0..=20, invites = 0..=169
07:58:40, pos = 1116, all_rooms = 0..=99, visible_rooms = 0..=20, invites = 0..=169
07:58:40, pos = 1117, all_rooms = 0..=149, visible_rooms = 0..=20, invites = 0..=169
07:58:40, pos = 1118, all_rooms = 0..=199, visible_rooms = 0..=20, invites = 0..=169
07:58:41, pos = 1119, all_rooms = 0..=249, visible_rooms = 0..=20, invites = 0..=169
07:58:41, pos = 1120, all_rooms = 0..=299, visible_rooms = 0..=20, invites = 0..=169

Nothing fancy here. We are receiving updates, the sync is working. I don't know what's the problem. Are you sure no message was sent in this room (ElementX-internal) for 42mn? Or maybe Synapse was laggy? Or maybe the proxy missed the update? But on the RoomList side, I don't see anything in particular :-(.