/messages pagination fails with "Host not in room" if backfill request goes to a server with outdated state
#12490
Comments
|
Example more than 92 messages back by splitting up the requests:
|
|
It seems like if I do enough small requests, I do eventually hit a point I can't paginate past even with limit=1. |
DMRobertson
added
T-Defect
richvdh
changed the title
/messages pagination fails with a limit over 91 if a remote server returns 403
|
At first glance, it sounds like:
|
|
The person paginating was in the room all the time. It isn't exactly 91 events, sometimes it is more, if you paginate in smaller batches. So this is probably some state events, that get pulled in for state res from a server, that isn't in the room anymore or so? |
|
I'm seeing the same thing in one of the Gitter rooms:
Because the backfill is failing: |
reivilibre
removed
the
T-Defect
richvdh
added
T-Defect
richvdh
changed the title
/messages pagination fails with a limit over 91 if a remote server returns 403/messages pagination fails with "Host not in room" if backfill request goes to a server with outdated state
|
Presumably we should just move on to the next homeserver to try backfilling from when one returns a 4XX, rather than confusingly bubbling that request up to the client? |
|
Related: #12584 |
Yeah, I think this might have regressed with #7556. Though there is a bit of a balance here between trying a range of different servers, and not taking all week to reply to the client. |
MadLittleMods
added
the
A-Messages-Endpoint
Description
Users reported that their client can't scroll back past a certain point and their client shows "Host not in room". Investigating further shows that Quaternion uses a random integer as the limit, usually between 700 and 100 in the failing requests. Manually doing /messages requests works fine if limit is 91 or smaller, but fails with a limit of 92 or higher. Paginating backwards using the batch token from a 91er request works fine however. Noticeable is that in the logs the server seems to reach out to a server, that isn't in the room anymore.
Might be related to #3736
Logs:
@40000000625dc0172eb74b3a 2022-04-18 19:45:54,783 - synapse.access.http.8108 - 382 - DEBUG - GET-22 - 2001:a61:11a3:9101:8f84:fef4:1526:b3cc - 8108 - Received request: GET /_matrix/client/r0/rooms/!WgEsWTOEGkIcwYphxi:maunium.net/messages?from=s2787474_44251527_2053_3734916_138866_47_132417_2929243_1&dir=b&limit=92 @40000000625dc0172ebe1322 2022-04-18 19:45:54,784 - synapse.storage.txn - 614 - DEBUG - GET-22 - [TXN START] {get_user_by_access_token-ca} @40000000625dc0172ebf1c16 2022-04-18 19:45:54,784 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {get_user_by_access_token-ca} SELECT users.name as user_id, users.is_guest, users.shadow_banned, access_tokens.id as token_id, access_tokens.device_id, access_tokens.valid_until_ms, access_tokens.user_id as token_owner, access_tokens.used as token_used FROM users INNER JOIN access_tokens on users.name = COALESCE(puppets_user_id, access_tokens.user_id) WHERE token = ? @40000000625dc0172ebfd502 2022-04-18 19:45:54,784 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {get_user_by_access_token-ca} ('syt_ZGVlcGJsdWV2Nw_scJXlBpavOMEKhpjbdWq_1mJ4F5',) @40000000625dc0172ec7bcaf 2022-04-18 19:45:54,784 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {get_user_by_access_token-ca} 0.000384 sec @40000000625dc0172eca5dcb 2022-04-18 19:45:54,784 - synapse.storage.txn - 717 - DEBUG - GET-22 - [TXN END] {get_user_by_access_token-ca} 0.000815 sec @40000000625dc0172ed6eda6 2022-04-18 19:45:54,785 - synapse.storage.txn - 614 - DEBUG - GET-22 - [TXN START] {get_latest_event_ids_in_room-cb} @40000000625dc0172ed7bc41 2022-04-18 19:45:54,785 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {get_latest_event_ids_in_room-cb} SELECT event_id FROM event_forward_extremities WHERE room_id = ? @40000000625dc0172ed82d29 2022-04-18 19:45:54,785 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {get_latest_event_ids_in_room-cb} ['!WgEsWTOEGkIcwYphxi:maunium.net'] @40000000625dc0172ee41258 2022-04-18 19:45:54,786 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {get_latest_event_ids_in_room-cb} 0.000736 sec @40000000625dc0172ee4f787 2022-04-18 19:45:54,786 - synapse.storage.txn - 717 - DEBUG - GET-22 - [TXN END] {get_latest_event_ids_in_room-cb} 0.000951 sec @40000000625dc0172eea238f 2022-04-18 19:45:54,787 - synapse.state - 178 - DEBUG - GET-22 - calling resolve_state_groups from get_current_state @40000000625dc0172eeb37bf 2022-04-18 19:45:54,787 - synapse.util.metrics - 152 - DEBUG - GET-22 - Entering block resolve_state_groups_for_events @40000000625dc0172eebd5e5 2022-04-18 19:45:54,787 - synapse.state - 419 - DEBUG - GET-22 - resolve_state_groups event_ids ['$K4WAiSNwhIOG0LhSXipzpewnNq26l1ICiUzRy3mi4ho'] @40000000625dc0172ef3817f 2022-04-18 19:45:54,787 - synapse.storage.txn - 614 - DEBUG - GET-22 - [TXN START] {_get_state_group_for_events-cc} @40000000625dc0172ef4411c 2022-04-18 19:45:54,787 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_group_for_events-cc} SELECT event_id, state_group FROM event_to_state_groups WHERE event_id = ANY(?) @40000000625dc0172ef4afde 2022-04-18 19:45:54,787 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_group_for_events-cc} [['$K4WAiSNwhIOG0LhSXipzpewnNq26l1ICiUzRy3mi4ho']] @40000000625dc0172efc917a 2022-04-18 19:45:54,788 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_group_for_events-cc} 0.000442 sec @40000000625dc0172efd91b4 2022-04-18 19:45:54,788 - synapse.storage.txn - 717 - DEBUG - GET-22 - [TXN END] {_get_state_group_for_events-cc} 0.000672 sec @40000000625dc0172f0656c7 2022-04-18 19:45:54,788 - synapse.storage.txn - 614 - DEBUG - GET-22 - [TXN START] {_get_state_groups_from_groups-cd} @40000000625dc0172f074c02 2022-04-18 19:45:54,788 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-cd} SET LOCAL enable_seqscan=off @40000000625dc0172f08d37e 2022-04-18 19:45:54,789 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-cd} 0.000065 sec @40000000625dc0172f09c5dd 2022-04-18 19:45:54,789 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-cd} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) ORDER BY type, state_key, state_group DESC @40000000625dc0172f0a3702 2022-04-18 19:45:54,789 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-cd} [351659] @40000000625dc0172f3e024c 2022-04-18 19:45:54,792 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-cd} 0.003355 sec @40000000625dc0172f413c29 2022-04-18 19:45:54,792 - synapse.storage.txn - 717 - DEBUG - GET-22 - [TXN END] {_get_state_groups_from_groups-cd} 0.003876 sec @40000000625dc0172f4d6ae1 2022-04-18 19:45:54,793 - synapse.storage.txn - 614 - DEBUG - GET-22 - [TXN START] {get_state_group_delta-ce} @40000000625dc0172f4e5989 2022-04-18 19:45:54,793 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {get_state_group_delta-ce} SELECT prev_state_group FROM state_group_edges WHERE state_group = ? @40000000625dc0172f4eed32 2022-04-18 19:45:54,793 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {get_state_group_delta-ce} [351659] @40000000625dc0172f5b8f0e 2022-04-18 19:45:54,794 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {get_state_group_delta-ce} 0.000727 sec @40000000625dc0172f5c9c50 2022-04-18 19:45:54,794 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {get_state_group_delta-ce} SELECT type, state_key, event_id FROM state_groups_state WHERE state_group = ? @40000000625dc0172f5d10e7 2022-04-18 19:45:54,794 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {get_state_group_delta-ce} [351659] @40000000625dc0172f65131d 2022-04-18 19:45:54,795 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {get_state_group_delta-ce} 0.000491 sec @40000000625dc0172f66fcb6 2022-04-18 19:45:54,795 - synapse.storage.txn - 717 - DEBUG - GET-22 - [TXN END] {get_state_group_delta-ce} 0.001688 sec @40000000625dc0172f6bedce 2022-04-18 19:45:54,795 - synapse.util.metrics - 165 - DEBUG - GET-22 - Exiting block resolve_state_groups_for_events @40000000625dc0172f6eea93 2022-04-18 19:45:54,795 - synapse.state - 178 - DEBUG - GET-22 - calling resolve_state_groups from get_current_state @40000000625dc0172f6fc3c8 2022-04-18 19:45:54,795 - synapse.util.metrics - 152 - DEBUG - GET-22 - Entering block resolve_state_groups_for_events @40000000625dc0172f704b45 2022-04-18 19:45:54,795 - synapse.state - 419 - DEBUG - GET-22 - resolve_state_groups event_ids ['$K4WAiSNwhIOG0LhSXipzpewnNq26l1ICiUzRy3mi4ho'] @40000000625dc0172f730b4d 2022-04-18 19:45:54,796 - synapse.util.metrics - 165 - DEBUG - GET-22 - Exiting block resolve_state_groups_for_events @40000000625dc0172f77248d 2022-04-18 19:45:54,796 - synapse.storage.databases.main.events_worker - 1104 - DEBUG - GET-22 - Loading 1 events: {'$52BjNBDKWoeQ3Otj-om1j5ZVOqU9d3bLy30qe5MKOJE'} @40000000625dc0172f9e2d4e 2022-04-18 19:45:54,798 - synapse.storage.databases.main.events_worker - 1107 - DEBUG - GET-22 - Loaded 1 events (1 rows) @40000000625dc0172fa35c82 2022-04-18 19:45:54,799 - synapse.storage.txn - 614 - DEBUG - GET-22 - [TXN START] {get_current_topological_token-d0} @40000000625dc0172fa40b22 2022-04-18 19:45:54,799 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {get_current_topological_token-d0} SELECT coalesce(MIN(topological_ordering), 0) FROM events WHERE room_id = ? AND stream_ordering >= ? @40000000625dc0172fa48a36 2022-04-18 19:45:54,799 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {get_current_topological_token-d0} ('!WgEsWTOEGkIcwYphxi:maunium.net', 2787474) @40000000625dc0172fb18c6d 2022-04-18 19:45:54,800 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {get_current_topological_token-d0} 0.000765 sec @40000000625dc0172fb3a99b 2022-04-18 19:45:54,800 - synapse.storage.txn - 717 - DEBUG - GET-22 - [TXN END] {get_current_topological_token-d0} 0.001073 sec @40000000625dc0172fb8e16b 2022-04-18 19:45:54,800 - synapse.util.async_helpers - 407 - DEBUG - GET-22 - Acquired uncontended linearizer lock 'room_backfill' for key '!WgEsWTOEGkIcwYphxi:maunium.net' @40000000625dc0172fbc2524 2022-04-18 19:45:54,800 - synapse.storage.txn - 614 - DEBUG - GET-22 - [TXN START] {get_oldest_event_ids_with_depth_in_room-d1} @40000000625dc0172fbd4dd6 2022-04-18 19:45:54,800 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {get_oldest_event_ids_with_depth_in_room-d1} SELECT b.event_id, MAX(e.depth) FROM events as e /** * Get the edge connections from the event_edges table * so we can see whether this event's prev_events points * to a backward extremity in the next join. */ INNER JOIN event_edges as g ON g.event_id = e.event_id /** * We find the "oldest" events in the room by looking for * events connected to backwards extremeties (oldest events * in the room that we know of so far). */ INNER JOIN event_backward_extremities as b ON g.prev_event_id = b.event_id WHERE b.room_id = ? AND g.is_state is ? GROUP BY b.event_id @40000000625dc0172fbde949 2022-04-18 19:45:54,800 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {get_oldest_event_ids_with_depth_in_room-d1} ('!WgEsWTOEGkIcwYphxi:maunium.net', False) @40000000625dc0172fdbfdd9 2022-04-18 19:45:54,802 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {get_oldest_event_ids_with_depth_in_room-d1} 0.001933 sec @40000000625dc0172fdda22c 2022-04-18 19:45:54,803 - synapse.storage.txn - 717 - DEBUG - GET-22 - [TXN END] {get_oldest_event_ids_with_depth_in_room-d1} 0.002209 sec @40000000625dc0172fe4dd4c 2022-04-18 19:45:54,803 - synapse.storage.txn - 614 - DEBUG - GET-22 - [TXN START] {get_insertion_event_backward_extremities_in_room-d2} @40000000625dc0172fe63255 2022-04-18 19:45:54,803 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {get_insertion_event_backward_extremities_in_room-d2} SELECT b.event_id, MAX(e.depth) FROM insertion_events as i /* We only want insertion events that are also marked as backwards extremities */ INNER JOIN insertion_event_extremities as b USING (event_id) /* Get the depth of the insertion event from the events table */ INNER JOIN events AS e USING (event_id) WHERE b.room_id = ? GROUP BY b.event_id @40000000625dc0172fe6e8bf 2022-04-18 19:45:54,803 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {get_insertion_event_backward_extremities_in_room-d2} ('!WgEsWTOEGkIcwYphxi:maunium.net',) @40000000625dc0172ff81732 2022-04-18 19:45:54,804 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {get_insertion_event_backward_extremities_in_room-d2} 0.001083 sec @40000000625dc0172ff9aed8 2022-04-18 19:45:54,804 - synapse.storage.txn - 717 - DEBUG - GET-22 - [TXN END] {get_insertion_event_backward_extremities_in_room-d2} 0.001433 sec @40000000625dc0172ffe417f 2022-04-18 19:45:54,805 - synapse.handlers.federation - 171 - DEBUG - GET-22 - _maybe_backfill_inner: extremities oldest_events_with_depth={'$URkPMCBQD9mbfkCxPi6u8KuzgeIDMTfPTm5dxK2xcxg': 18310, '$KAl3fHFZWLRFY7hOBydg0Ip0JG3UH5nIUegLF-YRiCI': 6399, '$rTqJ12jXLA4PRiG2D2eIDM5JmEx1dg-Yp8RX-eDBYe8': 44920, '$xPZsjOJeagFkznBJHVVQazquO3vUxdlCXebpRLx7lWI': 18221, '$LZ5CCqv1eskPsU17lnmYmStZ-3Xme7J8Ei65pQojsa8': 2079, '$HK9li69JmQ4aBgR8WkihY1t3-mqyxXjW7eg4geTJv2E': 11143, '$nvcX87N155Fm8VIPKYiG5FPuR26O8O5uHJgHQ9IAysE': 10017, '$hkzBjY9ZGdWkGJOc0-FMuKlz_wjewq59FWUkoLxjUw0': 10371, '$jHVbbpBjsh2tQm2row2-Op2-QzMQpGcML06aqQinvHU': 10343, '$C1AR1-8ZqR88dzFh9e10OP6dimwV5p1Kte2b6Ooe6yQ': 10834, '$kEan4U6ZWXXnF2xz_T2x6vS69_hzGLY58Iz9rMY6zFw': 8548, '$2vzoitDD8w9gjfn1ra7z99wJ1Ax8obvuGW3ArSsTwHg': 12847, '$6nrHqe4-__0mqAeL-BllD6wMraLmvSirZ7OTeSKskXk': 10371, '$Pnr6U0i7BGcttZKs8yKdEL8jEBS1GXgFEY12EbbaYC4': 10406, '$ojdlOaYw67ioTg8wo3X06dATJU6WfKkTxHkaiZkvXfU': 10371, '$ItUseJty28KtJug3BVoaaBWlK55Ej4ujpEUPuxvDKwk': 24632, '$gy8rtbIZVBi7B86m6nVkA07uUTy2UDJERz9IKnfLgtM': 10229, '$7dJVn-v76UU_-ACiZEHUli58XlJSSONr-IZNqBSJh2U': 10232, '$CbXbdFOMf3lyMlBA4KNXSArJuGoaLOknzs_ZmQbMADM': 10371, '$dKKF3rDYKU8gKw4m_g_q1mD_eeshKlfPUtM6vRt5iis': 8554, '$s0wHtvYv3A3vaHj5EJixMSf8C2xhT1BUgSU9IQk0zMI': 18224, '$nsltwb79D-tKat2O5JQPclsjj96JYbLRFsmwXJcEY90': 7781, '$lSuXGthTJ9RYetKVyxMY2URi2A9d8-YdLdtBKwNEHX8': 6494, '$33yzFvHBEwsz1EXmin43o1OFkLRhqdWM0GLBbEl16UA': 10044, '$Uqwa3Yr3G84a0W81Uv4PZn7ht6WjwrwHJ1UYzaOa4WI': 10371, '$E_EtTta_3yYmarlMRNuzIFdMZWNd5-W6JAj6hC8b2F8': 2175, '$tJWZOk2uqHHi8oHYS-OKo5IsbS_9OVqzDhlxn--Swi4': 18240} insertion_events_to_be_backfilled={} @40000000625dc0173001cbdd 2022-04-18 19:45:54,805 - synapse.storage.txn - 614 - DEBUG - GET-22 - [TXN START] {get_successor_events-d3} @40000000625dc017300291db 2022-04-18 19:45:54,805 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {get_successor_events-d3} SELECT event_id FROM event_edges WHERE prev_event_id = ANY(?) @40000000625dc01730037e47 2022-04-18 19:45:54,805 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {get_successor_events-d3} [['$URkPMCBQD9mbfkCxPi6u8KuzgeIDMTfPTm5dxK2xcxg', '$KAl3fHFZWLRFY7hOBydg0Ip0JG3UH5nIUegLF-YRiCI', '$rTqJ12jXLA4PRiG2D2eIDM5JmEx1dg-Yp8RX-eDBYe8', '$xPZsjOJeagFkznBJHVVQazquO3vUxdlCXebpRLx7lWI', '$LZ5CCqv1eskPsU17lnmYmStZ-3Xme7J8Ei65pQojsa8', '$HK9li69JmQ4aBgR8WkihY1t3-mqyxXjW7eg4geTJv2E', '$nvcX87N155Fm8VIPKYiG5FPuR26O8O5uHJgHQ9IAysE', '$hkzBjY9ZGdWkGJOc0-FMuKlz_wjewq59FWUkoLxjUw0', '$jHVbbpBjsh2tQm2row2-Op2-QzMQpGcML06aqQinvHU', '$C1AR1-8ZqR88dzFh9e10OP6dimwV5p1Kte2b6Ooe6yQ', '$kEan4U6ZWXXnF2xz_T2x6vS69_hzGLY58Iz9rMY6zFw', '$2vzoitDD8w9gjfn1ra7z99wJ1Ax8obvuGW3ArSsTwHg', '$6nrHqe4-__0mqAeL-BllD6wMraLmvSirZ7OTeSKskXk', '$Pnr6U0i7BGcttZKs8yKdEL8jEBS1GXgFEY12EbbaYC4', '$ojdlOaYw67ioTg8wo3X06dATJU6WfKkTxHkaiZkvXfU', '$ItUseJty28KtJug3BVoaaBWlK55Ej4ujpEUPuxvDKwk', '$gy8rtbIZVBi7B86m6nVkA07uUTy2UDJERz9IKnfLgtM', '$7dJVn-v76UU_-ACiZEHUli58XlJSSONr-IZNqBSJh2U', '$CbXbdFOMf3lyMlBA4KNXSArJuGoaLOknzs_ZmQbMADM', '$dKKF3rDYKU8gKw4m_g_q1mD_eeshKlfPUtM6vRt5iis', '$s0wHtvYv3A3vaHj5EJixMSf8C2xhT1BUgSU9IQk0zMI', '$nsltwb79D-tKat2O5JQPclsjj96JYbLRFsmwXJcEY90', '$lSuXGthTJ9RYetKVyxMY2URi2A9d8-YdLdtBKwNEHX8', '$33yzFvHBEwsz1EXmin43o1OFkLRhqdWM0GLBbEl16UA', '$Uqwa3Yr3G84a0W81Uv4PZn7ht6WjwrwHJ1UYzaOa4WI', '$E_EtTta_3yYmarlMRNuzIFdMZWNd5-W6JAj6hC8b2F8', '$tJWZOk2uqHHi8oHYS-OKo5IsbS_9OVqzDhlxn--Swi4']] @40000000625dc0173014e7dc 2022-04-18 19:45:54,806 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {get_successor_events-d3} 0.001089 sec @40000000625dc01730164329 2022-04-18 19:45:54,806 - synapse.storage.txn - 717 - DEBUG - GET-22 - [TXN END] {get_successor_events-d3} 0.001363 sec @40000000625dc017301f5abb 2022-04-18 19:45:54,807 - synapse.storage.databases.main.events_worker - 1104 - DEBUG - GET-22 - Loading 24 events: {'$JrHrhEkJQNhMw6DkHBVfSd-jhzpY6YOgUHkC0PpIBcA', '$c36FdM4ygifUOhi3gSqOvOc4iHi7Vt3q_nu9RuMBU_k', '$rxKxk25S1MardckAvvX2AjzUd3liLuxKlU6rw5TMikM', '$B81H3RUg8syMfNqZQEXZSPXt4kF1lE_LyUikMAjvkEA', '$OlIHZUgA-0IV4nSAeeRn9zvd4Xie45cTUa0LTIZq3qQ', '$HFw8m60seNH_WSQDz2Cj6dAk-emkjygbqX6mL3jm1cc', '$YEBB0-429qHgq2O3sgm5kw0WznlP-iQj3Pp2nVuc-Wg', '$FVkPFSjnH06PavGH8xZYg_y5FJ9Ox2JMfJulj8MsG2Q', '$xcyDnCe75B_Iy6C5gZ4y3jrw7qRe2UtBYo-bYWpruyA', '$nL0wjdq6XJH7GWCW1tvfoeRfprAyL5U6ExyAkRBd9uA', '$2jGWAwaTzPV_VuUdmQaQj2--86C_EUo-wXvFGJMYG7M', '$WCp-2SLEL745gxtHB8jsn-fCHqjHBYULREsEOTS4q0Q', '$pUS3gobBSp_KlovIQf9lTOQudvv1M1smAtENd_RB1oM', '$VxMyCymG1wMpiM482RdZ6yu86kUuXIyEA_AQpF6gr6A', '$h81RjxVIH6F7PNF2-0PUV_j7ZGO9fqbrJiy1MeK4oe0', '$BKkDC5m6IOYPlxtr7VGdDnoqRNC0B7LojS2UW9G7wKw', '$CAh6F8A-2z3-b5ZX0e6IfD5_ERDfH7c5C_4pjN-gxZQ', '$ABi7lIbN8uYNfGdnvQl3hA9-yCHCdKDjFT6yBSPXGNE', '$c2o1hyzyHkrwf-sXX_FdnYxOvS1ixbyrR8OyClLj5r0', '$PB8dVVVtQJ_PzZRWLIBD8XNuUEWcdPx30JYbm84i_2Y', '$cOnlC5HQ77Jm6xlg1_YTD4Y3DVoeN2R0y2H3NneJa5c', '$inNIm2nxjlHvYs37rT3dnKOgTVMSYbyhItftzw_lt-M', '$fX3Z_9BbmBLulBD79U5TtzwqLMZLue8kGifPt4_72DY', '$wgBif5XzXMh1pih5CUPRoFGoWY5V5mWwibbDUBr9bok'} @40000000625dc01730469f8f 2022-04-18 19:45:54,809 - synapse.storage.databases.main.events_worker - 1107 - DEBUG - GET-22 - Loaded 24 events (24 rows) @40000000625dc017305a7163 2022-04-18 19:45:54,811 - synapse.storage.databases.main.events_worker - 1104 - DEBUG - GET-22 - Loading 1 events: {'$NKbs-ITMxMxxmzUNfuhVcXdYDI2dZ_KtaXtixmtzqSI'} @40000000625dc0173083f717 2022-04-18 19:45:54,813 - synapse.storage.databases.main.events_worker - 1107 - DEBUG - GET-22 - Loaded 1 events (1 rows) @40000000625dc01730863e61 2022-04-18 19:45:54,813 - synapse.storage.databases.main.events_worker - 965 - DEBUG - GET-22 - Also fetching redaction events {'$PB8dVVVtQJ_PzZRWLIBD8XNuUEWcdPx30JYbm84i_2Y'} @40000000625dc01730873812 2022-04-18 19:45:54,814 - synapse.storage.databases.main.events_worker - 1104 - DEBUG - GET-22 - Loading 1 events: {'$PB8dVVVtQJ_PzZRWLIBD8XNuUEWcdPx30JYbm84i_2Y'} @40000000625dc017309aa8ff 2022-04-18 19:45:54,815 - synapse.storage.databases.main.events_worker - 1107 - DEBUG - GET-22 - Loaded 1 events (1 rows) @40000000625dc017309e364c 2022-04-18 19:45:54,815 - synapse.storage.databases.main.events_worker - 1237 - DEBUG - GET-22 - Redacting $NKbs-ITMxMxxmzUNfuhVcXdYDI2dZ_KtaXtixmtzqSI due to $PB8dVVVtQJ_PzZRWLIBD8XNuUEWcdPx30JYbm84i_2Y @40000000625dc01730c246d3 2022-04-18 19:45:54,817 - synapse.storage.txn - 614 - DEBUG - GET-22 - [TXN START] {_get_state_group_for_events-d7} @40000000625dc01730c34e5e 2022-04-18 19:45:54,818 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_group_for_events-d7} SELECT event_id, state_group FROM event_to_state_groups WHERE event_id = ANY(?) @40000000625dc01730c438f4 2022-04-18 19:45:54,818 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_group_for_events-d7} [['$JrHrhEkJQNhMw6DkHBVfSd-jhzpY6YOgUHkC0PpIBcA', '$c36FdM4ygifUOhi3gSqOvOc4iHi7Vt3q_nu9RuMBU_k', '$rxKxk25S1MardckAvvX2AjzUd3liLuxKlU6rw5TMikM', '$B81H3RUg8syMfNqZQEXZSPXt4kF1lE_LyUikMAjvkEA', '$OlIHZUgA-0IV4nSAeeRn9zvd4Xie45cTUa0LTIZq3qQ', '$HFw8m60seNH_WSQDz2Cj6dAk-emkjygbqX6mL3jm1cc', '$YEBB0-429qHgq2O3sgm5kw0WznlP-iQj3Pp2nVuc-Wg', '$FVkPFSjnH06PavGH8xZYg_y5FJ9Ox2JMfJulj8MsG2Q', '$xcyDnCe75B_Iy6C5gZ4y3jrw7qRe2UtBYo-bYWpruyA', '$2jGWAwaTzPV_VuUdmQaQj2--86C_EUo-wXvFGJMYG7M', '$WCp-2SLEL745gxtHB8jsn-fCHqjHBYULREsEOTS4q0Q', '$pUS3gobBSp_KlovIQf9lTOQudvv1M1smAtENd_RB1oM', '$VxMyCymG1wMpiM482RdZ6yu86kUuXIyEA_AQpF6gr6A', '$h81RjxVIH6F7PNF2-0PUV_j7ZGO9fqbrJiy1MeK4oe0', '$BKkDC5m6IOYPlxtr7VGdDnoqRNC0B7LojS2UW9G7wKw', '$CAh6F8A-2z3-b5ZX0e6IfD5_ERDfH7c5C_4pjN-gxZQ', '$ABi7lIbN8uYNfGdnvQl3hA9-yCHCdKDjFT6yBSPXGNE', '$c2o1hyzyHkrwf-sXX_FdnYxOvS1ixbyrR8OyClLj5r0', '$PB8dVVVtQJ_PzZRWLIBD8XNuUEWcdPx30JYbm84i_2Y', '$cOnlC5HQ77Jm6xlg1_YTD4Y3DVoeN2R0y2H3NneJa5c', '$inNIm2nxjlHvYs37rT3dnKOgTVMSYbyhItftzw_lt-M', '$fX3Z_9BbmBLulBD79U5TtzwqLMZLue8kGifPt4_72DY', '$wgBif5XzXMh1pih5CUPRoFGoWY5V5mWwibbDUBr9bok']] @40000000625dc01730d2a70f 2022-04-18 19:45:54,819 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_group_for_events-d7} 0.000894 sec @40000000625dc01730d4036a 2022-04-18 19:45:54,819 - synapse.storage.txn - 717 - DEBUG - GET-22 - [TXN END] {_get_state_group_for_events-d7} 0.001203 sec @40000000625dc01730e75100 2022-04-18 19:45:54,820 - synapse.storage.txn - 614 - DEBUG - GET-22 - [TXN START] {_get_state_groups_from_groups-d8} @40000000625dc01730e87bc4 2022-04-18 19:45:54,820 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} SET LOCAL enable_seqscan=off @40000000625dc01730ea11f7 2022-04-18 19:45:54,820 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000064 sec @40000000625dc01730eb25eb 2022-04-18 19:45:54,820 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc01730ebb22f 2022-04-18 19:45:54,820 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [40718, 'm.room.history_visibility', ''] @40000000625dc01730fcc854 2022-04-18 19:45:54,821 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.001073 sec @40000000625dc01730fde2c7 2022-04-18 19:45:54,821 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc01730fe5bfc 2022-04-18 19:45:54,821 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [25362, 'm.room.history_visibility', ''] @40000000625dc017310617b5 2022-04-18 19:45:54,822 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000470 sec @40000000625dc01731070287 2022-04-18 19:45:54,822 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc01731077ab8 2022-04-18 19:45:54,822 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [31063, 'm.room.history_visibility', ''] @40000000625dc017310d66a3 2022-04-18 19:45:54,822 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000351 sec @40000000625dc017310e4bc8 2022-04-18 19:45:54,822 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc017310ec33a 2022-04-18 19:45:54,823 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [28313, 'm.room.history_visibility', ''] @40000000625dc01731146016 2022-04-18 19:45:54,823 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000332 sec @40000000625dc017311542ce 2022-04-18 19:45:54,823 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc0173115c08d 2022-04-18 19:45:54,823 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [28314, 'm.room.history_visibility', ''] @40000000625dc017311afa98 2022-04-18 19:45:54,823 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000303 sec @40000000625dc017311bdfc7 2022-04-18 19:45:54,823 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc017311c5afb 2022-04-18 19:45:54,823 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [28318, 'm.room.history_visibility', ''] @40000000625dc0173121af7a 2022-04-18 19:45:54,824 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000313 sec @40000000625dc01731228ec0 2022-04-18 19:45:54,824 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc01731230614 2022-04-18 19:45:54,824 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [28319, 'm.room.history_visibility', ''] @40000000625dc01731282d2e 2022-04-18 19:45:54,824 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000296 sec @40000000625dc017312912a3 2022-04-18 19:45:54,824 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc01731299a03 2022-04-18 19:45:54,824 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [351521, 'm.room.history_visibility', ''] @40000000625dc0173141df93 2022-04-18 19:45:54,826 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.001523 sec @40000000625dc01731430325 2022-04-18 19:45:54,826 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc01731438419 2022-04-18 19:45:54,826 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [30372, 'm.room.history_visibility', ''] @40000000625dc0173149342d 2022-04-18 19:45:54,826 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000335 sec @40000000625dc017314a211c 2022-04-18 19:45:54,826 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc017314a9b4b 2022-04-18 19:45:54,826 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [30373, 'm.room.history_visibility', ''] @40000000625dc017314f78f9 2022-04-18 19:45:54,827 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000280 sec @40000000625dc017315059b2 2022-04-18 19:45:54,827 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc0173150eb71 2022-04-18 19:45:54,827 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [27496, 'm.room.history_visibility', ''] @40000000625dc017315594a3 2022-04-18 19:45:54,827 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000266 sec @40000000625dc01731568029 2022-04-18 19:45:54,827 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc0173156e8b2 2022-04-18 19:45:54,827 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [28201, 'm.room.history_visibility', ''] @40000000625dc017315bd72a 2022-04-18 19:45:54,828 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000288 sec @40000000625dc017315ca51a 2022-04-18 19:45:54,828 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc017315d0d7b 2022-04-18 19:45:54,828 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [28202, 'm.room.history_visibility', ''] @40000000625dc0173161efdb 2022-04-18 19:45:54,828 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000283 sec @40000000625dc0173162c10a 2022-04-18 19:45:54,828 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc01731632744 2022-04-18 19:45:54,828 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [28400, 'm.room.history_visibility', ''] @40000000625dc01731689869 2022-04-18 19:45:54,828 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000322 sec @40000000625dc01731696c60 2022-04-18 19:45:54,828 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc0173169d3a8 2022-04-18 19:45:54,828 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [30449, 'm.room.history_visibility', ''] @40000000625dc017316ec592 2022-04-18 19:45:54,829 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000287 sec @40000000625dc017316f9d91 2022-04-18 19:45:54,829 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc01731700714 2022-04-18 19:45:54,829 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [29426, 'm.room.history_visibility', ''] @40000000625dc0173174cb5b 2022-04-18 19:45:54,829 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000274 sec @40000000625dc0173175afa4 2022-04-18 19:45:54,829 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc01731761501 2022-04-18 19:45:54,829 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [30450, 'm.room.history_visibility', ''] @40000000625dc017317afb4b 2022-04-18 19:45:54,830 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000287 sec @40000000625dc017317bc7b4 2022-04-18 19:45:54,830 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc017317c2f1a 2022-04-18 19:45:54,830 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [29427, 'm.room.history_visibility', ''] @40000000625dc0173180c67e 2022-04-18 19:45:54,830 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000267 sec @40000000625dc017318191b1 2022-04-18 19:45:54,830 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc0173181f84f 2022-04-18 19:45:54,830 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [29429, 'm.room.history_visibility', ''] @40000000625dc01731873675 2022-04-18 19:45:54,830 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000296 sec @40000000625dc017318820d9 2022-04-18 19:45:54,830 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc017318889bc 2022-04-18 19:45:54,831 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [29428, 'm.room.history_visibility', ''] @40000000625dc017318d60cc 2022-04-18 19:45:54,831 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000279 sec @40000000625dc017318e35f0 2022-04-18 19:45:54,831 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc017318e9db0 2022-04-18 19:45:54,831 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [28151, 'm.room.history_visibility', ''] @40000000625dc017319383c8 2022-04-18 19:45:54,831 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000286 sec @40000000625dc01731946929 2022-04-18 19:45:54,831 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc0173194dc7f 2022-04-18 19:45:54,831 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [28152, 'm.room.history_visibility', ''] @40000000625dc017319a8556 2022-04-18 19:45:54,832 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000324 sec @40000000625dc017319b812e 2022-04-18 19:45:54,832 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {_get_state_groups_from_groups-d8} WITH RECURSIVE state(state_group) AS ( VALUES(?::bigint) UNION ALL SELECT prev_state_group FROM state_group_edges e, state s WHERE s.state_group = e.state_group ) SELECT DISTINCT ON (type, state_key) type, state_key, event_id FROM state_groups_state WHERE state_group IN ( SELECT state_group FROM state ) AND ((type = ? AND state_key = ?)) ORDER BY type, state_key, state_group DESC @40000000625dc017319bea7f 2022-04-18 19:45:54,832 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {_get_state_groups_from_groups-d8} [28153, 'm.room.history_visibility', ''] @40000000625dc01731a0f8be 2022-04-18 19:45:54,832 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {_get_state_groups_from_groups-d8} 0.000296 sec @40000000625dc01731a2cd86 2022-04-18 19:45:54,832 - synapse.storage.txn - 717 - DEBUG - GET-22 - [TXN END] {_get_state_groups_from_groups-d8} 0.012287 sec @40000000625dc01731bb4c76 2022-04-18 19:45:54,834 - synapse.handlers.federation - 226 - DEBUG - GET-22 - _maybe_backfill_inner: filtered_extremities [, , , , , , , , , , , , , , , , , , , , , , , ] @40000000625dc01731bd58d0 2022-04-18 19:45:54,834 - synapse.handlers.federation - 272 - DEBUG - GET-22 - room_id: !WgEsWTOEGkIcwYphxi:maunium.net, backfill: current_depth: 45103, limit: 92, max_depth: 44920, extrems (27): [('$rTqJ12jXLA4PRiG2D2eIDM5JmEx1dg-Yp8RX-eDBYe8', 44920), ('$ItUseJty28KtJug3BVoaaBWlK55Ej4ujpEUPuxvDKwk', 24632), ('$URkPMCBQD9mbfkCxPi6u8KuzgeIDMTfPTm5dxK2xcxg', 18310), ('$tJWZOk2uqHHi8oHYS-OKo5IsbS_9OVqzDhlxn--Swi4', 18240), ('$s0wHtvYv3A3vaHj5EJixMSf8C2xhT1BUgSU9IQk0zMI', 18224), ('$xPZsjOJeagFkznBJHVVQazquO3vUxdlCXebpRLx7lWI', 18221), ('$2vzoitDD8w9gjfn1ra7z99wJ1Ax8obvuGW3ArSsTwHg', 12847), ('$HK9li69JmQ4aBgR8WkihY1t3-mqyxXjW7eg4geTJv2E', 11143), ('$C1AR1-8ZqR88dzFh9e10OP6dimwV5p1Kte2b6Ooe6yQ', 10834), ('$Pnr6U0i7BGcttZKs8yKdEL8jEBS1GXgFEY12EbbaYC4', 10406), ('$hkzBjY9ZGdWkGJOc0-FMuKlz_wjewq59FWUkoLxjUw0', 10371), ('$6nrHqe4-__0mqAeL-BllD6wMraLmvSirZ7OTeSKskXk', 10371), ('$ojdlOaYw67ioTg8wo3X06dATJU6WfKkTxHkaiZkvXfU', 10371), ('$CbXbdFOMf3lyMlBA4KNXSArJuGoaLOknzs_ZmQbMADM', 10371), ('$Uqwa3Yr3G84a0W81Uv4PZn7ht6WjwrwHJ1UYzaOa4WI', 10371), ('$jHVbbpBjsh2tQm2row2-Op2-QzMQpGcML06aqQinvHU', 10343), ('$7dJVn-v76UU_-ACiZEHUli58XlJSSONr-IZNqBSJh2U', 10232), ('$gy8rtbIZVBi7B86m6nVkA07uUTy2UDJERz9IKnfLgtM', 10229), ('$33yzFvHBEwsz1EXmin43o1OFkLRhqdWM0GLBbEl16UA', 10044), ('$nvcX87N155Fm8VIPKYiG5FPuR26O8O5uHJgHQ9IAysE', 10017), ('$dKKF3rDYKU8gKw4m_g_q1mD_eeshKlfPUtM6vRt5iis', 8554), ('$kEan4U6ZWXXnF2xz_T2x6vS69_hzGLY58Iz9rMY6zFw', 8548), ('$nsltwb79D-tKat2O5JQPclsjj96JYbLRFsmwXJcEY90', 7781), ('$lSuXGthTJ9RYetKVyxMY2URi2A9d8-YdLdtBKwNEHX8', 6494), ('$KAl3fHFZWLRFY7hOBydg0Ip0JG3UH5nIUegLF-YRiCI', 6399), ('$E_EtTta_3yYmarlMRNuzIFdMZWNd5-W6JAj6hC8b2F8', 2175), ('$LZ5CCqv1eskPsU17lnmYmStZ-3Xme7J8Ei65pQojsa8', 2079)] filtered_sorted_extremeties_tuple: [('$rTqJ12jXLA4PRiG2D2eIDM5JmEx1dg-Yp8RX-eDBYe8', 44920), ('$ItUseJty28KtJug3BVoaaBWlK55Ej4ujpEUPuxvDKwk', 24632), ('$URkPMCBQD9mbfkCxPi6u8KuzgeIDMTfPTm5dxK2xcxg', 18310), ('$tJWZOk2uqHHi8oHYS-OKo5IsbS_9OVqzDhlxn--Swi4', 18240), ('$s0wHtvYv3A3vaHj5EJixMSf8C2xhT1BUgSU9IQk0zMI', 18224), ('$xPZsjOJeagFkznBJHVVQazquO3vUxdlCXebpRLx7lWI', 18221), ('$2vzoitDD8w9gjfn1ra7z99wJ1Ax8obvuGW3ArSsTwHg', 12847), ('$HK9li69JmQ4aBgR8WkihY1t3-mqyxXjW7eg4geTJv2E', 11143), ('$C1AR1-8ZqR88dzFh9e10OP6dimwV5p1Kte2b6Ooe6yQ', 10834), ('$Pnr6U0i7BGcttZKs8yKdEL8jEBS1GXgFEY12EbbaYC4', 10406), ('$hkzBjY9ZGdWkGJOc0-FMuKlz_wjewq59FWUkoLxjUw0', 10371), ('$6nrHqe4-__0mqAeL-BllD6wMraLmvSirZ7OTeSKskXk', 10371), ('$ojdlOaYw67ioTg8wo3X06dATJU6WfKkTxHkaiZkvXfU', 10371), ('$CbXbdFOMf3lyMlBA4KNXSArJuGoaLOknzs_ZmQbMADM', 10371), ('$Uqwa3Yr3G84a0W81Uv4PZn7ht6WjwrwHJ1UYzaOa4WI', 10371), ('$jHVbbpBjsh2tQm2row2-Op2-QzMQpGcML06aqQinvHU', 10343), ('$7dJVn-v76UU_-ACiZEHUli58XlJSSONr-IZNqBSJh2U', 10232), ('$gy8rtbIZVBi7B86m6nVkA07uUTy2UDJERz9IKnfLgtM', 10229), ('$33yzFvHBEwsz1EXmin43o1OFkLRhqdWM0GLBbEl16UA', 10044), ('$nvcX87N155Fm8VIPKYiG5FPuR26O8O5uHJgHQ9IAysE', 10017), ('$dKKF3rDYKU8gKw4m_g_q1mD_eeshKlfPUtM6vRt5iis', 8554), ('$kEan4U6ZWXXnF2xz_T2x6vS69_hzGLY58Iz9rMY6zFw', 8548), ('$nsltwb79D-tKat2O5JQPclsjj96JYbLRFsmwXJcEY90', 7781), ('$lSuXGthTJ9RYetKVyxMY2URi2A9d8-YdLdtBKwNEHX8', 6494), ('$KAl3fHFZWLRFY7hOBydg0Ip0JG3UH5nIUegLF-YRiCI', 6399), ('$E_EtTta_3yYmarlMRNuzIFdMZWNd5-W6JAj6hC8b2F8', 2175), ('$LZ5CCqv1eskPsU17lnmYmStZ-3Xme7J8Ei65pQojsa8', 2079)] @40000000625dc01731bea262 2022-04-18 19:45:54,834 - synapse.state - 178 - DEBUG - GET-22 - calling resolve_state_groups from get_current_state @40000000625dc01731bfbdd9 2022-04-18 19:45:54,834 - synapse.util.metrics - 152 - DEBUG - GET-22 - Entering block resolve_state_groups_for_events @40000000625dc01731c07064 2022-04-18 19:45:54,834 - synapse.state - 419 - DEBUG - GET-22 - resolve_state_groups event_ids ['$K4WAiSNwhIOG0LhSXipzpewnNq26l1ICiUzRy3mi4ho'] @40000000625dc01731c4338b 2022-04-18 19:45:54,834 - synapse.util.metrics - 165 - DEBUG - GET-22 - Exiting block resolve_state_groups_for_events @40000000625dc01731ccb068 2022-04-18 19:45:54,835 - synapse.storage.databases.main.events_worker - 1104 - DEBUG - GET-22 - Loading 116 events: {'$_RKL--OPauLtaC0i4Wl-P_Mcr6vrj48p_S90do_rus4', '$LMaGNUZ2dvbHqv53paNUktI8hguiZ_RW2nU5FSeBBVA', '$TgeIBWrqTtQTdgKw9a4guxoVTLypJjOTDNu1y4FJYUg', '$VWz3-hziAB3t4xySS6N4XtQPavOJ5LFTuZqxZ08hQSc', '$v0EFS8IhvYhF8UfSR5vl-Xn5n3dMycKkXP61Dq27OUY', '$7ssH5fQ5RtKjCdtFm1tCS50S3CHFzpbIvODtZcRd1Xc', '$WqUmsc2_17dFLtXS-lXAzksuS8zSY-8PQRT3qFBX--A', '$dIn8iZBYBA5JTx-cURflVYPodrbhnS4XkMLus7wfVUc', '$B1FzYWhYFRXeBhHIMeMHJ7yOS4NMsGKzxy1sBFT-J5Y', '$oe3JsreXd8Rtk2e2-gNDifkEAKRRyHqef0U9HJ5fHS4', '$BwHcfls29rrM3_neRhIf532f3U5Ce-mK5Se5_w7Hvxk', '$de1ZQ0H3JOkqrKJG4Y5leu_BHARtw7K0C7wpYeUPjmc', '$cOVa9RGP43yvZ0C1tbtQpIRIgGnTpby8UaM8h8SgHeM', '$tgqM0CSVpP89uxAM0_trI98NklIBA9UFPMAca8OUoQc', '$KWSkQ53j5LyopK8oFq14MLTFGCSSX4a-eD0QBR0v8mo', '$oHEupTr5QecDFXjwrO5JswG47nBT64J8pm8VSbZdRpQ', '$RO9ChaGrYEEViXhxhl4dlBNpmEunnTcGp7mrGomXL1I', '$pR0iB_-Il0YSY_llY-MtnfEZLl4jYJGi7vOwrchPK4s', '$EMUPlOQFxRpDQtD1OEAVGPNQ_rBvlbxO9I24qIz867U', '$N5yE56GnfTdH71iOYxeX0EwWYYkGMQrnmsbU2W__67Y', '$yiuz_w0gazdHQOaciu_N9R5mfUTqDSgkKWL9EWKL2dM', '$x4Aa9XZJWTXA2jWTBYppRM41zPS7QR0RmrMdtAhqSKo', '$89uQY7F-mqDIf22zvmhSJcfOSQD2QrdPNAAaXfQkOhE', '$NawNfYWBwOETZ9-B7W6DtiVdApJCcKngsA9TUhqpYTQ', '$Qn6QStj7yE2YCDdpZh3wnxlKPOrmgAS7ZfzVTiuB4Ps', '$O6Dd29F3-5czuES2kT-3yFUVnYMvuVL71jfPU2n6syw', '$m-Srx0yADN9tUNn12FpJF-Q6vuanOC8SWT6H8HEDPNk', '$pmizKDiiyUyLaVNEk0r_zH8bEULZjrmfJkyYCkjfqjQ', '$d-VbetN2sCUSsMOkoK8-TVecdcVzVxPGSfBUT530Fj4', '$ncYvhbqoNEIYGBcPMj5WTlwsip89kpjkELISpwUJUzk', '$DU2dSDRdFqh2xGepO3LlPjWvrsNv2auo7QMRJtYjDHk', '$FkntIbN6HPknZ-sZmjCw-BFJRh5ZPzZZH_Gp-TJq9yk', '$hkMZKT16s8JiacWDP0ZQpd7ozHg7POAJHOqpUmNDfY8', '$uNSlUCjFcFo06ZJSmQCbf0bIVZtX8V2fHKDCJxCv2fo', '$7UEA3srT9M7OIXUwGnD7VnFkmCqeunamiWeXOVMEAxk', '$tZvsmhtacfv_4LHQyplok7YT0237iK-hPHGtAtsFO7s', '$SA3CYupiipashNNwE_6ylR58ffTyMptUGl5eCvBFru8', '$_bkHxBQtjBNDGe8Iii4oOdfYR118oMoNvO9y5Dd4GPM', '$r-TJiqkgPaCprVPiy21H2B72-VYh45eEOPvbgdfq-Gs', '$79Bgzv2PsdUhed6utpEK7cFl0JXMve0hB7syVjmSlHQ', '$HnnDyMei9o42ghvB1LOyJS6oK1edsjZmlEmFKXIm0Qo', '$sehvR0PjSOTkdKgGfq0x_4lYjh5sakxLfUkhOhOJuwI', '$7S-xvseOhlkPIwDuzwQDzoOGXnTipgpVglYGbSa7Dqs', '$oitQreRvwFXGL41MxpLk1NpoV7wNyTIMsJmKILVGNxg', '$5Pn0T9f_YPJrklY80oNwedtNOEZy2DxKa-ArmkyN8g4', '$tom3VzqEVeIwvz1_5AmdKre5h0hUPS8lO3AfbSyBpk8', '$bX5n8KxDJLLx8u0wEOOqWR8i_blAMgCZ7_THv4xwLk0', '$16sgeESi4fB-4UQRlqNP3jPbKO_67DjEV3TjBjbCXcs', '$3tP9lrR2aGYY1Fl0Cy3CP3M-vW96_5_WBhKtJIqHPSA', '$bhsKg8_sYX7extaPLiKmPXBRdxfPTddSBRhgj9FQ5cM', '$vtQla8_vGyfm7mnNB6z7YymzTVKkDQFJe2qe6yw3yKw', '$XvIzDiEofc0gVhZq0dOWKOkj8TTGFsh-Ls7psMicOYU', '$vKPnSxRpbV64InEQlZtUZT4kfZCpv0em2GkwWmeg940', '$o_63JkubqknUAIN3ANnG9VvRI6qYJQkcR6Fvh9I-N2A', '$2Ex18n5p5jShsDC3nDQwDAWHfYkiPSuvoDV6eG7l7XM', '$5G0uEFkw_c4XnCw2xbLVW9e9Q3BRi-f-xGIZRIphlus', '$ld22v_S-P0uStW1zWjC5akO7WUi2o9EQQfZAH7-G1VU', '$th5PIX3oz2ZBJX9vmYXeqVXySS-WN7PbeszFjLZ9bYc', '$1-idfxnLo-Vh4rC9rcHvZ_uEB91782Qc474XSdse82Q', '$2fZLJVABquw0QAqSjdntk-ZvyWmWWVRTguDbPDTk1sM', '$vzFfyJUvyI8hPSkdWT71-FZaNYm5eDarE97ZFIRrhvE', '$p_5xEuFbw03V9I9FPUPpqDjvrzGD5SG9wGbt7GVUFp4', '$IA3XkLB8FN1NonkIuw5m9ug10fGGcMPI_0MwE3bSZmw', '$7ohifRGSeY3PvSwnMIxTQPt-m4HnssfqRig3prY4i_Y', '$noQOOQLwKmVYY5VhKSU_AQuMsiFjeRZIT-pAY10b0Zk', '$cUP5M3PhGuzV_bdCzUeIO16WPsj-m8Z1KQeTCYOz8-Y', '$KL48TPH6-psDhNffd12P-fbTq5Jj5mwg326NaBs8Qzw', '$ZPTmpSPO82rdwy_rdtNCsi9hpej3mpKP8nIRI35KVEM', '$WhHKup5X5XrbkS0RGLtij61AiM0f9pg8tpuMznGXARk', '$uf_PZoaC2tcXrysWcxQwneQm3bexdAm9g8I0I1SAc2Q', '$Dg0tiO8eBGpfILpP6bm6p_OnqMsJXHllTdTAAhJ5o9M', '$g8Dj718S1YV4l3ABEsi3lhZECV-6MKpFQbJHWIW5ffI', '$DbSW7TkhbMhi9QUNGi46oR0D7vnqqMGKaFVS7kZyu1U', '$VHTdG7fkxh7ghmG9hYoumJjtAZ76DUQ2GInCbh6j7bg', '$XOTPBUvZDInuy-4C3GzQ2M1CrIazSjqp_GzPWuyCt-U', '$jIPNfG_HYRX1geZuEpUi7aHqlXIJykbV58IXFsK7EIo', '$0TomO8QOKk1s-faq0cftzUN27OxvDrJHHTojEgMygbg', '$Oz62JknyRb11JkyvXGeityKv4KTJn2AOnLjRt1V8rWc', '$XPoHrfOek_T2PRfLRmi54O68uCbhhEYkz3Ev0Tw_dQs', '$tF51AMuF31Ak1wsG3mSvTloyFyOYeN0cIr2_Zi-N65g', '$D-vHr5zOcYG5Qe1O7l8_qSLiYm0HQ5Pa35YbwEBaNck', '$ZM7xkx4q9fvb-JVLNFTMT2NttqugCJMerfz5Z7HBLOw', '$fvbXBlpjidvtkILXrVI-X4a6oYdomxrS8B-h1Ia_mqM', '$58YSnzcD_g412hkQuOhSMAJZ66KBeCs5mtjUAHH8p7g', '$T0fH0BZZdtWGdrGGHovJJlQ2Aim6hRKsQJkvlSluY3s', '$4SnF8r-7WUlVgGw7L84US80v7RnZqAFOOgyy3_8-5Nk', '$_m5WoTt51O9YUw1_Y6BDxpHrQOKyPdJHbm_Atw_YRL0', '$G2_9_jhMxB3fgDuD1idVC2zvJJuGkC8RWX5awsD2dw0', '$x3vS7TVo9uLKCWetVvLtI-pJW_1E7wt6besthTrQZrY', '$C9ciiay53w4zaksDvbqbZ4MK3fB2uaCgtQyfPPRw1K4', '$TZ0bmgJ5n-64z8IzNTL39jJ6ZaCMpGYSxeLUh9zTckM', '$N5ohU2ipjZvQDWFw-g6BxD2u-jd7t9jNpBSG2eIqAUo', '$YZXELrUhxIHjas17dBCWxFLko1eXiedfTEJIdUZ7--I', '$cWdTTZulyRAd0rVD0z33QpW5JgpVfpbghbbAcBl_49M', '$Aed8I9CBa2D8VSmX5M-wo7mlkLcXr_MQxklF95en7F4', '$uBXkcv8bNukKZZ6F0gvvEDf6NsJEYA5jlUw-AAaLDl4', '$Gi9GFrTL5nxvsWVhRyGnhCRiwuO1oz0vQpar38CvVK8', '$QNIohD47g111cHu5jjD6-FwbYoXTNj_x7Dn-ZbfVmoI', '$XLtL4JnSl4R2F23i5AXpbxcpzbwKqsckyyW5bpSg-ek', '$dJ0IEMvBc8MWUJgWvA5KPiRAkaqwtqt_BxhxBz0TET8', '$9DIE8XrS32jFFsBbHSFimAFvbwehmxQ0B321HJP2X2A', '$HByKQukahwiLanjGFGnYdO9Zumriq7tNT-5jzmN5xOk', '$q3QrbCdoApdzVMmjCctlN6DXCMB1UOt4iC8bW3awJqM', '$UZUj9yQ_wGckqBL6NYcdOBFurKKIZXeXO4zdaT7orgM', '$DPZtIA8K-a0ER34iORtm7SG-5N19eTPua1m-QhPAdwg', '$k421E9r6jZaWGeTT8y_mRZQR5xrFdDkkvcGxYXc1C7Y', '$V6q3OTaByS0KywOVy4U5cD4JAOYUfjShiQTSFJP-Iu8', '$3ylSajUI6JO5hD9VTH7tSwtdulXILcpgfnLyA-FKrkk', '$G7jaObl7xXHVaLrN2xJOIHyohP0njKjm0bzCEQhgz30', '$zWN-I7oNAs5oFaZJDIT2LHVf9PlSYUhfpAO_-EIh5O8', '$XmaXzIs7VVwE2vYvWbDan39IDBCJrzI9nAQsv8wnveM', '$E-cg3n6QA0gHykD3voSmDU0Rnhjg9Pu6kZuFlPUesT4', '$F5pqTn7XuqeicD5dyvZ7Yjt_DMfWPhwW5OvkfJYwGL8', '$J3o1B5VcaRwWic2Pv9JNdhvoqay4nPgn_Gw37IKhK-c', '$bFH9Q-fFC7zsBH5ZyVcSTa08fTdknRui6PmM_jhFHfg', '$7DL9KpHYKUKi8AhtklOFGiZRmGd8oujH_hSv56rEQSg'} @40000000625dc017326c8eb5 2022-04-18 19:45:54,845 - synapse.storage.databases.main.events_worker - 1107 - DEBUG - GET-22 - Loaded 116 events (116 rows) @40000000625dc017330e4f5d 2022-04-18 19:45:54,856 - synapse.federation.federation_client - 246 - DEBUG - GET-22 - backfill extrem={'$rTqJ12jXLA4PRiG2D2eIDM5JmEx1dg-Yp8RX-eDBYe8': 44920, '$ItUseJty28KtJug3BVoaaBWlK55Ej4ujpEUPuxvDKwk': 24632, '$URkPMCBQD9mbfkCxPi6u8KuzgeIDMTfPTm5dxK2xcxg': 18310, '$tJWZOk2uqHHi8oHYS-OKo5IsbS_9OVqzDhlxn--Swi4': 18240, '$s0wHtvYv3A3vaHj5EJixMSf8C2xhT1BUgSU9IQk0zMI': 18224} @40000000625dc017330f2fd9 2022-04-18 19:45:54,856 - synapse.federation.transport.client - 152 - DEBUG - GET-22 - backfill dest=imninja.net, room_id=!WgEsWTOEGkIcwYphxi:maunium.net, event_tuples={'$rTqJ12jXLA4PRiG2D2eIDM5JmEx1dg-Yp8RX-eDBYe8': 44920, '$ItUseJty28KtJug3BVoaaBWlK55Ej4ujpEUPuxvDKwk': 24632, '$URkPMCBQD9mbfkCxPi6u8KuzgeIDMTfPTm5dxK2xcxg': 18310, '$tJWZOk2uqHHi8oHYS-OKo5IsbS_9OVqzDhlxn--Swi4': 18240, '$s0wHtvYv3A3vaHj5EJixMSf8C2xhT1BUgSU9IQk0zMI': 18224}, limit=100 @40000000625dc0173319fad1 2022-04-18 19:45:54,857 - synapse.storage.txn - 614 - DEBUG - GET-22 - [TXN START] {get_destination_retry_timings-da} @40000000625dc017331b11e6 2022-04-18 19:45:54,857 - synapse.storage.SQL - 347 - DEBUG - GET-22 - [SQL] {get_destination_retry_timings-da} SELECT failure_ts, retry_last_ts, retry_interval FROM destinations WHERE destination = ? @40000000625dc017331b8a99 2022-04-18 19:45:54,857 - synapse.storage.SQL - 352 - DEBUG - GET-22 - [SQL values] {get_destination_retry_timings-da} ['imninja.net'] @40000000625dc01733209e85 2022-04-18 19:45:54,857 - synapse.storage.SQL - 373 - DEBUG - GET-22 - [SQL time] {get_destination_retry_timings-da} 0.000293 sec @40000000625dc0173322177c 2022-04-18 19:45:54,857 - synapse.storage.txn - 717 - DEBUG - GET-22 - [TXN END] {get_destination_retry_timings-da} 0.000601 sec @40000000625dc0173329e7ae 2022-04-18 19:45:54,858 - synapse.http.matrixfederationclient - 536 - DEBUG - GET-22 - {GET-O-4} [imninja.net] Sending request: GET matrix://imninja.net/_matrix/federation/v1/backfill/%21WgEsWTOEGkIcwYphxi%3Amaunium.net?v=%24rTqJ12jXLA4PRiG2D2eIDM5JmEx1dg-Yp8RX-eDBYe8&v=%24ItUseJty28KtJug3BVoaaBWlK55Ej4ujpEUPuxvDKwk&v=%24URkPMCBQD9mbfkCxPi6u8KuzgeIDMTfPTm5dxK2xcxg&v=%24tJWZOk2uqHHi8oHYS-OKo5IsbS_9OVqzDhlxn--Swi4&v=%24s0wHtvYv3A3vaHj5EJixMSf8C2xhT1BUgSU9IQk0zMI&limit=100; timeout 60.000000s @40000000625dc017332b88d6 2022-04-18 19:45:54,858 - synapse.util.metrics - 152 - DEBUG - GET-22 - Entering block outbound_request @40000000625dc017332f932d 2022-04-18 19:45:54,858 - synapse.util.metrics - 152 - DEBUG - GET-22 - Entering block get_well_known @40000000625dc01733309173 2022-04-18 19:45:54,858 - synapse.http.federation.well_known_resolver - 253 - INFO - GET-22 - Fetching https://imninja.net/.well-known/matrix/server @40000000625dc0173334b132 2022-04-18 19:45:54,859 - synapse.http.proxyagent - 223 - DEBUG - GET-22 - Requesting b'https://imninja.net/.well-known/matrix/server' via @40000000625dc01738041ba6 2022-04-18 19:45:54,939 - synapse.http.federation.well_known_resolver - 190 - INFO - GET-22 - Response from .well-known: {'m.server': 'imninja.net:443'} @40000000625dc0173805495b 2022-04-18 19:45:54,939 - synapse.util.metrics - 165 - DEBUG - GET-22 - Exiting block get_well_known @40000000625dc017380ba335 2022-04-18 19:45:54,940 - synapse.http.federation.matrix_federation_agent - 353 - DEBUG - GET-22 - Connecting to imninja.net:443 @40000000625dc018018abc02 2022-04-18 19:45:55,025 - synapse.util.metrics - 165 - DEBUG - GET-22 - Exiting block outbound_request @40000000625dc018018ca5cd 2022-04-18 19:45:55,025 - synapse.http.matrixfederationclient - 595 - INFO - GET-22 - {GET-O-4} [imninja.net] Got response headers: 403 Forbidden @40000000625dc0180191034f 2022-04-18 19:45:55,026 - synapse.http.matrixfederationclient - 673 - WARNING - GET-22 - {GET-O-4} [imninja.net] Request failed: GET matrix://imninja.net/_matrix/federation/v1/backfill/%21WgEsWTOEGkIcwYphxi%3Amaunium.net?v=%24rTqJ12jXLA4PRiG2D2eIDM5JmEx1dg-Yp8RX-eDBYe8&v=%24ItUseJty28KtJug3BVoaaBWlK55Ej4ujpEUPuxvDKwk&v=%24URkPMCBQD9mbfkCxPi6u8KuzgeIDMTfPTm5dxK2xcxg&v=%24tJWZOk2uqHHi8oHYS-OKo5IsbS_9OVqzDhlxn--Swi4&v=%24s0wHtvYv3A3vaHj5EJixMSf8C2xhT1BUgSU9IQk0zMI&limit=100: HttpResponseException('403: Forbidden') @40000000625dc01801922cdd 2022-04-18 19:45:55,026 - synapse.util.async_helpers - 466 - DEBUG - GET-22 - Releasing linearizer lock 'room_backfill' for key '!WgEsWTOEGkIcwYphxi:maunium.net' @40000000625dc01801947229 2022-04-18 19:45:55,026 - synapse.http.server - 95 - INFO - GET-22 - SynapseError: 403 - Host not in room. @40000000625dc018019bcf0f 2022-04-18 19:45:55,026 - synapse.access.http.8108 - 427 - INFO - GET-22 - 2001:a61:11a3:9101:8f84:fef4:1526:b3cc - 8108 - {@deepbluev7:nheko.im} Processed request: 0.243sec/0.000sec (0.030sec, 0.001sec) (0.002sec/0.028sec/12) 53B 403 "GET /_matrix/client/r0/rooms/!WgEsWTOEGkIcwYphxi:maunium.net/messages?from=s2787474_44251527_2053_3734916_138866_47_132417_2929243_1&dir=b&limit=92 HTTP/1.0" "curl/7.79.1" [142 dbevts]Steps to reproduce
I have no idea, but in the affected room any /messages request with a high enough limit does reproduce it.
I would the request to either return 91 events or return 92 events as it does when splitting up the request into multiple. It clearly shouldn't fail, just because it only has 91 events to return right now or because one server doesn't answer, if it can still return some events.
Version information
If not matrix.org:
Version: 1.57.0rc1
Install method: ebuild
The text was updated successfully, but these errors were encountered: