"No state group for unknown or outlier event" error in federation

[mytbk]

Description

In synapse to 1.60.0, I found the "No state group for unknown or outlier event" run time error in the journal (in log output section).

There are a lot of such events, giving a runtime error about once per minute.

Steps to reproduce

Start the synapse service and view the log with journalctl, then see the runtime errors.

Homeserver

matrixim.cc

Synapse Version

{"server_version":"1.60.0","python_version":"3.10.5"}

Installation Method

Other (please mention below)

Platform

Arch Linux matrix-synapse package 1.60.0-1.

Relevant log output

Jun 11 02:19:58 matrixim synapse[3229]: 2022-06-11 02:19:58,370 - synapse.federation.sender.per_destination_queue - 374 - ERROR - federation_trans
action_transmission_loop-1388 - TX [matrix.lokiberra.tk] Failed to send transaction
Jun 11 02:19:58 matrixim synapse[3229]: Traceback (most recent call last):
Jun 11 02:19:58 matrixim synapse[3229]:   File "/usr/lib/python3.10/site-packages/twisted/internet/defer.py", line 1661, in _inlineCallbacks
Jun 11 02:19:58 matrixim synapse[3229]:     result = current_context.run(gen.send, result)
Jun 11 02:19:58 matrixim synapse[3229]: StopIteration: []
Jun 11 02:19:58 matrixim synapse[3229]: During handling of the above exception, another exception occurred:
Jun 11 02:19:58 matrixim synapse[3229]: Traceback (most recent call last):
Jun 11 02:19:58 matrixim synapse[3229]:   File "/usr/lib/python3.10/site-packages/synapse/federation/sender/per_destination_queue.py", line 279, in _transaction_transmission_loop
Jun 11 02:19:58 matrixim synapse[3229]:     await self._catch_up_transmission_loop()
Jun 11 02:19:58 matrixim synapse[3229]:   File "/usr/lib/python3.10/site-packages/synapse/federation/sender/per_destination_queue.py", line 494, in _catch_up_transmission_loop
Jun 11 02:19:58 matrixim synapse[3229]:     hosts = await self._state.get_hosts_in_room_at_events(
Jun 11 02:19:58 matrixim synapse[3229]:   File "/usr/lib/python3.10/site-packages/synapse/state/__init__.py", line 258, in get_hosts_in_room_at_events
Jun 11 02:19:58 matrixim synapse[3229]:     entry = await self.resolve_state_groups_for_events(room_id, event_ids)
Jun 11 02:19:58 matrixim synapse[3229]:   File "/usr/lib/python3.10/site-packages/synapse/util/metrics.py", line 113, in measured_func
Jun 11 02:19:58 matrixim synapse[3229]:     r = await func(self, *args, **kwargs)
Jun 11 02:19:58 matrixim synapse[3229]:   File "/usr/lib/python3.10/site-packages/synapse/state/__init__.py", line 421, in resolve_state_groups_for_events
Jun 11 02:19:58 matrixim synapse[3229]:     state_groups = await self.state_store.get_state_group_for_events(event_ids)
Jun 11 02:19:58 matrixim synapse[3229]:   File "/usr/lib/python3.10/site-packages/synapse/storage/state.py", line 868, in get_state_group_for_events
Jun 11 02:19:58 matrixim synapse[3229]:     return await self.stores.main._get_state_group_for_events(event_ids)
Jun 11 02:19:58 matrixim synapse[3229]:   File "/usr/lib/python3.10/site-packages/twisted/internet/defer.py", line 1661, in _inlineCallbacks
Jun 11 02:19:58 matrixim synapse[3229]:     result = current_context.run(gen.send, result)
Jun 11 02:19:58 matrixim synapse[3229]:   File "/usr/lib/python3.10/site-packages/synapse/storage/databases/main/state.py", line 331, in _get_state_group_for_events
Jun 11 02:19:58 matrixim synapse[3229]:     raise RuntimeError("No state group for unknown or outlier event %s" % e)
Jun 11 02:19:58 matrixim synapse[3229]: RuntimeError: No state group for unknown or outlier event $j6Qxtlh-qcXquAz1rwD_9apbSIFn3x8D-9I5zTsJruA

Anything else that would be useful to know?

No response

[richvdh]

possibly related to #12507.

[erikjohnston]

This looks like a duplicate of #12507 to me.

[mytbk]

1.61.0 still has this issue.
From the traceback, this doesn't seem to be the same as #12507, although they have the same exception.

[mytbk]

Also, the query select * from event_forward_extremities efe left join events e using (event_id) where e.event_id is null; in #12507 (comment) returns 0 rows.

[richvdh]

not the same as #12507 then!

[mytbk]

In 1.61.0, I observe another exception that also emits "No state group for unknown or outlier event", don't know what happens. Some exception begins with "Exception: Error fetching missing prev_events for ...", and some StopIteration exception.

Here's the log of ~2min since one start.
1.txt

[mweinelt]

@mytbk Curious, are you using retention settings and/or https://github.com/matrix-org/rust-synapse-compress-state/?

[mytbk]

@mweinelt

My retention settings:

retention:
  enabled: true

  default_policy:
    min_lifetime: 1d
    max_lifetime: 1y

  allowed_lifetime_min: 1d
  allowed_lifetime_max: 1y

  purge_jobs:
    - longest_max_lifetime: 3d
      interval: 12h
    - shortest_max_lifetime: 3d
      interval: 1d

I also used rust-synapse-compress-state before.

[FrankNagel]

I may be in a similar situation: I have configured a default retention time of 240d on my server (and I run rust-synapse-compress-state as a cron job every night). Some days ago I joined !OGEhHVWSdvArJzumhm:matrix.org (#matrix.matrix.org) and two days later the room stopped syncing. I investigated the forward extremities of this room and got two different results from the API and querying the DB directly:

API:

# curl --header "Authorization: Bearer XXX" 'https://matrix.uni-marburg.de/_synapse/admin/v1/rooms/!OGEhHVWSdvArJzumhm:matrix.org/forward_extremities' | jq .

{
  "count": 5,
  "results": [
    {
      "event_id": "$w__T5VCKv34SVaoVF4LoIynZDo5QqJ4mgzCq9XCaaAg",
      "state_group": 79056,
      "depth": 466487,
      "received_ts": 1656433481438
    },
    {
      "event_id": "$FJU7WQNE9c1QcZYZvh5p9o_f1mnXBPuoYbccaCWZNbk",
      "state_group": 80290,
      "depth": 466977,
      "received_ts": 1656600524544
    },
    {
      "event_id": "$m9S8nYfhe-MBDODoxTR-33HRd8-jtt35KoVUV7AbGuQ",
      "state_group": 79705,
      "depth": 465281,
      "received_ts": 1656529102606
    },
    {
      "event_id": "$3uLkuz0dKwartpR4_qTPEKezBtp31a0goxBZXfnU9nw",
      "state_group": 79711,
      "depth": 463617,
      "received_ts": 1656348839094
    },
    {
      "event_id": "$X-1osxxtdtlvcre3QZEcIooCMl3qGE4epxL5ahiLQ8E",
      "state_group": 79709,
      "depth": 463617,
      "received_ts": 1656348838539
    }
  ]
}

DB:

synapse=# select to_timestamp(e.origin_server_ts/1000), e.* readable_os_ts from events as e join event_forward_extremities efe on e.event_id = efe.event_id where e.room_id = '!OGEhHVWSdvArJzumhm:matrix.org' order by origin_server_ts DESC;
    
          to_timestamp      | 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 |          state_key          | rejection_reason
    ------------------------+----------------------+----------------------------------------------+------------------------+--------------------------------+---------+-------------------+-----------+---------+--------+------------------+---------------+--------------------------------+--------------+---------------+-----------------+-----------------------------+------------------
     2022-06-30 16:47:57+02 |               466977 | $FJU7WQNE9c1QcZYZvh5p9o_f1mnXBPuoYbccaCWZNbk | m.room.member          | !OGEhHVWSdvArJzumhm:matrix.org |         |                   | t         | f       | 466977 |    1656600477278 | 1656600524544 | @drdrjojo:matrix.org           | f            | master        |         3353182 | @drdrjojo:matrix.org        |
     2022-06-28 18:23:20+02 |               466487 | $w__T5VCKv34SVaoVF4LoIynZDo5QqJ4mgzCq9XCaaAg | org.matrix.dummy_event | !OGEhHVWSdvArJzumhm:matrix.org |         |                   | t         | f       | 466487 |    1656433400757 | 1656433481438 | @nagelfr:matrix.uni-marburg.de | f            | master        |         3347260 |                             |
     2022-06-25 15:15:33+02 |               465281 | $m9S8nYfhe-MBDODoxTR-33HRd8-jtt35KoVUV7AbGuQ | m.room.message         | !OGEhHVWSdvArJzumhm:matrix.org |         |                   | t         | f       | 465281 |    1656162933269 | 1656529102606 | @ninchuka:envs.net             | f            | master        |         3350666 |                             |
     2022-06-20 08:44:44+02 |               463617 | $X-1osxxtdtlvcre3QZEcIooCMl3qGE4epxL5ahiLQ8E | m.room.member          | !OGEhHVWSdvArJzumhm:matrix.org |         |                   | t         | f       | 463617 |    1655707484365 | 1656348838539 | @seastar8170:matrix.org        | f            | master        |        -1157546 | @seastar8170:matrix.org     |
     2022-06-20 08:44:25+02 |               463617 | $3uLkuz0dKwartpR4_qTPEKezBtp31a0goxBZXfnU9nw | m.room.member          | !OGEhHVWSdvArJzumhm:matrix.org |         |                   | t         | f       | 463617 |    1655707465432 | 1656348839094 | @NormietoTechie:libera.chat    | f            | master        |        -1158279 | @NormietoTechie:libera.chat |
     2021-10-16 22:25:50+02 |               361271 | $bCFEYaBSTOOLr8326cbXpy6V7I-N3E2YxlbC5ddpZ1s | m.room.member          | !OGEhHVWSdvArJzumhm:matrix.org |         |                   | t         | t       | 361271 |    1634415950431 | 1656348857068 | @testuser88:schoeneberge.eu    | f            | master        |        -1175678 | @testuser88:schoeneberge.eu |
    (6 rows)

The DB shows one entry more than the API i.e. $bCFEYaBSTOOLr8326cbXpy6V7I-N3E2YxlbC5ddpZ1s.

Every event I receive for #matrix.matrix.org fails at the end with an exception as follows:

2022-07-06 10:37:16,905 - synapse.federation.federation_server - 1156 - ERROR - _process_incoming_pdus_in_room_inner-74 - Failed to handle PDU $_tsx0pE8rlFcqDf7kvOnsa6yccs45Sd732OUdqATPBY
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
    result = current_context.run(gen.send, result)
StopIteration: [{'event_id': '$3uLkuz0dKwartpR4_qTPEKezBtp31a0goxBZXfnU9nw', 'state_group': 79711}, {'event_id': '$FJU7WQNE9c1QcZYZvh5p9o_f1mnXBPuoYbccaCWZNbk', 'state_group': 80290}, {'event_id': '$X-1osxxtdtlvcre3QZEcIooCMl3qGE4epxL5ah
iLQ8E', 'state_group': 79709}, {'event_id': '$m9S8nYfhe-MBDODoxTR-33HRd8-jtt35KoVUV7AbGuQ', 'state_group': 79705}, {'event_id': '$w__T5VCKv34SVaoVF4LoIynZDo5QqJ4mgzCq9XCaaAg', 'state_group': 79056}]

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 236, in on_receive_pdu
    await self._get_missing_events_for_pdu(
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 687, in _get_missing_events_for_pdu
    await self._process_pulled_events(origin, missing_events, backfilled=False)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 725, in _process_pulled_events
    await self._process_pulled_event(origin, ev, backfilled=backfilled)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 781, in _process_pulled_event
    await self._process_received_pdu(
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 1112, in _process_received_pdu
    await self._check_for_soft_fail(event, state_ids, origin=origin)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 1636, in _check_for_soft_fail
    state_sets_d = await self._state_storage_controller.get_state_groups_ids(
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/controllers/state.py", line 103, in get_state_groups_ids
    event_to_groups = await self.get_state_group_for_events(event_ids)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/controllers/state.py", line 341, in get_state_group_for_events
    return await self.stores.main._get_state_group_for_events(event_ids)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
    result = current_context.run(gen.send, result)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/databases/main/state.py", line 376, in _get_state_group_for_events
    raise RuntimeError("No state group for unknown or outlier event %s" % e)
RuntimeError: No state group for unknown or outlier event $bCFEYaBSTOOLr8326cbXpy6V7I-N3E2YxlbC5ddpZ1s

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/federation/federation_server.py", line 1146, in _process_incoming_pdus_in_room_inner
    await self._federation_event_handler.on_receive_pdu(
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 240, in on_receive_pdu
    raise Exception(
Exception: Error fetching missing prev_events for $_tsx0pE8rlFcqDf7kvOnsa6yccs45Sd732OUdqATPBY: No state group for unknown or outlier event $bCFEYaBSTOOLr8326cbXpy6V7I-N3E2YxlbC5ddpZ1s

As you can see the event mentioned in the Traceback is the one extra forward extremity in the database.

My working hyposthesis is, that bad things start to happen if you get forward extremities outside the retention window which may or may not have something to do with the use of rust-synapse-compress-state.

[FrankNagel]

First I tried increase the retention time which did not resolve my issue. But a

synapse=# delete from event_forward_extremities where event_id = '$bCFEYaBSTOOLr8326cbXpy6V7I-N3E2YxlbC5ddpZ1s';

got the room to sync again.

[mweinelt]

I can confirm that got rooms for me working as well.