AssertionError in _reset_federation_positions_txn()

[mr-graf]

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

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 <synapse.rest.health.HealthResource object at 0x7fe2e6ab7e50> to path b'/health'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <twisted.web.resource.EncodingResourceWrapper object at 0x7fe2e426f5b0> to path b'/_matrix/client'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7fe2e426f610> to path b'/.well-known'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.admin.AdminRestResource object at 0x7fe2e426f7f0> to path b'/_synapse/admin'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.synapse.client.pick_idp.PickIdpResource object at 0x7fe2e420a1c0> to path b'/_synapse/client/pick_idp'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7fe2e420a280> to path b'/_synapse/client/pick_username'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.synapse.client.new_user_consent.NewUserConsentResource object at 0x7fe2e420a5b0> to path b'/_synapse/client/new_user_consent'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.synapse.client.sso_register.SsoRegisterResource object at 0x7fe2e420a5e0> to path b'/_synapse/client/sso_register'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.synapse.client.unsubscribe.UnsubscribeResource object at 0x7fe2e420a850> to path b'/_synapse/client/unsubscribe'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.synapse.client.password_reset.PasswordResetSubmitTokenResource object at 0x7fe2e420a880> 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 <synapse.rest.media.media_repository_resource.MediaRepositoryResource object at 0x7fe2e420a8b0> to path b'/_matrix/media/r0'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.media.media_repository_resource.MediaRepositoryResource object at 0x7fe2e420a8b0> to path b'/_matrix/media/v3'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.media.media_repository_resource.MediaRepositoryResource object at 0x7fe2e420a8b0> to path b'/_matrix/media/v1'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.federation.transport.server.TransportLayerServer object at 0x7fe2e420ad60> to path b'/_matrix/federation'
synapse.util.httpresourcetree - 56 - INFO - sentinel - Attaching <synapse.rest.key.v2.KeyResource object at 0x7fe2e420ae20> 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 <lambda>
    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.

[intelfx]

Additional: federation_stream_position on server-2.com turned out empty upon investigation. Inserting ('federation', 0, 'does-not-exist'), ('events', 0, 'does-not-exist') into the table as per the full schema was enough to resolve the incident.

[reivilibre]

Since you don't actually say it explicitly as far as I see: I take it that you previously had send_federation: false? and now you re-enabled that and it complained?

Without looking into it, I'm not sure why this should differ from the way a fresh database is set up.

I am not sure we actually document this anywhere, but as far as I remember the preferred way to disable federation is to set an empty federation allowlist/whitelist.