federation_inbound_events_staging is not cleared when a room is purged

[cremesk]

Description

since #11806 has been fixed, I now see the following message in my log:

2022-01-26 11:21:14,293 - synapse.metrics.background_process_metrics - 244 - ERROR - _handle_old_staged_events-1273 - Background process '_handle_old_staged_events' threw an exception
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/metrics/background_process_metrics.py", line 242, in run
    return await func(*args, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/federation/federation_server.py", line 170, in _handle_old_staged_events
    room_version = await self.store.get_room_version(room_id)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/databases/main/state.py", line 65, in get_room_version
    return await self.db_pool.runInteraction(
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/database.py", line 741, in runInteraction
    result = await self.runWithConnection(
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/database.py", line 846, in runWithConnection
    return await make_deferred_yieldable(
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/python/threadpool.py", line 238, in inContext
    result = inContext.theWork()  # type: ignore[attr-defined]
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/python/threadpool.py", line 254, in <lambda>
    inContext.theWork = lambda: context.call(  # type: ignore[attr-defined]
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/python/context.py", line 118, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/python/context.py", line 83, in callWithContext
    return func(*args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/enterprise/adbapi.py", line 293, in _runWithConnection
    compat.reraise(excValue, excTraceback)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/python/deprecate.py", line 298, in deprecatedFunction
    return function(*args, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/python/compat.py", line 404, in reraise
    raise exception.with_traceback(traceback)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/enterprise/adbapi.py", line 284, in _runWithConnection
    result = func(conn, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/database.py", line 841, in inner_func
    return func(db_conn, *args, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/database.py", line 609, in new_transaction
    r = func(cursor, *args, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/databases/main/state.py", line 84, in get_room_version_txn
    room_version_id = self.get_room_version_id_txn(txn, room_id)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/databases/main/state.py", line 132, in get_room_version_id_txn
    raise NotFoundError("Could not room_version for %s" % (room_id,))
synapse.api.errors.NotFoundError: 404: Could not room_version for !YDqJPFEKtBIEGBHqZE:matrix.org

Version information

• Homeserver: envs.net
• Version: v1.51.0
• Install method: package manager
• Platform: VM / Debian 11

[cremesk]

maybe the issue is related to: #11808 ?

[reivilibre]

maybe the issue is related to: #11808 ?

I don't think it's likely, sorry — you'd run into the same issue with that.

[DMRobertson]

Hi @cremesk, that room was recently the victim of some spam. It is possible the room was recently purged (via the admin delete room API)?. There's a known problem involving purging a room and later rejoining it, see #11521.

[DMRobertson]

Otherwise, are there any other logs containing that room ID? Is that error message appearing repeatedly, or did it only show up once?

[cremesk]

Hi @cremesk, that room was recently the victim of some spam. It is possible the room was recently purged (via the admin delete room API)?. There's a known problem involving purging a room and later rejoining it, see #11521.

ah okay I see.. yes this is probably really the problem. I had actually nuke the room before.

Otherwise, are there any other logs containing that room ID? Is that error message appearing repeatedly, or did it only show up once?

no sorry. i can't find other logs with the room_id.

[DMRobertson]

Thanks for confirming (and reporting!). Let's mark this as a duplicate of #11521.

[richvdh]

I think it's slightly different to #11521, in that #11521 is about what happens when you try to rejoin the room, whereas this is due to events continuing to arrive over federation (or due to them being stacked up in the queue - not sure we actively purge the incoming federation queue on room purge?)

There's certainly a common root cause in that we don't correctly clear the in-memory caches after a purge, though.

[cremesk]

i have now removed 'federation_inbound_events_staging' from the deleted room. so it seems like I no longer get the log message 'Background process' _handle_old_staged_events 'throw an exception`

DELETE FROM federation_inbound_events_staging where room_id='!YDqJPFEKtBIEGBHqZE:matrix.org';
DELETE 27024

(most of the messages were from matrix.kiwifarms.net)

[richvdh]

right, so I think there is an easy fix to this particular case, which is to clear out the staging table when the room is purged.

[erikjohnston]

This is just a case of adding the table to the list:

synapse/synapse/storage/databases/main/purge_events.py

Lines 394 to 423 in d66d68f

	for table in (
	"current_state_events",
	"destination_rooms",
	"event_backward_extremities",
	"event_forward_extremities",
	"event_push_actions",
	"event_search",
	"events",
	"group_rooms",
	"receipts_graph",
	"receipts_linearized",
	"room_aliases",
	"room_depth",
	"room_memberships",
	"room_stats_state",
	"room_stats_current",
	"room_stats_earliest_token",
	"stream_ordering_to_exterm",
	"users_in_public_rooms",
	"users_who_share_private_rooms",
	# no useful index, but let's clear them anyway
	"appservice_room_list",
	"e2e_room_keys",
	"event_push_summary",
	"pusher_throttle",
	"group_summary_rooms",
	"room_account_data",
	"room_tags",
	"local_current_membership",
	):

[DMRobertson]

(Would foreign keys make it obvious that we missed this?)