Synapse decided I'm no longer a member of a room

[namazso]

Description

So the story starts at a room I'm in (PG Lounge) started missing a lot of peoples messages. I wrote it off as some synapse bug, and proceeded to just purge the room and rejoin. This seemed to fix it for about 4 days. This morning, Synapse decided that I am no longer a member of the room. Upon rejoining, most messages are missing and the timeline is messed up:

Steps to reproduce

I don't know.

Homeserver

namazso.eu

Synapse Version

1.78.0

Installation Method

Docker (matrixdotorg/synapse)

Database

PostgreSQL 12. Single server. Yes, about 2 years ago. No.

Workers

Single process

Platform

Probably not relevant, but Fedora IoT, official docker container.

Configuration

Presence is enabled.

Relevant log output

2023-03-13 06:18:55,764 - synapse.federation.sender.per_destination_queue - 561 - INFO - federation_transaction_transmission_loop-314815 - Catching up rooms to conorz.tk: '!xGDfMAzPVtiqAxdQIu:privacyguides.org'
2023-03-13 06:21:52,697 - synapse.handlers.typing - 373 - INFO - PUT-148747 - Got typing update from @123bob123:matrix.org: {'room_id': '!xGDfMAzPVtiqAxdQIu:privacyguides.org', 'typing': True, 'user_id': '@123bob123:matrix.org'}
2023-03-13 06:22:02,693 - synapse.handlers.typing - 373 - INFO - PUT-148750 - Got typing update from @123bob123:matrix.org: {'room_id': '!xGDfMAzPVtiqAxdQIu:privacyguides.org', 'typing': False, 'user_id': '@123bob123:matrix.org'}
2023-03-13 06:22:06,687 - synapse.handlers.typing - 373 - INFO - PUT-148752 - Got typing update from @123bob123:matrix.org: {'room_id': '!xGDfMAzPVtiqAxdQIu:privacyguides.org', 'typing': True, 'user_id': '@123bob123:matrix.org'}
2023-03-13 06:22:13,948 - synapse.handlers.typing - 373 - INFO - PUT-148759 - Got typing update from @123bob123:matrix.org: {'room_id': '!xGDfMAzPVtiqAxdQIu:privacyguides.org', 'typing': False, 'user_id': '@123bob123:matrix.org'}
2023-03-13 06:22:14,702 - synapse.federation.federation_server - 1236 - INFO - _process_incoming_pdus_in_room_inner-6145 - handling received PDU in room !xGDfMAzPVtiqAxdQIu:privacyguides.org: <FrozenEventV3 event_id=$30_fuaLRkoj8MMbkl9YBlQ88x-QeHrntdSQMV0FLjEQ, type=m.room.message, state_key=None, outlier=False>
2023-03-13 06:22:17,692 - synapse.handlers.typing - 373 - INFO - PUT-148761 - Got typing update from @123bob123:matrix.org: {'room_id': '!xGDfMAzPVtiqAxdQIu:privacyguides.org', 'typing': True, 'user_id': '@123bob123:matrix.org'}
2023-03-13 06:22:19,910 - synapse.handlers.typing - 373 - INFO - PUT-148762 - Got typing update from @123bob123:matrix.org: {'room_id': '!xGDfMAzPVtiqAxdQIu:privacyguides.org', 'typing': False, 'user_id': '@123bob123:matrix.org'}
2023-03-13 06:22:20,145 - synapse.federation.federation_server - 1236 - INFO - _process_incoming_pdus_in_room_inner-6146 - handling received PDU in room !xGDfMAzPVtiqAxdQIu:privacyguides.org: <FrozenEventV3 event_id=$B_8RZjqAPFRFh4GruU5oR7X5sFsQvKDueVZ_OCEdm5k, type=m.room.message, state_key=None, outlier=False>
2023-03-13 06:24:54,323 - synapse.federation.sender.per_destination_queue - 561 - INFO - federation_transaction_transmission_loop-317840 - Catching up rooms to projectsegfau.lt: '!xGDfMAzPVtiqAxdQIu:privacyguides.org'
2023-03-13 06:39:21,005 - synapse.federation.federation_server - 1236 - INFO - _process_incoming_pdus_in_room_inner-6168 - handling received PDU in room !xGDfMAzPVtiqAxdQIu:privacyguides.org: <FrozenEventV3 event_id=$9nL14NRJg1_n8U4klVLXNQYsCdEWIPn1MW31dM_zxBY, type=m.room.member, state_key=@double0beagle:matrix.org, outlier=False>
2023-03-13 06:49:57,469 - synapse.federation.sender.per_destination_queue - 561 - INFO - federation_transaction_transmission_loop-317856 - Catching up rooms to projectsegfau.lt: '!xGDfMAzPVtiqAxdQIu:privacyguides.org'
2023-03-13 07:14:57,581 - synapse.federation.sender.per_destination_queue - 561 - INFO - federation_transaction_transmission_loop-322628 - Catching up rooms to projectsegfau.lt: '!xGDfMAzPVtiqAxdQIu:privacyguides.org'
2023-03-13 07:32:02,394 - synapse.federation.sender.per_destination_queue - 561 - INFO - federation_transaction_transmission_loop-322712 - Catching up rooms to conorz.tk: '!xGDfMAzPVtiqAxdQIu:privacyguides.org'
2023-03-13 07:39:57,554 - synapse.federation.sender.per_destination_queue - 561 - INFO - federation_transaction_transmission_loop-325709 - Catching up rooms to projectsegfau.lt: '!xGDfMAzPVtiqAxdQIu:privacyguides.org'
2023-03-13 08:05:00,869 - synapse.federation.sender.per_destination_queue - 561 - INFO - federation_transaction_transmission_loop-327248 - Catching up rooms to projectsegfau.lt: '!xGDfMAzPVtiqAxdQIu:privacyguides.org'
2023-03-13 08:07:55,540 - synapse.federation.federation_server - 1236 - INFO - _process_incoming_pdus_in_room_inner-6243 - handling received PDU in room !xGDfMAzPVtiqAxdQIu:privacyguides.org: <FrozenEventV3 event_id=$2Voa-IClLrUoa4ByjY4tvhSeVhKhbq2bcbPxVAS-scM, type=m.room.message, state_key=None, outlier=False>
2023-03-13 08:08:35,089 - synapse.state - 656 - INFO - persist_events-11923 - Resolving state for !xGDfMAzPVtiqAxdQIu:privacyguides.org with groups [1259202, 1259266]
2023-03-13 08:08:36,102 - synapse.state - 656 - INFO - persist_events-11925 - Resolving state for !xGDfMAzPVtiqAxdQIu:privacyguides.org with groups [1259202, 1259267, 1259266]
2023-03-13 08:08:38,060 - synapse.state - 656 - INFO - persist_events-11927 - Resolving state for !xGDfMAzPVtiqAxdQIu:privacyguides.org with groups [1259202, 1259267, 1259268, 1259266]
2023-03-13 08:08:45,513 - synapse.state - 656 - INFO - persist_events-11940 - Resolving state for !xGDfMAzPVtiqAxdQIu:privacyguides.org with groups [1259202, 1259267, 1259266, 1259268, 1259269]
2023-03-13 08:08:46,793 - synapse.state - 656 - INFO - persist_events-11942 - Resolving state for !xGDfMAzPVtiqAxdQIu:privacyguides.org with groups [1259202, 1259267, 1259266, 1259268, 1259269, 1259271]
2023-03-13 08:08:47,060 - synapse.handlers.sync - 1373 - INFO - GET-152610 - User membership change between getting rooms and current token: @namazso:namazso.eu leave !xGDfMAzPVtiqAxdQIu:privacyguides.org
2023-03-13 08:09:52,837 - synapse.federation.federation_server - 1236 - INFO - _process_incoming_pdus_in_room_inner-6251 - handling received PDU in room !xGDfMAzPVtiqAxdQIu:privacyguides.org: <FrozenEventV3 event_id=$VxMSAfYKzPFDdOYVKISxwFWj58fzkFQV9oK0Xb9zRxs, type=m.room.message, state_key=None, outlier=False>
2023-03-13 08:10:12,257 - synapse.state - 656 - INFO - GET-152740-$tAUp2CEzV6UVgnnyP0KtsnLnM48B-SGXWt6-InGOWOk - Resolving state for !xGDfMAzPVtiqAxdQIu:privacyguides.org with groups [1259275, 1259276]
2023-03-13 08:10:20,674 - synapse.handlers.sync - 1373 - INFO - GET-152839 - User membership change between getting rooms and current token: @namazso:namazso.eu join !xGDfMAzPVtiqAxdQIu:privacyguides.org
2023-03-13 08:10:30,834 - synapse.state - 656 - INFO - persist_events-12056 - Resolving state for !xGDfMAzPVtiqAxdQIu:privacyguides.org with groups [1259283, 1259278]
2023-03-13 08:10:38,105 - synapse.state - 656 - INFO - persist_events-12067 - Resolving state for !xGDfMAzPVtiqAxdQIu:privacyguides.org with groups [1259283, 1259284, 1259278]
2023-03-13 08:10:45,766 - synapse.state - 656 - INFO - persist_events-12079 - Resolving state for !xGDfMAzPVtiqAxdQIu:privacyguides.org with groups [1259283, 1259284, 1259285, 1259278]
2023-03-13 08:11:15,155 - synapse.state - 656 - INFO - persist_events-12086 - Resolving state for !xGDfMAzPVtiqAxdQIu:privacyguides.org with groups [1259278, 1259283, 1259284, 1259285, 1259286]

Anything else that would be useful to know?

No response

[namazso]

Note that this issue reappeared after a room purge, so either that is broken, or the issue is federated back.

[DMRobertson]

Reminds me a bit of #14539.

[MichaelSasser]

@DMRobertson You might be on to something. I had this kind of issue around the same time, maybe a week or two I've created #14539, with #element-web-announcements:matrix.org (!bijaLdadorKgNGtHdA:matrix.org). I dismissed it as an artifact of retention. Synapse was hanging up on some user profile. It ended up basically like @namazso described. I could fix it by purging the room, and a few hours later I ran into the same issue again. This time purging the room ended up in an error, and I was unable to /leave in element-web. Even force purging was not possible. So, I ended up removing the room the same way I described in #14539 (Please don't use this method. Even though it might have worked back then, the database schema might have changed). Since then, I had no more issues with the room.
I wouldn't have thought about those problems might have a connection because the messages only appeared out of order and new messages were not visible in the timeline anymore after a certain point in time. In #14539 the same messages (same event_id) were visible in multiple locations (two or more) across multiple homeservers.

[H-Shay]

Looking at the logs and seeing lines indicating state resolution happening right before the membership change makes me wonder if this was a case of state reset.