UniqueViolation: duplicate key value violates unique constraint "event_reference_hashes_event_id_algorithm_key"

[Bubu]

Description

I get pages and pages of these errors in my log:
Dec 17 23:22:45 bubu synapse[453]: psycopg2.errors.UniqueViolation: duplicate key value violates unique constraint "event_reference_hashes_event_id_algorithm_key"

Dec 17 23:23:09 bubu synapse[453]: DETAIL:  Key (event_id, algorithm)=($1554237769161789KEmwb:matrix.org, sha256) already exists.
Dec 17 23:23:15 bubu synapse[453]: 2019-12-17 23:23:15,068 - synapse.storage.data_stores.main.events - 87 - ERROR - persist_events-58 - IntegrityError, retrying.
Dec 17 23:23:15 bubu synapse[453]: Traceback (most recent call last):
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/synapse/storage/data_stores/main/events.py", line 85, in f
Dec 17 23:23:15 bubu synapse[453]:     res = yield func(self, *args, delete_existing=False, **kwargs)
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
Dec 17 23:23:15 bubu synapse[453]:     result = result.throwExceptionIntoGenerator(g)
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
Dec 17 23:23:15 bubu synapse[453]:     return g.throw(self.type, self.value, self.tb)
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/synapse/storage/data_stores/main/events.py", line 208, in _persist_events_and_state_updates
Dec 17 23:23:15 bubu synapse[453]:     yield self.db.runInteraction(
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
Dec 17 23:23:15 bubu synapse[453]:     result = result.throwExceptionIntoGenerator(g)
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
Dec 17 23:23:15 bubu synapse[453]:     return g.throw(self.type, self.value, self.tb)
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/synapse/storage/database.py", line 449, in runInteraction
Dec 17 23:23:15 bubu synapse[453]:     result = yield self.runWithConnection(
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
Dec 17 23:23:15 bubu synapse[453]:     result = result.throwExceptionIntoGenerator(g)
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
Dec 17 23:23:15 bubu synapse[453]:     return g.throw(self.type, self.value, self.tb)
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/synapse/storage/database.py", line 503, in runWithConnection
Dec 17 23:23:15 bubu synapse[453]:     result = yield make_deferred_yieldable(
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/twisted/python/threadpool.py", line 250, in inContext
Dec 17 23:23:15 bubu synapse[453]:     result = inContext.theWork()
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/twisted/python/threadpool.py", line 266, in <lambda>
Dec 17 23:23:15 bubu synapse[453]:     inContext.theWork = lambda: context.call(ctx, func, *args, **kw)
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/twisted/python/context.py", line 122, in callWithContext
Dec 17 23:23:15 bubu synapse[453]:     return self.currentContext().callWithContext(ctx, func, *args, **kw)
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/twisted/python/context.py", line 85, in callWithContext
Dec 17 23:23:15 bubu synapse[453]:     return func(*args,**kw)
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/twisted/enterprise/adbapi.py", line 306, in _runWithConnection
Dec 17 23:23:15 bubu synapse[453]:     compat.reraise(excValue, excTraceback)
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/twisted/python/compat.py", line 464, in reraise
Dec 17 23:23:15 bubu synapse[453]:     raise exception.with_traceback(traceback)
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/twisted/enterprise/adbapi.py", line 297, in _runWithConnection
Dec 17 23:23:15 bubu synapse[453]:     result = func(conn, *args, **kw)
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/synapse/storage/database.py", line 501, in inner_func
Dec 17 23:23:15 bubu synapse[453]:     return func(conn, *args, **kwargs)
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/synapse/storage/database.py", line 339, in new_transaction
Dec 17 23:23:15 bubu synapse[453]:     r = func(cursor, *args, **kwargs)
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/synapse/logging/utils.py", line 79, in wrapped
Dec 17 23:23:15 bubu synapse[453]:     return f(*args, **kwargs)
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/synapse/storage/data_stores/main/events.py", line 456, in _persist_events_txn
Dec 17 23:23:15 bubu synapse[453]:     self._update_metadata_tables_txn(
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/synapse/storage/data_stores/main/events.py", line 960, in _update_metadata_tables_txn
Dec 17 23:23:15 bubu synapse[453]:     self._store_event_reference_hashes_txn(
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/synapse/storage/data_stores/main/signatures.py", line 101, in _store_event_reference_hashes_txn
Dec 17 23:23:15 bubu synapse[453]:     self.db.simple_insert_many_txn(txn, table="event_reference_hashes", values=vals)
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/synapse/storage/database.py", line 614, in simple_insert_many_txn
Dec 17 23:23:15 bubu synapse[453]:     txn.executemany(sql, vals)
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/synapse/storage/database.py", line 145, in executemany
Dec 17 23:23:15 bubu synapse[453]:     self._do_execute(self.txn.executemany, sql, *args)
Dec 17 23:23:15 bubu synapse[453]:   File "/usr/lib/python3.8/site-packages/synapse/storage/database.py", line 168, in _do_execute
Dec 17 23:23:15 bubu synapse[453]:     return func(sql, *args)

Steps to reproduce

• ?

(I tried joining #freenode_#archlinux:matrix.org, in which I've been before. It didn't work, I'm unsure if that's related)

Version information

• Homeserver: bubu1.eu

• Version: 1.7.0

• Install method: arch package

• Platform: Archlinux

[Bubu]

This disappears after restarting synapse but happens again, if I try to join #archlinux again. I can't join that room.

[Bubu]

Not sure if that's related but before the log flooding with the error above I get one of these errors in the log:
Dec 18 15:09:40 bubu synapse[22004]: 2019-12-18 15:09:40,355 - synapse.storage.data_stores.main.room - 492 - ERROR - POST-3069 - store_room with room_id=!kbmCAHJXpbUYAMzNZc:matrix.org failed: duplicate key value violates unique constraint "rooms_pkey"

[Bubu]

@richvdh

Got some more logs (reverse order):

sudo journalctl -ru synapse | grep POST-1135
Dec 18 18:25:29 bubu synapse[24855]: 2019-12-18 18:25:29,597 - synapse.storage.data_stores.main.room - 492 - ERROR - POST-1135 - store_room with room_id=!kbmCAHJXpbUYAMzNZc:matrix.org failed: duplicate key value violates unique constraint "rooms_pkey"
Dec 18 18:25:29 bubu synapse[24855]: 2019-12-18 18:25:29,596 - synapse.http.site - 202 - WARNING - POST-1135 - Error processing request <XForwardedForRequest at 0x7f1ade2cabb0 method='POST' uri='/_matrix/client/r0/join/%23freenode_%23archlinux%3Amatrix.org' clientproto='HTTP/1.1' site=8008>: <class 'twisted.internet.error.ConnectionDone'> Connection was closed cleanly.
Dec 18 18:24:51 bubu synapse[24855]: 2019-12-18 18:24:51,089 - synapse.http.matrixfederationclient - 159 - INFO - POST-1135 - {PUT-O-3368} [matrix.org] Completed: 200 OK
Dec 18 18:24:47 bubu synapse[24855]: 2019-12-18 18:24:47,375 - synapse.http.matrixfederationclient - 435 - INFO - POST-1135 - {PUT-O-3368} [matrix.org] Got response headers: 200 OK
Dec 18 18:24:25 bubu synapse[24855]: 2019-12-18 18:24:25,237 - synapse.http.matrixfederationclient - 402 - INFO - POST-1135 - {PUT-O-3368} [matrix.org] Sending request: PUT matrix://matrix.org/_matrix/federation/v1/send_join/%21kbmCAHJXpbUYAMzNZc%3Amatrix.org/%2415766898650IKziA%3Abubu1.eu; timeout 60.000000s
Dec 18 18:24:25 bubu synapse[24855]: 2019-12-18 18:24:25,232 - synapse.http.matrixfederationclient - 159 - INFO - POST-1135 - {GET-O-3367} [matrix.org] Completed: 200 OK
Dec 18 18:24:25 bubu synapse[24855]: 2019-12-18 18:24:25,231 - synapse.http.matrixfederationclient - 435 - INFO - POST-1135 - {GET-O-3367} [matrix.org] Got response headers: 200 OK
Dec 18 18:24:24 bubu synapse[24855]: 2019-12-18 18:24:24,494 - synapse.http.matrixfederationclient - 402 - INFO - POST-1135 - {GET-O-3367} [matrix.org] Sending request: GET matrix://matrix.org/_matrix/federation/v1/make_join/%21kbmCAHJXpbUYAMzNZc%3Amatrix.org/%40bubu%3Abubu1.eu?ver=1&ver=2&ver=3&ver=4&ver=5; timeout 20.000000s
Dec 18 18:24:24 bubu synapse[24855]: 2019-12-18 18:24:24,475 - synapse.http.matrixfederationclient - 159 - INFO - POST-1135 - {GET-O-3366} [matrix.org] Completed: 200 OK
Dec 18 18:24:24 bubu synapse[24855]: 2019-12-18 18:24:24,474 - synapse.http.matrixfederationclient - 435 - INFO - POST-1135 - {GET-O-3366} [matrix.org] Got response headers: 200 OK
Dec 18 18:24:24 bubu synapse[24855]: 2019-12-18 18:24:24,389 - synapse.http.matrixfederationclient - 402 - INFO - POST-1135 - {GET-O-3366} [matrix.org] Sending request: GET matrix://matrix.org/_matrix/federation/v1/query/directory?room_alias=%23freenode_%23archlinux%3Amatrix.org; timeout 10.000000s
Dec 18 18:24:24 bubu synapse[24855]: 2019-12-18 18:24:24,387 - synapse.access.http.8008 - 228 - INFO - POST-1135 - 5.28.114.171 - 8008 - Received request: POST /_matrix/client/r0/join/%23freenode_%23archlinux%3Amatrix.org

Full log in the timeframe noted above (not reversed):
join_error.log

[Bubu]

I finally ended up in the archlinux room after that latest join attempt... 🤯

[Bubu]

join_error_long.log

Longer log file as requested.

[Bubu]

Even more logs :)
moar_logs.log

[richvdh]

ok so that was (eventually) successful. Two things of note there:

• store_room with room_id=!kbmCAHJXpbUYAMzNZc:matrix.org failed: duplicate key value violates unique constraint "rooms_pkey": this is a somewhat known, essentially harmless, issue (duplicate key value violates unique constraint "rooms_pkey" error when rejoining a room #3374).
• many instances of psycopg2.errors.UniqueViolation: duplicate key value violates unique constraint "event_reference_hashes_event_id_algorithm_key". I've not seen this before and am going to investigate a little.

[richvdh]

many instances of psycopg2.errors.UniqueViolation: duplicate key value violates unique constraint "event_reference_hashes_event_id_algorithm_key". I've not seen this before and am going to investigate a little.

hrm. event_reference_hashes is updated after events etc, which also has a unique key on the event id, so this suggests that for some reason Bubu had entries in the event_reference_hashes table and not events/event_json/etc. This is... surprising. (cf #6574)