search

matrix-org / synapse

Synapse: Matrix homeserver written in Python/Twisted.
https://matrix-org.github.io/synapse
Apache License 2.0
11.82k stars 2.13k forks source link

Appservice transaction IDs reset with sqlite3 #14556

Open AndrewFerr opened 1 year ago

AndrewFerr commented 1 year ago

Description

When using a sqlite3 database, rebooting Synapse may cause it to reset its transaction ID count, meaning the IDs of future transactions will start from 1. This means existing appservices which use the transaction ID to deduplicate events may consider new transactions as ones they've seen before, until Synapse's transaction ID catches up to the most recent transaction ID that the appservice actually handled.

Steps to reproduce

Homeserver

Local testing homeserver

Synapse Version

v1.69.0

Installation Method

Other (please mention below)

Database

SQLite

Workers

Single process

Platform

Fedora Linux 37 (Workstation Edition), 64-bit

Configuration

Some experimental features:

  msc3202_device_masquerading: true
  msc3202_transaction_extensions: true
  msc2409_to_device_messages_enabled: true

Relevant log output

2022-11-21 00:05:45,174 - synapse.http.client - 446 - INFO - as-sender-cbbc31bc977778a22b4455144c9e5307d8fc81beaf6c6a941ab47c3a4f3f8007-0 - Received response to PUT http://localhost:5858/transactions/1?access_token=<redacted>: 200
2022-11-21 00:05:46,995 - synapse.http.client - 446 - INFO - as-sender-cbbc31bc977778a22b4455144c9e5307d8fc81beaf6c6a941ab47c3a4f3f8007-1 - Received response to PUT http://localhost:5858/transactions/2?access_token=<redacted>: 200
...
2022-11-21 02:35:22,785 - synapse.http.client - 446 - INFO - as-sender-cbbc31bc977778a22b4455144c9e5307d8fc81beaf6c6a941ab47c3a4f3f8007-241 - Received response to PUT http://localhost:5858/transactions/459?access_token=<redacted>: 200
2022-11-21 02:35:42,427 - root - 343 - WARNING - main - ***** STARTING SERVER *****
...
2022-11-21 02:35:42,428 - synapse.storage.databases - 66 - INFO - main - [database config 'master']: Checking database server
2022-11-21 02:35:42,428 - synapse.storage.databases - 69 - INFO - main - [database config 'master']: Preparing for databases ['main', 'state']
2022-11-21 02:35:42,428 - synapse.storage.prepare_database - 115 - INFO - main - ['main', 'state']: Checking existing schema version
2022-11-21 02:35:42,430 - synapse.storage.prepare_database - 119 - INFO - main - ['main', 'state']: Existing schema is 73 (+8 deltas)
2022-11-21 02:35:42,430 - synapse.storage.databases.main - 311 - INFO - main - Checking database for consistency with configuration...
2022-11-21 02:35:42,430 - synapse.storage.prepare_database - 411 - INFO - main - Applying schema deltas for v73
2022-11-21 02:35:42,430 - synapse.storage.prepare_database - 546 - INFO - main - Schema now up to date
2022-11-21 02:35:42,442 - synapse.storage.databases - 84 - INFO - main - [database config 'master']: Starting 'main' database
2022-11-21 02:35:42,442 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_stream(stream_id): 30
2022-11-21 02:35:42,442 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for user_signature_stream(stream_id): 27
2022-11-21 02:35:42,442 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_outbound_pokes(stream_id): 1
2022-11-21 02:35:42,442 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_lists_changes_in_room(stream_id): 30
...
2022-11-21 02:35:42,445 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for receipts_linearized(stream_id): 322
2022-11-21 02:35:42,446 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for events(stream_ordering): 3281
2022-11-21 02:35:42,446 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for events(stream_ordering): -1
2022-11-21 02:35:42,446 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for ex_outlier_stream(event_stream_ordering): -1
2022-11-21 02:35:42,447 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for device_inbox(stream_id): 1
2022-11-21 02:35:42,450 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for pushers(id): 1
2022-11-21 02:35:42,450 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for deleted_pushers(stream_id): 1
2022-11-21 02:35:42,451 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules_stream(stream_id): 1
2022-11-21 02:35:42,451 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for room_account_data(stream_id): 768
2022-11-21 02:35:42,451 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for room_tags_revisions(stream_id): 33
2022-11-21 02:35:42,451 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for e2e_cross_signing_keys(stream_id): 10
2022-11-21 02:35:42,451 - synapse.storage.databases.main.event_push_actions - 907 - INFO - main - Searching for stream ordering 1 month ago
2022-11-21 02:35:42,451 - synapse.storage.databases.main.event_push_actions - 911 - INFO - main - Found stream ordering 1 month ago: it's 2
2022-11-21 02:35:42,452 - synapse.storage.databases.main.event_push_actions - 914 - INFO - main - Searching for stream ordering 1 day ago
2022-11-21 02:35:42,452 - synapse.storage.databases.main.event_push_actions - 918 - INFO - main - Found stream ordering 1 day ago: it's 2653
2022-11-21 02:35:42,452 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules(id): 1
2022-11-21 02:35:42,452 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for push_rules_enable(id): 1
2022-11-21 02:35:42,452 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for presence_stream(stream_id): 4726
2022-11-21 02:35:42,453 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for access_tokens(id): 13
2022-11-21 02:35:42,453 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for refresh_tokens(id): 1
2022-11-21 02:35:42,453 - synapse.storage.util.id_generators - 88 - INFO - main - Initialising stream generator for event_reports(id): 1
2022-11-21 02:35:42,454 - synapse.storage.databases - 101 - INFO - main - [database config 'master']: Starting 'state' database
2022-11-21 02:35:42,455 - synapse.storage.databases - 116 - INFO - main - [database config 'master']: prepared
2022-11-21 02:35:42,455 - synapse.server - 310 - INFO - main - Finished setting up.
2022-11-21 02:35:42,465 - synapse.push.pusher - 38 - INFO - main - email enable notifs: False
2022-11-21 02:35:42,466 - synapse.federation.federation_server - 1397 - INFO - main - Registering federation EDU handler for 'm.device_list_update'
2022-11-21 02:35:42,466 - synapse.federation.federation_server - 1417 - INFO - main - Registering federation query handler for 'profile'
2022-11-21 02:35:42,467 - synapse.federation.federation_server - 1397 - INFO - main - Registering federation EDU handler for 'm.presence'
2022-11-21 02:35:42,467 - synapse.federation.federation_server - 1397 - INFO - main - Registering federation EDU handler for 'm.typing'
2022-11-21 02:35:42,468 - synapse.federation.federation_server - 1417 - INFO - main - Registering federation query handler for 'directory'
2022-11-21 02:35:42,469 - twisted - 274 - INFO - main - Redirected stdout/stderr to logs
2022-11-21 02:35:42,469 - synapse.app.homeserver - 165 - INFO - sentinel - Running
2022-11-21 02:35:42,472 - synapse.app.homeserver - 29 - INFO - sentinel - Set file limit to: 524288
2022-11-21 02:35:42,473 - synapse.handlers.deactivate_account - 230 - INFO - user_parter_loop-0 - Starting user parter
2022-11-21 02:35:42,476 - synapse.util.caches.lrucache - 225 - INFO - sentinel - Expiring LRU caches after 1800 seconds
2022-11-21 02:35:42,494 - synapse.federation.federation_server - 1397 - INFO - sentinel - Registering federation EDU handler for 'm.receipt'
2022-11-21 02:35:42,494 - synapse.federation.federation_server - 1397 - INFO - sentinel - Registering federation EDU handler for 'm.signing_key_update'
2022-11-21 02:35:42,494 - synapse.federation.federation_server - 1397 - INFO - sentinel - Registering federation EDU handler for 'org.matrix.signing_key_update'
2022-11-21 02:35:42,494 - synapse.federation.federation_server - 1417 - INFO - sentinel - Registering federation query handler for 'client_keys'
2022-11-21 02:35:42,495 - synapse.federation.federation_server - 1397 - INFO - sentinel - Registering federation EDU handler for 'm.direct_to_device'
2022-11-21 02:35:42,504 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.health.HealthResource object at 0x7f2e808dd210> to path b'/health'
2022-11-21 02:35:42,504 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.ClientRestResource object at 0x7f2e808dcb80> to path b'/_matrix/client'
2022-11-21 02:35:42,504 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7f2e808c95a0> to path b'/.well-known'
2022-11-21 02:35:42,504 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.admin.AdminRestResource object at 0x7f2e808caf50> to path b'/_synapse/admin'
2022-11-21 02:35:42,504 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.pick_idp.PickIdpResource object at 0x7f2e80916920> to path b'/_synapse/client/pick_idp'
2022-11-21 02:35:42,505 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <twisted.web.resource.Resource object at 0x7f2e80916860> to path b'/_synapse/client/pick_username'
2022-11-21 02:35:42,505 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.new_user_consent.NewUserConsentResource object at 0x7f2e80916350> to path b'/_synapse/client/new_user_consent'
2022-11-21 02:35:42,505 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.sso_register.SsoRegisterResource object at 0x7f2e80915930> to path b'/_synapse/client/sso_register'
2022-11-21 02:35:42,505 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.synapse.client.unsubscribe.UnsubscribeResource object at 0x7f2e809164a0> to path b'/_synapse/client/unsubscribe'
2022-11-21 02:35:42,505 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching FilePath('/home/andrewf/git/synapse/synapse/static') to path b'/_matrix/static'
2022-11-21 02:35:42,505 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7f2e80915f60> to path b'/_matrix/media/r0'
2022-11-21 02:35:42,505 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7f2e80915f60> to path b'/_matrix/media/v3'
2022-11-21 02:35:42,505 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x7f2e80915f60> to path b'/_matrix/media/v1'
2022-11-21 02:35:42,505 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.federation.transport.server.TransportLayerServer object at 0x7f2e80916650> to path b'/_matrix/federation'
2022-11-21 02:35:42,505 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching <synapse.rest.key.v2.KeyApiV2Resource object at 0x7f2e80915fc0> to path b'/_matrix/key/v2'
2022-11-21 02:35:42,506 - twisted - 274 - INFO - sentinel - SynapseSite starting on 8008
2022-11-21 02:35:42,506 - twisted - 274 - INFO - sentinel - SynapseSite starting on 8008
2022-11-21 02:35:42,506 - synapse.app.homeserver - 172 - INFO - sentinel - Synapse now listening on TCP port 8008
2022-11-21 02:35:42,507 - synapse.storage.database - 844 - WARNING - sentinel - Starting db txn 'count_daily_users' from sentinel context
2022-11-21 02:35:42,507 - synapse.storage.database - 909 - WARNING - sentinel - Starting db connection from sentinel context: metrics will be lost
2022-11-21 02:35:42,508 - synapse.handlers.deactivate_account - 240 - INFO - user_parter_loop-0 - User parter finished: stopping
2022-11-21 02:35:42,509 - synapse.push.pusherpool - 347 - INFO - start_pushers-0 - Started pushers
2022-11-21 02:35:42,545 - synapse.storage.background_updates - 288 - INFO - background_updates-0 - Starting background schema updates for database master
2022-11-21 02:35:42,547 - synapse.storage.background_updates - 305 - INFO - background_updates-0 - No more background updates to do. Unscheduling background update task.
...
2022-11-21 02:36:10,558 - synapse.appservice.scheduler - 109 - INFO - as_scheduler-0 - Starting appservice scheduler
2022-11-21 02:36:10,568 - synapse.storage.databases.main.appservice - 82 - WARNING - as-sender-cbbc31bc977778a22b4455144c9e5307d8fc81beaf6c6a941ab47c3a4f3f8007-0 - Falling back to slow query, you should port to postgres
2022-11-21 02:36:10,604 - synapse.federation.sender - 453 - INFO - process_event_queue_for_federation-1 - Unexpectedly did not have cached prev group for $zPajLiYej9pNNOrUMFFBdq4UjcUyBsSsWUtnLIkwWPs
2022-11-21 02:36:10,657 - synapse.federation.sender - 453 - INFO - process_event_queue_for_federation-2 - Unexpectedly did not have cached prev group for $vpouQ3UpBfGoHJT9c-R6Xr48JUsDwpSUstScRgG4KoA
2022-11-21 02:36:10,713 - synapse.federation.sender - 453 - INFO - process_event_queue_for_federation-3 - Unexpectedly did not have cached prev group for $XO78uxt3mRK1mG-f_92dqF73X8uvefHi5WLv9WKH07A
2022-11-21 02:36:10,734 - synapse.federation.sender - 453 - INFO - process_event_queue_for_federation-3 - Unexpectedly did not have cached prev group for $-SbQAA4nW92YVqnfhFKb9nkx2cZnkTSqOKKFXPAva_M
2022-11-21 02:36:10,750 - synapse.federation.sender - 453 - INFO - process_event_queue_for_federation-3 - Unexpectedly did not have cached prev group for $Ce5zroxgIm9eGxz5JGzM5AjwpGajq5aIVbS8LK2C4kc
2022-11-21 02:36:10,761 - synapse.federation.sender - 453 - INFO - process_event_queue_for_federation-3 - Unexpectedly did not have cached prev group for $XePbyhhL2xHlcHfzLqEgsXJRseT_our97WY39mkf9fs
2022-11-21 02:36:10,777 - synapse.federation.sender - 453 - INFO - process_event_queue_for_federation-3 - Unexpectedly did not have cached prev group for $2nSdDQv843erLQP6FomcW8JehV13F85MZ3K9V7asmaA
2022-11-21 02:36:10,804 - synapse.federation.sender - 453 - INFO - process_event_queue_for_federation-4 - Unexpectedly did not have cached prev group for $RZxk8h7vSxdKzST3cLGxM4GJRSZq2NGRdU3MGAT4hH4
...
2022-11-21 02:36:10,858 - synapse.federation.sender - 453 - INFO - process_event_queue_for_federation-5 - Unexpectedly did not have cached prev group for $LzPYTJTedYoPkAUX7bz8qnYAScVdHQxwvSy9URqar9A
...
2022-11-21 02:36:12,453 - synapse.storage.databases.main.event_push_actions - 1061 - INFO - rotate_notifs-0 - Rotating notifications
2022-11-21 02:36:12,454 - synapse.storage.databases.main.event_push_actions - 1234 - INFO - rotate_notifs-0 - Rotating notifications up to: 3291
2022-11-21 02:36:12,454 - synapse.storage.databases.main.event_push_actions - 1320 - INFO - rotate_notifs-0 - Rotating notifications, handling 2 rows
2022-11-21 02:36:12,466 - synapse.storage.databases.main.event_push_actions - 1408 - INFO - rotate_notifs-0 - Rotating notifications, deleted 0 push actions
2022-11-21 02:36:12,476 - synapse.util.caches.lrucache - 212 - INFO - LruCache._expire_old_entries-0 - Dropped 0 items from caches
...
2022-11-21 02:36:42,167 - synapse.http.client - 446 - INFO - as-sender-cbbc31bc977778a22b4455144c9e5307d8fc81beaf6c6a941ab47c3a4f3f8007-0 - Received response to PUT http://localhost:5858/transactions/1?access_token=<redacted>: 200
2022-11-21 02:36:42,184 - synapse.http.client - 446 - INFO - as-sender-cbbc31bc977778a22b4455144c9e5307d8fc81beaf6c6a941ab47c3a4f3f8007-0 - Received response to PUT http://localhost:5858/transactions/2?access_token=<redacted>: 200
...

Anything else that would be useful to know?

DMRobertson commented 1 year ago

Not sure what's going on here. We use a sequence generator

https://github.com/matrix-org/synapse/blob/aa70556699e649f46f51a198fb104eecdc0d311b/synapse/storage/databases/main/appservice.py#L88-L95

which on sqlite uses a LocalSequenceGenerator

https://github.com/matrix-org/synapse/blob/51a5da74ccd383806378b53ee8a09e27a8829f31/synapse/storage/util/sequence.py#L276-L279

which calls a _callback function to get the starting position of the sequence

https://github.com/matrix-org/synapse/blob/51a5da74ccd383806378b53ee8a09e27a8829f31/synapse/storage/util/sequence.py#L204-L224

That callback does lookup existing txns:

https://github.com/matrix-org/synapse/blob/aa70556699e649f46f51a198fb104eecdc0d311b/synapse/storage/databases/main/appservice.py#L81-L86

But we delete from that table when completing an AS transaction

https://github.com/matrix-org/synapse/blob/aa70556699e649f46f51a198fb104eecdc0d311b/synapse/storage/databases/main/appservice.py#L311-L331

so I think that catchup mechanism only works if you have outstanding transactions?

DMRobertson commented 1 year ago

Related:

richvdh commented 1 year ago

This did indeed change in #12209: as of that change, we no longer persist the "last transaction ID" to the database, so if there are no pending transactions, then there is no way to figure out what ID we should start from. I vaguely remember being aware of it at the time, and concluding that the win in the common case of using postgres was worth it, versus the edge-case of trying to use appservices with sqlite. (see also https://github.com/matrix-org/synapse/pull/12209#discussion_r835152122).

I guess a proper fix to this will need dedicated sqlite support.