Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

Waiting for existing lookups for ['matrix.org'] to complete / duplicate key value violates unique constraint "event_json_event_id_key" #8889

Closed
schildbach opened this issue Dec 7, 2020 · 12 comments
Closed

Waiting for existing lookups for ['matrix.org'] to complete / duplicate key value violates unique constraint "event_json_event_id_key" #8889

schildbach opened this issue Dec 7, 2020 · 12 comments
Labels
z-question (Deprecated Label)

Comments

@schildbach
Copy link

Synapse: 1.23.0 docker image on Ubuntu 20.04 all updated running on virtual server (amd64)
Postgres: 10.13 docker image on Ubuntu 20.04 all updated running on virtual server (amd64)

Since a few days, my clients cannot decrypt half of the encrypted messages. Re-requesting encryption keys does nothing. And there are some messages I don't even see placeholders for. My Synapse log file shows tens of thousands of these messages:

synapse_1   | 2020-12-06 04:07:30,494 - synapse.crypto.keyring - 297 - INFO - PUT-8724-$160722728931907MTnpk:t2bot.io-$1607223571599165IsYDO:matrix.org-$1607223564599139XNgYk:matrix.org-$1603449069253728qjdBb:matrix.org - Waiting for existing lookups for ['matrix.org'] to complete [loop 1]
synapse_1   | 2020-12-06 04:07:30,497 - synapse.crypto.keyring - 297 - INFO - PUT-8724-$160722728931907MTnpk:t2bot.io-$1607223571599165IsYDO:matrix.org-$1607223564599139XNgYk:matrix.org-$1603449069253728qjdBb:matrix.org - Waiting for existing lookups for ['matrix.org'] to complete [loop 2]
synapse_1   | 2020-12-06 04:07:30,498 - synapse.crypto.keyring - 297 - INFO - PUT-8724-$160722728931907MTnpk:t2bot.io-$1607223571599165IsYDO:matrix.org-$1607223564599139XNgYk:matrix.org-$1605917201710656kuzpV:matrix.org - Waiting for existing lookups for ['matrix.org'] to complete [loop 1]
synapse_1   | 2020-12-06 04:07:30,501 - synapse.crypto.keyring - 297 - INFO - PUT-8724-$160722728931907MTnpk:t2bot.io-$1607223571599165IsYDO:matrix.org-$1607223564599139XNgYk:matrix.org-$1605917201710656kuzpV:matrix.org - Waiting for existing lookups for ['matrix.org'] to complete [loop 2]
synapse_1   | 2020-12-06 04:07:30,503 - synapse.crypto.keyring - 297 - INFO - PUT-8724-$160722728931907MTnpk:t2bot.io-$1607223571599165IsYDO:matrix.org-$1607223564599139XNgYk:matrix.org-$160710514383625xeACt:matrix.org - Waiting for existing lookups for ['matrix.org'] to complete [loop 1]
synapse_1   | 2020-12-06 04:07:30,506 - synapse.crypto.keyring - 297 - INFO - PUT-8724-$160722728931907MTnpk:t2bot.io-$1607223571599165IsYDO:matrix.org-$1607223564599139XNgYk:matrix.org-$160710514383625xeACt:matrix.org - Waiting for existing lookups for ['matrix.org'] to complete [loop 2]
synapse_1   | 2020-12-06 04:07:30,508 - synapse.crypto.keyring - 297 - INFO - PUT-8724-$160722728931907MTnpk:t2bot.io-$1607223571599165IsYDO:matrix.org-$1607223564599139XNgYk:matrix.org-$16055434841940397ZagnG:matrix.org - Waiting for existing lookups for ['matrix.org'] to complete [loop 1]
synapse_1   | 2020-12-06 04:07:30,511 - synapse.crypto.keyring - 297 - INFO - PUT-8724-$160722728931907MTnpk:t2bot.io-$1607223571599165IsYDO:matrix.org-$1607223564599139XNgYk:matrix.org-$16055434841940397ZagnG:matrix.org - Waiting for existing lookups for ['matrix.org'] to complete [loop 2]
synapse_1   | 2020-12-06 04:07:30,512 - synapse.crypto.keyring - 297 - INFO - PUT-8724-$160722728931907MTnpk:t2bot.io-$1607223571599165IsYDO:matrix.org-$1607223564599139XNgYk:matrix.org-$16049229661956872JfDFz:matrix.org - Waiting for existing lookups for ['matrix.org'] to complete [loop 1]

Not sure if this is related: My Postgres log shows this message about every 5-10 minutes:

Dec 07 11:21:23 ultima docker-compose[4099416]: postgres_1  | 2020-12-07 11:21:23.571 GMT [86793] ERROR:  duplicate key value violates unique constraint "event_json_event_id_key"
Dec 07 11:21:23 ultima docker-compose[4099416]: postgres_1  | 2020-12-07 11:21:23.571 GMT [86793] DETAIL:  Key (event_id)=($1540391163900579eFHGv:matrix.org) already exists.
Dec 07 11:21:23 ultima docker-compose[4099416]: postgres_1  | 2020-12-07 11:21:23.571 GMT [86793] STATEMENT:  INSERT INTO event_json (event_id, format_version, internal_metadata, json, room_id) VALUES('$1540391163900579eFHGv:matrix.org', 1, '{"outlier":true}', '{"origin":"matrix.org","origin_server_ts":1540391163656,"sender":"@freenode_aydio:matrix.org","event_id":"$1540391163900579eFHGv:matrix.org","prev_events":[["$1540390778895990wNpZO:matrix.org",{"sha256":"ManYwFfEhLYEDfqN2iia5S+SOqZSE7gb6/KVayjosto"}]],"membership":"leave","state_key":"@freenode_aydio:matrix.org","content":{"membership":"leave"},"depth":4027,"prev_state":[],"room_id":"!HwocBmCtBcHQhILtYQ:matrix.org","auth_events":[["$15397953202596535MatZu:matrix.org",{"sha256":"Hb0gL+cwqLbP0o1gom24hXRfnjCGfdGmke04iwxnWDE"}],["$1540318414223781MMcBQ:matrix.org",{"sha256":"SszqUy4N1AaWHX1Wa9seddmdNJ9ooudr/vG0QilHq/c"}],["$1539081878940WKURF:matrix.org",{"sha256":"iGoAlyRGxK7N9oMrciHqdkC20g0vlJ4AAAG0+osnCPQ"}]],"hashes":{"sha256":"B06KleCJd23H8vP9mh8bn+nrM8x4pOS+FsVANwfun3g"},"type":"m.room.member","signatures":{"matrix.org":{"ed25519:auto":"tHPGqnCKEZ/ZGxMNnPWGYDuDUwIMCQli2sI5d0FktdYjOrbSevaoxiH7Slg+NLIhuCbNNIvFWfsgmxqPA9I0Bg"}},"unsigned":{"replaces_state":"$1540318414223781MMcBQ:matrix.org","age":66948445155}}', '!HwocBmCtBcHQhILtYQ:matrix.org')

The #synapse:matrix.org doesn't work for me because lots of messages I don't seem to see, which is why I reported the issue here.
@schildbach
Copy link
Author

Probably a manifestation of the same issue:

synapse_1   | 2020-12-07 12:19:49,537 - synapse.handlers.federation - 2385 - INFO - PUT-42-$16073404591067546WBRas:matrix.org-$16073322121031598BcnDn:matrix.org-$16073316181029338OzRwD:matrix.org-$160692347737986
60821}}', '!HwocBmCtBcHQhILtYQ:matrix.org')
synapse_1   |     (remote_state, _,) = await self._get_state_for_room(
synapse_1   |   File "/usr/local/lib/python3.8/site-packages/synapse/handlers/federation.py", line 590, in _get_state_for_room
synapse_1   |     event_map = await self._get_events_from_store_or_dest(
synapse_1   |   File "/usr/local/lib/python3.8/site-packages/synapse/handlers/federation.py", line 648, in _get_events_from_store_or_dest
synapse_1   |     await self._get_events_and_persist(
synapse_1   |   File "/usr/local/lib/python3.8/site-packages/synapse/handlers/federation.py", line 1250, in _get_events_and_persist
synapse_1   |     await self._handle_new_events(
synapse_1   |   File "/usr/local/lib/python3.8/site-packages/synapse/handlers/federation.py", line 1940, in _handle_new_events
synapse_1   |     await self.persist_events_and_notify(
synapse_1   |   File "/usr/local/lib/python3.8/site-packages/synapse/handlers/federation.py", line 2912, in persist_events_and_notify
synapse_1   |     events, max_stream_token = await self.storage.persistence.persist_events(
synapse_1   |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/persist_events.py", line 240, in persist_events
synapse_1   |     ret_vals = await make_deferred_yieldable(
synapse_1   | twisted.internet.defer.FirstError: FirstError[#0, [Failure instance: Traceback: <class 'psycopg2.errors.UniqueViolation'>: duplicate key value violates unique constraint "event_json_event_id_key"
synapse_1   | DETAIL:  Key (event_id)=($1540318414223781MMcBQ:matrix.org) already exists.
synapse_1   | 
synapse_1   | /usr/local/lib/python3.8/site-packages/twisted/internet/defer.py:654:_runCallbacks
synapse_1   | /usr/local/lib/python3.8/site-packages/twisted/internet/defer.py:1475:gotResult
synapse_1   | /usr/local/lib/python3.8/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
synapse_1   | /usr/local/lib/python3.8/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
synapse_1   | --- <exception caught here> ---
synapse_1   | /usr/local/lib/python3.8/site-packages/synapse/storage/persist_events.py:150:handle_queue_loop
synapse_1   | /usr/local/lib/python3.8/site-packages/synapse/storage/persist_events.py:302:persisting_queue
synapse_1   | /usr/local/lib/python3.8/site-packages/synapse/storage/persist_events.py:502:_persist_events
synapse_1   | /usr/local/lib/python3.8/site-packages/synapse/storage/databases/main/events.py:161:_persist_events_and_state_updates
synapse_1   | /usr/local/lib/python3.8/site-packages/synapse/storage/database.py:632:runInteraction
synapse_1   | /usr/local/lib/python3.8/site-packages/synapse/storage/database.py:712:runWithConnection
synapse_1   | /usr/local/lib/python3.8/site-packages/twisted/python/threadpool.py:250:inContext
synapse_1   | /usr/local/lib/python3.8/site-packages/twisted/python/threadpool.py:266:<lambda>
synapse_1   | /usr/local/lib/python3.8/site-packages/twisted/python/context.py:122:callWithContext
synapse_1   | /usr/local/lib/python3.8/site-packages/twisted/python/context.py:85:callWithContext
synapse_1   | /usr/local/lib/python3.8/site-packages/twisted/enterprise/adbapi.py:306:_runWithConnection
synapse_1   | /usr/local/lib/python3.8/site-packages/twisted/python/compat.py:464:reraise
synapse_1   | /usr/local/lib/python3.8/site-packages/twisted/enterprise/adbapi.py:297:_runWithConnection
synapse_1   | /usr/local/lib/python3.8/site-packages/synapse/storage/database.py:707:inner_func
synapse_1   | /usr/local/lib/python3.8/site-packages/synapse/storage/database.py:510:new_transaction
synapse_1   | /usr/local/lib/python3.8/site-packages/synapse/logging/utils.py:71:wrapped
synapse_1   | /usr/local/lib/python3.8/site-packages/synapse/storage/databases/main/events.py:362:_persist_events_txn
synapse_1   | /usr/local/lib/python3.8/site-packages/synapse/storage/databases/main/events.py:820:_store_event_txn
synapse_1   | /usr/local/lib/python3.8/site-packages/synapse/storage/database.py:864:simple_insert_many_txn
synapse_1   | /usr/local/lib/python3.8/site-packages/synapse/storage/database.py:274:executemany
synapse_1   | /usr/local/lib/python3.8/site-packages/synapse/storage/database.py:297:_do_execute
synapse_1   | ]]

@schildbach
Copy link
Author

I have found one event that is present in event_json but not events:

synapse=# select * from events where event_id='$1540391163900579eFHGv:matrix.org';
 stream_ordering | topological_ordering | event_id | type | room_id | content | unrecognized_keys | processed | outlier | depth | origin_server_ts | received_ts | sender | contains_url | instance_name 
-----------------+----------------------+----------+------+---------+---------+-------------------+-----------+---------+-------+------------------+-------------+--------+--------------+---------------
(0 rows)

synapse=# select * from event_json where event_id='$1540391163900579eFHGv:matrix.org';
             event_id              |            room_id             |              internal_metadata              |                                                                                                 
                                                                                                                                                                                                                    
                                                                                                                                                                                                                    
              json                                                                                                                                                                                                  
                                                                                                                                                                                                                    
                                                                                                                                  | format_version 
-----------------------------------+--------------------------------+---------------------------------------------+-------------------------------------------------------------------------------------------------
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
----------------------------------------------------------------------------------------------------------------------------------+----------------
 $1540391163900579eFHGv:matrix.org | !HwocBmCtBcHQhILtYQ:matrix.org | {"outlier": true, "stream_ordering": -2300} | {"origin": "matrix.org", "origin_server_ts": 1540391163656, "sender": "@freenode_aydio:matrix.or
g", "event_id": "$1540391163900579eFHGv:matrix.org", "prev_events": [["$1540390778895990wNpZO:matrix.org", {"sha256": "ManYwFfEhLYEDfqN2iia5S+SOqZSE7gb6/KVayjosto"}]], "membership": "leave", "state_key": "@freeno
de_aydio:matrix.org", "content": {"membership": "leave"}, "depth": 4027, "prev_state": [], "room_id": "!HwocBmCtBcHQhILtYQ:matrix.org", "auth_events": [["$15397953202596535MatZu:matrix.org", {"sha256": "Hb0gL+cwq
LbP0o1gom24hXRfnjCGfdGmke04iwxnWDE"}], ["$1540318414223781MMcBQ:matrix.org", {"sha256": "SszqUy4N1AaWHX1Wa9seddmdNJ9ooudr/vG0QilHq/c"}], ["$1539081878940WKURF:matrix.org", {"sha256": "iGoAlyRGxK7N9oMrciHqdkC20g0v
lJ4AAAG0+osnCPQ"}]], "hashes": {"sha256": "B06KleCJd23H8vP9mh8bn+nrM8x4pOS+FsVANwfun3g"}, "type": "m.room.member", "signatures": {"matrix.org": {"ed25519:auto": "tHPGqnCKEZ/ZGxMNnPWGYDuDUwIMCQli2sI5d0FktdYjOrbSev
aoxiH7Slg+NLIhuCbNNIvFWfsgmxqPA9I0Bg"}}, "unsigned": {"replaces_state": "$1540318414223781MMcBQ:matrix.org", "age": 11484741051}} |              1
(1 row)

@schildbach
Copy link
Author

Got advice from #synapse:matrix.org to delete the event:

delete from event_json where event_id='$1540391163900579eFHGv:matrix.org';

so I've just done that.

@schildbach
Copy link
Author

Just got advice from #synapse:matrix.org that the Waiting for existing lookups for… messages are not indicative of a problem.

@schildbach
Copy link
Author

schildbach commented Dec 7, 2020 •
edited
Loading

Deleted a second stray entry from event_json: $1540368006678658TCkTD:matrix.org

@anoadragon453
Copy link
Member

Just got advice from #synapse:matrix.org that the Waiting for existing lookups for… messages are not indicative of a problem.

Indeed, the problem here is likely matrix.org slowness rather than anything to do with your homeserver in particular.

I'd be surprised if either of these issues would cause Unable to Decrypt failures however. If you could submit debug logs from a client sending an event and (more importantly) the device that cannot decrypt that event and reference this github issue then we can take a look at why those particular messages are failing.

@anoadragon453 anoadragon453 added the z-question (Deprecated Label) label Dec 7, 2020
@schildbach
Copy link
Author 

synapse=# select * from event_edges where event_id = '$1540391163900579eFHGv:matrix.org';
             event_id              |           prev_event_id           |            room_id             | is_state 
-----------------------------------+-----------------------------------+--------------------------------+----------
 $1540391163900579eFHGv:matrix.org | $1540390778895990wNpZO:matrix.org | !HwocBmCtBcHQhILtYQ:matrix.org | f
(1 row)

synapse=# delete from event_edges where event_id = '$1540391163900579eFHGv:matrix.org';
DELETE 1

@anoadragon453
Copy link
Member

Logs received, thanks.

@schildbach
Copy link
Author

If you could submit debug logs from a client sending an event and (more importantly) the device that cannot decrypt that event and reference this github issue then we can take a look at why those particular messages are failing.

Thanks for the offer! I just sent the Element-Web debug log for the receiving side. I currently don't have access to the sending side.

@schildbach
Copy link
Author

@anoadragon453 Did you fix something on the matrix.org side? I just received all (most?) of the encryption keys.

@anoadragon453
Copy link
Member

@schildbach nothing done manually. We did just have a spike of EDUs go out though. May've just been a case of stuff taking a while to process/temporary networking issues on either side.

@schildbach
Copy link
Author

After lots of help from #synapse:matrix.org, I've been given the hint to leave the offending room, and optionally re-join it after some time.

I left the F-Droid room (which by the way I didn't interact with lately), and my issues were resolved shortly after. So I'll close this.

Many thanks to everyone who was involved!

@schildbach schildbach mentioned this issue Jan 2, 2021
Closed
@JanZerebecki JanZerebecki mentioned this issue Aug 30, 2021
Closed
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
z-question (Deprecated Label)
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@schildbach @anoadragon453