Rejected event made it into `current_state_events`, leading to errors such as `404: Could not find event` #6867

Half-Shot · 2020-02-06T17:46:24Z

I'm not seeing any inbound federation to #irc:matrix.org (!BAXLHOFjvDKUeLafmO:matrix.org), and my logs are full of:

2020-02-06 17:42:19,652 - synapse.federation.transport.server - 161 - INFO - PUT-81436- Request from raim.ist
2020-02-06 17:42:19,653 - synapse.federation.transport.server - 406 - INFO - PUT-81436- Received txn 1580999134839 from raim.ist. (PDUs: 1, EDUs: 1)
2020-02-06 17:42:19,673 - synapse.http.client - 284 - INFO - PUT-81436- Sending request POST http://127.0.0.1:9593/_synapse/replication/fed_send_edu/m.receipt/BIetiYxCmo
2020-02-06 17:42:19,754 - synapse.federation.transport.server - 427 - ERROR - PUT-81436- on_incoming_transaction failed
Traceback (most recent call last):
  File "/opt/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: {'$NVI5AZqJdV7KyJPF3XFlxzRiiD0G86IBbWi7JxxUr0g': {'event_id': '$NVI5AZqJdV7KyJPF3XFlxzRiiD0G86IBbWi7JxxUr0g', 'internal_metadata': '{"outlier": false, "stream_ordering": -150956}', 'json': '{"auth_events": ["$fgAiL9F7RRbilPAfTVYhaOPl7sunZZVhtUCPvphGDL4", "$S38/aRG4Qz8eIdrTyzJuQdH3Ieus1Y1dhczoFKnOB7M", "$AQfAndymjyEmF3BjyHxwK9wIBZxMq0i8APoWoPIubNM"], "content": {"allow": ["*"], "allow_ip_literals": false, "deny": ["calamari.space", "*.200acres.org", "*.glowers.club", "*.gossip.love", "*.matrix.kiwifarms.net", "*.nerdsin.space", "*.ordoevangelistarum.com", "*.zemos.net", "200acres.org", "ardaxi.com", "c-24-11-108-182.hsd1.ut.comcast.net", "glowers.club", "gossip.love", "matrix.kiwifarms.net", "nerdsin.space", "ordoevangelistarum.com", "zemos.net"]}, "depth": 18623, "hashes": {"sha256": "jD2Wrs+hrdFRZOkpO63fGdxu4ku05dYXmDM61pneUgQ"}, "origin": "matrix.org", "origin_server_ts": 1579737097568, "prev_events": ["$+80N8tyd9FlDbCsIdBQqY5+7vv5Be2bJdIcT95JS2YM"], "prev_state": [], "room_id": "!BAXLHOFjvDKUeLafmO:matrix.org", "sender": "@abuse:matrix.org", "state_key": "", "type": "m.room.server_acl", "signatures": {"matrix.org": {"ed25519:a_RXGa": "s+o7wIY57ea0FZBZC2CjhWgU7FRKxl9E9HNQizL+USvQEfF0C9AaVYYxBaqoySNvPUfE5jPWrFVoS5yOtJ/0Dg"}}, "unsigned": {"age": 31784513, "replaces_state": "$+80N8tyd9FlDbCsIdBQqY5+7vv5Be2bJdIcT95JS2YM"}}', 'format_version': 2, 'rejected_reason': 'auth_error', 'redactions': []}}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: {}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: {}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: []

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/synapse/lib/python3.7/site-packages/synapse/federation/transport/server.py", line 424, in on_PUT
    origin, transaction_data
  File "/opt/synapse/lib/python3.7/site-packages/synapse/federation/federation_server.py", line 129, in on_incoming_transaction
    origin, transaction, request_time
  File "/opt/synapse/lib/python3.7/site-packages/synapse/federation/federation_server.py", line 181, in _handle_incoming_transaction
    ).addErrback(unwrapFirstError)
  File "/opt/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/synapse/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/opt/synapse/lib/python3.7/site-packages/synapse/federation/federation_server.py", line 293, in _handle_pdus_in_txn
    process_pdus_for_room, pdus_by_room.keys(), TRANSACTION_CONCURRENCY_LIMIT
  File "/opt/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/synapse/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/opt/synapse/lib/python3.7/site-packages/synapse/util/async_helpers.py", line 155, in _concurrently_execute_inner
    await maybe_awaitable(func(next(it)))
  File "/opt/synapse/lib/python3.7/site-packages/synapse/federation/federation_server.py", line 266, in process_pdus_for_room
    await self.check_server_matches_acl(origin_host, room_id)
  File "/opt/synapse/lib/python3.7/site-packages/synapse/federation/federation_server.py", line 710, in check_server_matches_acl
    acl_event = await self.store.get_event(acl_event_id)
  File "/opt/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/opt/synapse/lib/python3.7/site-packages/synapse/storage/data_stores/main/events_worker.py", line 190, in get_event
    raise NotFoundError("Could not find event %s" % (event_id,))
synapse.api.errors.NotFoundError: 404: Could not find event $NVI5AZqJdV7KyJPF3XFlxzRiiD0G86IBbWi7JxxUr0g
2020-02-06 17:42:19,755 - synapse.http.server - 81 - INFO - PUT-81436- <XForwardedForRequest at 0x7f47ea9f94e0 method='PUT' uri='/_matrix/federation/v1/send/1580999134839' clientproto='HTTP/1.0' site=8053> SynapseError: 404 - Could not find event $NVI5AZqJdV7KyJPF3XFlxzRiiD0G86IBbWi7JxxUr0g
2020-02-06 17:42:19,756 - synapse.access.http.8053 - 302 - INFO - PUT-81436- - - 8053 - {raim.ist} Processed request: 0.105sec/0.000sec (0.010sec, 0.000sec) (0.001sec/0.073sec/2) 101B 404 "PUT /_matrix/federation/v1/send/1580999134839 HTTP/1.0" "Synapse/1.10.0rc2" [1 dbevts]

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

erikjohnston · 2020-02-06T17:48:41Z

Hmm, looks like you're either missing the ACL event or its been reject and somehow its ended up in current state? Might be worth seeing if leaving/rejoining fixes?

Half-Shot · 2020-02-06T17:48:44Z

That event is:

        34586311 |                18623 | $NVI5AZqJdV7KyJPF3XFlxzRiiD0G86IBbWi7JxxUr0g | m.room.server_acl | !BAXLHOFjvDKUeLafmO:matrix.org |         |                   | t         | f       | 18623 |    1579737097568 | 1579768916963 | @abuse:matrix.org | f

Which is also in:

                   event_id                   |   reason   |  last_check   
----------------------------------------------+------------+---------------
 $NVI5AZqJdV7KyJPF3XFlxzRiiD0G86IBbWi7JxxUr0g | auth_error | 1579768916993

erikjohnston · 2020-02-06T17:51:01Z

Ruh roh

richvdh · 2020-02-09T18:04:31Z

@Half-Shot: is that event the one in current_state_events for that room_id/event_type?

Half-Shot · 2020-02-10T11:15:35Z

@richvdh Yup:

halfshotuk_synapse=> select * from current_state_events WHERE room_id = '!BAXLHOFjvDKUeLafmO:matrix.org' AND type = 'm.room.server_acl';
                   event_id                   |            room_id             |       type        | state_key | membership 
----------------------------------------------+--------------------------------+-------------------+-----------+------------
 $NVI5AZqJdV7KyJPF3XFlxzRiiD0G86IBbWi7JxxUr0g | !BAXLHOFjvDKUeLafmO:matrix.org | m.room.server_acl |           | 
(1 row)

richvdh · 2020-02-10T11:23:14Z

well boo. An event that fails auth shouldn't make it into current_state_events afaik.

I don't suppose you have logs going back as far as Jan 23rd (when that event landed)?

Half-Shot · 2020-02-10T11:53:26Z

The logs have rotated many times since then :(

richvdh · 2020-05-11T13:17:18Z

we're going to park this until we have logs to demonstrate it happening

richvdh · 2020-10-02T16:20:03Z

I have a feeling that this sort of thing could have happened pre-synapse 1.6.0 due to #6289. 1.6.0 was released on 2019/11/26; I wonder if @Half-Shot was still running an older version on 23rd Jan.

Interestingly it turns out @uhoreg has the same problem with the same room.

uhoreg · 2020-10-02T17:06:21Z

Workaround was to leave the room and re-join.

richvdh · 2021-08-13T12:22:22Z

#10589 reports a similar problem with another event ($Dv3wmat7XbtBm4O37eT+Oa2kxHKUfCj36nCMiHyj5F4) in the same room - again, predating Synapse 1.6.0.

richvdh · 2021-08-13T12:24:07Z

We're hoping this is fixed going forward, so I'm going to close this.

richvdh · 2021-08-27T09:53:32Z

Seems like this can still happen. @Nim65s:matrix.org reported it happening on $xaDjW7VJVmywHlla60UIw5Q8C9aFl2VdyyuHIOC3Roc, an event sent in !OGEhHVWSdvArJzumhm:matrix.org on 2021-07-30.

nim65s · 2021-08-27T11:13:10Z

a DELETE https://matrix.tetaneutral.net/_synapse/admin/v1/rooms/!OGEhHVWSdvArJzumhm:matrix.org with purge=true fixed the errors on our side. Thanks a lot @richvdh for the help, but I think this issue still exist.

richvdh added the info-needed label Feb 9, 2020

richvdh changed the title ~~NotFoundError: 404: Could not find event on incoming transactions to !BAXLHOFjvDKUeLafmO:matrix.org~~ Rejected event made it into current_state_events, leading to errors such as 404: Could not find event Feb 10, 2020

richvdh removed the info-needed label Feb 10, 2020

richvdh added z-p2 (Deprecated Label) z-bug (Deprecated Label) labels May 11, 2020

richvdh mentioned this issue Aug 13, 2021

Error: 404 - Could not find event - on incoming federation transaction PUT queries #10589

Closed

richvdh closed this as completed Aug 13, 2021

MurzNN mentioned this issue Aug 13, 2021

/federation/v1/send returns 404 and logs at INFO for "Could not find event" errors #10597

Open

akhilman mentioned this issue Aug 15, 2021

** Unable to decrypt: The sender's device has not sent us the keys for this message. ** element-hq/element-web#16163

Open

richvdh reopened this Aug 27, 2021

reivilibre added S-Major Major functionality / product severely impaired, no satisfactory workaround. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. and removed z-bug (Deprecated Label) z-p2 (Deprecated Label) labels Aug 27, 2021

erikjohnston mentioned this issue Jul 5, 2022

Make _get_state_map_for_room not break when room state events don't contain an event id. #13174

Merged

4 tasks

matrixbot mentioned this issue Dec 21, 2023

Rejected event made it into current_state_events, leading to errors such as 404: Could not find event element-hq/synapse#6867

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Rejected event made it into `current_state_events`, leading to errors such as `404: Could not find event` #6867

Rejected event made it into `current_state_events`, leading to errors such as `404: Could not find event` #6867

Half-Shot commented Feb 6, 2020

erikjohnston commented Feb 6, 2020

Half-Shot commented Feb 6, 2020 •

edited

Loading

erikjohnston commented Feb 6, 2020

richvdh commented Feb 9, 2020

Half-Shot commented Feb 10, 2020

richvdh commented Feb 10, 2020

Half-Shot commented Feb 10, 2020 •

edited

Loading

richvdh commented May 11, 2020

richvdh commented Oct 2, 2020 •

edited

Loading

uhoreg commented Oct 2, 2020

richvdh commented Aug 13, 2021 •

edited

Loading

richvdh commented Aug 13, 2021

richvdh commented Aug 27, 2021

nim65s commented Aug 27, 2021

Rejected event made it into current_state_events, leading to errors such as 404: Could not find event #6867

Rejected event made it into current_state_events, leading to errors such as 404: Could not find event #6867

Comments

Half-Shot commented Feb 6, 2020

erikjohnston commented Feb 6, 2020

Half-Shot commented Feb 6, 2020 • edited Loading

erikjohnston commented Feb 6, 2020

richvdh commented Feb 9, 2020

Half-Shot commented Feb 10, 2020

richvdh commented Feb 10, 2020

Half-Shot commented Feb 10, 2020 • edited Loading

richvdh commented May 11, 2020

richvdh commented Oct 2, 2020 • edited Loading

uhoreg commented Oct 2, 2020

richvdh commented Aug 13, 2021 • edited Loading

richvdh commented Aug 13, 2021

richvdh commented Aug 27, 2021

nim65s commented Aug 27, 2021

Rejected event made it into `current_state_events`, leading to errors such as `404: Could not find event` #6867

Rejected event made it into `current_state_events`, leading to errors such as `404: Could not find event` #6867

Half-Shot commented Feb 6, 2020 •

edited

Loading

Half-Shot commented Feb 10, 2020 •

edited

Loading

richvdh commented Oct 2, 2020 •

edited

Loading

richvdh commented Aug 13, 2021 •

edited

Loading