Message retention expiry causes 'Duplicate key value violates unique constraint "event_relations_id"'

[pv]

Description

Running synapse homeserver, with freshly created DB, ends up with database integrity errors appearing in the logs after a few days. In usage, these appear as timeline backfill failing to fill in beyond 1-2 days back. The (experimental) retention feature is enabled, might have to do with this.

Error traceback:

2020-06-13 15:25:39,124 - synapse.storage.data_stores.main.events - 95 - ERROR - persist_events-9 - IntegrityError, retrying.
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py", line 93, in f
    res = yield func(self, *args, delete_existing=False, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/venvs/matrix-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/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py", line 211, in _persist_events_and_state_updates
    new_forward_extremeties=new_forward_extremeties,
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/venvs/matrix-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/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py", line 527, in runInteraction
    **kwargs
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/venvs/matrix-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/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py", line 575, in runWithConnection
    self._db_pool.runWithConnection(inner_func, *args, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/threadpool.py", line 250, in inContext
    result = inContext.theWork()
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/threadpool.py", line 266, in <lambda>
    inContext.theWork = lambda: context.call(ctx, func, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/context.py", line 122, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/context.py", line 85, in callWithContext
    return func(*args,**kw)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/enterprise/adbapi.py", line 306, in _runWithConnection
    compat.reraise(excValue, excTraceback)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/compat.py", line 464, in reraise
    raise exception.with_traceback(traceback)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/enterprise/adbapi.py", line 297, in _runWithConnection
    result = func(conn, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py", line 572, in inner_func
    return func(conn, *args, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py", line 418, in new_transaction
    r = func(cursor, *args, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/logging/utils.py", line 73, in wrapped
    return f(*args, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py", line 451, in _persist_events_txn
    backfilled=backfilled,
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py", line 1001, in _update_metadata_tables_txn
    self._handle_event_relations(txn, event)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py", line 1299, in _handle_event_relations
    "aggregation_key": aggregation_key,
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py", line 653, in simple_insert_txn
    txn.execute(sql, vals)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py", line 210, in execute
    self._do_execute(self.txn.execute, sql, *args)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py", line 236, in _do_execute
    return func(sql, *args)
psycopg2.errors.UniqueViolation: duplicate key value violates unique constraint "event_relations_id"
DETAIL:  Key (event_id)=($hnVIuNuExbqJ-9iXkDpaRAGdKdeDue4YI8w9G1qOSHc) already exists.

2020-06-13 15:25:39,130 - synapse.storage.data_stores.main.events - 815 - INFO - persist_events-9 - Deleting existing
2020-06-13 15:25:39,147 - synapse.handlers.federation - 1064 - ERROR - GET-1637 - Failed to backfill from matrix.org because FirstError[#0, [Failure instance: Traceback: <class 'psycopg2.errors.UniqueViolation'>: duplicate key value violates unique constraint "event_relations_id"
DETAIL:  Key (event_id)=($hnVIuNuExbqJ-9iXkDpaRAGdKdeDue4YI8w9G1qOSHc) already exists.

/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py:654:_runCallbacks
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py:1475:gotResult
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
--- <exception caught here> ---
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/persist_events.py:152:handle_queue_loop
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/persist_events.py:262:persisting_queue
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/persist_events.py:438:_persist_events
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py:96:f
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py:211:_persist_events_and_state_updates
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py:527:runInteraction
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py:575:runWithConnection
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/threadpool.py:250:inContext
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/threadpool.py:266:<lambda>
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/context.py:122:callWithContext
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/context.py:85:callWithContext
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/enterprise/adbapi.py:306:_runWithConnection
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/compat.py:464:reraise
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/enterprise/adbapi.py:297:_runWithConnection
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py:572:inner_func
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py:418:new_transaction
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/logging/utils.py:73:wrapped
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py:451:_persist_events_txn
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py:1001:_update_metadata_tables_txn
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py:1299:_handle_event_relations
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py:653:simple_insert_txn
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py:210:execute
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py:236:_do_execute
]]
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/handlers/federation.py", line 1033, in try_backfill
    dom, room_id, limit=100, extremities=extremities
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/handlers/federation.py", line 909, in backfill
    await self._handle_new_event(dest, event, backfilled=True)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/handlers/federation.py", line 1845, in _handle_new_event
    [(event, context)], backfilled=backfilled
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/handlers/federation.py", line 2870, in persist_events_and_notify
    event_and_contexts, backfilled=backfilled
twisted.internet.defer.FirstError: FirstError[#0, [Failure instance: Traceback: <class 'psycopg2.errors.UniqueViolation'>: duplicate key value violates unique constraint "event_relations_id"
DETAIL:  Key (event_id)=($hnVIuNuExbqJ-9iXkDpaRAGdKdeDue4YI8w9G1qOSHc) already exists.

/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py:654:_runCallbacks
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py:1475:gotResult
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
--- <exception caught here> ---
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/persist_events.py:152:handle_queue_loop
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/persist_events.py:262:persisting_queue
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/persist_events.py:438:_persist_events
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py:96:f
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py:211:_persist_events_and_state_updates
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py:527:runInteraction
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py:575:runWithConnection
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/threadpool.py:250:inContext
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/threadpool.py:266:<lambda>
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/context.py:122:callWithContext
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/context.py:85:callWithContext
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/enterprise/adbapi.py:306:_runWithConnection
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/compat.py:464:reraise
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/enterprise/adbapi.py:297:_runWithConnection
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py:572:inner_func
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py:418:new_transaction
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/logging/utils.py:73:wrapped
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py:451:_persist_events_txn
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py:1001:_update_metadata_tables_txn
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py:1299:_handle_event_relations
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py:653:simple_insert_txn
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py:210:execute
/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py:236:_do_execute
]]

Steps to reproduce

1. Start new Synapse server from scratch, with retention enabled. Config mostly default otherwise:

pid_file: "/var/run/matrix-synapse.pid"
use_presence: false
federation_ip_range_blacklist:
  - '127.0.0.0/8'
  - '10.0.0.0/8'
  - '172.16.0.0/12'
  - '192.168.0.0/16'
  - '100.64.0.0/10'
  - '169.254.0.0/16'
  - '::1/128'
  - 'fe80::/64'
  - 'fc00::/7'
listeners:
  - port: 8008
    tls: false
    type: http
    x_forwarded: true
    bind_addresses: ['::1', '127.0.0.1']
    resources:
      - names: [client, federation]
        compress: false
redaction_retention_period: 1d
retention:
  enabled: true
  default_policy:
    min_lifetime: 7d
    max_lifetime: 30d
  allowed_lifetime_min: 7d
  allowed_lifetime_max: 30d
acme:
    enabled: false
database:
  name: psycopg2
  args:
    user: matrix-synapse
    password: <redacted>
    database: matrix-synapse
    host: 127.0.0.1
    cp_min: 5
    cp_max: 10
log_config: "/etc/matrix-synapse/log.yaml"
media_store_path: "/var/lib/matrix-synapse/media"
enable_registration: false
enable_3pid_lookup: false
signing_key_path: "/etc/matrix-synapse/homeserver.signing.key"
trusted_key_servers:
  - server_name: "matrix.org"

2. Create an account and join #synapse:matrix.org using Riot

3. Log out and wait for a few days.

4. Log in and try scrolling upward on #synapse. The room timeline can be scrolled a few days back (1-2 days, not the 7 days in the retention config), but at some point backfilling stops working, and it will just show a spinner that never completes

5. In the server logs, observe the database integrity errors and resulting backfill failure messages

I have double checked that postgres db was created using the correct encoding options. The issue seems quite reproducible: I've dropped the server DB several times and started from scratch, and it seems to occur every time. Did not test if it occurs with retention disabled, but suspect not.

Version information

• Version: matrix-synapse-py3 1.15.0+buster1 on Debian buster
• Install method: Debian packages provided by matrix.org
• Platform: Debian buster amd64, postgres

[clokep]

Talked about this a bit in #synapse-dev:matrix.org:

it'll be due to the retention stuff
vaping parts of the db but not all of it
so when we try to repopulate the deleted events, we get constraint violations

[richvdh]

next steps here are to check that event_relations are being correctly cleared out when events are purged.

[clokep]

It seems the event_relations table is missing from the _purge_history_txn. (It is handled when a room is completely purged in purge_room, but not in purge_history.)