Device lists are desynchronizing

[turt2live]

Description

People seem to be seeing/getting outdated device lists from Synapse regardless of server. This is manifesting in the fairly normal ways: wrong names, devices that should have been deleted, etc. New devices seem to be included correctly all the time, but usually with a mix of incorrect devices.

insert into device_lists_remote_resync (user_id, added_ts) values ('@victim:example.org', (extract(epoch from now())::bigint * 1000)); fixes the problem for the relevant victims.

Appears to be a wider issue than just matrix.org

Known cases:

• Someone deleted their extra devices, but no one saw that.
• Someone cross-signed their new device, but no one believed them.
• Someone renamed their device, but no one saw that.

The rename trick for trying to confuse/convince the server into updating doesn't appear to work anymore either - only the database insert functions.

Started appearing months ago.

[clokep]

Is this a duplicate / superset of #8459?

[turt2live]

ah ha, I did report it at the time - I'm so smart. I'd close #8459 in favour of this as this is the more general version of "it's all broken", but I'll leave that up to you.

[richvdh]

related: #4827?

[deepbluev7]

We have a similar issue. We have a bot with 1500 devices (for E2EE performance testing). Its device list only shows up on some servers though. This may be easier to reproduce with such bigger device lists?

[Erethon]

Just ran into this myself, a friend on matrix.org had about 480 devices, deleted all of them except 4 and my homeserver reported 318 devices still being around. Running the insert query from the OP fixed it for me.

[deepbluev7]

In our case it was

synapse/synapse/handlers/device.py

Line 902 in b460a08

# If the remote server has more than ~1000 devices for this user

which stopped syncing our 1500 devices list.

[532910]

Is there a way to force resync? I have a DM with me (from my HS) and a guy from matrix.org. He added a new device and than deleted it, but I still see that device as unverified in DM.

[erikjohnston]

Are people still seeing this issue? Specifically deleting devices not propagating over federation? There's been some work in this area over the past year IIRC.

---

Is there a way to force resync? I have a DM with me (from my HS) and a guy from matrix.org. He added a new device and than deleted it, but I still see that device as unverified in DM.

@532910 The DB query in the issue description probably still works

[532910]

The DB query in the issue description probably still works

Indeed!

[rihardsk]

@erikjohnston i'm still facing the issue, yes. On Synapse 1.48.

[babolivier]

I'm seeing one unverified device for @sneaker-net:matrix.org from @babolivier:element.io but they've assured me they've verified it on their end.

[DMRobertson]

From my reading of the spec, clients either

• watch device_lists.changed/left in the sync response, or
• periodically query /keys/changes after syncs

to discover device list changes or that they can forget a user's devices entirely.

Assuming my understanding is correct, I see three ways this can go wrong on Synapse's end. Either:

1. the /sync response incorrectly calculates the list of changed or left users in device_lists; or
2. the /keys/changed response makes such an incorrect calculation; or
3. the /keys/query response incorrectly reports the device list for the user in question.

I'm going to ignore (2) because /keys/changed is hardly ever used on matrix.org (circa 100 per day) compared to /keys/query (circa a million per day).

Do we have any idea whether the problems are due to (1) or (3)? Guessing (1) but I'd like to just think things through carefully. Edit: actually, some of the older comments on this issue sound like they're describing (3)?

Edit 17th Jan 2021: I hadn't fully appreciated that this relies on EDUs over federation. We need to also investigate if something goes wrong sending edus or receiving edus.

[turt2live]

The symptoms feel like they're more pointing towards (3), given viewing the user's device list should fix it. It's worth noting that most of the incorrect cases of device lists are over federation, so possibly Synapse rate limiting itself from querying for updates?

Noting mostly the comment about 480 devices turning into 4, but the server reported 318 - this sounds like after 162 updates over federation, the receiving server decided to rate limit itself and stopped parsing them for some reason. Given 162 isn't really close to a cutoff point that I'd expect to see in code, it sounds time-based (X updates per Y minutes, or something).

[DMRobertson]

Thanks @turt2live, that's very helpful. There is some logic related to rate limiting, though I'm not familiar with the details.

synapse/synapse/handlers/device.py

Lines 869 to 879 in 88a78c6

	logger.debug("Attempting to resync the device list for %s", user_id)
	log_kv({"message": "Doing resync to update device list."})
	# Fetch all devices for the user.
	origin = get_domain_from_id(user_id)
	try:
	result = await self.federation.query_user_devices(origin, user_id)
	except NotRetryingDestination:
	if mark_failed_as_stale:
	# Mark the remote user's device list as stale so we know we need to retry
	# it later.
	await self.store.mark_remote_user_device_cache_as_stale(user_id)

I spent today trying to write a dumb complement test that spams lots of device creations in succession, and checks they can be queried after they appear in a sync result. This isn't reliable unless I add some additional Sleep calls in there. Very odd. Odder still because complement is running against a monolith-mode Synapse, so there shouldn't be any replication delays to worry about.

[DMRobertson]

This isn't reliable unless I add some additional Sleep calls in there.

This is explained by the fact that registering a new device and uploading keys sends out two m.device_list_updates over federation: one for the displayname, and one for the keys. Accounting for that, I don't see any kinds of weirdness.

[DMRobertson]

I don't think we can practically make progress without a way to semi-reliably reproduce one of these problems, or else logs from both homeservers (one of them being matrix.org is fine) capturing the problem.

If there's anyone on matrix.org who sees this a lot, please let me know and we can set up additional debug tracing specifically for your mxid.

[richvdh]

it may be that the fix to #11727 helps with this.

[turt2live]

I had this happen with a matrix.org user fwiw, but no idea when it desynchronized so not entirely valuable. Unfortunately only happen to notice that the device lists are wrong when people send DMs (which doesn't happen all that often) and they've been cross-sign verified, so the new device sticks out as a red alarm badge.

[neilalexander]

Seemingly had this problem today with my @neilalexander:matrix.org user when I logged in with session ID LZOCIDQOCP. Device list updates don't seem to have been sent properly over federation. Relevant logs on matrix.org should be between Mon 17 Jan ~ 15:00 to 15:40 GMT.

[DMRobertson]

#11760 Adds some additional debugging for this. It's off by default, but can be enabled by adding a logging config entry as follows:

loggers:
    # debug for https://github.com/matrix-org/synapse/issues/8631
    synapse.8631_debug:
        level: DEBUG

I suspect we'll get the most value out of seeing this on the sender side, but there is logging on the receive side as well. I'd be very grateful if anyone who sees this frequently could apply this to their homeserver.

[tril0byte]

I spent some time with getting the debug logs activated and they are logging all right. Made test accounts on 2 synapse homeservers I'm running and they are sending device list updates successfully with no problems. I haven't been able to trigger the glitch here. So far my experience it has only happened with updating device lists on a matrix.org account (not propagating to federation). I intend to do further tests later, directed to adding/removing/updating devices specifically on a matrix.org account.

[tril0byte]

the debug code seems faulty, on homeservers with it enabled, I can no longer receive messages.

2022-03-23 20:29:02,722 - synapse.access.http.8813 - 448 - INFO - PUT-42 - 54.37.22.104 - 8813 - {zaplog.pro} Processed request: 
0.006sec/0.002sec (0.006sec, 0.000sec) (0.000sec/0.000sec/0) 31B 400 "PUT /_matrix/federation/v1/send/1647989527544 HTTP/1.0" "Sy
napse/1.55.0" [0 dbevts]
2022-03-23 20:29:55,846 - synapse.federation.transport.server.federation - 108 - INFO - PUT-43 - Received txn 1645740405899 from 
86thumbs.net. (PDUs: 0, EDUs: 1)
2022-03-23 20:29:55,846 - synapse.federation.transport.server.federation - 126 - ERROR - PUT-43 - 'dict' object has no attribute 
'edu_type'
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
    result = current_context.run(gen.send, result)
StopIteration: 0

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
    result = current_context.run(gen.send, result)
StopIteration: {'ed25519:a_HMBy': FetchKeyResult(verify_key=<nacl.signing.VerifyKey object at 0x7f7c4416b2e8>, valid_until_ts=1648102945835)}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/transport/server/federation.py", line 115, in on_PUT
    for edu in transaction_data.get("edus", [])
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/transport/server/federation.py", line 116, in <listcomp>
    if edu.edu_type in DEVICE_UPDATE_EDUS
AttributeError: 'dict' object has no attribute 'edu_type'

I disabled the 8631 specific debugging from workers handling inbound requests for /_matrix/federation/v1/send/ and I can receive messages again.

[DMRobertson]

the debug code seems faulty

Indeed, apologies; that's my bug. #11890 and #12098 together should fix that. Those are included with Synapse 1.54 and above.

[richvdh]

I think this is still waiting for people to enable the debug logging and report their findings.

@DMRobertson is that correct?

[DMRobertson]

@richvdh that's right. Lacking a way to reproduce this, we don't yet understand if the problem is in sending out the updates or receiving them.

[richvdh]

I've now enabled the additional logging on matrix.org, so if any users on there observe this problem, please let us know so we can investigate.

[jblachly]

I'm having this problem on the @mozilla home server if anyone here is admin and can enable the debug logging

[anoadragon453]

Due to lack of reports for this issue (desynchronization of device lists), I'm going to close this to help free up our backlog of issues.

The debug logging (which can be enabled by the config mentioned in #8631 (comment)) is still available to test with. If you experience this issue as described and are able to provide logs with the above option enabled to help us debug, please @-mention myself in a comment with those logs and we'll re-open the issue. Thanks!