Appservice transaction IDs reset with sqlite3

[AndrewFerr]

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

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?

• Synapse was installed via git & poetry.
• This might be related to Use a sequence to generate AS transaction IDs, drop last_txn AS state #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.

[DMRobertson]

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

synapse/synapse/storage/databases/main/appservice.py

Lines 88 to 95 in aa70556

	self._as_txn_seq_gen = build_sequence_generator(
	db_conn,
	database.engine,
	get_max_as_txn_id,
	"application_services_txn_id_seq",
	table="application_services_txns",
	id_column="txn_id",
	)

which on sqlite uses a LocalSequenceGenerator

synapse/synapse/storage/util/sequence.py

Lines 276 to 279 in 51a5da7

	if isinstance(database_engine, PostgresEngine):
	seq: SequenceGenerator = PostgresSequenceGenerator(sequence_name)
	else:
	seq = LocalSequenceGenerator(get_first_callback)

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

synapse/synapse/storage/util/sequence.py

Lines 204 to 224 in 51a5da7

	def __init__(self, get_first_callback: GetFirstCallbackType):
	"""
	Args:
	get_first_callback: a callback which is called on the first call to
	get_next_id_txn; should return the curreent maximum id
	"""
	# the callback. this is cleared after it is called, so that it can be GCed.
	self._callback: Optional[GetFirstCallbackType] = get_first_callback
	# The current max value, or None if we haven't looked in the DB yet.
	self._current_max_id: Optional[int] = None
	self._lock = threading.Lock()
	def get_next_id_txn(self, txn: Cursor) -> int:
	# We do application locking here since if we're using sqlite then
	# we are a single process synapse.
	with self._lock:
	if self._current_max_id is None:
	assert self._callback is not None
	self._current_max_id = self._callback(txn)
	self._callback = None

That callback does lookup existing txns:

synapse/synapse/storage/databases/main/appservice.py

Lines 81 to 86 in aa70556

	def get_max_as_txn_id(txn: Cursor) -> int:
	logger.warning("Falling back to slow query, you should port to postgres")
	txn.execute(
	"SELECT COALESCE(max(txn_id), 0) FROM application_services_txns"
	)
	return cast(Tuple[int], txn.fetchone())[0]

But we delete from that table when completing an AS transaction

synapse/synapse/storage/databases/main/appservice.py

Lines 311 to 331 in aa70556

	async def complete_appservice_txn(
	self, txn_id: int, service: ApplicationService
	) -> None:
	"""Completes an application service transaction.
	Args:
	txn_id: The transaction ID being completed.
	service: The application service which was sent this transaction.
	"""
	def _complete_appservice_txn(txn: LoggingTransaction) -> None:
	# Delete txn
	self.db_pool.simple_delete_txn(
	txn,
	"application_services_txns",
	{"txn_id": txn_id, "as_id": service.id},
	)
	await self.db_pool.runInteraction(
	"complete_appservice_txn", _complete_appservice_txn
	)

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

[DMRobertson]

Related:

• Use a sequence to generate AS transaction IDs, drop last_txn AS state #12209
• Remove code which updates application_services_state.last_txn #12680
• Drop unused column application_services_state.last_txn #13627

[richvdh]

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 #12209 (comment)).

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