Clients incorrectly denied permission to view some events

[telmich]

Description

Loading the start of the time timeline in some rooms fails.

Steps to reproduce

• find a room that is marked unread in element-web
• try to access the first message
• You get the "Failed to load timeline position: tried to load a specific point in this room's timeline, but you do not have permission to view the message in question." error message

Note: this does not apply to all rooms, but in our instance to a lot of rooms.

Expectation: old events can always be loaded.

Further investigating shows that a request to

https://ungleich.matrix.ungleich.cloud/_matrix/client/r0/rooms/!qlfxvXwtSjmInWnicT%3Aungleich.ch/context/%24PsaDH5PnSV5u4lx3-06R2R9-vbDWUU8ErR2hOntC5e4?filter=%7B%22lazy_load_members%22%3Atrue%7D

fails with:

{"errcode":"M_FORBIDDEN","error":"You don't have permission to access that event."}

I first thought that might be related to us running matrix-org/rust-synapse-compress-state#27 , however we only compressed rooms with 10k+ events and many rooms that are much smaller are affected.

The users trying to access the events are often even an admin in the room, so a permission issue is unlikely.

Version information

• Homeserver: ungleich.matrix.ungleich.cloud

If not matrix.org:

• Version: {"server_version":"1.37.1","python_version":"3.7.3"}

• Install method: package manager

• Platform: Debian 10, no containers

[anoadragon453]

Have you enabled the experimental Message retention policy feature or otherwise used the Purge History Admin API?

Essentially this error will be returned if the server doesn't find any events for the client's context request:

synapse/synapse/handlers/room.py

Lines 1092 to 1094 in a683028

	filtered = await filter_evts([event])
	if not filtered:
	raise AuthError(403, "You don't have permission to access that event.")

This can happen for a number of reasons. Perhaps the events have been purged using the above features/API, or all possible returnable events have been soft-failed (less likely).

Did you notice this start happening immediately after running the state compressor, or immediately after an update - or has this been an ongoing problem? I'm not aware of any side effects of the state compressor that may cause what you're seeing, but it is possible.

[telmich]

@anoadragon453 We started seeing this +/- after running the state compressor.
The Message retention policy feature nor the purge history were used, the instance was not updated anytime near that problem starting.

Looking at the database, it seems that the events are still stored. It is also shown in a lot of direct messages.
This problem does not happen for all participants of a room, but seems to happen only to some.

[telmich]

I have an update on this: I found one (!!) session that can actually read the old messages. All other sessions are getting denied. I have key backup configured to be on on all sessions. This might (probably is) an older session.

How do sessions vs. users relate to being able to see events?

[erikjohnston]

How do sessions vs. users relate to being able to see events?

That's odd, all the checks are done per-user and not per-device. Were the different sessions on different clients (e.g. web vs android)?

I think this error is coming from:

synapse/synapse/handlers/room.py

Lines 1089 to 1091 in a743bf4

	filtered = await filter_evts([event])
	if not filtered:
	raise AuthError(403, "You don't have permission to access that event.")

Are the users encountering this still in the room? Does jumping to other locations work? Can you check in the DB what event $PsaDH5PnSV5u4lx3-06R2R9-vbDWUU8ErR2hOntC5e4 is please, e.g. event type? I'm wondering if clients are trying to jump back to e.g. the create event or something, which would 403 for everyone bar the creator.

[telmich]

@erikjohnston As i am (luckily?) one of the affected users I can test and report first hand:

• Mainly using element-web, but also element on android
• The behaviour is different for different users in the room. Usually it works fine for all users, but one
• Jumping to no location works and the room looks as if there are no messages
• However when "new messages" are written now, I can read them

DB output:

matrix-synapse=# select * from events where event_id = '$PsaDH5PnSV5u4lx3-06R2R9-vbDWUU8ErR2hOntC5e4';
 topological_ordering |                   event_id                   |       type       |             room_id             | content | unrecognized_keys | processed | outlier | depth | origin_server_ts |  received_ts  |      sender       | contains_url | instance_name | stream_ordering 
----------------------+----------------------------------------------+------------------+---------------------------------+---------+-------------------+-----------+---------+-------+------------------+---------------+-------------------+--------------+---------------+-----------------
                   87 | $PsaDH5PnSV5u4lx3-06R2R9-vbDWUU8ErR2hOntC5e4 | m.room.encrypted | !qlfxvXwtSjmInWnicT:ungleich.ch |         |                   | t         | f       |    87 |    1609020325854 | 1609020325868 | @nico:ungleich.ch | f            |               |         5238914
(1 row)

[erikjohnston]

Are you still in the room?

I'd be interested in getting the state at that event. Do you have a manhole listener enabled? If so if you could ran the following commands in it (replacing @user:example.com with your own user ID):

>>> from twisted.internet.defer import ensureDeferred as e
>>> from synapse.storage.state import StateFilter
>>> from synapse.api.constants import EventTypes
>>> e(hs.get_storage().state.get_state_for_event("$PsaDH5PnSV5u4lx3-06R2R9-vbDWUU8ErR2hOntC5e4", StateFilter.from_types([(EventTypes.RoomHistoryVisibility, ""), (EventTypes.Member, "@user:example.com")])))
< ... wait for the deferred to complete ... >
>>> d = _
>>> [e.content for e in d.result.values()]

And copy the final output, which will tell us a) whether it thinks you were in the room at the time and b) the history visibility setting that is being used.

If not I can find the necessary DB queries .

[telmich]

@erikjohnston In the above python code, hs is not defined - is it possible some code is missing?

>>> from twisted.internet.defer import ensureDeferred as e
>>> from synapse.storage.state import StateFilter
>>> from synapse.api.constants import EventTypes
>>> e(hs.get_storage().state.get_state_for_event("$PsaDH5PnSV5u4lx3-06R2R9-vbDWUU8ErR2hOntC5e4", StateFilter.from_types([(EventTypes.RoomHistoryVisibility, ""), (EventTypes.Member, "@nico:ungleich.ch")])))                                                                                                        
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
NameError: name 'hs' is not defined

There is no manhole listener configured.

[erikjohnston]

Ah, that only works in the manhole as described in: https://matrix-org.github.io/synapse/develop/manhole.html, which lets you ssh into a running Synapse and you get a python shell.

[telmich]

Good morning @erikjohnston, below is the output:

>>> from twisted.internet.defer import ensureDeferred as e
>>> from synapse.storage.state import StateFilter
>>> from synapse.api.constants import EventTypes
>>> e(hs.get_storage().state.get_state_for_event("$PsaDH5PnSV5u4lx3-06R2R9-vbDWUU8ErR2hOntC5e4", StateFilter.from_types([(EventTypes.RoomHistoryVisibility, ""), (EventTypes.Member, "@nico:ungleich.ch")])))
<Deferred #0>
Deferred #0 called back: {('m.room.history_visibility', ''): <FrozenEventV3 event_id='$Tvg_ZJZNAvja9fWNx_I8xLo7cq3oU2P0lzOUCuijukU', type='m.room.history_visibility', state_key=''>, ('m.room.member', '@nico:ungleich.ch'): <FrozenEventV3 event_id='$ACMqTmSK5EdVwEKF3lWhPCPVqU0pShcf26N7GNIRaI0', type='m.room.member', state_key='@nico:ungleich.ch'>}
>>>

[erikjohnston]

Hi, thanks! Sorry, could you also do the last two lines? i.e.

>>> d = _
>>> [e.content for e in d.result.values()]

[telmich]

Sorry, sure, here it is:

>>> from twisted.internet.defer import ensureDeferred as e
>>> from synapse.storage.state import StateFilter
>>> from synapse.api.constants import EventTypes
>>> e(hs.get_storage().state.get_state_for_event("$PsaDH5PnSV5u4lx3-06R2R9-vbDWUU8ErR2hOntC5e4", StateFilter.from_types([(EventTypes.RoomHistoryVisibility, ""), (EventTypes.Member, "@nico:ungleich.ch")])))
<Deferred #0>
Deferred #0 called back: {('m.room.history_visibility', ''): <FrozenEventV3 event_id='$Tvg_ZJZNAvja9fWNx_I8xLo7cq3oU2P0lzOUCuijukU', type='m.room.history_visibility', state_key=''>, ('m.room.member', '@nico:ungleich.ch'): <FrozenEventV3 event_id='$ACMqTmSK5EdVwEKF3lWhPCPVqU0pShcf26N7GNIRaI0', type='m.room.member', state_key='@nico:ungleich.ch'>}
>>> d = _
>>> [e.content for e in d.result.values()]
[{'history_visibility': 'invited'}, {'membership': 'join', 'displayname': 'nico🇨🇭', 'avatar_url': 'mxc://ungleich.ch/NEILcXUZjHhAxxbBTtYxmnkN'}]
>>>

[erikjohnston]

Thanks! Very interesting, so the history visibility is invited but you are actually joined to the room at that point, so we really shouldn't be denying it. Hmm.

[erikjohnston]

I think we have enough to try and investigate this

[telmich]

A heads up from my side: originally this seemed to only affect one user, now we have about 5-10 users affected by this problem and it seems to impact working with matrix, as the rooms that cannot properly accessed turn up as rooms with "unread messages" and thus block the access to the rooms with real unread messages.

[telmich]

Ping - is there anything we can do to analyse this problem? We are now having reports from some dozens of users and dozens of rooms.

[callahad]

At this point we believe you've provided sufficient information, we just need to find time to dedicate a few days of engineering effort to further investigation. Oddly, we've not heard of this problem from other homeserver admins, which makes it challenging to prioritize, since it seems to be a local effect.

[telmich]

@callahad If you have some pointers on where to start / where the source of problem is, we might be able to dive into it and submit a patch

[richvdh]

I suppose it might be worth throwing some debug into filter_events_for_client ?

[Ofenhed]

I have the same error message on iOS when scrolling through an encrypted chat history on a server that is not related to OPs server, so it might be a problem you will see a lot of very soon. It seems to happen by chance when scrolling, as the error message shows up at different places each time I try it. Not entirely sure it's related, though, as I'm not the server admin.

Edit: Although it seems random, I have never been able to reach all the way to the first unread message, and the "Jump to unread" button doesn't work.

[Fnux]

We actually have a mix of M_UNKNOWN and M_FORBIDDEN events. For M_UNKNOWN - could not find event $X - the event $X is not present in the events DB table but is reference as prev_event_id in the event_edges. I wonder if missing events in the graph / chain could lead to the M_FORBIDDEN issue (where the event does exist in database)? I have to read more on how the whole room state / grpah is computed.

Edit/note: I investigate ungleich's / Nico's server.

[telmich]

An update: we have migrate to 1.60.0 some time ago, but the issue still persists.