synapse
synapse copied to clipboard
matrix-org
Migration `79/04_mitigate_stream_ordering_update_race` fails because `there is no unique constraint matching given keys for referenced table "events"`
Description
Similar to #10691, I'm having issues after a system update. After an upgrade (from Debian 11 to 12) and a reboot, I get the following error on startup: psycopg2.errors.InvalidForeignKey: there is no unique constraint matching given keys for referenced table "events"
What's strange is I don't think synapse actually updated. It looks like it's still using a bullseye version, and I have daily unattended upgrades so it shouldn't have changed much. I've compared the schema to the one referenced in the source code, but I don't see any missing keys.
synapse=> \d events
Table "public.events"
Column | Type | Collation | Nullable | Default
----------------------+---------+-----------+----------+---------
stream_ordering | integer | | not null |
topological_ordering | bigint | | not null |
event_id | text | | not null |
type | text | | not null |
room_id | text | | not null |
content | text | | |
unrecognized_keys | text | | |
processed | boolean | | not null |
outlier | boolean | | not null |
depth | bigint | | not null | 0
origin_server_ts | bigint | | |
received_ts | bigint | | |
sender | text | | |
contains_url | boolean | | |
instance_name | text | | |
stream_ordering2 | bigint | | |
state_key | text | | |
rejection_reason | text | | |
Indexes:
"events_pkey" PRIMARY KEY, btree (stream_ordering)
"event_contains_url_index" btree (room_id, topological_ordering, stream_ordering) WHERE contains_url = true AND outlier = false
"events_event_id_key" UNIQUE CONSTRAINT, btree (event_id)
"events_order_room" btree (room_id, topological_ordering, stream_ordering)
"events_room_stream" btree (room_id, stream_ordering)
"events_ts" btree (origin_server_ts, stream_ordering)
Referenced by:
TABLE "event_edges" CONSTRAINT "event_edges_event_id_fkey" FOREIGN KEY (event_id) REFERENCES events(event_id) NOT VALID
TABLE "event_forward_extremities" CONSTRAINT "event_forward_extremities_event_id" FOREIGN KEY (event_id) REFERENCES events(event_id) DEFERRABLE INITIALLY DEFERRED NOT VALID
TABLE "current_state_events" CONSTRAINT "event_stream_ordering_fkey" FOREIGN KEY (event_stream_ordering) REFERENCES events(stream_ordering) NOT VALID
TABLE "local_current_membership" CONSTRAINT "event_stream_ordering_fkey" FOREIGN KEY (event_stream_ordering) REFERENCES events(stream_ordering) NOT VALID
TABLE "room_memberships" CONSTRAINT "event_stream_ordering_fkey" FOREIGN KEY (event_stream_ordering) REFERENCES events(stream_ordering) NOT VALID
TABLE "event_txn_id_device_id" CONSTRAINT "event_txn_id_device_id_event_id_fkey" FOREIGN KEY (event_id) REFERENCES events(event_id) ON DELETE CASCADE
TABLE "event_txn_id" CONSTRAINT "event_txn_id_event_id_fkey" FOREIGN KEY (event_id) REFERENCES events(event_id) ON DELETE CASCADE
TABLE "partial_state_events" CONSTRAINT "partial_state_events_event_id_fkey" FOREIGN KEY (event_id) REFERENCES events(event_id)
TABLE "partial_state_rooms" CONSTRAINT "partial_state_rooms_join_event_id_fkey" FOREIGN KEY (join_event_id) REFERENCES events(event_id)
TABLE "un_partial_stated_event_stream" CONSTRAINT "un_partial_stated_event_stream_event_id_fkey" FOREIGN KEY (event_id) REFERENCES events(event_id) ON DELETE CASCADE
Rules:
populate_stream_ordering2 AS
ON INSERT TO events DO UPDATE events SET stream_ordering2 = new.stream_ordering
WHERE events.stream_ordering = new.stream_ordering
Steps to reproduce
- Upgrade from Debian 11 to 12
- Start the server
Homeserver
My self-hosted server
Synapse Version
1.90.0+bullseye1
Installation Method
Debian packages from packages.matrix.org
Database
PostgreSQL, single server, never ported.
Workers
I don't know
Platform
Debian 12 (previously 11) on a VPS
Configuration
No response
Relevant log output
2023-08-27 22:28:54,839 - root - 348 - WARNING - main - ***** STARTING SERVER *****
2023-08-27 22:28:54,839 - root - 349 - WARNING - main - Server /opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/app/homeserver.py version 1.90.0
2023-08-27 22:28:54,839 - root - 354 - INFO - main - Server hostname: REDACTED
2023-08-27 22:28:54,839 - root - 355 - INFO - main - Instance name: master
2023-08-27 22:28:54,839 - root - 356 - INFO - main - Twisted reactor: EPollReactor
2023-08-27 22:28:54,839 - synapse.app.homeserver - 350 - INFO - main - Setting up server
2023-08-27 22:28:54,839 - synapse.server - 337 - INFO - main - Setting up.
2023-08-27 22:28:54,853 - synapse.storage.databases - 66 - INFO - main - [database config 'master']: Checking database server
2023-08-27 22:28:54,854 - synapse.storage.databases - 69 - INFO - main - [database config 'master']: Preparing for databases ['main', 'state']
2023-08-27 22:28:54,855 - synapse.storage.prepare_database - 120 - INFO - main - ['main', 'state']: Checking existing schema version
2023-08-27 22:28:54,857 - synapse.storage.prepare_database - 124 - INFO - main - ['main', 'state']: Existing schema is 79 (+0 deltas)
2023-08-27 22:28:54,857 - synapse.storage.databases.main - 323 - INFO - main - Checking database for consistency with configuration...
2023-08-27 22:28:54,858 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v79
2023-08-27 22:28:54,859 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 79/03_read_write_locks_triggers.sql.postgres
2023-08-27 22:28:54,886 - synapse.storage.prepare_database - 509 - INFO - main - Running 79/04_mitigate_stream_ordering_update_race.py:run_create
2023-08-27 22:28:54,895 - synapse.app._base - 215 - ERROR - main - Exception during startup
Traceback (most recent call last):
File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/app/homeserver.py", line 353, in setup
hs.setup()
File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/server.py", line 339, in setup
self.datastores = Databases(self.DATASTORE_CLASS, self)
File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/databases/__init__.py", line 74, in __init__
prepare_database(
File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/prepare_database.py", line 141, in prepare_database
_upgrade_existing_database(
File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/prepare_database.py", line 510, in _upgrade_existing_database
module.run_create(cur, database_engine)
File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/schema/main/delta/79/04_mitigate_stream_ordering_update_race.py", line 58, in run_create
cur.execute(add_cse_sql)
File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/database.py", line 417, in execute
self._do_execute(self.txn.execute, sql, parameters)
File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/database.py", line 471, in _do_execute
return func(sql, *args, **kwargs)
psycopg2.errors.InvalidForeignKey: there is no unique constraint matching given keys for referenced table "events"
### Anything else that would be useful to know?
_No response_
The SQL in question is
https://github.com/matrix-org/synapse/blob/8ebfd577e237eb7b364a692c88e14bc8820980d1/synapse/storage/schema/main/delta/79/04_mitigate_stream_ordering_update_race.py#L54-L58
which suggests that there isn't a unique index on events(stream_ordering2). This is surprising.
Can you SELECT * FROM background_updates; and paste the response here?
Yep, here's the output. out.txt
update_name | progress_json | depends_on | ordering
------------------------------------------------------------------+------------------------------------------------------------------------------------+-----------------------------------------------+----------
media_repository_drop_index_wo_method_2 | {} | remote_media_repository_thumbnails_method_idx | 5911
populate_stream_ordering2 | {} | | 6001
index_stream_ordering2 | {} | populate_stream_ordering2 | 6001
index_stream_ordering2_room_order | {} | index_stream_ordering2 | 6001
index_stream_ordering2_contains_url | {} | index_stream_ordering2_room_order | 6001
index_stream_ordering2_room_stream | {} | index_stream_ordering2_contains_url | 6001
index_stream_ordering2_ts | {} | index_stream_ordering2_room_stream | 6001
replace_stream_ordering_column | {} | index_stream_ordering2_ts | 6001
populate_room_depth_min_depth2 | {} | | 6103
replace_room_depth_min_depth | {} | populate_room_depth2 | 6103
remove_deleted_email_pushers | {} | | 6302
populate_rooms_creator_column | {} | | 6302
presence_stream_not_offline_index | {} | | 6304
event_arbitrary_relations | {} | | 6507
remove_dead_devices_from_device_inbox | {} | | 6508
delete_account_data_for_deactivated_users | {} | | 6803
cache_invalidation_index_by_instance | {} | | 6902
state_group_edges_unique_idx | {} | | 7008
event_edges_drop_invalid_rows | {} | | 7101
event_edges_replace_index | {} | event_edges_drop_invalid_rows | 7101
add_room_type_column | {} | | 0
event_push_actions_stream_highlight_index | {} | | 7202
events_populate_state_key_rejections | {"min_stream_ordering_exclusive": -4047, "max_stream_ordering_inclusive": 1011910} | | 7203
populate_event_stream_ordering | {} | | 0
event_push_summary_unique_index2 | {} | | 7006
receipts_linearized_unique_index | {} | | 7007
receipts_graph_unique_index | {} | | 7007
threads_backfill | {} | | 7309
device_lists_changes_in_room_by_room_index | {} | | 7313
populate_user_directory_createtables | {} | | 7322
populate_user_directory_process_rooms | {} | populate_user_directory_createtables | 7322
populate_user_directory_process_users | {} | populate_user_directory_process_rooms | 7322
populate_user_directory_cleanup | {} | populate_user_directory_process_users | 7322
populate_stats_process_rooms | {} | | 7322
populate_stats_process_users | {} | | 7322
events_jump_to_date_index | {} | | 7324
set_device_id_for_pushers | {} | | 7402
room_membership_user_room_index | {} | | 7403
delete_e2e_backup_keys_for_deactivated_users | {} | | 7404
profiles_full_user_id_key_idx | {} | | 7501
full_users_filters_unique_idx | {} | | 7502
populate_full_user_id_profiles | {} | | 7703
populate_full_user_id_user_filters | {} | | 7704
event_push_actions_thread_id | {} | event_push_actions_staging_thread_id | 7706
event_push_actions_staging_thread_id | {} | | 7706
event_push_summary_thread_id | {} | event_push_actions_thread_id | 7706
event_push_drop_null_thread_id_indexes | {} | event_push_summary_thread_id | 7706
current_state_events_stream_ordering_idx | {} | | 7714
local_current_membership_stream_ordering_idx | {} | | 7714
room_memberships_stream_ordering_idx | {} | | 7714
event_forward_extremities_event_id_foreign_key_constraint_update | {} | | 7803
(51 rows)
It looks like you have a long backlog of background updates that have failed to apply, and that the migration in question is failing because it requires one of them to have completed. This is very strange and needs more investigation.
Can you downgrade to older versions of Synapse until you find one that starts up without the error message you quoted? Once Synapse is started, can you leave it running for an hour, then grep the logs for background update or background_update and upload them here?
Can you downgrade to older versions of Synapse until you find one that starts up without the error message you quoted? Once Synapse is started, can you leave it running for an hour, then grep the logs for background update or background_update and upload them here?
I think v1.87.0 should work since you want earlier than #15998 / #15887?
It looks like you have a long backlog of background updates that have failed to apply, and that the migration in question is failing because it requires one of them to have completed. This is very strange and needs more investigation.
Can you downgrade to older versions of Synapse until you find one that starts up without the error message you quoted? Once Synapse is started, can you leave it running for an hour, then grep the logs for
background updateorbackground_updateand upload them here?
The relevant bit seems to be:
2023-08-29 17:22:03,215 - synapse.storage.background_updates - 461 - INFO - background_updates-0 - Starting update batch on background update 'replace_stream_ordering_column'
2023-08-29 17:22:03,923 - synapse.storage.databases.main.events_bg_updates - 1300 - INFO - background_updates-0 - completing stream_ordering migration: UPDATE events SET stream_ordering2 = stream_ordering WHERE stream_ordering2 IS NULL
2023-08-29 17:22:03,927 - synapse.storage.databases.main.events_bg_updates - 1300 - INFO - background_updates-0 - completing stream_ordering migration: DROP RULE populate_stream_ordering2 ON events
2023-08-29 17:22:03,936 - synapse.storage.databases.main.events_bg_updates - 1300 - INFO - background_updates-0 - completing stream_ordering migration: ALTER TABLE events DROP COLUMN stream_ordering
2023-08-29 17:22:03,962 - synapse.storage.background_updates - 332 - ERROR - background_updates-0 - Error doing update
File "/opt/venvs/matrix-synapse/lib/python3.11/site-packages/synapse/storage/background_updates.py", line 323, in run_background_updates
result = await self.do_next_background_update(sleep)
File "/opt/venvs/matrix-synapse/lib/python3.11/site-packages/synapse/storage/background_updates.py", line 454, in do_next_background_update
await self._do_background_update(desired_duration_ms)
File "/opt/venvs/matrix-synapse/lib/python3.11/site-packages/synapse/storage/background_updates.py", line 497, in _do_background_update
File "/opt/venvs/matrix-synapse/lib/python3.11/site-packages/synapse/storage/databases/main/events_bg_updates.py", line 1313, in _background_replace_stream_ordering_column
I'm also having this problem, but I am upgrading from an older database (v59).
For me, the problem seems to be that background_updates queued in v60 are not able to run before the v79 update throws an exception, which then prevents synapse from starting.
I can see why this is failing though, the index doesn't exist because the v60 background_updates haven't run.
Delta 60 sets these up when it creates the stream_ordering2 field:
-- ... and some more to build indexes on it. These aren't really interdependent
-- but the backround_updates manager can only handle a single dependency per update.
INSERT INTO background_updates (ordering, update_name, progress_json, depends_on) VALUES
(6001, 'index_stream_ordering2', '{}', 'populate_stream_ordering2'),
(6001, 'index_stream_ordering2_room_order', '{}', 'index_stream_ordering2'),
(6001, 'index_stream_ordering2_contains_url', '{}', 'index_stream_ordering2_room_order'),
(6001, 'index_stream_ordering2_room_stream', '{}', 'index_stream_ordering2_contains_url'),
(6001, 'index_stream_ordering2_ts', '{}', 'index_stream_ordering2_room_stream');
Because my homeserver refuses to start now, I can't get these background updates to run. This will probably happen to anyone who upgrades from <= 60 to 79.
I suspect if I can just prevent 79 from running temporarily, then the v60 background updates will run, and then I can let v79 do its thing. But I'm not sure how to disable it. Or how the problem needs to be solved longterm!
My logs / etc:
empty background_updates table starting out in v59:
synapse=# select * from background_updates;
update_name | progress_json | depends_on | ordering
-------------+---------------+------------+----------
(0 rows)
On my new server, it runs through the upgrade patches on the old database, but then fails at delta 79
My homeserver.log output of the upgrade:
2023-08-29 17:07:24,564 - synapse.storage.databases.main - 323 - INFO - main - Checking database for consistency with configuration...
2023-08-29 17:07:24,566 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v59
2023-08-29 17:07:24,569 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 59/08delete_pushers_for_deactivated_accounts.sql
2023-08-29 17:07:24,571 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 59/08delete_stale_pushers.sql
2023-08-29 17:07:24,573 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 59/09rejected_events_metadata.sql
2023-08-29 17:07:24,574 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 59/10delete_purged_chain_cover.sql
2023-08-29 17:07:24,575 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 59/11add_knock_members_to_stats.sql
2023-08-29 17:07:24,576 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 59/11drop_thumbnail_constraint.sql.postgres
2023-08-29 17:07:24,578 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 59/12account_validity_token_used_ts_ms.sql
2023-08-29 17:07:24,579 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 59/12presence_stream_instance.sql
2023-08-29 17:07:24,580 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 59/12presence_stream_instance_seq.sql.postgres
2023-08-29 17:07:24,585 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 59/13users_to_send_full_presence_to.sql
2023-08-29 17:07:24,592 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 59/14refresh_tokens.sql
2023-08-29 17:07:24,599 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 59/15locks.sql
2023-08-29 17:07:24,605 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 59/16federation_inbound_staging.sql
2023-08-29 17:07:24,613 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v60
2023-08-29 17:07:24,614 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 60/01recreate_stream_ordering.sql.postgres
2023-08-29 17:07:24,618 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 60/02change_stream_ordering_columns.sql.postgres
2023-08-29 17:07:24,654 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v61
2023-08-29 17:07:24,655 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 61/01change_appservices_txns.sql.postgres
2023-08-29 17:07:24,665 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 61/01insertion_event_lookups.sql
2023-08-29 17:07:24,686 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 61/02drop_redundant_room_depth_index.sql
2023-08-29 17:07:24,688 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 61/02state_groups_state_n_distinct.sql.postgres
2023-08-29 17:07:24,691 - synapse.storage.prepare_database - 509 - INFO - main - Running 61/03recreate_min_depth.py:run_create
2023-08-29 17:07:24,703 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v62
2023-08-29 17:07:24,704 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 62/01insertion_event_extremities.sql
2023-08-29 17:07:24,711 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v63
2023-08-29 17:07:24,712 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 63/01create_registration_tokens.sql
2023-08-29 17:07:24,718 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 63/02delete_unlinked_email_pushers.sql
2023-08-29 17:07:24,720 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 63/02populate-rooms-creator.sql
2023-08-29 17:07:24,721 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 63/03session_store.sql
2023-08-29 17:07:24,727 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 63/04add_presence_stream_not_offline_index.sql
2023-08-29 17:07:24,729 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v64
2023-08-29 17:07:24,730 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 64/01msc2716_chunk_to_batch_rename.sql.postgres
2023-08-29 17:07:24,735 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v65
2023-08-29 17:07:24,736 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 65/01msc2716_insertion_event_edges.sql
2023-08-29 17:07:24,739 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 65/03remove_hidden_devices_from_device_inbox.sql
2023-08-29 17:07:24,741 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 65/04_local_group_updates.sql
2023-08-29 17:07:24,742 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 65/05_remove_room_stats_historical_and_user_stats_historical.sql
2023-08-29 17:07:24,746 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 65/06remove_deleted_devices_from_device_inbox.sql
2023-08-29 17:07:24,750 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 65/07_arbitrary_relations.sql
2023-08-29 17:07:24,751 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 65/08_device_inbox_background_updates.sql
2023-08-29 17:07:24,752 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 65/10_expirable_refresh_tokens.sql
2023-08-29 17:07:24,754 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 65/11_devices_auth_provider_session.sql
2023-08-29 17:07:24,763 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v66
2023-08-29 17:07:24,763 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v67
2023-08-29 17:07:24,764 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 67/01drop_public_room_list_stream.sql
2023-08-29 17:07:24,767 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v68
2023-08-29 17:07:24,768 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 68/01event_columns.sql
2023-08-29 17:07:24,771 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 68/02_msc2409_add_device_id_appservice_stream_type.sql
2023-08-29 17:07:24,772 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 68/03_delete_account_data_for_deactivated_accounts.sql
2023-08-29 17:07:24,774 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 68/04_refresh_tokens_index_next_token_id.sql
2023-08-29 17:07:24,778 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 68/04partial_state_rooms.sql
2023-08-29 17:07:24,796 - synapse.storage.prepare_database - 509 - INFO - main - Running 68/05partial_state_rooms_triggers.py:run_create
2023-08-29 17:07:24,798 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 68/06_msc3202_add_device_list_appservice_stream_type.sql
2023-08-29 17:07:24,799 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v69
2023-08-29 17:07:24,801 - synapse.storage.prepare_database - 509 - INFO - main - Running 69/01as_txn_seq.py:run_create
2023-08-29 17:07:24,802 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 69/01device_list_oubound_by_room.sql
2023-08-29 17:07:24,810 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 69/02cache_invalidation_index.sql
2023-08-29 17:07:24,812 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v70
2023-08-29 17:07:24,813 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 70/01clean_table_purged_rooms.sql
2023-08-29 17:07:24,814 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 70/08_state_group_edges_unique.sql
2023-08-29 17:07:24,816 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v71
2023-08-29 17:07:24,817 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 71/01rebuild_event_edges.sql.postgres
2023-08-29 17:07:24,820 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 71/01remove_noop_background_updates.sql
2023-08-29 17:07:24,825 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 71/02event_push_summary_unique.sqlI'm upgrading from the old Debian 10 buster-backports version to the matrix.org repository version on Debian 11.
2023-08-29 17:07:24,826 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v72
2023-08-29 17:07:24,827 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 72/01add_room_type_to_state_stats.sql
2023-08-29 17:07:24,829 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 72/01event_push_summary_receipt.sql
2023-08-29 17:07:24,834 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 72/02event_push_actions_index.sql
2023-08-29 17:07:24,836 - synapse.storage.prepare_database - 509 - INFO - main - Running 72/03bg_populate_events_columns.py:run_create
2023-08-29 17:07:24,839 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 72/03drop_event_reference_hashes.sql
2023-08-29 17:07:24,842 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 72/03remove_groups.sql
2023-08-29 17:07:24,872 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 72/04drop_column_application_services_state_last_txn.sql.postgres
2023-08-29 17:07:24,877 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 72/05receipts_event_stream_ordering.sql
2023-08-29 17:07:24,879 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 72/05remove_unstable_private_read_receipts.sql
2023-08-29 17:07:24,882 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 72/06add_consent_ts_to_users.sql
2023-08-29 17:07:24,883 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 72/06thread_notifications.sql
2023-08-29 17:07:24,886 - synapse.storage.prepare_database - 513 - INFO - main - Running 72/07force_update_current_state_events_membership.py:run_upgrade
2023-08-29 17:07:24,886 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 72/07thread_receipts.sql.postgres
2023-08-29 17:07:24,923 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 72/08begin_cache_invalidation_seq_at_2.sql.postgres
2023-08-29 17:07:24,933 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 72/08thread_receipts.sql
2023-08-29 17:07:24,934 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v73
2023-08-29 17:07:24,936 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 73/01event_failed_pull_attempts.sql
2023-08-29 17:07:24,943 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 73/02add_pusher_enabled.sql
2023-08-29 17:07:24,944 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 73/02room_id_indexes_for_purging.sql
2023-08-29 17:07:24,951 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 73/03pusher_device_id.sql
2023-08-29 17:07:24,952 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 73/03users_approved_column.sql
2023-08-29 17:07:24,954 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 73/04partial_join_details.sql
2023-08-29 17:07:24,956 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 73/04pending_device_list_updates.sql
2023-08-29 17:07:24,964 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 73/05old_push_actions.sql.postgres
2023-08-29 17:07:24,970 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 73/06thread_notifications_thread_id_idx.sql
2023-08-29 17:07:24,972 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 73/08thread_receipts_non_null.sql.postgres
2023-08-29 17:07:24,973 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 73/09partial_joined_via_destination.sql
2023-08-29 17:07:24,975 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 73/09threads_table.sql
2023-08-29 17:07:24,984 - synapse.storage.prepare_database - 509 - INFO - main - Running 73/10_update_sqlite_fts4_tokenizer.py:run_create
2023-08-29 17:07:24,984 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 73/10login_tokens.sql
2023-08-29 17:07:24,993 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 73/11event_search_room_id_n_distinct.sql.postgres
2023-08-29 17:07:24,995 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 73/12refactor_device_list_outbound_pokes.sql
2023-08-29 17:07:25,003 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 73/13add_device_lists_index.sql
2023-08-29 17:07:25,005 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 73/20_un_partial_stated_room_stream.sql
2023-08-29 17:07:25,012 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 73/21_un_partial_stated_room_stream_seq.sql.postgres
2023-08-29 17:07:25,014 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 73/22_rebuild_user_dir_stats.sql
2023-08-29 17:07:25,015 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 73/22_un_partial_stated_event_stream.sql
2023-08-29 17:07:25,024 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 73/23_fix_thread_index.sql
2023-08-29 17:07:25,026 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 73/23_un_partial_stated_room_stream_seq.sql.postgres
2023-08-29 17:07:25,028 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 73/24_events_jump_to_date_index.sql
2023-08-29 17:07:25,030 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 73/25drop_presence.sql
2023-08-29 17:07:25,033 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v74
2023-08-29 17:07:25,034 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 74/01_user_directory_stale_remote_users.sql
2023-08-29 17:07:25,045 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 74/02_set_device_id_for_pushers_bg_update.sql
2023-08-29 17:07:25,046 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 74/03_membership_tables_event_stream_ordering.sql.postgres
2023-08-29 17:07:25,051 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 74/03_room_membership_index.sql
2023-08-29 17:07:25,052 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 74/04_delete_e2e_backup_keys_for_deactivated_users.sql
2023-08-29 17:07:25,054 - synapse.storage.prepare_database - 509 - INFO - main - Running 74/04_membership_tables_event_stream_ordering_triggers.py:run_create
2023-08-29 17:07:25,057 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 74/05_events_txn_id_device_id.sql
2023-08-29 17:07:25,068 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 74/90COMMENTS_destinations.sql.postgres
2023-08-29 17:07:25,071 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v75
2023-08-29 17:07:25,072 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v76
2023-08-29 17:07:25,073 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 76/01_add_profiles_full_user_id_column.sql
2023-08-29 17:07:25,075 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 76/02_add_user_filters_full_user_id_column.sql
2023-08-29 17:07:25,076 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 76/03_per_user_experimental_features.sql
2023-08-29 17:07:25,082 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 76/04_add_room_forgetter.sql
2023-08-29 17:07:25,086 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v77
2023-08-29 17:07:25,087 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 77/01_add_profiles_not_valid_check.sql.postgres
2023-08-29 17:07:25,088 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 77/02_add_user_filters_not_valid_check.sql.postgres
2023-08-29 17:07:25,090 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 77/03bg_populate_full_user_id_profiles.sql
2023-08-29 17:07:25,091 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 77/04bg_populate_full_user_id_user_filters.sql
2023-08-29 17:07:25,092 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 77/05thread_notifications_backfill.sql
2023-08-29 17:07:25,100 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 77/06thread_notifications_not_null_event_push_actions.sql.postgres
2023-08-29 17:07:25,103 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 77/06thread_notifications_not_null_event_push_actions_staging.sql.postgres
2023-08-29 17:07:25,103 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 77/06thread_notifications_not_null_event_push_actions_staging.sql.postgres
2023-08-29 17:07:25,107 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 77/06thread_notifications_not_null_event_push_summary.sql.postgres
2023-08-29 17:07:25,110 - synapse.storage.prepare_database - 526 - INFO - main - Applying schema 77/14bg_indices_event_stream_ordering.sql
2023-08-29 17:07:25,113 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v78
2023-08-29 17:07:25,116 - synapse.storage.prepare_database - 513 - INFO - main - Running 78/01_validate_and_update_profiles.py:run_upgrade
2023-08-29 17:07:25,122 - synapse.storage.prepare_database - 513 - INFO - main - Running 78/02_validate_and_update_user_filters.py:run_upgrade
2023-08-29 17:07:25,130 - synapse.storage.prepare_database - 509 - INFO - main - Running 78/03event_extremities_constraints.py:run_create
2023-08-29 17:07:25,135 - synapse.storage.prepare_database - 509 - INFO - main - Running 78/04_add_full_user_id_index_user_filters.py:run_create
2023-08-29 17:07:25,136 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v79
2023-08-29 17:07:25,138 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 79/03_read_write_locks_triggers.sql.postgres
2023-08-29 17:07:25,170 - synapse.storage.prepare_database - 509 - INFO - main - Running 79/04_mitigate_stream_ordering_update_race.py:run_create
2023-08-29 17:07:25,196 - synapse.app._base - 215 - ERROR - main - Exception during startup
Traceback (most recent call last):
File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/app/homeserver.py", line 353, in setup
hs.setup()
File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/server.py", line 339, in setup
self.datastores = Databases(self.DATASTORE_CLASS, self)
File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/databases/__init__.py", line 74, in __init__
prepare_database(
File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/prepare_database.py", line 141, in prepare_database
_upgrade_existing_database(
File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/prepare_database.py", line 510, in _upgrade_existing_database
module.run_create(cur, database_engine)
File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/schema/main/delta/79/04_mitigate_stream_ordering_update_race.py", line 58, in run_create
cur.execute(add_cse_sql)
File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/database.py", line 417, in execute
self._do_execute(self.txn.execute, sql, parameters)
File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/database.py", line 469, in _do_execute
return func(sql, *args, **kwargs)
psycopg2.errors.InvalidForeignKey: there is no unique constraint matching given keys for referenced table "events"
my background_tasks table has 55 new rows in it after the upgrade:
synapse=# SELECT * FROM background_updates;
update_name | progress_json | depends_on | ordering
------------------------------------------------------------------+-----------------------------------------------------------------------------------+-----------------------------------------------+----------
remove_deactivated_pushers | {} | | 5908
remove_stale_pushers | {} | | 5908
rejected_events_metadata | {} | | 5828
purged_chain_cover | {} | | 5910
media_repository_drop_index_wo_method_2 | {} | remote_media_repository_thumbnails_method_idx | 5911
populate_stream_ordering2 | {} | | 6001
index_stream_ordering2 | {} | populate_stream_ordering2 | 6001
index_stream_ordering2_room_order | {} | index_stream_ordering2 | 6001
index_stream_ordering2_contains_url | {} | index_stream_ordering2_room_order | 6001
index_stream_ordering2_room_stream | {} | index_stream_ordering2_contains_url | 6001
index_stream_ordering2_ts | {} | index_stream_ordering2_room_stream | 6001
replace_stream_ordering_column | {} | index_stream_ordering2_ts | 6001
populate_room_depth_min_depth2 | {} | | 6103
replace_room_depth_min_depth | {} | populate_room_depth2 | 6103
remove_deleted_email_pushers | {} | | 6302
populate_rooms_creator_column | {} | | 6302
presence_stream_not_offline_index | {} | | 6304
event_arbitrary_relations | {} | | 6507
remove_dead_devices_from_device_inbox | {} | | 6508
delete_account_data_for_deactivated_users | {} | | 6803
cache_invalidation_index_by_instance | {} | | 6902
state_group_edges_unique_idx | {} | | 7008
event_edges_drop_invalid_rows | {} | | 7101
event_edges_replace_index | {} | event_edges_drop_invalid_rows | 7101
add_room_type_column | {} | | 0
event_push_actions_stream_highlight_index | {} | | 7202
events_populate_state_key_rejections | {"min_stream_ordering_exclusive": -4265, "max_stream_ordering_inclusive": 635228} | | 7203
populate_event_stream_ordering | {} | | 0
event_push_summary_unique_index2 | {} | | 7006
receipts_linearized_unique_index | {} | | 7007
receipts_graph_unique_index | {} | | 7007
threads_backfill | {} | | 7309
device_lists_changes_in_room_by_room_index | {} | | 7313
populate_user_directory_createtables | {} | | 7322
populate_user_directory_process_rooms | {} | populate_user_directory_createtables | 7322
populate_user_directory_process_users | {} | populate_user_directory_process_rooms | 7322
populate_user_directory_cleanup | {} | populate_user_directory_process_users | 7322
populate_stats_process_rooms | {} | | 7322
populate_stats_process_users | {} | | 7322
events_jump_to_date_index | {} | | 7324
set_device_id_for_pushers | {} | | 7402
room_membership_user_room_index | {} | | 7403
delete_e2e_backup_keys_for_deactivated_users | {} | | 7404
profiles_full_user_id_key_idx | {} | | 7501
full_users_filters_unique_idx | {} | | 7502
populate_full_user_id_profiles | {} | | 7703
populate_full_user_id_user_filters | {} | | 7704
event_push_actions_thread_id | {} | event_push_actions_staging_thread_id | 7706
event_push_actions_staging_thread_id | {} | | 7706
event_push_summary_thread_id | {} | event_push_actions_thread_id | 7706
event_push_drop_null_thread_id_indexes | {} | event_push_summary_thread_id | 7706
current_state_events_stream_ordering_idx | {} | | 7714
local_current_membership_stream_ordering_idx | {} | | 7714
room_memberships_stream_ordering_idx | {} | | 7714
event_forward_extremities_event_id_foreign_key_constraint_update | {} | | 7803
(55 rows)
and my events table is missing that unique index alright:
synapse=# \d events
Table "public.events"
Column | Type | Collation | Nullable | Default
----------------------+---------+-----------+----------+---------
stream_ordering | integer | | not null |
topological_ordering | bigint | | not null |
event_id | text | | not null |
type | text | | not null |
room_id | text | | not null |
content | text | | |
unrecognized_keys | text | | |
processed | boolean | | not null |
outlier | boolean | | not null |
depth | bigint | | not null | 0
origin_server_ts | bigint | | |
received_ts | bigint | | |
sender | text | | |
contains_url | boolean | | |
instance_name | text | | |
stream_ordering2 | bigint | | |
state_key | text | | |
rejection_reason | text | | |
Indexes:
"events_pkey" PRIMARY KEY, btree (stream_ordering)
"events_event_id_key" UNIQUE CONSTRAINT, btree (event_id)
"events_order_room" btree (room_id, topological_ordering, stream_ordering)
"events_room_stream" btree (room_id, stream_ordering)
"events_ts" btree (origin_server_ts, stream_ordering)
Referenced by:
TABLE "event_edges" CONSTRAINT "event_edges_event_id_fkey" FOREIGN KEY (event_id) REFERENCES events(event_id) NOT VALID
TABLE "event_forward_extremities" CONSTRAINT "event_forward_extremities_event_id" FOREIGN KEY (event_id) REFERENCES events(event_id) DEFERRABLE INITIALLY DEFERRED NOT VALID
TABLE "current_state_events" CONSTRAINT "event_stream_ordering_fkey" FOREIGN KEY (event_stream_ordering) REFERENCES events(stream_ordering) NOT VALID
TABLE "local_current_membership" CONSTRAINT "event_stream_ordering_fkey" FOREIGN KEY (event_stream_ordering) REFERENCES events(stream_ordering) NOT VALID
TABLE "room_memberships" CONSTRAINT "event_stream_ordering_fkey" FOREIGN KEY (event_stream_ordering) REFERENCES events(stream_ordering) NOT VALID
TABLE "event_txn_id_device_id" CONSTRAINT "event_txn_id_device_id_event_id_fkey" FOREIGN KEY (event_id) REFERENCES events(event_id) ON DELETE CASCADE
TABLE "event_txn_id" CONSTRAINT "event_txn_id_event_id_fkey" FOREIGN KEY (event_id) REFERENCES events(event_id) ON DELETE CASCADE
TABLE "partial_state_events" CONSTRAINT "partial_state_events_event_id_fkey" FOREIGN KEY (event_id) REFERENCES events(event_id)
TABLE "partial_state_rooms" CONSTRAINT "partial_state_rooms_join_event_id_fkey" FOREIGN KEY (join_event_id) REFERENCES events(event_id)
TABLE "un_partial_stated_event_stream" CONSTRAINT "un_partial_stated_event_stream_event_id_fkey" FOREIGN KEY (event_id) REFERENCES events(event_id) ON DELETE CASCADE
Rules:
populate_stream_ordering2 AS
ON INSERT TO events DO UPDATE events SET stream_ordering2 = new.stream_ordering
WHERE events.stream_ordering = new.stream_ordering
It looks like @gpetters94's installation couldn't run
-- ALTER TABLE events DROP COLUMN stream_ordering;
from https://github.com/matrix-org/synapse/blob/2b78981736f9004f99b1760e3e77b234f92755a7/synapse/storage/databases/main/events_bg_updates.py#L40-L52
Can you share the output of \d events please?
@damienvancouver: thanks for the report, but can you hold off for the time being? I would like to use this issue to fix one installation first and then see if that fix also works for you.
The relevant bit seems to be:
2023-08-29 17:22:03,215 - synapse.storage.background_updates - 461 - INFO - background_updates-0 - Starting update batch on background update 'replace_stream_ordering_column' 2023-08-29 17:22:03,923 - synapse.storage.databases.main.events_bg_updates - 1300 - INFO - background_updates-0 - completing stream_ordering migration: UPDATE events SET stream_ordering2 = stream_ordering WHERE stream_ordering2 IS NULL 2023-08-29 17:22:03,927 - synapse.storage.databases.main.events_bg_updates - 1300 - INFO - background_updates-0 - completing stream_ordering migration: DROP RULE populate_stream_ordering2 ON events 2023-08-29 17:22:03,936 - synapse.storage.databases.main.events_bg_updates - 1300 - INFO - background_updates-0 - completing stream_ordering migration: ALTER TABLE events DROP COLUMN stream_ordering 2023-08-29 17:22:03,962 - synapse.storage.background_updates - 332 - ERROR - background_updates-0 - Error doing update File "/opt/venvs/matrix-synapse/lib/python3.11/site-packages/synapse/storage/background_updates.py", line 323, in run_background_updates result = await self.do_next_background_update(sleep) File "/opt/venvs/matrix-synapse/lib/python3.11/site-packages/synapse/storage/background_updates.py", line 454, in do_next_background_update await self._do_background_update(desired_duration_ms) File "/opt/venvs/matrix-synapse/lib/python3.11/site-packages/synapse/storage/background_updates.py", line 497, in _do_background_update File "/opt/venvs/matrix-synapse/lib/python3.11/site-packages/synapse/storage/databases/main/events_bg_updates.py", line 1313, in _background_replace_stream_ordering_column
It is frustrating that this obscures the exception from the background update. Maybe I can improve this...
\d events
The output of \d events is:
Table "public.events"
Column | Type | Collation | Nullable | Default
----------------------+---------+-----------+----------+---------
stream_ordering | integer | | not null |
topological_ordering | bigint | | not null |
event_id | text | | not null |
type | text | | not null |
room_id | text | | not null |
content | text | | |
unrecognized_keys | text | | |
processed | boolean | | not null |
outlier | boolean | | not null |
depth | bigint | | not null | 0
origin_server_ts | bigint | | |
received_ts | bigint | | |
sender | text | | |
contains_url | boolean | | |
instance_name | text | | |
stream_ordering2 | bigint | | |
state_key | text | | |
rejection_reason | text | | |
Indexes:
"events_pkey" PRIMARY KEY, btree (stream_ordering)
"event_contains_url_index" btree (room_id, topological_ordering, stream_ordering) WHERE contains_url = true AND outlier = false
"event_contains_url_index2" btree (room_id, topological_ordering, stream_ordering2) WHERE contains_url = true AND outlier = false
"events_event_id_key" UNIQUE CONSTRAINT, btree (event_id)
"events_order_room" btree (room_id, topological_ordering, stream_ordering)
"events_order_room2" btree (room_id, topological_ordering, stream_ordering2)
"events_room_stream" btree (room_id, stream_ordering)
"events_room_stream2" btree (room_id, stream_ordering2)
"events_stream_ordering" UNIQUE, btree (stream_ordering2)
"events_ts" btree (origin_server_ts, stream_ordering)
"events_ts2" btree (origin_server_ts, stream_ordering2)
Referenced by:
TABLE "event_edges" CONSTRAINT "event_edges_event_id_fkey" FOREIGN KEY (event_id) REFERENCES events(event_id) NOT VALID
TABLE "event_forward_extremities" CONSTRAINT "event_forward_extremities_event_id" FOREIGN KEY (event_id) REFERENCES events(event_id) DEFERRABLE INITIALLY DEFERRED NOT VALID
TABLE "current_state_events" CONSTRAINT "event_stream_ordering_fkey" FOREIGN KEY (event_stream_ordering) REFERENCES events(stream_ordering) NOT VALID
TABLE "local_current_membership" CONSTRAINT "event_stream_ordering_fkey" FOREIGN KEY (event_stream_ordering) REFERENCES events(stream_ordering) NOT VALID
TABLE "room_memberships" CONSTRAINT "event_stream_ordering_fkey" FOREIGN KEY (event_stream_ordering) REFERENCES events(stream_ordering) NOT VALID
TABLE "event_txn_id_device_id" CONSTRAINT "event_txn_id_device_id_event_id_fkey" FOREIGN KEY (event_id) REFERENCES events(event_id) ON DELETE CASCADE
TABLE "event_txn_id" CONSTRAINT "event_txn_id_event_id_fkey" FOREIGN KEY (event_id) REFERENCES events(event_id) ON DELETE CASCADE
TABLE "partial_state_events" CONSTRAINT "partial_state_events_event_id_fkey" FOREIGN KEY (event_id) REFERENCES events(event_id)
TABLE "partial_state_rooms" CONSTRAINT "partial_state_rooms_join_event_id_fkey" FOREIGN KEY (join_event_id) REFERENCES events(event_id)
TABLE "un_partial_stated_event_stream" CONSTRAINT "un_partial_stated_event_stream_event_id_fkey" FOREIGN KEY (event_id) REFERENCES events(event_id) ON DELETE CASCADE
Rules:
populate_stream_ordering2 AS
ON INSERT TO events DO UPDATE events SET stream_ordering2 = new.stream_ordering
WHERE events.stream_ordering = new.stream_ordering
It looks like @gpetters94's installation couldn't run
-- ALTER TABLE events DROP COLUMN stream_ordering;
... bugger. Is this because of the foreign keys on this column?
TABLE "current_state_events" CONSTRAINT "event_stream_ordering_fkey" FOREIGN KEY (event_stream_ordering) REFERENCES events(stream_ordering) NOT VALID
TABLE "local_current_membership" CONSTRAINT "event_stream_ordering_fkey" FOREIGN KEY (event_stream_ordering) REFERENCES events(stream_ordering) NOT VALID
TABLE "room_memberships" CONSTRAINT "event_stream_ordering_fkey" FOREIGN KEY (event_stream_ordering) REFERENCES events(stream_ordering) NOT VALID
@DMRobertson Shared with my privately:
Hypothesis (unchecked): if you run this migration (
74/03_membership_tables_event_stream_ordering.sql.postgres) before you run this background update (replace_stream_ordering_column) you’re going to end up in a world of pain.
So there's a couple of things here:
- How do we fix @gpetters94's broken database?
- How do we keep others from ending up in the same position?
- How do we keep this from happening in the future?
Let's start with the first one. Note that we highly don't recommend manually modifying your database without input from us.
Our goal is to get the background updates to "catch-up" and finish before some of the foreground updates have run.
Looking at #15677 I think the manual fixes in there are "correct", but the automated fixed added in #15887 might not be working properly? Or might not have worked yet, it seems to require that index_stream_ordering2 has run, but replace_stream_ordering_column has not.
Looking at the background updates given above, but then the logs given above it looks like some additional background updates have run now and in-fact you should have the needed index:
2023-08-29 17:21:36,010 - synapse.storage.background_updates - 461 - INFO - background_updates-0 - Starting update batch on background update 'index_stream_ordering2'
2023-08-29 17:21:36,014 - synapse.storage.background_updates - 740 - INFO - background_updates-0 - Adding index events_stream_ordering to events
Just to double check, is this still failing with the same error? Can you redump the applied background updates and confirm which version of Synapse you're now running?
I was able to fix my broken database with the following workaround. All commands below ran as root (or you can add "sudo" first if you aren't the root user)
- Stop matrix-synapse service:
systemctl stop matrix-synapse - Using your favourite text editor, edit the file /opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/schema/__init__.py. e.g.
nano /opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/schema/__init__.py(if it's a file not found see the instructions at the bottom for finding the right path). - Adjust the line:
SCHEMA_VERSION = 80 # remember to update the list below when updatingand change the 80 to 78, so the line now reads:SCHEMA_VERSION = 78 # CHANGED FROM 80 remember to update the list below when updating. Note that the SCHEMA_VERSION might not be 80 any more by the time you are reading this. Change it to 78 still (we are trying to prevent update 79 running) but make note of what it was so you can change it back! - Save the init.py file
- Now restart synapse with:
systemctl start matrix-synapse. Matrix will start up but it will not try and apply schema update 79. Update 78 is going to take a while depending on how big your events table is. It took me several hours with 600k event rows. Tail the log file (tail -f /var/log/matrix-synapse/homeserver.logandctrl-Cto exit), so you can see when it's finally finished applying the update 79 updates, it's fairly obvious once that starts happening, there will be no more log file entries of the job running and it will just be "normal" matrix logs because your clients will be reconnected (yay!). - When the updates are finished, we need to allow updates 79+ to run. Shut down matrix again (briefly):
systemctl stop matrix-synapse - Now return or re-launch your text edit of __init__.py
- Change the line back to how it was (SCHEMA_VERSION = 80 or whatever you changed from)
- Now save and exit the editor
- restart matrix with
systemctl start matrix-synapse - Updates 79 and 80 will apply cleanly, you are done!
Things that might go wrong:
If you didn't install via the matrix.org repo packages, your __init__.py might be in a different spot. Try to find your top level matrix dir with which matrix-homeserver .. then go one folder up from that (it will be in the matrix-dir/bin ) and run the command grep -r SCHEMA_VERSION and it should return a bunch of results from the __init__.py you are looking for.
If you restart too early before those background updates are done, it will crash the same way again. Just repeat the process but wait longer!
I hope this helps out, it totally worked for me. In hindsight I should have gone from the Debian 10 backports package to the Debian 11 backports package (which is v78), before going to the matrix.org package which is v80. For those who read the warnings in time, that upgrade path should avoid this problem and the need for a workaround.
Subscribed. I believe I have the same problem. Stuck on v1.88.0. When I try to upgrade to v1.89.0 or later it errors out.
docker logs from postgres container: 2023-09-24 04:31:08.285 UTC [116] STATEMENT:
ALTER TABLE current_state_events ADD CONSTRAINT event_stream_ordering_fkey
FOREIGN KEY (event_stream_ordering) REFERENCES events(stream_ordering2) NOT VALID;
docker logs from synapse container:
2023-09-24 00:34:09,393 - synapse.app.homeserver - 350 - INFO - main - Setting up server
2023-09-24 00:34:09,393 - synapse.server - 336 - INFO - main - Setting up.
2023-09-24 00:34:09,410 - synapse.storage.databases - 66 - INFO - main - [database config 'master']: Checking database server
2023-09-24 00:34:09,415 - synapse.storage.databases - 69 - INFO - main - [database config 'master']: Preparing for databases ['main', 'state']
2023-09-24 00:34:09,415 - synapse.storage.prepare_database - 120 - INFO - main - ['main', 'state']: Checking existing schema version
2023-09-24 00:34:09,427 - synapse.storage.prepare_database - 124 - INFO - main - ['main', 'state']: Existing schema is 79 (+0 deltas)
2023-09-24 00:34:09,427 - synapse.storage.databases.main - 323 - INFO - main - Checking database for consistency with configuration...
2023-09-24 00:34:09,431 - synapse.storage.prepare_database - 418 - INFO - main - Applying schema deltas for v79
2023-09-24 00:34:09,436 - synapse.storage.prepare_database - 534 - INFO - main - Applying engine-specific schema 79/03_read_write_locks_triggers.sql.postgres
2023-09-24 00:34:09,624 - synapse.storage.prepare_database - 509 - INFO - main - Running 79/04_mitigate_stream_ordering_update_race.py:run_create
2023-09-24 00:34:09,677 - synapse.app._base - 215 - ERROR - main - Exception during startup
Traceback (most recent call last):
File "/usr/local/lib/python3.11/site-packages/synapse/app/homeserver.py", line 353, in setup
hs.setup()
File "/usr/local/lib/python3.11/site-packages/synapse/server.py", line 338, in setup
self.datastores = Databases(self.DATASTORE_CLASS, self)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/synapse/storage/databases/__init__.py", line 74, in __init__
prepare_database(
I have the same issue upgrading from 1.53 to 1.95.1. So I restored database from backup and currently installing 1.71.0. I think it would be resonable to deny start-up in newer version if schema is too old and to give user message to install older version first.
I think it would be resonable to deny start-up in newer version if schema is too old and to give user message to install older version first.
This is essentially the idea behind #16397.
@gpetters94, are you able to answer Patrick's questions from https://github.com/matrix-org/synapse/issues/16192#issuecomment-1711758663?
Just to double check, is this still failing with the same error? Can you redump the applied background updates and confirm which version of Synapse you're now running?
I was able to fix my issue which looked like it had 2 problems within (https://github.com/matrix-org/synapse/issues/16192#issuecomment-1732475428)
-
The background updates were stuck and it seemed to be related to duplicate entries in the db. The following issue helped me to identify and delete those duplicate entries in the db (https://github.com/matrix-org/synapse/issues/8781#issuecomment-745239615). After the duplicates were deleted the background updates were chugging along again but then got stuck again.
-
The second error gave the following in the log:
psycopg2.errors.DependentObjectsStillExist: cannot drop column stream_ordering of table events because other objects depend on it
DETAIL: constraint event_stream_ordering_fkey on table current_state_events depends on column stream_ordering of table events
constraint event_stream_ordering_fkey on table local_current_membership depends on column stream_ordering of table events
constraint event_stream_ordering_fkey on table room_memberships depends on column stream_ordering of table events
To get around this problem I used the work around from this issue (https://github.com/matrix-org/synapse/issues/15677).
After apply the second workaround the background_updates table eventually emptied and then updating to v1.96.1 went smoothly.
I hope this may help others that may be in my situation