history purge does not remove `redactions`, causing backfill to fail

[jwh]

Description

2020-11-03 00:15:22,910 - synapse.handlers.federation - 596 - WARNING - GET-101024 - Failed to fetch missing state/auth events for $-UIzk2q1h4lzcIoiH8PbTmj8J3-LIJS04l_1bcozSeo {'$xM3Wv8GUU39u2ihr3I1xY2C4kxirgTqqtQqqYlZdqG4', '$6t2x6QF6MYqInr976BQrqd5fc9G8IUkhwa3OPTIEC7E', '$lLR9FKrM-R0J_lFgTZ8lRTj5u9hB6UUv4TbUVTfHepY', '$xAMXdmqI5m6yCvohFsX61GMzEn9ntoQVOiNjR8i_jmY', '$kLFaE-QKOnRoRtM3stSDUav0EzOi_PX2R_9TGp23m0A', '$Gsv4UnCSnaoim7CV3_3LbRaVZUTcxLuhImAwL7_z5Ss', '$5pJ-oeWmqWE-mBHvyhC_C5QqqIEXi2fpa1p1JBJD8HM', '$dSFyjXMIVWwrnTwZBofMgggmFcfWpF5S-qd0LBcEy2c', '$NqZw81jCfyk9yXt3KVk3YqS4w_k3qEw49yyVRJsoUtU', '$BRrLqFq4-JKxoFm61DxYa3Zxbl7BVXl3WGU7OJ7hslM'}
2020-11-03 00:15:23,064 - synapse.handlers.federation - 1129 - ERROR - GET-101024 - Failed to backfill from maunium.net because FirstError[#0, [Failure instance: Traceback: <class 'psycopg2.errors.UniqueViolation'>: duplicate key value violates unique constraint "redactions_event_id_key"
DETAIL:  Key (event_id)=($-UIzk2q1h4lzcIoiH8PbTmj8J3-LIJS04l_1bcozSeo) already exists.

/usr/lib/python3.8/site-packages/twisted/internet/defer.py:654:_runCallbacks
/usr/lib/python3.8/site-packages/twisted/internet/defer.py:1475:gotResult
/usr/lib/python3.8/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/usr/lib/python3.8/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
--- <exception caught here> ---
/usr/lib/python3.8/site-packages/synapse/storage/persist_events.py:150:handle_queue_loop
/usr/lib/python3.8/site-packages/synapse/storage/persist_events.py:302:persisting_queue
/usr/lib/python3.8/site-packages/synapse/storage/persist_events.py:502:_persist_events
/usr/lib/python3.8/site-packages/synapse/storage/databases/main/events.py:161:_persist_events_and_state_updates
/usr/lib/python3.8/site-packages/synapse/storage/database.py:627:runInteraction
/usr/lib/python3.8/site-packages/synapse/storage/database.py:707:runWithConnection
/usr/lib/python3.8/site-packages/twisted/python/threadpool.py:250:inContext
/usr/lib/python3.8/site-packages/twisted/python/threadpool.py:266:<lambda>
/usr/lib/python3.8/site-packages/twisted/python/context.py:122:callWithContext
/usr/lib/python3.8/site-packages/twisted/python/context.py:85:callWithContext
/usr/lib/python3.8/site-packages/twisted/enterprise/adbapi.py:306:_runWithConnection
/usr/lib/python3.8/site-packages/twisted/python/compat.py:464:reraise
/usr/lib/python3.8/site-packages/twisted/enterprise/adbapi.py:297:_runWithConnection
/usr/lib/python3.8/site-packages/synapse/storage/database.py:702:inner_func
/usr/lib/python3.8/site-packages/synapse/storage/database.py:505:new_transaction
/usr/lib/python3.8/site-packages/synapse/logging/utils.py:71:wrapped
/usr/lib/python3.8/site-packages/synapse/storage/databases/main/events.py:399:_persist_events_txn
/usr/lib/python3.8/site-packages/synapse/storage/databases/main/events.py:954:_update_metadata_tables_txn
/usr/lib/python3.8/site-packages/synapse/storage/databases/main/events.py:1060:_store_redaction
/usr/lib/python3.8/site-packages/synapse/storage/database.py:809:simple_insert_txn
/usr/lib/python3.8/site-packages/synapse/storage/database.py:266:execute
/usr/lib/python3.8/site-packages/synapse/storage/database.py:292:_do_execute
]]
Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/synapse/handlers/federation.py", line 1097, in try_backfill
    await self.backfill(
  File "/usr/lib/python3.8/site-packages/synapse/handlers/federation.py", line 909, in backfill
    await self._handle_new_events(dest, room_id, ev_infos, backfilled=True)
  File "/usr/lib/python3.8/site-packages/synapse/handlers/federation.py", line 1940, in _handle_new_events
    await self.persist_events_and_notify(
  File "/usr/lib/python3.8/site-packages/synapse/handlers/federation.py", line 2912, in persist_events_and_notify
    events, max_stream_token = await self.storage.persistence.persist_events(
  File "/usr/lib/python3.8/site-packages/synapse/storage/persist_events.py", line 240, in persist_events
    ret_vals = await make_deferred_yieldable(
twisted.internet.defer.FirstError: FirstError[#0, [Failure instance: Traceback: <class 'psycopg2.errors.UniqueViolation'>: duplicate key value violates unique constraint "redactions_event_id_key"
DETAIL:  Key (event_id)=($-UIzk2q1h4lzcIoiH8PbTmj8J3-LIJS04l_1bcozSeo) already exists.

/usr/lib/python3.8/site-packages/twisted/internet/defer.py:654:_runCallbacks
/usr/lib/python3.8/site-packages/twisted/internet/defer.py:1475:gotResult
/usr/lib/python3.8/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/usr/lib/python3.8/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
--- <exception caught here> ---
/usr/lib/python3.8/site-packages/synapse/storage/persist_events.py:150:handle_queue_loop
/usr/lib/python3.8/site-packages/synapse/storage/persist_events.py:302:persisting_queue
/usr/lib/python3.8/site-packages/synapse/storage/persist_events.py:502:_persist_events
/usr/lib/python3.8/site-packages/synapse/storage/databases/main/events.py:161:_persist_events_and_state_updates
/usr/lib/python3.8/site-packages/synapse/storage/database.py:627:runInteraction
/usr/lib/python3.8/site-packages/synapse/storage/database.py:707:runWithConnection
/usr/lib/python3.8/site-packages/twisted/python/threadpool.py:250:inContext
/usr/lib/python3.8/site-packages/twisted/python/threadpool.py:266:<lambda>
/usr/lib/python3.8/site-packages/twisted/python/context.py:122:callWithContext
/usr/lib/python3.8/site-packages/twisted/python/context.py:85:callWithContext
/usr/lib/python3.8/site-packages/twisted/enterprise/adbapi.py:306:_runWithConnection
/usr/lib/python3.8/site-packages/twisted/python/compat.py:464:reraise
/usr/lib/python3.8/site-packages/twisted/enterprise/adbapi.py:297:_runWithConnection
/usr/lib/python3.8/site-packages/synapse/storage/database.py:702:inner_func
/usr/lib/python3.8/site-packages/synapse/storage/database.py:505:new_transaction
/usr/lib/python3.8/site-packages/synapse/logging/utils.py:71:wrapped
/usr/lib/python3.8/site-packages/synapse/storage/databases/main/events.py:399:_persist_events_txn
/usr/lib/python3.8/site-packages/synapse/storage/databases/main/events.py:954:_update_metadata_tables_txn
/usr/lib/python3.8/site-packages/synapse/storage/databases/main/events.py:1060:_store_redaction
/usr/lib/python3.8/site-packages/synapse/storage/database.py:809:simple_insert_txn
/usr/lib/python3.8/site-packages/synapse/storage/database.py:266:execute
/usr/lib/python3.8/site-packages/synapse/storage/database.py:292:_do_execute
]]

Steps to reproduce

• Setup fresh Synapse instance
• use it, after a few days rooms appear as unread and are missing history or element think there is history when there isn't
• suffer

This time round (2nd time this exact issue has happened), the affected rooms are:

• @appservice-irc:matrix.org (some history appears, element thinks there is unread history prior to the creation of the room)
• 3 local mautrix bridges (no history, element thinks there is unread history prior to the creation of the room)

No errors are emitted by synapse, element just returns a permission denied type message when hitting "jump to unread"

Version information

1.20.0 -> 1.22.1

• Install method:
  pip

• Platform:
  Arch, LXD container

[jwh]

I'm not sure the duplicate key issues and the broken rooms are related as the events in question aren't related to the rooms that are broken, they appear to be arbitary - whats more odd is that it only seems to happen when I'm away from my machine and element is idle

[erikjohnston]

That sounds worrying. Can you share your full logs please (at INFO level if they're at WARN currently)?

[jwh]

I'll see if I can reproduce it, I already have logging set to DEBUG so hopefully I'll be able to catch it - separately though I was under the impression that the redactions issue was fixed but it does seem to happen with the latest release, only for that particular room though - perhaps some broken events being received from some servers? not really sure how to diagnose that

[erikjohnston]

Thanks! Yup, I thought the redactions problem was fixed, but perhaps it didn't fix existing problems?

[jwh]

I'm pretty sure I saw it after a fresh install on 1.22 but I'll see if I can rejoin a few rooms and trigger it

[jwh]

Alright, so pretty sure the history weirdness is just an element issue, only 1 error and 3 warnings (unrelated) logged with DEBUG on, and triggering activity from another client fixes the state on the broken element instance - haven't seen the redactions issue again, sorry for the noise! just spotted it, I'll pester you on matrix if you don't mind so I can share the logs

[erikjohnston]

Had a chat with @jwh and it looks like this is caused by the fact that purging history in the room doesn't appear to delete from the redactions table:

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

Lines 206 to 216 in 7941372

	for table in (
	"events",
	"event_json",
	"event_auth",
	"event_edges",
	"event_forward_extremities",
	"event_reference_hashes",
	"event_relations",
	"event_search",
	"rejections",
	):

In @jwh this was caused by using the room retention settings, but it will also affect anyone who uses the purge history admin API.

[richvdh]

I'm not really sure what this issue is about - could someone update the summary to be clearer?