element-hq / element-hq/synapse

AssertionError in _reset_federation_positions_txn()

Open
#16,993 2 comments 0 reactions 0 assignees View on GitHub
A-Federation O-Uncommon S-Major T-Defect
Dominant language
Python
Stars
4.6k
Forks
600
Avg merge
5d 22h
Merged PRs (30d)
51

Description

### Description

AssertionError in _reset_federation_positions_txn() due to empty federation_stream_position table when federation was previously disabled on a server.

### Steps to reproduce

There are two servers in different cities. There has been no federation for many years. But now we need it. After switching on the federation the guest from the other server has problems.
I.e. if I invite someone to server-1 from server-2, the person from server-2 sees the invitation, accepts it and can write. His messages are visible on server-1, but he doesn't see replies from server-1, but he sees all messages from server-2 (where he is registered). And the same situation if someone from server-1 is invited to server-2. It doesn't see any messages from people on server-2.

### Homeserver

Two servers server-1.com and server-2.com (fictitious names)

### Synapse Version

1.101.0 on both servers

### Installation Method

Other (please mention below)

### Database

One PostgreSQL server is in use (14.3). Have not ported data from SQLite. Did not restore from backup earlier.

### Workers

Single process

### Platform

Slackware64-15.0
PostgreSQL-14.3
Python 3.9.16

### Configuration

_No response_

### Relevant log output

```shell
root - 355 - WARNING - main - ***** STARTING SERVER *****
root - 356 - WARNING - main - Server /usr/lib64/python3.9/site-packages/synapse/app/homeserver.py version 1.101.0
root - 361 - WARNING - main - Copyright (c) 2023 New Vector, Inc
root - 362 - WARNING - main - Licensed under the AGPL 3.0 license. Website: https://github.com/element-hq/synapse
root - 365 - INFO - main - Server hostname: server-2.com
root - 366 - INFO - main - Instance name: master
root - 367 - INFO - main - Twisted reactor: EPollReactor
synapse.app.homeserver - 356 - INFO - main - Setting up server
synapse.server - 345 - INFO - main - Setting up.
synapse.storage.databases - 73 - INFO - main - [database config 'master']: Checking database server
synapse.storage.databases - 76 - INFO - main - [database config 'master']: Preparing for databases ['main', 'state']
synapse.storage.prepare_database - 135 - INFO - main - ['main', 'state']: Checking existing schema version
synapse.storage.prepare_database - 139 - INFO - main - ['main', 'state']: Existing schema is 84 (+3 deltas)
synapse.storage.databases.main - 388 - INFO - main - Checking database for consistency with configuration...
synapse.storage.prepare_database - 433 - INFO - main - Applying schema deltas for v84
synapse.storage.prepare_database - 568 - INFO - main - Schema now up to date
synapse.storage.databases - 91 - INFO - main - [database config 'master']: Starting 'main' database
synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for pushers(id): 297607
synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for deleted_pushers(stream_id): 297566
synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for push_rules_stream(stream_id): 703
synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for e2e_cross_signing_keys(stream_id): 237
synapse.storage.databases.main.event_push_actions - 1206 - INFO - main - Searching for stream ordering 1 month ago
synapse.storage.databases.main.event_push_actions - 1210 - INFO - main - Found stream ordering 1 month ago: it's 203279
synapse.storage.databases.main.event_push_actions - 1213 - INFO - main - Searching for stream ordering 1 day ago
synapse.storage.databases.main.event_push_actions - 1217 - INFO - main - Found stream ordering 1 day ago: it's 205930
synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for push_rules(id): 270
synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for push_rules_enable(id): 269
synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for access_tokens(id): 2635
synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for refresh_tokens(id): 1
synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for event_reports(id): 2
synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for device_lists_stream(stream_id): 8316
synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for user_signature_stream(stream_id): 7900
synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for device_lists_outbound_pokes(stream_id): 1
synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for device_lists_changes_in_room(stream_id): 8316
synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for device_lists_remote_pending(stream_id): 1
synapse.storage.util.id_generators - 99 - INFO - main - Initialising stream generator for device_lists_changes_converted_stream_position(stream_id): 8323
synapse.storage.databases - 108 - INFO - main - [database config 'master']: Starting 'state' database
synapse.storage.databases - 123 - INFO - main - [database config 'master']: prepared
synapse.server - 348 - INFO - main - Finished setting up.
synapse.push.pusher - 45 - INFO - main - email enable notifs: True
synapse.push.pusher - 54 - INFO - main - defined email pusher type
synapse.federation.federation_server - 1379 - INFO - main - Registering federation EDU handler for 'm.device_list_update'
synapse.federation.federation_server - 1399 - INFO - main - Registering federation query handler for 'profile'
synapse.federation.federation_server - 1379 - INFO - main - Registering federation EDU handler for 'm.presence'
synapse.federation.federation_server - 1379 - INFO - main - Registering federation EDU handler for 'm.typing'
synapse.federation.federation_server - 1399 - INFO - main - Registering federation query handler for 'directory'
twisted - 282 - INFO - main - Redirected stdout/stderr to logs
synapse.app.homeserver - 149 - WARNING - sentinel - Starting daemon.
synapse.app.homeserver - 179 - INFO - sentinel - Running
synapse.app.homeserver - 36 - INFO - sentinel - Set file limit to: 4096
synapse.handlers.deactivate_account - 240 - INFO - user_parter_loop-0 - Starting user parter
synapse.util.caches.lrucache - 230 - INFO - sentinel - Expiring LRU caches after 1800 seconds
synapse.push.mailer - 131 - INFO - sentinel - Created Mailer for app_name Matrix
synapse.push.mailer - 131 - INFO - sentinel - Created Mailer for app_name Matrix
synapse.push.mailer - 131 - INFO - sentinel - Created Mailer for app_name Matrix
synapse.federation.federation_server - 1379 - INFO - sentinel - Registering federation EDU handler for 'm.receipt'
synapse.federation.federation_server - 1379 - INFO - sentinel - Registering federation EDU handler for 'm.signing_key_update'
synapse.federation.federation_server - 1379 - INFO - sentinel - Registering federation EDU handler for 'org.matrix.signing_key_update'
synapse.federation.federation_server - 1399 - INFO - sentinel - Registering federation query handler for 'client_keys'
synapse.federation.federation_server - 1379 - INFO - sentinel - Registering federation EDU handler for 'm.direct_to_device'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching to path b'/health'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching to path b'/_matrix/client'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching to path b'/.well-known'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching to path b'/_synapse/admin'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching to path b'/_synapse/client/pick_idp'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching to path b'/_synapse/client/pick_username'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching to path b'/_synapse/client/new_user_consent'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching to path b'/_synapse/client/sso_register'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching to path b'/_synapse/client/unsubscribe'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching to path b'/_synapse/client/password_re
set/email/submit_token'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching FilePath('/usr/lib64/python3.9/site-packages/synapse/static') to path b'/_matrix/static'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching to path b'/_matrix/media/r0'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching to path b'/_matrix/media/v3'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching to path b'/_matrix/media/v1'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching to path b'/_matrix/federation'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching to path b'/_matrix/key'
twisted - 282 - INFO - sentinel - SynapseSite starting on 8008
synapse.app._base - 438 - INFO - sentinel - Synapse now listening on TCP port 8008
synapse.storage.background_updates - 415 - INFO - background_updates-0 - Starting background schema updates for database master
synapse.handlers.deactivate_account - 250 - INFO - user_parter_loop-0 - User parter finished: stopping
synapse.push.pusherpool - 424 - INFO - start_pushers-0 - Starting pusher @graf:server-2.com / de.spiritcroc.riotx:fwbL-8qATd2a4ts4_JDgci:APA91bH-H_U99CffILwC2KPJt6_0cnlRDVQXslZVXGHpBy0hxJojONdueDb2Iv2QtZ6DP
3lEbm-MisG7x-MxxoDv5hNGla2LG3MIFGOL0heCsEaCaOdlObcxQD7MWwQZp-8HfKmoX9qL
synapse.storage.background_updates - 433 - INFO - background_updates-0 - No more background updates to do. Unscheduling background update task.
synapse.push.pusherpool - 372 - INFO - start_pushers-0 - Started pushers
synapse.access.http.8008 - 472 - INFO - GET-5 - 192.168.15.248 - 8008 - {None} Processed request: 0.000sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 318B 200 "GET /_matrix/client/versions HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" [0 dbevts]
synapse.access.http.8008 - 472 - INFO - GET-9 - 192.168.15.248 - 8008 - {@graf:server-2.com} Processed request: 0.266sec/0.001sec (0.002sec, 0.000sec) (0.004sec/0.005sec/4) 258B 200 "GET /_matrix/client/v3/sync?filter=6&timeout=30000&set_presence=unavailable&since=s206020_8262154_0_684778_946232_703_12843_8323_0_2 HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" [0 dbevts]
synapse.federation.sender.transaction_manager - 127 - INFO - federation_transaction_transmission_loop-0 - TX [server-1.com] {1709724486719} Sending transaction [1709724486719], (PDUs: 0, EDUs: 1)
synapse.http.federation.well_known_resolver - 260 - INFO - federation_transaction_transmission_loop-0 - Fetching https://server-1.com/.well-known/matrix/server
synapse.http.federation.well_known_resolver - 197 - INFO - federation_transaction_transmission_loop-0 - Response from .well-known: {'m.server': 'server-1.com:443'}
synapse.http.matrixfederationclient - 362 - INFO - federation_transaction_transmission_loop-0 - {PUT-O-1} [server-1.com] Completed request: 200 OK in 0.14 secs, got 11 bytes - PUT matrix-federation://server-1.com/_matrix/federation/v1/send/1709724486719
synapse.federation.sender.transaction_manager - 180 - INFO - federation_transaction_transmission_loop-0 - TX [server-1.com] {1709724486719} got 200 response
synapse.federation.sender.transaction_manager - 127 - INFO - federation_transaction_transmission_loop-1 - TX [server-1.com] {1709724486720} Sending transaction [1709724486720], (PDUs: 0, EDUs: 1)
synapse.access.http.8008 - 472 - INFO - GET-18 - 192.168.15.248 - 8008 - {@graf:server-2.com} Processed request: 0.046sec/0.000sec (0.007sec, 0.000sec) (0.006sec/0.028sec/21) 259B 200 "GET /_matrix/client/v3/sync?filter=6&timeout=30000&set_presence=online&since=s206020_8262155_0_684778_946232_703_12843_8323_0_2 HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0
Safari/537.36" [0 dbevts]
synapse.http.matrixfederationclient - 362 - INFO - federation_transaction_transmission_loop-1 - {PUT-O-2} [server-1.com] Completed request: 200 OK in 0.06 secs, got 11 bytes - PUT matrix-federation://server-1.com/_matrix/federation/v1/send/1709724486720
synapse.federation.sender.transaction_manager - 180 - INFO - federation_transaction_transmission_loop-1 - TX [server-1.com] {1709724486720} got 200 response
synapse.access.http.8008 - 472 - INFO - GET-23 - 192.168.15.248 - 8008 - {None} Processed request: 0.000sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 30B 200 "GET /.well-known/matrix/server HTTP/1.1" "Synapse/1.101.0" [0 dbevts]
synapse.federation.transport.server.federation - 112 - INFO - PUT-24 - Received txn 1709724480908 from server-1.com. (PDUs: 0, EDUs: 1)
synapse.access.http.8008 - 472 - INFO - GET-22 - 192.168.15.248 - 8008 - {@graf:server-2.com} Processed request: 0.445sec/0.001sec (0.002sec, 0.001sec) (0.001sec/0.003sec/4) 262B 200 "GET /_matrix/client/v3/sync?filter=6&timeout=30000&set_presence=online&since=s206020_8262156_0_684778_946232_703_12843_8323_0_2 HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 S
afari/537.36" [0 dbevts]
synapse.access.http.8008 - 472 - INFO - PUT-24 - 192.168.15.248 - 8008 - {server-1.com} Processed request: 0.029sec/0.000sec (0.004sec, 0.000sec) (0.002sec/0.019sec/6) 11B 200 "PUT /_matrix/federation/v1/send/1709724480908 HTTP/1.1" "Synapse/1.101.0" [0 dbevts]
synapse.metrics.background_process_metrics - 253 - ERROR - process_event_queue_for_federation-0 - Background process 'process_event_queue_for_federation' threw an exception
Traceback (most recent call last):
File "/usr/lib64/python3.9/site-packages/synapse/metrics/background_process_metrics.py", line 251, in run
return await func(*args, **kwargs)
File "/usr/lib64/python3.9/site-packages/synapse/federation/sender/__init__.py", line 478, in _process_event_queue_loop
last_token = await self.store.get_federation_out_pos("events")
File "/usr/lib64/python3.9/site-packages/synapse/storage/databases/main/stream.py", line 1266, in get_federation_out_pos
await self.db_pool.runInteraction(
File "/usr/lib64/python3.9/site-packages/synapse/storage/database.py", line 951, in runInteraction
return await delay_cancellation(_runInteraction())
File "/usr/lib64/python3.9/site-packages/twisted/internet/defer.py", line 1999, in _inlineCallbacks
result = context.run(
File "/usr/lib64/python3.9/site-packages/twisted/python/failure.py", line 519, in throwExceptionIntoGenerator
return g.throw(self.value.with_traceback(self.tb))
File "/usr/lib64/python3.9/site-packages/synapse/storage/database.py", line 917, in _runInteraction
result = await self.runWithConnection(
File "/usr/lib64/python3.9/site-packages/synapse/storage/database.py", line 1046, in runWithConnection
return await make_deferred_yieldable(
File "/usr/lib64/python3.9/site-packages/twisted/python/threadpool.py", line 269, in inContext
result = inContext.theWork() # type: ignore[attr-defined]
File "/usr/lib64/python3.9/site-packages/twisted/python/threadpool.py", line 285, in
inContext.theWork = lambda: context.call( # type: ignore[attr-defined]
File "/usr/lib64/python3.9/site-packages/twisted/python/context.py", line 117, in callWithContext
return self.currentContext().callWithContext(ctx, func, *args, **kw)
File "/usr/lib64/python3.9/site-packages/twisted/python/context.py", line 82, in callWithContext
return func(*args, **kw)
File "/usr/lib64/python3.9/site-packages/twisted/enterprise/adbapi.py", line 282, in _runWithConnection
result = func(conn, *args, **kw)
File "/usr/lib64/python3.9/site-packages/synapse/storage/database.py", line 1039, in inner_func
return func(db_conn, *args, **kwargs)
File "/usr/lib64/python3.9/site-packages/synapse/storage/database.py", line 779, in new_transaction
r = func(cursor, *args, **kwargs)
File "/usr/lib64/python3.9/site-packages/synapse/storage/databases/main/stream.py", line 1336, in _reset_federation_positions_txn
assert set(min_positions) == {"federation", "events"}
AssertionError
synapse.access.http.8008 - 472 - INFO - PUT-30 - 192.168.15.248 - 8008 - {@graf:server-2.com} Processed request: 0.129sec/0.008sec (0.008sec, 0.001sec) (0.006sec/0.014sec/17) 79B 200 "PUT /_matrix/client/v3
/rooms/!lOTCYlSEcbgDywEMpb%3Aserver-2.com/send/m.room.encrypted/m1709724491470.24 HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" [3 dbevts]
synapse.access.http.8008 - 472 - INFO - GET-26 - 192.168.15.248 - 8008 - {@graf:server-2.com} Processed request: 4.462sec/0.000sec (0.008sec, 0.000sec) (0.006sec/0.015sec/11) 987B 200 "GET /_matrix/client/v
3/sync?filter=6&timeout=30000&set_presence=online&since=s206020_8262157_0_684778_946232_703_12843_8323_0_2 HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0
Safari/537.36" [1 dbevts]
synapse.access.http.8008 - 472 - INFO - GET-32 - 192.168.15.248 - 8008 - {None} Processed request: 0.002sec/0.000sec (0.001sec, 0.000sec) (0.000sec/0.001sec/2) 99B 200 "GET /_matrix/client/v3/profile/%40gra
f%3Aserver-2.com HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" [0 dbevts]
synapse.access.http.8008 - 472 - INFO - POST-36 - 192.168.15.248 - 8008 - {@graf:server-2.com} Processed request: 0.009sec/0.001sec (0.001sec, 0.000sec) (0.001sec/0.006sec/4) 5453B 200 "POST /_matrix/client
/v3/keys/query HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" [0 dbevts]
synapse.access.http.8008 - 472 - INFO - POST-38 - 192.168.15.248 - 8008 - {@graf:server-2.com} Processed request: 0.022sec/0.001sec (0.004sec, 0.001sec) (0.002sec/0.014sec/6) 22B 200 "POST /_matrix/client/v
3/rooms/!lOTCYlSEcbgDywEMpb%3Aserver-2.com/read_markers HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" [0 dbevts]
synapse.access.http.8008 - 472 - INFO - GET-37 - 192.168.15.248 - 8008 - {@graf:server-2.com} Processed request: 0.032sec/0.000sec (0.002sec, 0.001sec) (0.001sec/0.003sec/4) 389B 200 "GET /_matrix/client/v3
/sync?filter=6&timeout=30000&set_presence=online&since=s206021_8262157_0_684778_946232_703_12843_8323_0_2 HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 S
afari/537.36" [0 dbevts]
synapse.access.http.8008 - 472 - INFO - GET-40 - 192.168.15.248 - 8008 - {@graf:server-2.com} Processed request: 0.003sec/0.000sec (0.002sec, 0.000sec) (0.000sec/0.002sec/2) 280B 200 "GET /_matrix/client/v3
/room_keys/version HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" [0 dbevts]
twisted - 282 - INFO - sentinel - Received SIGTERM, shutting down.
synapse.storage.databases.main.lock - 113 - INFO - LockStore._on_shutdown-0 - Dropping held locks due to shutdown
synapse.storage.databases.main.lock - 124 - INFO - LockStore._on_shutdown-0 - Dropped locks due to shutdown
synapse.handlers.presence - 890 - INFO - presence.on_shutdown-0 - Performing _on_shutdown. Persisting 6 unpersisted changes
synapse.app._base - 498 - INFO - sentinel - Shutting down...
synapse.handlers.presence - 902 - INFO - presence.on_shutdown-0 - Finished _on_shutdown
synapse.http.site - 384 - INFO - GET-47 - Connection from client lost before response was sent
synapse.http.site - 384 - INFO - GET-42 - Connection from client lost before response was sent
synapse.http.site - 384 - INFO - GET-20 - Connection from client lost before response was sent
twisted - 282 - INFO - sentinel - (TCP Port 8008 Closed)
twisted - 282 - INFO - sentinel - Main loop terminated.
synapse.app.homeserver - 143 - WARNING - sentinel - Stopping daemon.
```

### Anything else that would be useful to know?

In the logs where I restarted both servers.
@graf:server-2.com sent a message to @sara:server-1.com.
@sara:server-1.com is not seeing the message from @graf:server-2.com. Stopped both servers.

Contributor guide

Open the contributing guide

Research direction

Start by reading _reset_federation_positions_txn() and inspecting how the federation_stream_position table is populated and queried when federation is re-enabled. Reproduce the transition from disabled to enabled federation using the reported two-server setup, then verify that the assertion no longer occurs and both servers receive each other's messages.

Written by the indexing model from the issue text.

Assessment

Tech stack
postgresql, python
Domain
backend, databases, distributed-systems
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
38/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.