search

element-hq / synapse

Synapse: Matrix homeserver written in Python/Twisted.
https://element-hq.github.io/synapse
GNU Affero General Public License v3.0
1.33k stars 160 forks source link

background_drop_invalid_event_edges_rows failed #16193

Open matrixbot opened 9 months ago

matrixbot commented 9 months ago

This issue has been migrated from #16193.

Description

Background update to drop invalid event edge rows failed.

Steps to reproduce

Homeserver

tusooa.xyz

Synapse Version

1.90.0

Installation Method

Docker (matrixdotorg/synapse)

Database

postgresql 13. single server. yes, used portdb. yes, once restored.

Workers

Multiple workers

Platform

Ubuntu 22.04, Kubernetes (4-node kubeadm cluster)

Configuration

No response

Relevant log output

2023-08-27 23:49:32,646 - synapse.storage.background_updates - 302 - ERROR - background_updates-0 - Error doing update
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/synapse/storage/background_updates.py", line 294, in run_background_updates
    result = await self.do_next_background_update(sleep)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/synapse/storage/background_updates.py", line 424, in do_next_background_update
    await self._do_background_update(desired_duration_ms)
  File "/usr/local/lib/python3.11/site-packages/synapse/storage/background_updates.py", line 467, in _do_background_update
    items_updated = await update_handler(progress, batch_size)
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/synapse/storage/databases/main/events_bg_updates.py", line 1408, in _background_drop_invalid_event_edges_rows
    done = await self.db_pool.runInteraction(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 924, in runInteraction
    return await delay_cancellation(_runInteraction())
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/twisted/internet/defer.py", line 1693, in _inlineCallbacks
    result = context.run(
             ^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/twisted/python/failure.py", line 518, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 890, in _runInteraction
    result = await self.runWithConnection(
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1019, in runWithConnection
    return await make_deferred_yieldable(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/twisted/python/threadpool.py", line 244, in inContext
    result = inContext.theWork()  # type: ignore[attr-defined]
             ^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/twisted/python/threadpool.py", line 260, in <lambda>
    inContext.theWork = lambda: context.call(  # type: ignore[attr-defined]
                                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/twisted/python/context.py", line 117, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/twisted/python/context.py", line 82, in callWithContext
    return func(*args, **kw)
           ^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/twisted/enterprise/adbapi.py", line 282, in _runWithConnection
    result = func(conn, *args, **kw)
             ^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 1012, in inner_func
    return func(db_conn, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 752, in new_transaction
    r = func(cursor, *args, **kwargs)
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/synapse/storage/databases/main/events_bg_updates.py", line 1403, in drop_invalid_event_edges_txn
    txn.execute(
  File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 417, in execute
    self._do_execute(self.txn.execute, sql, parameters)
  File "/usr/local/lib/python3.11/site-packages/synapse/storage/database.py", line 469, in _do_execute
    return func(sql, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
psycopg2.errors.ForeignKeyViolation: insert or update on table "event_edges" violates foreign key constraint "event_edges_event_id_fkey"
DETAIL:  Key (event_id)=($ukE7gZZjUyJ6AWo3j-yziYIwtm5QBWh4_V-AwoChtqs) is not present in table "events".

Anything else that would be useful to know?

No response

tusooa commented 6 months ago

I have set the database statement timeout to 100 hours. The timeout no longer occurs, but it seems that the job is somehow running itself again without actually completing it.

$ grep purge /mnt/gv1/matrix-kube/synapse/homeserver.log
2024-03-02 09:29:01,595 - synapse.handlers.room - 1967 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl - Shutting down room '!YTvKGNlinIzlkMTVRl:matrix.org'
2024-03-02 09:29:01,603 - synapse.handlers.pagination - 388 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl - starting purge room_id=!YTvKGNlinIzlkMTVRl:matrix.org force=False
2024-03-02 09:29:01,627 - synapse.storage.databases.main.purge_events - 350 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] Starting initial main purge of [1/2]
2024-03-02 12:13:25,550 - synapse.storage.databases.main.purge_events - 404 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from event_auth_chain_links
2024-03-02 12:14:37,296 - synapse.storage.databases.main.purge_events - 427 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from event_auth
2024-03-02 12:15:16,085 - synapse.storage.databases.main.purge_events - 427 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from event_edges
2024-03-02 12:17:00,312 - synapse.storage.databases.main.purge_events - 427 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from event_json
2024-03-02 12:19:09,983 - synapse.storage.databases.main.purge_events - 427 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from event_push_actions_staging
2024-03-02 12:19:09,989 - synapse.storage.databases.main.purge_events - 427 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from event_relations
2024-03-02 12:19:20,125 - synapse.storage.databases.main.purge_events - 427 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from event_to_state_groups
2024-03-02 12:20:05,861 - synapse.storage.databases.main.purge_events - 427 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from event_auth_chains
2024-03-02 12:20:08,434 - synapse.storage.databases.main.purge_events - 427 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from event_auth_chain_to_calculate
2024-03-02 12:20:09,594 - synapse.storage.databases.main.purge_events - 427 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from redactions
2024-03-02 12:20:09,976 - synapse.storage.databases.main.purge_events - 427 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from rejections
2024-03-02 12:20:29,287 - synapse.storage.databases.main.purge_events - 427 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from state_events
2024-03-02 12:20:32,516 - synapse.storage.databases.main.purge_events - 480 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from current_state_events
2024-03-02 12:20:32,523 - synapse.storage.databases.main.purge_events - 480 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from destination_rooms
2024-03-02 12:20:32,553 - synapse.storage.databases.main.purge_events - 480 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from event_backward_extremities
2024-03-02 12:20:32,581 - synapse.storage.databases.main.purge_events - 480 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from event_forward_extremities
2024-03-02 12:20:32,585 - synapse.storage.databases.main.purge_events - 480 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from event_push_actions
2024-03-02 12:20:32,596 - synapse.storage.databases.main.purge_events - 480 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from event_search
2024-03-02 12:20:43,493 - synapse.storage.databases.main.purge_events - 480 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from event_failed_pull_attempts
2024-03-02 12:20:43,552 - synapse.storage.databases.main.purge_events - 480 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from partial_state_events
2024-03-02 12:20:43,558 - synapse.storage.databases.main.purge_events - 480 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from partial_state_rooms_servers
2024-03-02 12:20:43,561 - synapse.storage.databases.main.purge_events - 480 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from partial_state_rooms
2024-03-02 12:20:43,564 - synapse.storage.databases.main.purge_events - 480 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from local_current_membership
2024-03-02 12:20:43,585 - synapse.storage.databases.main.purge_events - 480 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from room_memberships
2024-03-02 12:20:45,709 - synapse.storage.databases.main.purge_events - 480 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] removing from events
2024-03-02 18:05:41,341 - synapse.handlers.room - 1967 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl - Shutting down room '!YTvKGNlinIzlkMTVRl:matrix.org'
2024-03-02 18:05:41,349 - synapse.handlers.pagination - 388 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl - starting purge room_id=!YTvKGNlinIzlkMTVRl:matrix.org force=False
2024-03-02 18:05:41,370 - synapse.storage.databases.main.purge_events - 350 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] Starting initial main purge of [1/2]
tusooa commented 6 months ago 
2024-03-02 18:05:41,370 - synapse.storage.databases.main.purge_events - 350 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] Starting initial main purge of [1/2]
2024-03-02 21:19:40,714 - synapse.handlers.room - 1967 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl - Shutting down room '!YTvKGNlinIzlkMTVRl:matrix.org'
2024-03-02 21:19:40,736 - synapse.handlers.pagination - 388 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl - starting purge room_id=!YTvKGNlinIzlkMTVRl:matrix.org force=False
2024-03-02 21:19:41,657 - synapse.storage.databases.main.lock - 508 - ERROR - sentinel - Lock for (purge_pagination_lock, !YTvKGNlinIzlkMTVRl:matrix.org) dropped without being released
2024-03-02 21:19:41,674 - synapse.storage.databases.main.lock - 508 - ERROR - sentinel - Lock for (purge_pagination_lock, !YTvKGNlinIzlkMTVRl:matrix.org) dropped without being released
2024-03-02 21:19:49,343 - synapse.storage.databases.main.lock - 508 - ERROR - sentinel - Lock for (purge_pagination_lock, !YTvKGNlinIzlkMTVRl:matrix.org) dropped without being released
2024-03-02 21:19:56,544 - synapse.storage.databases.main.lock - 508 - ERROR - sentinel - Lock for (purge_pagination_lock, !YTvKGNlinIzlkMTVRl:matrix.org) dropped without being released
2024-03-02 21:20:17,862 - synapse.storage.databases.main.lock - 508 - ERROR - sentinel - Lock for (purge_pagination_lock, !YTvKGNlinIzlkMTVRl:matrix.org) dropped without being released
2024-03-02 21:20:58,018 - synapse.storage.databases.main.purge_events - 350 - INFO - task-shutdown_and_purge_room-0-mOLgNeupZJJuLaxl-!YTvKGNlinIzlkMTVRl:matrix.org - [purge] Starting initial main purge of [1/2]