Deactivating account with `{erase: true}` fails with internal server error #12257

RenWal · 2022-03-20T17:10:23Z

Description

When attempting GDPR-compliant user deactivation using POST /_synapse/admin/v1/deactivate/@user:domain.tld with {erase: true}, the request fails with M_UNKNOWN and ValueError: mxc URI '' did not match expected format appears in the homeserver log file. Without the erase parameter, deletion works.

Interestingly, when deleting multiple accounts in a row with {erase: true}, they are not kicked from their rooms, but as soon as we then delete a single additional user with {erase: false}, the user parter kicks in and immediately also kicks all the users for which deletion previously failed.

I'm unsure whether this is relevant, but some details about our setup:

We run https://github.com/matrix-org/matrix-synapse-ldap3 against OpenLDAP as our authentication backend
All accounts are provisioned using using the user creation/modification admin API and do not have a password set in Synapse (since authentication is done against LDAP)
When a user is removed from our organization, our backend tools delete the account both in Synapse and in LDAP (We've tested that ordering makes no difference, i.e., the error doesn't disappear if we keep the LDAP entry around until Synapse is done with the deactivation)

Steps to reproduce

provision a user account through the admin API with no password (we set just displayname and the email address in the POST body)
(you may log in as that user, or don't, this appears to make no difference)
use the deactivate account API with {erase: true} to deactivate the account
see that the request fails and that you can still log in with that user account (although all active sessions were terminated), and the account is still member of its rooms

Server logs showing two deletion failures with the erase option and one success without it

2022-03-20 17:16:25,248 - synapse.http.server - 100 - ERROR - POST-40008 - Failed handle request via 'DeactivateAccountRestServlet': <XForwardedForRequest at 0x7fb22425afd0 method='POST' uri='/_synapse/admin/v1/deactivate/@testaccount1:domain.tld' clientproto='HTTP/1.0' site='8008'>
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/util/caches/descriptors.py", line 313, in _wrapped
    ret = cache.get(cache_key, callback=invalidate_callback)
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/util/caches/deferred_cache.py", line 176, in get
    raise KeyError()
KeyError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/http/server.py", line 269, in _async_render_wrapper
    callback_return = await self._async_render(request)
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/http/server.py", line 471, in _async_render
    callback_return = await raw_callback_return
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/rest/admin/users.py", line 616, in on_POST
    result = await self._deactivate_account_handler.deactivate_account(
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/handlers/deactivate_account.py", line 139, in deactivate_account
    await self._profile_handler.set_avatar_url(
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/handlers/profile.py", line 306, in set_avatar_url
    if not await self.check_avatar_size_and_mime_type(new_avatar_url):
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
    result = current_context.run(gen.send, result)
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/handlers/profile.py", line 348, in check_avatar_size_and_mime_type
    server_name, _, media_id = parse_and_validate_mxc_uri(mxc)
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/util/stringutils.py", line 188, in parse_and_validate_mxc_uri
    raise ValueError("mxc URI %r did not match expected format" % (mxc,))
ValueError: mxc URI '' did not match expected format
2022-03-20 17:16:25,261 - synapse.access.http.8008 - 427 - INFO - POST-40008 - 127.0.0.1 - 8008 - {@backendbot:domain.tld} Processed request: 0.169sec/0.001sec (0.044sec, 0.005sec) (0.012sec/0.101sec/17) 55B 500 "POST /_synapse/admin/v1/deactivate/@testaccount1:domain.tld HTTP/1.0" "python-requests/2.26.0" [0 dbevts]
2022-03-20 17:19:12,819 - synapse.storage.databases.main.event_push_actions - 608 - INFO - event_push_action_stream_orderings-561 - Searching for stream ordering 1 month ago
2022-03-20 17:19:12,840 - synapse.storage.databases.main.event_push_actions - 612 - INFO - event_push_action_stream_orderings-561 - Found stream ordering 1 month ago: it's 14461
2022-03-20 17:19:12,840 - synapse.storage.databases.main.event_push_actions - 615 - INFO - event_push_action_stream_orderings-561 - Searching for stream ordering 1 day ago
2022-03-20 17:19:12,854 - synapse.storage.databases.main.event_push_actions - 619 - INFO - event_push_action_stream_orderings-561 - Found stream ordering 1 day ago: it's 14619
2022-03-20 17:26:34,757 - synapse.http.server - 100 - ERROR - POST-40121 - Failed handle request via 'DeactivateAccountRestServlet': <XForwardedForRequest at 0x7fb20c7bed30 method='POST' uri='/_synapse/admin/v1/deactivate/@testaccount2:domain.tld' clientproto='HTTP/1.0' site='8008'>
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/util/caches/descriptors.py", line 313, in _wrapped
    ret = cache.get(cache_key, callback=invalidate_callback)
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/util/caches/deferred_cache.py", line 176, in get
    raise KeyError()
KeyError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/http/server.py", line 269, in _async_render_wrapper
    callback_return = await self._async_render(request)
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/http/server.py", line 471, in _async_render
    callback_return = await raw_callback_return
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/rest/admin/users.py", line 616, in on_POST
    result = await self._deactivate_account_handler.deactivate_account(
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/handlers/deactivate_account.py", line 139, in deactivate_account
    await self._profile_handler.set_avatar_url(
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/handlers/profile.py", line 306, in set_avatar_url
    if not await self.check_avatar_size_and_mime_type(new_avatar_url):
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
    result = current_context.run(gen.send, result)
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/handlers/profile.py", line 348, in check_avatar_size_and_mime_type
    server_name, _, media_id = parse_and_validate_mxc_uri(mxc)
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/util/stringutils.py", line 188, in parse_and_validate_mxc_uri
    raise ValueError("mxc URI %r did not match expected format" % (mxc,))
ValueError: mxc URI '' did not match expected format
2022-03-20 17:26:34,762 - synapse.access.http.8008 - 427 - INFO - POST-40121 - 127.0.0.1 - 8008 - {@backendbot:domain.tld} Processed request: 0.064sec/0.001sec (0.016sec, 0.004sec) (0.006sec/0.037sec/12) 55B 500 "POST /_synapse/admin/v1/deactivate/@testaccount2:domain.tld HTTP/1.0" "python-requests/2.26.0" [0 dbevts]
2022-03-20 17:26:39,320 - synapse.handlers.deactivate_account - 220 - INFO - user_parter_loop-1 - Starting user parter
2022-03-20 17:26:39,329 - synapse.handlers.deactivate_account - 226 - INFO - user_parter_loop-1 - User parter parting '@testaccount1:domain.tld'
2022-03-20 17:26:39,329 - synapse.handlers.deactivate_account - 240 - INFO - user_parter_loop-1 - User parter parting '@testaccount1:domain.tld' from '!<redacted>:domain.tld'
2022-03-20 17:26:39,553 - synapse.handlers.deactivate_account - 196 - INFO - POST-40127 - Rejected invite for deactivated user '@testaccount2:domain.tld' in room '!<redacted>:domain.tld'
2022-03-20 17:26:39,623 - synapse.handlers.deactivate_account - 240 - INFO - user_parter_loop-1 - User parter parting '@testaccount1:domain.tld' from '!<redacted>:domain.tld'
2022-03-20 17:26:39,847 - synapse.handlers.deactivate_account - 196 - INFO - POST-40127 - Rejected invite for deactivated user '@testaccount2:domain.tld' in room '!<redacted>:domain.tld'
2022-03-20 17:26:39,972 - synapse.handlers.deactivate_account - 240 - INFO - user_parter_loop-1 - User parter parting '@testaccount1:domain.tld' from '!<redacted>:domain.tld'
2022-03-20 17:26:40,011 - synapse.access.http.8008 - 427 - INFO - POST-40127 - 127.0.0.1 - 8008 - {@backendbot:domain.tld} Processed request: 0.726sec/0.016sec (0.040sec, 0.027sec) (0.053sec/0.229sec/30) 37B 200 "POST /_synapse/admin/v1/deactivate/@testaccount2:domain.tld HTTP/1.0" "python-requests/2.26.0" [0 dbevts]
2022-03-20 17:26:40,169 - synapse.handlers.deactivate_account - 240 - INFO - user_parter_loop-1 - User parter parting '@testaccount1:domain.tld' from '!<redacted>:domain.tld'
2022-03-20 17:26:40,412 - synapse.handlers.deactivate_account - 229 - INFO - user_parter_loop-1 - User parter finished parting '@testaccount1:domain.tld'
2022-03-20 17:26:40,420 - synapse.handlers.deactivate_account - 226 - INFO - user_parter_loop-1 - User parter parting '@testaccount2:domain.tld'
2022-03-20 17:26:40,446 - synapse.handlers.deactivate_account - 229 - INFO - user_parter_loop-1 - User parter finished parting '@testaccount2:domain.tld'
2022-03-20 17:26:40,451 - synapse.handlers.deactivate_account - 230 - INFO - user_parter_loop-1 - User parter finished: stopping

Version information

Homeserver: (withheld)

If not matrix.org:

Version: 1.54.0 on Python 3.8.10
Install method: debian package matrix-synapse-py3 1.54.0+focal1

Platform: Ubuntu Server 20.04.4 LTS, VM

The text was updated successfully, but these errors were encountered:

dklimpel · 2022-03-20T20:37:41Z

IMO it was introduced in #11846
If you set erase: true avatar url is an empty string "" and the parse_and_validate_mxc_uri fails.

But it is not clear why this test not fails:

synapse/tests/rest/admin/test_user.py

Line 1008 in bf9d549

def test_deactivate_user_erase_true(self) -> None:

ShadowJonathan · 2022-03-20T22:48:52Z

But it is not clear why this test not fails:

Because it only tests a valid MXC URI, and a case where it's None, not where its ""

DMRobertson · 2022-03-21T18:21:44Z

Thanks @RenWal for a very thorough report.

To my mind, the root cause here is having two ways of representing "this user doesn't have an avatar set". The database allows profiles.displayname and profiles.avatar_url to be nullable strings. I don't see a meaningful distinction between the empty string and a NULL value here.

A point fix would be to only call check_avatar_size_and_mime_type if new_avatar_url is truthy here.

synapse/synapse/handlers/profile.py

Lines 306 to 307 in 300ed0b

    
           if not await self.check_avatar_size_and_mime_type(new_avatar_url): 
        
               raise SynapseError(403, "This avatar is not allowed", Codes.FORBIDDEN)

DMRobertson · 2022-03-21T18:25:29Z

@RenWal: as a potential workaround, it might be possible to use the admin API to set a user's avatar url to null, and then deactivating their account with erasure as you tried previously. Would you mind trying that to see if it works?

(I agree we should fix the bug in the meantime.)

DMRobertson · 2022-03-21T19:01:56Z

Also note: to reproduce this one must either set max_avatar_size or allowed_avatar_mimetypes in Synapse's config.

Fixes #12257.

RenWal · 2022-03-21T19:29:43Z

@RenWal: as a potential workaround, it might be possible to use the admin API to set a user's avatar url to null, and then deactivating their account with erasure as you tried previously. Would you mind trying that to see if it works?

Thanks for the suggestion! Unfortunately, that does not appear to work. In fact, we're showing this data for a freshly created user:

{
 "name": "@testaccount5:domain.tld",
 "is_guest": 0,
 "admin": 0,
 "consent_version": null,
 "consent_server_notice_sent": null,
 "appservice_id": null,
 "creation_ts": 1647890169,
 "user_type": null,
 "deactivated": 0,
 "shadow_banned": false,
 "displayname": "Account5 TestAccount",
 "avatar_url": null,
 "threepids": [
  {
   "medium": "email",
   "address": "sinkhole+synapsetest5@domain.tld",
   "validated_at": 1647890169357,
   "added_at": 1647890169357
  }
 ],
 "external_ids": []
}

This looks like avatar_url has already been null, hence setting it to null using the admin API does nothing.

DMRobertson · 2022-03-25T13:09:35Z

That's... confusing.

I think the change in #12261 should allow you to erase users again. Would you be able to confirm if that's the case @RenWal? It should land in the next release, 1.56, scheduled for Tuesday 5th April.

Hopefully this fixes #12257. Co-authored-by: Patrick Cloke <clokep@users.noreply.github.com>

RenWal · 2022-03-25T16:32:15Z

We've verified that fffb3c4 no longer exhibits this issue in our staging environment. We'll report back in case we still experience problems once we deploy 1.56 to production, but I'm pretty confident that this fix is all we need. Thank you for the quick handling of this issue!

DMRobertson added the T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. label Mar 21, 2022

DMRobertson added the P3 (OBSOLETE: use S- labels.) Approved backlog: not yet scheduled, will accept patches label Mar 21, 2022

DMRobertson pushed a commit that referenced this issue Mar 21, 2022

Don't reject an empty string as an invalid avatar

ba5fd0f

Fixes #12257.

DMRobertson mentioned this issue Mar 21, 2022

Always allow the empty string as an avatar_url. #12261

Merged

DMRobertson closed this as completed in #12261 Mar 25, 2022

DMRobertson pushed a commit that referenced this issue Mar 25, 2022

Always allow the empty string as an avatar_url. (#12261)

fffb3c4

Hopefully this fixes #12257. Co-authored-by: Patrick Cloke <clokep@users.noreply.github.com>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Deactivating account with `{erase: true}` fails with internal server error #12257

Deactivating account with `{erase: true}` fails with internal server error #12257

RenWal commented Mar 20, 2022 •

edited

dklimpel commented Mar 20, 2022 •

edited

ShadowJonathan commented Mar 20, 2022

DMRobertson commented Mar 21, 2022

DMRobertson commented Mar 21, 2022 •

edited

DMRobertson commented Mar 21, 2022

RenWal commented Mar 21, 2022

DMRobertson commented Mar 25, 2022

RenWal commented Mar 25, 2022

Deactivating account with {erase: true} fails with internal server error #12257

Deactivating account with {erase: true} fails with internal server error #12257

Comments

RenWal commented Mar 20, 2022 • edited

Description

Steps to reproduce

Version information

dklimpel commented Mar 20, 2022 • edited

ShadowJonathan commented Mar 20, 2022

DMRobertson commented Mar 21, 2022

DMRobertson commented Mar 21, 2022 • edited

DMRobertson commented Mar 21, 2022

RenWal commented Mar 21, 2022

DMRobertson commented Mar 25, 2022

RenWal commented Mar 25, 2022

Deactivating account with `{erase: true}` fails with internal server error #12257

Deactivating account with `{erase: true}` fails with internal server error #12257

RenWal commented Mar 20, 2022 •

edited

dklimpel commented Mar 20, 2022 •

edited

DMRobertson commented Mar 21, 2022 •

edited