synapse user_parter removes other users from room when deactivation endpoint is called

Description

Whenever I call the deactivate (+erase) endpoint on synapse (this case for userA) it kept removing another user (userB) from all rooms. Today this happened for a second user (userC). The notable difference here is that userB had left one of the rooms on their own. C hasn't so far.

Steps to reproduce

Deactivate+Erase userA
Watch public rooms
See userA unsetting their display name and leaving
See userB and userC leaving all public rooms they were in

Homeserver

Selfhostes

Synapse Version

1.94.0

Installation Method

Docker (matrixdotorg/synapse)

Database

single postgres server, no restore from backup

Workers

Single process

Platform

Debian 11 with docker

Configuration

Presence and retention are enabled in the affected public rooms. The public rooms have a 48h retention policy for about 1.5 years.

The homeserver does not federate.

Relevant log output

2023-10-31 09:18:04,843 - synapse.handlers.deactivate_account - 158 - INFO - POST-911131 - Marking @userA:myhomeserver as erased
2023-10-31 09:18:04,845 - synapse.federation.sender - 592 - INFO - process_event_queue_for_federation-1377 - Unexpectedly did not have cached prev group for $oxitnVVee-cjwUyKUZgPf1iHCbQ0kYYvXbov3uoZXyU
2023-10-31 09:18:04,853 - synapse.handlers.deactivate_account - 234 - INFO - user_parter_loop-5 - Starting user parter
2023-10-31 09:18:04,861 - synapse.handlers.deactivate_account - 240 - INFO - user_parter_loop-5 - User parter parting '@userB:myhomeserver'
2023-10-31 09:18:04,873 - synapse.handlers.deactivate_account - 254 - INFO - user_parter_loop-5 - User parter parting '@userB:myhomeserver' from '!wmwqhJvBlcVtlMzYXp:myhomeserver'
2023-10-31 09:18:05,119 - synapse.handlers.deactivate_account - 254 - INFO - user_parter_loop-5 - User parter parting '@userB:myhomeserver' from '!WCxYbgOzUJowbPisiS:myhomeserver'
2023-10-31 09:18:05,127 - synapse.federation.sender - 592 - INFO - process_event_queue_for_federation-1378 - Unexpectedly did not have cached prev group for $S4RKH353eV6CNCxkP3aVVVreIu6qLYmuqZEhwV9fhDE
2023-10-31 09:18:05,338 - synapse.handlers.deactivate_account - 243 - INFO - user_parter_loop-5 - User parter finished parting '@userB:myhomeserver'
2023-10-31 09:18:05,339 - synapse.federation.sender - 592 - INFO - process_event_queue_for_federation-1379 - Unexpectedly did not have cached prev group for $mJL1JXe8swj8vFf0MZLdXvwx4UZxRf1YyAw1Q42L-yw
2023-10-31 09:18:05,343 - synapse.handlers.deactivate_account - 240 - INFO - user_parter_loop-5 - User parter parting '@userC:myhomeserver'
2023-10-31 09:18:05,352 - synapse.handlers.deactivate_account - 254 - INFO - user_parter_loop-5 - User parter parting '@userC:myhomeserver' from '!wmwqhJvBlcVtlMzYXp:myhomeserver'
2023-10-31 09:18:05,553 - synapse.handlers.deactivate_account - 254 - INFO - user_parter_loop-5 - User parter parting '@userC:myhomeserver' from '!WfkDZztWcIEzOOmRNW:myhomeserver'

Anything else that would be useful to know?

No response

Oct 31 '23 10:10 ThoreKr

2023-10-31 09:18:04,861 - synapse.handlers.deactivate_account - 240 - INFO - user_parter_loop-5 - User parter parting '@userB:myhomeserver'
2023-10-31 09:18:05,343 - synapse.handlers.deactivate_account - 240 - INFO - user_parter_loop-5 - User parter parting '@userC:myhomeserver'

These lines should only be logged if userB and userC are pending deactivation:

https://github.com/matrix-org/synapse/blob/v1.94.0/synapse/handlers/deactivate_account.py#L237-L240

Can you confirm (or refute) that these users have been deactivated?

Oct 31 '23 11:10 DMRobertson

These lines should only be logged if userB and userC are pending deactivation:

https://github.com/matrix-org/synapse/blob/v1.94.0/synapse/handlers/deactivate_account.py#L237-L240

Can you confirm (or refute) that these users have been deactivated?

These users were not deactivated through the admin API. I will try to get hold of the affected users to check whether they used the delete account feature. ubserB usually rejoins the parted rooms after some time (manually).

From the admin API I can see the following information:

{
	"name": "@userB:myhomeserver",
	"admin": false,
	"deactivated": false,
	"locked": false,
	"shadow_banned": false,
	"creation_ts": 1693854141,
	"appservice_id": null,
	"consent_server_notice_sent": null,
	"consent_version": null,
	"consent_ts": null,
	"user_type": null,
	"is_guest": false,
	"displayname": "userB",
	"avatar_url": null,
	"threepids": [],
	"external_ids": [
		{
			"auth_provider": "oidc-keycloak",
			"external_id": "..."
		}
	],
	"erased": false,
	"last_seen_ts": 1698432079706
}

{
	"name": "@userC:myhomeserver",
	"admin": false,
	"deactivated": false,
	"locked": false,
	"shadow_banned": false,
	"creation_ts": 1698440166,
	"appservice_id": null,
	"consent_server_notice_sent": null,
	"consent_version": null,
	"consent_ts": null,
	"user_type": null,
	"is_guest": false,
	"displayname": "userC",
	"avatar_url": null,
	"threepids": [],
	"external_ids": [
		{
			"auth_provider": "oidc-keycloak",
			"external_id": "..."
		}
	],
	"erased": false,
	"last_seen_ts": 1698447042385
}

Oct 31 '23 12:10 ThoreKr

Odd. Both show up as "deactivated": false there. Could they have been self-deactivated and then reactivated, maybe?

https://github.com/matrix-org/synapse/blob/9407d5ba78d1e5275b5817ae9e6aedf7d1ca14f7/synapse/handlers/deactivate_account.py#L139-L141 is the only place where we should mark users as pending deactivation. This is called by:

POST /deactivate/... to the admin API https://github.com/matrix-org/synapse/blob/cc865fffc0e556005a6ab596717a77230ba82ee7/synapse/rest/admin/users.py#L711-L713
PUT /users/... to the admin API https://github.com/matrix-org/synapse/blob/cc865fffc0e556005a6ab596717a77230ba82ee7/synapse/rest/admin/users.py#L400-L403
POST /deactivate to the client-server API https://github.com/matrix-org/synapse/blob/cc865fffc0e556005a6ab596717a77230ba82ee7/synapse/rest/client/account.py#L303-L307 and https://github.com/matrix-org/synapse/blob/cc865fffc0e556005a6ab596717a77230ba82ee7/synapse/rest/client/account.py#L315-L317

Oct 31 '23 12:10 DMRobertson

Unfortunately I did not get a response from the initially affected users, but the same issue occured again today.

Two unrelated users got parted from all rooms, the admin API reports them as not deactivated. The other confusing part is that the parter log messages are always followed by a federation sender log message:

2023-11-12 12:42:17 - synapse.handlers.deactivate_account - 243 - INFO - user_parter_loop-12 - User parter finished parting '@deactivatedUser:myhomeserver'
2023-11-12 12:42:17 - synapse.federation.sender - 592 - INFO - process_event_queue_for_federation-1250 - Unexpectedly did not have cached prev group for $U7EL4oVPtl5FlSFYJJsS8M1bNQF_ogZ6x4oGO86Buys
2023-11-12 12:42:17 - synapse.handlers.deactivate_account - 240 - INFO - user_parter_loop-12 - User parter parting '@otherUser:myhomeserver'
2023-11-12 12:42:17 - synapse.handlers.deactivate_account - 254 - INFO - user_parter_loop-12 - User parter parting '@otherUser:myhomeserver' from '!wmwqhJvBlcVtlMzYXp:myhomeserver'
2023-11-12 12:42:17 - synapse.federation.sender - 592 - INFO - process_event_queue_for_federation-1251 - Unexpectedly did not have cached prev group for $e7jWpF4nC7JO28cV1knv1JicRBGNua7nce6bEcMt0dQ

However, the server has no enabled federation and there are no remote users in that room.

Nov 12 '23 12:11 ThoreKr