`/sync` fails with `SynapseError: 404 - Could not find event` if the last event is a redaction of an event that we don't have

[n3rdybyn47ur3]

Hello,

we noticed a strange login behaviour that only happens to some of our users:

When trying to log in (SAML) they got an 404 error after the SAML Authentication is allready completed (and the verification should start)

There are warnings to cachebuster GET requests in my synapse log:
2022-05-24 12:35:33,568 - synapse.http.server - 723 - WARNING - GET-125345 - Not sending response to request <XForwardedForRequest at 0x7fe7c3c40d00 method='GET' uri='/_matrix/client/r0/sync?filter=0&timeout=0&_cacheBuster=1653395733090' clientproto='HTTP/1.0' site='8008'>, already disconnected.

Sadly I could not find the coresponding one.

We have updated synapse more than once during the last weeks but since existing sessions reconnect without login its impossible to say, since when this happens. Most of the users can login fine. The problem occurs with Element Web, Desktop and Android App (all newest version.

[squahtx]

It's probably unrelated to SAML. Sounds similar to #12820, but it's hard to confirm because no one's posting their errors or logs.

Could you dig out some INFO-level Synapse logs that include the 404 response to /sync?

[n3rdybyn47ur3]

Yes, that should be possible. Tomorrow is a national holyday, so I will change the log level Friday morning and hopefully deliver logs Friday or Monday.

[rettichschnidi]

Same error on my homeserver. Multiple users affected, the two I investigated a bit more have the following logs (renamed to "user1" and "user2" here):

May 24 09:35:09 matrix-1 synapse[345874]: synapse.http.server: [GET-7246170] <XForwardedForRequest at 0x7fc781185bb0 method='GET' uri='/_matrix/client/r0/sync?filter=3&timeout=0&_cacheBuster=1653384908382' clientproto='HTTP/1.1' site='8008'> SynapseError: 404 - Could not find event $vrNBlJ52sq9ojxXRFl7JLoBU1A5zyEorDuoMYMxkz8g
May 24 09:35:09 matrix-1 synapse[345874]: synapse.access.http.8008: [GET-7246170] 127.0.0.1 - 8008 - {@user1:digitale-gesellschaft.ch} Processed request: 0.540sec/0.021sec (0.340sec, 0.035sec) (0.956sec/1.158sec/172) 101B 404 "GET /_matrix/client/r0/sync?filter=3&timeout=0&_cacheBuster=1653384908382 HTTP/1.1" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:100.0) Gecko/20100101 Firefox/100.0" [2 dbevts]

May 24 09:35:12 matrix-1 synapse[345874]: synapse.http.server: [GET-7246191] <XForwardedForRequest at 0x7fc73e1b4100 method='GET' uri='/_matrix/client/r0/sync?filter=1&timeout=0&_cacheBuster=1653384912246' clientproto='HTTP/1.1' site='8008'> SynapseError: 404 - Could not find event $2XH5WO75JB-dfBoAd7qjczsWwPVZUgcTYgNBa2p5_6s
May 24 09:35:12 matrix-1 synapse[345874]: synapse.access.http.8008: [GET-7246191] 127.0.0.1 - 8008 - {@user2:digitale-gesellschaft.ch} Processed request: 0.621sec/0.006sec (0.390sec, 0.017sec) (1.077sec/1.584sec/202) 101B 404 "GET /_matrix/client/r0/sync?filter=1&timeout=0&_cacheBuster=1653384912246 HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/99.0.4832.0 Safari/537.36" [2 dbevts]

Issue exists on Synapse 1.58.1 and 1.59.1 and on Element-Web 1.10.11, 1.10.12 and 1.10.13. Unsure if it already affected older versions.

[richvdh]

This sounds rather like #12571, but that should have been fixed in Synapse 1.59.0 (and later) :/

@rettichschnidi: can you run a query on your database and share the results?

SELECT * FROM events e LEFT JOIN rejections r USING (event_id)
WHERE event_id='$vrNBlJ52sq9ojxXRFl7JLoBU1A5zyEorDuoMYMxkz8g';

[rettichschnidi]

@richvdh:

synapse=# SELECT * FROM events e LEFT JOIN rejections r USING (event_id)
WHERE event_id='$vrNBlJ52sq9ojxXRFl7JLoBU1A5zyEorDuoMYMxkz8g';
                   event_id                   | topological_ordering |       type       |                   room_id                    | content | unrecognized_keys | processed | outlier | depth | origin_server_ts |  received_ts  |                  sender                   | contains_url | instance_name | stream_ordering | state_key | rejection_reason | reason | last_check
----------------------------------------------+----------------------+------------------+----------------------------------------------+---------+-------------------+-----------+---------+-------+------------------+---------------+-------------------------------------------+--------------+---------------+-----------------+-----------+------------------+--------+------------
 $vrNBlJ52sq9ojxXRFl7JLoBU1A5zyEorDuoMYMxkz8g |                   15 | m.room.redaction | !emUtfyPuSaXxMGNSQW:digitale-gesellschaft.ch |         |                   | t         | f       |    15 |    1633904626616 | 1633904626641 | @user3:digitale-gesellschaft.ch | f            | master        |         3665886 |           |                  |        |
(1 row)

synapse=#

(user3 is another alias for a 3rd user)

[richvdh]

That's... odd. Can you check event_json too?

SELECT event_id, internal_metadata FROM event_json WHERE event_id='$vrNBlJ52sq9ojxXRFl7JLoBU1A5zyEorDuoMYMxkz8g'; 

[rettichschnidi]

synapse=# SELECT event_id, internal_metadata FROM event_json WHERE event_id='$vrNBlJ52sq9ojxXRFl7JLoBU1A5zyEorDuoMYMxkz8g';
                   event_id                   |                        internal_metadata
----------------------------------------------+------------------------------------------------------------------
 $vrNBlJ52sq9ojxXRFl7JLoBU1A5zyEorDuoMYMxkz8g | {"token_id":2639,"txn_id":"m1633904625401.6","historical":false}
(1 row)

synapse=#

[richvdh]

hrm, another idea. Can you try these:

SELECT * FROM redactions WHERE event_id='$vrNBlJ52sq9ojxXRFl7JLoBU1A5zyEorDuoMYMxkz8g';
SELECT * FROM redactions WHERE redacts='$vrNBlJ52sq9ojxXRFl7JLoBU1A5zyEorDuoMYMxkz8g';

[rettichschnidi]

synapse=# SELECT * FROM redactions WHERE event_id='$vrNBlJ52sq9ojxXRFl7JLoBU1A5zyEorDuoMYMxkz8g';
                   event_id                   |                   redacts                    | have_censored |  received_ts
----------------------------------------------+----------------------------------------------+---------------+---------------
 $vrNBlJ52sq9ojxXRFl7JLoBU1A5zyEorDuoMYMxkz8g | $ikN-_JY29tlFZpZ4oRzFPp7mRFR_UYWzDFLduvPSkO8 | t             | 1633904626660
(1 row)

synapse=# SELECT * FROM redactions WHERE redacts='$vrNBlJ52sq9ojxXRFl7JLoBU1A5zyEorDuoMYMxkz8g';
 event_id | redacts | have_censored | received_ts
----------+---------+---------------+-------------
(0 rows)

synapse=#

[richvdh]

right, and can you do the same queries for $ikN-_JY29tlFZpZ4oRzFPp7mRFR_UYWzDFLduvPSkO8 ?

SELECT * FROM events e LEFT JOIN rejections r USING (event_id)
WHERE event_id='$ikN-_JY29tlFZpZ4oRzFPp7mRFR_UYWzDFLduvPSkO8';

SELECT event_id, internal_metadata FROM event_json
WHERE event_id='$ikN-_JY29tlFZpZ4oRzFPp7mRFR_UYWzDFLduvPSkO8';

(sorry, slightly grasping at straws here - I'm really struggling to understand what could cause that exception when the event is just there in the database)

[rettichschnidi]

synapse=# SELECT * FROM events e LEFT JOIN rejections r USING (event_id) WHERE event_id='$ikN-_JY29tlFZpZ4oRzFPp7mRFR_UYWzDFLduvPSkO8';
 event_id | topological_ordering | type | room_id | content | unrecognized_keys | processed | outlier | depth | origin_server_ts | received_ts | sender | contains_url | instance_name | stream_ordering | state_key | rejection_reason | reason | last_check
----------+----------------------+------+---------+---------+-------------------+-----------+---------+-------+------------------+-------------+--------+--------------+---------------+-----------------+-----------+------------------+--------+------------
(0 rows)

synapse=# SELECT event_id, internal_metadata FROM event_json WHERE event_id='$ikN-_JY29tlFZpZ4oRzFPp7mRFR_UYWzDFLduvPSkO8';
 event_id | internal_metadata
----------+-------------------
(0 rows)

synapse=#

Not great for the documentation here, but in case it helps I am available on Matrix in either #synapse:matrix.org or via DM (@rettichschnidi:digitale-gesellschaft.ch).

[rettichschnidi]

Maybe relevant details:

• two out of 379 users are known to be affected (maybe more are, but I have only logs back to May 24)
• Retention policy looks like this:

retention:
  enabled: true
  default_policy:
    min_lifetime: 1d
    max_lifetime: 90d
  allowed_lifetime_min: 1d
  allowed_lifetime_max: 90d

• Despite the retention policy: Our database is ever-growing and we do not really know why
• We used rust-synapse-compress-state and rust-synapse-find-unreferenced-state-groups in the past, but have not done so for 6+ months
• Running Ubuntu 20.04 using the official deb packages offered by the matrix.org
• Using libjemalloc to reduce RAM usage