lots of AssertionError: 'Attempting to create an event with no prev_events'

These suggest something is wrong with the room in question. We should filter out attempts to send to such rooms earlier on.

https://sentry.matrix.org/sentry/synapse-matrixorg/issues/119955

This assertionerror is what happens where previously we would have returned 'no create event in auth events'; as such this is closely related to #7642.

These rooms have no entries in event_forward_extremities or current_state_events.

They seem to divide into two sets:

rooms with an appservice user (typically an RSS bot) where the last regular user left some time ago. I suspect they have been cleared out by the the delete_old_current_state_events database schema update, though am a bit confused as to why this has happened given the appservice user is still a member.
rooms where we have received one or more invite events over federation, but apparently never (successfully?) joined the room.

rooms with an appservice user (typically an RSS bot) where the last regular user left some time ago. I suspect they have been cleared out by the the delete_old_current_state_events database schema update, though am a bit confused as to why this has happened given the appservice user is still a member.

It might be worth noting that, at the time we ran this update on matrix.org, it looked at current_state_events.membership to see which rooms were still active (that was later changed in #7854). But I don't know why that wouldn't be populated either, at least on matrix.org (other servers might have had a horrible mess, due to #6923).

New sentry issue: https://sentry.matrix.org/sentry/synapse-matrixorg/issues/189680/

Still very much a thing: https://sentry.matrix.org/sentry/synapse-matrixorg/issues/200257

@jaywink

This was noticed again when @neb_alertmanager:matrix.org was trying to join a room on 2021-12-01 14:08:56 with ID containing TZrnFfySWI after being invited by @jaywink.

Relevant stack trace:

Stack trace

2021-12-01 14:08:56,850 - synapse.http.server - 101 - ERROR - PUT-2311876 - Failed handle request via 'RoomSendEventRestServlet': <XForwardedForRequest at 0x7fe7a53f3bd8 method='PUT' uri='/_matrix/client/r0/rooms/%21redacted:federator.dev/send/m.room.message/go1638367736821254338?access_token=<redacted>' clientproto='HTTP/1.1' site='8138'>
Capture point (most recent call last):
  File "/usr/local/lib/python3.7/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/usr/local/lib/python3.7/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/home/synapse/src/synapse/app/generic_worker.py", line 508, in <module>
    start(sys.argv[1:])
  File "/home/synapse/src/synapse/app/generic_worker.py", line 503, in start
    _base.start_worker_reactor("synapse-generic-worker", config)
  File "/home/synapse/src/synapse/app/_base.py", line 125, in start_worker_reactor
    run_command=run_command,
  File "/home/synapse/src/synapse/app/_base.py", line 177, in start_reactor
    run()
  File "/home/synapse/src/synapse/app/_base.py", line 161, in run
    run_command()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/base.py", line 1318, in run
    self.mainLoop()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/base.py", line 1328, in mainLoop
    reactorBaseSelf.runUntilCurrent()
  File "/home/synapse/src/synapse/metrics/__init__.py", line 645, in f
    ret = func(*args, **kwargs)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/base.py", line 967, in runUntilCurrent
    f(*a, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 662, in callback
    self._startRunCallbacks(result)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 764, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 859, in _runCallbacks
    current.result, *args, **kwargs
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1751, in gotResult
    current_context.run(_inlineCallbacks, r, gen, status)
Traceback (most recent call last):
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1661, in _inlineCallbacks
    result = current_context.run(gen.send, result)
  File "/home/synapse/src/synapse/rest/client/room.py", line 272, in on_POST
    requester, event_dict, txn_id=txn_id
  File "/home/synapse/src/synapse/handlers/message.py", line 858, in create_and_send_nonmember_event
    depth=depth,
  File "/home/synapse/src/synapse/handlers/message.py", line 615, in create_event
    depth=depth,
  File "/home/synapse/src/synapse/util/metrics.py", line 106, in measured_func
    r = await func(self, *args, **kwargs)
  File "/home/synapse/src/synapse/handlers/message.py", line 959, in create_new_client_event
    ), "Attempting to create an event with no prev_events"
AssertionError: Attempting to create an event with no prev_events
2021-12-01 14:08:56,872 - synapse.access.http.8138 - 421 - INFO - PUT-2311876 - x.x.x.x - 8138 - {@neb_alertmanager:matrix.org} Processed request: 0.029sec/0.007sec (0.015sec, 0.000sec) (0.001sec/0.006sec/3) 55B 500 "PUT /_matrix/client/r0/rooms/%21redacted:federator.dev/send/m.room.message/go1638367736821254338?access_token=<redacted> HTTP/1.1" "Go-http-client/2.0" [0 dbevts]

Re above, this disappeared now, not sure if it was me 1) joining my matrix.org user to the room, 2) writing some events to the room (it was previously empty, just state events) or 3) re-inviting the bot to the room - but it's now happy.

I am seeing this issue on my self-hosted Synapse instance in one e2e-encrypted direct-message room with another user ("u2"). u2 dropped out of the Element Android client after I made a configuration error on the Identity server. This config error has been fixed meanwhile.

Still, when I attempt to send a message to u2 the following exception happens:

2021-12-12 08:39:57,112 - synapse.http.server - 97 - ERROR - PUT-606- Failed handle request via 'RoomSendEventRestServlet': <XForwardedForRequest at 0x7fb4fcc730d0 method='PUT' uri='/_matrix/client/r0/rooms/!rgZTHfiXTwUdnFmRPp:tgbyte.de/send/m.room.encrypted/$local.2e913437-5cb7-46c1-8574-214eec80b52b' clientproto='HTTP/1.1' site='8008'>
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/twisted/internet/defer.py", line 1661, in _inlineCallbacks
    result = current_context.run(gen.send, result)
  File "/usr/local/lib/python3.8/site-packages/synapse/rest/client/room.py", line 271, in on_POST
    ) = await self.event_creation_handler.create_and_send_nonmember_event(
  File "/usr/local/lib/python3.8/site-packages/synapse/handlers/message.py", line 850, in create_and_send_nonmember_event
    event, context = await self.create_event(
  File "/usr/local/lib/python3.8/site-packages/synapse/handlers/message.py", line 610, in create_event
    event, context = await self.create_new_client_event(
  File "/usr/local/lib/python3.8/site-packages/synapse/util/metrics.py", line 106, in measured_func
    r = await func(self, *args, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/synapse/handlers/message.py", line 957, in create_new_client_event
    assert (
AssertionError: Attempting to create an event with no prev_events

When u2 attempts to join the room (after restoring keys) synapse logs:

2021-12-12 08:36:02,567 - synapse.http.server - 97 - ERROR - POST-481- Failed handle request via 'RoomCreateRestServlet': <XForwardedForRequest at 0x7fb4f9c49ee0 method='POST' uri='/_matrix/client/r0/createRoom' clientproto='HTTP/1.1' site='8008'>
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/synapse/http/server.py", line 262, in _async_render_wrapper
    callback_return = await self._async_render(request)
  File "/usr/local/lib/python3.8/site-packages/synapse/http/server.py", line 451, in _async_render
    callback_return = await raw_callback_return
  File "/usr/local/lib/python3.8/site-packages/synapse/rest/client/room.py", line 89, in on_POST
    info, _ = await self._room_creation_handler.create_room(
  File "/usr/local/lib/python3.8/site-packages/synapse/handlers/room.py", line 817, in create_room
    last_stream_id = await self._send_events_for_new_room(
  File "/usr/local/lib/python3.8/site-packages/synapse/handlers/room.py", line 982, in _send_events_for_new_room
    await self.room_member_handler.update_membership(
  File "/usr/local/lib/python3.8/site-packages/synapse/handlers/room_member.py", line 486, in update_membership
    result = await self.update_membership_locked(
  File "/usr/local/lib/python3.8/site-packages/synapse/handlers/room_member.py", line 886, in update_membership_locked
    return await self._local_membership_update(
  File "/usr/local/lib/python3.8/site-packages/synapse/handlers/room_member.py", line 328, in _local_membership_update
    event, context = await self.event_creation_handler.create_event(
  File "/usr/local/lib/python3.8/site-packages/synapse/handlers/message.py", line 610, in create_event
    event, context = await self.create_new_client_event(
  File "/usr/local/lib/python3.8/site-packages/synapse/util/metrics.py", line 106, in measured_func
    r = await func(self, *args, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/synapse/handlers/message.py", line 957, in create_new_client_event
    assert (
AssertionError: Attempting to create an event with no prev_events

I have nightly backups of the Synapse state that I could restore. I also do have an Element Desktop client of u2 that has not been force-logged-out and of whose state I created a backup.

My homeserver is running Synapse v1.48.0.

Any ideas?

Edit: I see that #11243, which deals with this assertion, got merged yesterday. Any idea whether this will land in v1.49?

@ginkel

I wonder if the errors from @ginkel here are related to #11568?

Edit: I see that #11243, which deals with this assertion, got merged yesterday. Any idea whether this will land in v1.49?

Afraid not. That's scheduled for 1.50, to be released in the new year.

For searchability: the new phrase for this log line is 'Attempting to create a non-m.room.create event with no prev_events'.

https://sentry.matrix.org/sentry/synapse-matrixorg/issues/242065/?query=is%3Aunresolved appears to be another recent example, again with neb/RSS bot.

I've been bit by this bug and I'm not sure if it's due to data corruption, locale, or if I borked something in my attempts to fix.

The log shows multiple errors when I try to post to an existing room:

2022-02-26 13:15:47,156 - synapse.http.server - 95 - INFO - PUT-32264 - <XForwardedForRequest at 0x7fbd83ea23a0 method='PUT' uri='/_matrix/client/r0/rooms/!<removed>%3Achat.geekforbes.com/typing/%40lepr
asmurf%3Achat.geekforbes.com' clientproto='HTTP/1.1' site='8008'> SynapseError: 403 - User @leprasmurf:chat.geekforbes.com not in room !<removed>:chat.geekforbes.com

2022-02-26 13:15:47,187 - synapse.http.server - 95 - INFO - GET-32266 - <XForwardedForRequest at 0x7fbd84944a00 method='GET' uri='/_matrix/client/r0/rooms/!<removed>%3Achat.geekforbes.com/messages?limit
=20&dir=b&from=t2259-906458_91398659_0_2344659_216424_389_74954_1121410_15&filter=%7B%22lazy_load_members%22%3Atrue%7D' clientproto='HTTP/1.1' site='8008'> SynapseError: 403 - User @leprasmurf:chat.geekforbes.co
m not in room !<removed>:chat.geekforbes.com, and room previews are disabled

2022-02-26 13:15:47,189 - synapse.access.http.8008 - 427 - INFO - GET-32266 - 1.2.3.4 - 8008 - {@leprasmurf:chat.geekforbes.com} Processed request: 0.003sec/0.001sec (0.000sec, 0.003sec) (0.000sec/0.000sec
/0) 156B 403 "GET /_matrix/client/r0/rooms/!<removed>%3Achat.geekforbes.com/messages?limit=20&dir=b&from=t2259-906458_91398659_0_2344659_216424_389_74954_1121410_15&filter=%7B%22lazy_load_members%22%3At
rue%7D HTTP/1.1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.4 Chrome/94.0.4606.81 Electron/15.3.6 Safari/537.36" [0 dbevts]
2022-02-26 13:15:47,245 - synapse.http.server - 100 - ERROR - PUT-32267 - Failed handle request via 'RoomSendEventRestServlet': <XForwardedForRequest at 0x7fbd83f2a430 method='PUT' uri='/_matrix/client/r0/rooms/
!<removed>%3Achat.geekforbes.com/send/m.room.message/m1645881346525.59' clientproto='HTTP/1.1' site='8008'>
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
    result = current_context.run(gen.send, result)
  File "/usr/local/lib/python3.8/site-packages/synapse/rest/client/room.py", line 271, in on_POST
    ) = await self.event_creation_handler.create_and_send_nonmember_event(
  File "/usr/local/lib/python3.8/site-packages/synapse/handlers/message.py", line 854, in create_and_send_nonmember_event
    event, context = await self.create_event(
  File "/usr/local/lib/python3.8/site-packages/synapse/handlers/message.py", line 608, in create_event
    event, context = await self.create_new_client_event(
  File "/usr/local/lib/python3.8/site-packages/synapse/util/metrics.py", line 106, in measured_func
    r = await func(self, *args, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/synapse/handlers/message.py", line 974, in create_new_client_event
    assert (
AssertionError: Attempting to create a non-m.room.create event with no prev_events

2022-02-26 13:15:49,639 - synapse.http.server - 100 - ERROR - PUT-32270 - Failed handle request via 'RoomSendEventRestServlet': <XForwardedForRequest at 0x7fbd84216d90 method='PUT' uri='/_matrix/client/r0/rooms/
!<removed>%3Achat.geekforbes.com/send/m.room.message/m1645881346525.59' clientproto='HTTP/1.1' site='8008'>
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
    result = current_context.run(gen.send, result)
  File "/usr/local/lib/python3.8/site-packages/synapse/rest/client/room.py", line 271, in on_POST
    ) = await self.event_creation_handler.create_and_send_nonmember_event(
  File "/usr/local/lib/python3.8/site-packages/synapse/handlers/message.py", line 854, in create_and_send_nonmember_event
    event, context = await self.create_event(
  File "/usr/local/lib/python3.8/site-packages/synapse/handlers/message.py", line 608, in create_event
    event, context = await self.create_new_client_event(
  File "/usr/local/lib/python3.8/site-packages/synapse/util/metrics.py", line 106, in measured_func
    r = await func(self, *args, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/synapse/handlers/message.py", line 974, in create_new_client_event
    assert (
AssertionError: Attempting to create a non-m.room.create event with no prev_events

Synapse version: 1.53.0

This is happening to all the rooms that existed before. This example is a public room with no special permissions. Synapse-admin shows the room, shows my user in the room, and even shows the membership in the rooms state list (m.room.member event with my username).

New rooms seem to function without issue.

* edit1: Opened a dedicated issue for my instance as there seem to be more errors than listed here: 12147
* edit2: My issue was due to corruption in the database, more info in the linked issue.

We still see this today. At the time of writing, it is the noisiest error we see on Matrix.org's Sentry deployment.

I briefly looked at https://sentry.tools.element.io/organizations/element/issues/38924/events/f519ef8661df429fbbee8dac8dbb4fd9/?project=2 today. It seems to be as AS user controlled by neb_rssbot trying to post an m.room.message/m.notice message to a room.

The room in question

exists in the rooms table
has an event in the events table
has no rows in the current_state_events table
has no rows in the event_forward_extremities table

As an aside: how many stateless- and forward-extremityless rooms are there on matrix.org? Answer: lots.

matrix=> SELECT COUNT(*)
FROM rooms
WHERE NOT EXISTS (
    SELECT 1 FROM current_state_events cse WHERE cse.room_id = rooms.room_id
);
  count  
═════════
 1685836
(1 row)

Time: 35840.859 ms (00:35.841)

matrix=> SELECT COUNT(*)
matrix-> FROM rooms
matrix-> WHERE NOT EXISTS (
matrix(>     SELECT 1 FROM event_forward_extremities efe WHERE efe.room_id = rooms.room_id
matrix(> );
 count  
════════
 614767
(1 row)

As an aside: how many stateless- and forward-extremityless rooms are there on matrix.org? Answer: lots.

matrix=> SELECT COUNT(*)
FROM rooms
WHERE NOT EXISTS (
    SELECT 1 FROM current_state_events cse WHERE cse.room_id = rooms.room_id
);
  count  
═════════
 1685836
(1 row)

Time: 35840.859 ms (00:35.841)

matrix=> SELECT COUNT(*)
matrix-> FROM rooms
matrix-> WHERE NOT EXISTS (
matrix(>     SELECT 1 FROM event_forward_extremities efe WHERE efe.room_id = rooms.room_id
matrix(> );
 count  
════════
 614767
(1 row)

Curiously, the number of such rooms is still going up:

matrix=> SELECT COUNT(*) FROM rooms WHERE NOT EXISTS (SELECT 1 FROM current_state_events cse WHERE cse.room_id = rooms.room_id);
  count
---------
 1697883
(1 row)

matrix=> SELECT COUNT(*) FROM rooms WHERE NOT EXISTS (SELECT 1 FROM event_forward_extremities efe WHERE efe.room_id = rooms.room_id);
 count
--------
 615352
(1 row)

so we have one or more bugs to track down.

Fix error when sending message into deleted room.

Fix error when sending message into deleted room. (#15235)

Curiously, the number of such rooms is still going up:

matrix=> SELECT COUNT(*) FROM rooms WHERE NOT EXISTS (SELECT 1 FROM current_state_events cse WHERE cse.room_id = rooms.room_id);
  count
---------
 1697883
(1 row)

matrix=> SELECT COUNT(*) FROM rooms WHERE NOT EXISTS (SELECT 1 FROM event_forward_extremities efe WHERE efe.room_id = rooms.room_id);
 count
--------
 615352
(1 row)

Still rising:

matrix=> \d events
matrix=> SELECT COUNT(*) FROM rooms WHERE NOT EXISTS (SELECT 1 FROM current_state_events cse WHERE cse.room_id = rooms.room_id);
  count  
═════════
 2317176
(1 row)

Time: 72796.016 ms (01:12.796)
matrix=> SELECT COUNT(*) FROM rooms WHERE NOT EXISTS (SELECT 1 FROM event_forward_extremities efe WHERE efe.room_id = rooms.room_id);
 count  
════════
 674405
(1 row)

Time: 9279.226 ms (00:09.279)

I think that will happen if the server leaves the room, no?

Oh, maybe. I'd naively expect that room's row to be deleted from the rooms table if that was the case though. 🤷

Navigation Menu

Repository navigation

lots of AssertionError: 'Attempting to create an event with no prev_events' #8094

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

lots of AssertionError: 'Attempting to create an event with no prev_events' #8094

Description

Activity

richvdh commented on Aug 14, 2020

richvdh commented on Oct 8, 2020

richvdh commented on Oct 8, 2020

clokep commented on Jan 27, 2021

richvdh commented on Sep 23, 2021

anoadragon453 commented on Dec 1, 2021

jaywink commented on Dec 1, 2021

ginkel commented on Dec 12, 2021

DMRobertson commented on Dec 14, 2021

reivilibre commented on Feb 21, 2022

leprasmurf commented on Feb 26, 2022

DMRobertson commented on Oct 24, 2022

squahtx commented on Oct 31, 2022

DMRobertson commented on Aug 29, 2023

erikjohnston commented on Aug 29, 2023

DMRobertson commented on Aug 29, 2023

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions