element-hq / element-hq/synapse
Appservice transaction IDs reset with sqlite3
- Dominant language
- Python
- Stars
- 4.6k
- Forks
- 600
- Avg merge
- 5d 22h
- Merged PRs (30d)
- 51
Description
This issue has been migrated from [#14556](https://github.com/matrix-org/synapse/issues/14556).
---
### 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
- connect some appservices to Synapse
- boot Synapse & the appservices and run them for a while
- reboot Synapse
- watch Synapse & appservice logs to see transaction IDs start at 1 after the reboot
### 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
```shell
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=: 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=: 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=: 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 to path b'/health'
2022-11-21 02:35:42,504 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/client'
2022-11-21 02:35:42,504 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/.well-known'
2022-11-21 02:35:42,504 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/admin'
2022-11-21 02:35:42,504 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/pick_idp'
2022-11-21 02:35:42,505 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/pick_username'
2022-11-21 02:35:42,505 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/new_user_consent'
2022-11-21 02:35:42,505 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_synapse/client/sso_register'
2022-11-21 02:35:42,505 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching 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 to path b'/_matrix/media/r0'
2022-11-21 02:35:42,505 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/media/v3'
2022-11-21 02:35:42,505 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/media/v1'
2022-11-21 02:35:42,505 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching to path b'/_matrix/federation'
2022-11-21 02:35:42,505 - synapse.util.httpresourcetree - 47 - INFO - sentinel - Attaching 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=: 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=: 200
...
```
### Anything else that would be useful to know?
- Synapse was installed via git & poetry.
- This might be related to https://github.com/matrix-org/synapse/pull/12209.
- Relevant conversation in #synapse:matrix.org: https://matrix.to/#/!ehXvUhWNASUkSLvAGP:matrix.org/$q-eo3Z5f6Gg8zUask0IxWL_EI1wBKX-w-VGoFjXnkjY?via=matrix.org&via=element.io&via=envs.net
- My usecase for sqlite3 is to have a set of easily resettable Synapse databases for quick local testing. Having transaction IDs reset every so often gets in the way of testing Synapse with appservices, as it renders them mostly unusable until Synapse's transaction IDs catch up.
Contributor guide
Research direction
Start with synapse.storage.util.id_generators and the appservice transaction flow shown in the logs, then reproduce the SQLite reboot sequence from the issue. Trace how the transaction ID is initialized and persisted; done means IDs continue above the previously handled value after restarting Synapse, with regression coverage for the reboot case.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- python, sqlite
- Domain
- backend, databases
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 38/100