user_parter removes other users from room when deactivation endpoint is called

[ThoreKr]

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

[DMRobertson]

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?

[ThoreKr]

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
}

[DMRobertson]

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

synapse/synapse/handlers/deactivate_account.py

Lines 139 to 141 in 9407d5b

	# Add the user to a table of users pending deactivation (ie.
	# removal from all the rooms they're a member of)
	await self.store.add_user_pending_deactivation(user_id)

is the only place where we should mark users as pending deactivation. This is called by:

• POST /deactivate/... to the admin API

  synapse/synapse/rest/admin/users.py

  Lines 711 to 713 in cc865ff

  	result = await self._deactivate_account_handler.deactivate_account(
  	target_user_id, erase, requester, by_admin=True
  	)

• PUT /users/... to the admin API

  synapse/synapse/rest/admin/users.py

  Lines 400 to 403 in cc865ff

  	if deactivate and not user["deactivated"]:
  	await self.deactivate_account_handler.deactivate_account(
  	target_user.to_string(), False, requester, by_admin=True
  	)

• POST /deactivate to the client-server API

  synapse/synapse/rest/client/account.py

  Lines 303 to 307 in cc865ff

  	if requester.app_service:
  	await self._deactivate_account_handler.deactivate_account(
  	requester.user.to_string(), body.erase, requester
  	)
  	return 200, {}

  and

  synapse/synapse/rest/client/account.py

  Lines 315 to 317 in cc865ff

  	result = await self._deactivate_account_handler.deactivate_account(
  	requester.user.to_string(), body.erase, requester, id_server=body.id_server
  	)

[ThoreKr]

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.