/sync returns outdated OTK counts

[richvdh]

Typically, the way that /sync works is this:

• Assuming that anything at all has changed on the server since the since token, call current_sync_for_user to generate a sync response and new sync token.
• If nothing has happened in any of the syncing user's rooms, wait for a notification that something interesting has happened.
• If we get woken up, generate a new sync response and token.
• If nothing happens in 30 seconds, return the previously-generated response and token.

This means that, if the user is in no active rooms, the entire sync response and token are 30 seconds old.

This is particularly bad if the client uploads some OTKs in that 30-second slot, since the /sync response will include the OTK count from before the upload request.

The upshot of all this is that most clients end up uploading 100 keys when really they only meant to upload 50.

[BillCarsonFr]

This is particularly bad if the client uploads some OTKs in that 30-second slot, since the /sync response will include the OTK count from before the upload request.

We usually upload OTK at the end of a sync request and before doing a new sync request no?
Maybe we don't wait for the outgoing_requests (onSyncComplete) to be sent out before doing the next sync request on all implementations?

Not sure how Notification Sync vs Normal Sync might impact that. Or maye with the new sliding sync though

[BillCarsonFr]

I can confirm that from a fresh login with simplified sliding sync (EXA emulator on local synapse), that there are 2 consecutive upload_keys, publishing 100 OTK.

After first call

{
	"one_time_key_counts": {
		"signed_curve25519": 50
	}
}

After second call

{
	"one_time_key_counts": {
		"signed_curve25519": 100
	}
}

but this is before any sync call.

The first upload has the device keys
https://gist.github.com/BillCarsonFr/b8ceaf093a779cacc873e7c90641d19f

The second one only has otks + a fallback key
https://gist.github.com/BillCarsonFr/0c363dbf0aa71df3dc805efcd6ab4483

client logs
Generated new one-time keys count=50 in sync_once{pos="0/s1538_369851_32_494_1644_1_797_1363_0_1"} > handle_response > preprocess_to_device_events > receive_sync_changes > generate_one_time_keys_if_needed

2024-11-06T09:47:24.109508Z DEBUG matrix_sdk_crypto::olm::account: Generated new one-time keys count=50 discarded_keys=[] created_keys=["curve25519:XsagBrx9fFBGyqDxohr068eBxv59LtWzqzG7Bg9y/RA", "curve25519:xa5mqYvH7pJHDMwXBL+/dqsGLO/zBH/38KfEew7FFkg", "curve25519:Z5782hZoF8S5MKUEyJpdPucOJTepvYoOlVAlaQpYFik", "curve25519:w6WwtOR56oJrK2CKYvnKx9BjI1g25M7pSYhtxkMjJEI", "curve25519:bCqWpRWKZmqk5Au2kOfPKpfllX3XxG+XfuP6HEtbk1w", "curve25519:61iA/f4IMziWmQcWDvLi5KBwK76E/OuqsbSOxz0YTRg", "curve25519:mIYT5q0rZ9IP2Zy7hk3pAyR9s5r3Wnbxi6NnF6i3iQE", "curve25519:jx126IAB6diIfRNlI3mWbLpF2v+2LZ7wAi/39kg5tj4", "curve25519:dCSF9q0bFIEJtgP1Y5+w2xiDf+ipE5k6mdlest/j5XA", "curve25519:dC1IChg030kV3tv4i9TiLHjEdeFZcI0E5gLelJMXHl8", "curve25519:6cjzQPHBQcP1XMezWZ3gvZpa13CSudgET0LbVWncvCE", "curve25519:zY6ATUpi/gkz3Gp0eueiclxEfbbhUulBh6zjdBieEEA", "curve25519:QxpCk301kBtuZX+DBlhvK9vpMFJHIYoqUlYwdzITdFI", "curve25519:Qkz+KD7At4FtfeqMUjOUeFoj9H4Mx/iaoAJXC9jZ6hU", "curve25519:JroBFk0V/7C+rnPk/p2eUdNT1ipKaf3mlwWZZAMoPzk", "curve25519:ncWrYJjskR69iM9K7O2mEcJdD4nyVZhc/LQ+SUHUnlY", "curve25519:56Vz/sZ+Yo4Z5mtZhe7eVdszWIcr2WrgbN14eJ8IUWY", "curve25519:Jl/7Vpohkt17DBEFHYpu8eVjzEcu1cjL5kmjTHMZ/XM", "curve25519:HAoBKwoTGUCCjsmOwcMnI+D/86UnJbFJrn2aaavPhwg", "curve25519:QFyWQOzbr9HTyscG/u5qbg6qS1LUcFX0OXbx0JNGEm8", "curve25519:/F4YM/B8rlgsL79FjVqy6PwIB6ckQ9fF/DNAOHL3XU0", "curve25519:w4Hijpj2XluFsiQcOhtwOi66x7cgDxab+mulZ7PSTQY", "curve25519:p5rpnkwPM/1+vCtG+TpruqaTYqB/YCO74cZhumJsiAc", "curve25519:YiZ0+quCE0hqvFaOOArL+tdQR+Nz+HUrNMuHh5B0nT4", "curve25519:DlBVsHvshytOu0RxacOXhLjAK5Ig+pM+kNkMpJ5tqCg", "curve25519:Pbqb4tY0Qfk1hKOe0EcIYkA7KuWFqaP+U4r2oM9fcRI", "curve25519:S3HvJNY1uiIw88SfARI6yGobivM6Ejbs9JpbEr9elA4", "curve25519:COVb1V1f3TrzY0SuzEkd/Bh9c3dXIPJmAypaSOWfKmQ", "curve25519:3yM6Q0t7Hsuq56npqmhSdCGB3KQAozbJMGP58SV38lc", "curve25519:GlrNNKVLcip9+8vallYddiqAQd/lPZh3BXNSes8tF1c", "curve25519:C1wv4qe4ohdP2WGS4i+eAQrlogIgWyou3WhuSe34eEQ", "curve25519:souaaTy/4bz9sv20tSxS1rtokzqNvfkRcHAjdfBbaVE", "curve25519:mGBLWnXQE8/wNcbxk02gtyD9Dmnxs5S4YCl6WKl0GH8", "curve25519:LBvBnlZOrEWmvmIj5JA/CVEf9eJZfe0l2h6otsAy9X4", "curve25519:8PSWy4AQM0BaDkA3AQ1DiqsE77ZwllPYXWR3OToOEDU", "curve25519:4342MEQaYk/9KSXsURGX7K+/YZRE0GKj7LX/0Ed0I1Y", "curve25519:AzJsP50qUQkCeWRmy5PuPVKcSd3JJAuMMLDv5xGD40I", "curve25519:8qv9v30eyoliE8MKKdK3oKE7zKjhqF0G2ONH58nTwh8", "curve25519:lkBhABoaWxucj7QdAVDkE3BCF1S2nlS2VEY33Gqj7Fw", "curve25519:apXssSAfZZORWUb+kwyrvkARpYOI32tEd3d6H2BJrRY", "curve25519:kMqXAWZUJtZrY+h4AZyRHQ98mNVaVThsamAXU9aLvBc", "curve25519:88zElKGlIlAkz4cGkNBiaXVKvgouaAnodxRkEkA0WzY", "curve25519:SJYuA+IgV+96Is7NFN2aXjYuk4YkSYUSpw4x49YspHw", "curve25519:WSbPgaAw8sPq03KZw094XhWNhbCDGqGaQw3TcSSR9ms", "curve25519:2DKBaKYLFHgx0ExO5JdogOhk4oX6Gvo+H9wrOUbFECM", "curve25519:QTPwNbUqaEwMvzHU0A65OTD3YHZpsSiYooCzrMNrnSU", "curve25519:N+BP0OrvNTFz3QrC8N1T4jrChHU1toT7JiT5RYLn3ng", "curve25519:UnVs/MN9E9JO6Tt3OOMotbfBnWcG+s9l9XvkmmskKkI", "curve25519:rRLYi8K0fFckUk86IJ2Tj1VPtBA++3eG4UDDiCvnqXw", "curve25519:ppB+GikQj4GZ0I7FhxrFZ3dM2+nCdlkjel77IPm9hHQ"] | crates/matrix-sdk-crypto/src/olm/account.rs:582 | spans: next_sync_with_lock > sync_once{pos="0/s1538_369851_32_494_1644_1_797_1363_0_1"} > handle_response > preprocess_to_device_events > receive_sync_changes > generate_one_time_keys_if_needed
2024-11-06T09:47:24.112549Z TRACE matrix_sdk_crypto::store::caches: Flagging user for key query user="@alice:localhost" sequence_number=7 | crates/matrix-sdk-crypto/src/store/caches.rs:273 | spans: next_sync_with_lock > sync_once{pos="0/s1538_369851_32_494_1644_1_797_1363_0_1"} > handle_response > preprocess_to_device_events > receive_sync_changes

And Generated new one-time keys count=50 in sync_once > handle_response > preprocess_to_device_events > receive_sync_changes > generate_one_time_keys_if_needed

2024-11-06T09:47:57.572214Z DEBUG matrix_sdk_crypto::olm::account: Generated new one-time keys count=50 discarded_keys=[] created_keys=["curve25519:P6wUeOYb51rsDy87XRDJ7y0fGz2chWLAbzQI9LD45ig", "curve25519:6oT9wrr0jPAiXTbhufLEIBGQZ+IDf+SBrhiEttF4whA", "curve25519:2fht0cjnxUoI6bNPk6w8yh6bGUNDvAftkDbs7jWkjSw", "curve25519:VBC8DyLZj+2zsEjCFbfsXqW1DpygyCJ+L9kXiXI8xh0", "curve25519:ut8YVnGx7sWUxGIALFFKYIO4ESqH1D6iErdu5ur9Y10", "curve25519:96vJucGxBSh3qLai5/aTBMojckyEMrj2Zl+TP+oYoGI", "curve25519:Hhhs4IWI+ZK58GUv0Oy9TEBJ5sHjsqnPBHVeQDoxABE", "curve25519:de4O4NLRpvBI+HIL5rczXs64xoatuW+T8BB0efnj0QA", "curve25519:+VUohlKMFkZuEhiBt4OQJMWuBclvtUx6h4XwOs+WKws", "curve25519:8AIULx0g4kSMbx5MiVtUto0krq7gN4pae/b+sO3fwgU", "curve25519:7tiIWF51qRCa4QfSSYaIcECFMXoVpHQBTMUJGPM5TGM", "curve25519:dV/ZTo4jxsqtMkgnKl7hjviu6LF/B7KUuMVtbTncOGY", "curve25519:Jg64W54tKbGXjAf26pw+rjvJFeienTojjHHswDsvA0I", "curve25519:PcvHiva9qZEXj0rP+YHmuYMGtXL0udVoCT+hkMZ4jTk", "curve25519:hR+gSOJKeZiymQT2tIVeStMP7Zd4lJZFE1OIIlpku1Q", "curve25519:o1BT/9tNPmibj0zzzokPoefwK2tWWYSMh8LX3XlbuQQ", "curve25519:2k/itAdCCAUURwRyUhwizi8g0W4w5uRo8T6vulMYdDs", "curve25519:n5sJnhBYpj/l3oHCMI7QNa3B8Z/F0ErRcvbpeh5R7GM", "curve25519:RiuY3F4sVwjfeAf36Ul72CCssQa+DY6PoYCgSv+z1Xs", "curve25519:Bo9GTd1oTd+NEqCfnZaRmJXGyDmR+8AIORhGXnqqeyM", "curve25519:jSN1LCevQ6Vm5pAk26dvmhyTUkoxQBQviRhWvswbZgM", "curve25519:tqfGjiVpsxqr4G1L6eG6vCk70qCjExTtHhum8YsJplU", "curve25519:+yvZyu+6fnXjVrM0T7nRfu3vi+3SEd/kegrFRLN8+QM", "curve25519:zJynHJDQXCJJI+W6PSoGcmI7THuL0N1w4p+/TzyRhTc", "curve25519:JxrlClXtNM3dNu5fGHJ/XurLDazansfarWHjSLid2xI", "curve25519:kdbsGMGxGCQYJsNmBesk29MRRqp3plSGy0vGzZUGLAo", "curve25519:u8BjR67uSEKHaBUAAc6iTROEzrJ6LCfUMkvxR6NqPHY", "curve25519:kvI2Seb2LLz4P0F6+D1dnUWShhKe6pITUIlUoHgRjwE", "curve25519:7p7uTgOITmDJhealJGRBxYf6goVVI5ZWSQilrBuIAiE", "curve25519:D4FRjMwlRpw7DeVMn8tpkmHQPY92b6MLrmPeddYlKiw", "curve25519:S6BZYgCAw5nScrG5mJrTQ0kqoDXs3KiAA/4wZZxT/mU", "curve25519:uoGf85PoL004HlURp8FmEIYJuImdBrfMyypTZtN3txc", "curve25519:mlh4JH1YBSnE7t6tLTQfZBuRX7CV9rXgiV8AFJVR4GI", "curve25519:ElqyG2x80WcEH7oFsPodJgs/4iBr4Lf+k5hY1GCeXDU", "curve25519:Hxxx5d4WSBoruXaRE+Z7k/b/JNa1ULdOCDJbJMaoqVY", "curve25519:8qmTDLg4E8MiAZEsiq+s2Tc2e2nk1+RO14Wbl1KsnAc", "curve25519:V2DQ6kMw0UcXyWfHNDXM3V8HERT4PYPPhwBMyBSuYXQ", "curve25519:SNaPzJfZr11n6f1nAtFW/m2ik/1hQUkuPPsNh3t7/1Q", "curve25519:bcRuaaT5tXz3iX47XELmdfO5cu9+7eehAyyhRYa0vys", "curve25519:Cafcjx6hkMo4duOhLC7TfdXI56fJnTRtQr8f+7nxf3g", "curve25519:pPcsZOHjpvxHcbCbzMQ7z2gH8NU/kH+BV7PlWXlPumg", "curve25519:VwqOk9T67FFsx00cq+jkIYL/n0NmaD1NmDurnxfZwFo", "curve25519:M094qDRTDoB65bSa1cR3hZxBw/YufR7WAmXcYuGPljo", "curve25519:znKpODCZng2rCEfqdvcDG1ge0cUWoctOK6LAUZsKxAo", "curve25519:c+oufXDy85APMi3V+x9rtu6qdcmK/G10CnB20FoZyCk", "curve25519:jOjjnHt4XIchxVfk0T5+LaixWVYbb8q/sVxB+cPVpFI", "curve25519:d84lVNszuKDgfPEPIXqYjiFJYwgPDwGcRyDSwp6E5XA", "curve25519:UUgON6uDFqqQJpqpwVk1AkMlODCh5K8c8k9f3SjE/l8", "curve25519:wKeWfQuqr9PqbpMOdqXwHbJlUx9+JHh+xUE9Dg54KC8", "curve25519:lenwAg2PamrQBnfpdgqggZCMW/A9NVCxIwX1nMW48m8"] | crates/matrix-sdk-crypto/src/olm/account.rs:582 | spans: next_sync_with_lock > sync_once > handle_response > preprocess_to_device_events > receive_sync_changes > generate_one_time_keys_if_needed

I need to retry on a clean emulator, surprised to see that the tracing says sync_once > handle_response given that in the proxy I only see the sync occuring after the key upload

[BillCarsonFr]

Ok so here is the correct sequence:

The first encryption sync returns

{
	"pos": "0/s1538_369907_32_495_1645_1_797_1368_0_1",
	"rooms": {},
	"extensions": {
		"to_device": {
			"next_batch": "797",
			"events": []
		},
		"e2ee": {
			"device_one_time_keys_count": {
				"signed_curve25519": 0
			},
			"device_unused_fallback_key_types": []
		}
	}
}

Then the clients uploads 50 otks. (but no fallback )
POST http://127.0.0.1:8008/_matrix/client/v3/keys/upload -> 200 OK

{
	"one_time_key_counts": {
		"signed_curve25519": 50
	}
}

Then there is the second sync
http://127.0.0.1:8008/_matrix/client/unstable/org.matrix.simplified_msc3575/sync?pos=0%2Fs1538_369907_32_495_1645_1_797_1368_0_1&timeout=30000

Payload:

{
	"conn_id": "encryption",
	"txn_id": "21ac2ad3229f44a7903eb95b514f3cea",
	"extensions": {
		"to_device": {
			"enabled": true,
			"since": "797"
		},
		"e2ee": {
			"enabled": true
		}
	}
}

Response

	"extensions": {
		"to_device": {
			"next_batch": "797",
			"events": []
		},
		"e2ee": {
			"device_one_time_keys_count": {
				"signed_curve25519": 50
			},
			"device_unused_fallback_key_types": [],
			"device_lists": {
				"changed": ["@alice:localhost"],
				"left": []
			}
		}
	}

The signed_curve25519 is correct but yet the client upload again 50 otks plus the falback this time

The response is

{
	"one_time_key_counts": {
		"signed_curve25519": 100
	}
}

[BillCarsonFr]

Ok so I got what is tirggering this bg just after login.

On account creation the sdk create the olm_account and uploads the key. Around the same time a sync is started.

This is the race:

The sdk receives the device keys upload response, and call receive_keys_upload_response and then call update_key_counts using the count returned by the keys_upload count.
As seen in the logs Updated uploaded one-time key count 0 -> 50.

Meanwhile the initial sync response is handled, sync_once > handle_response > preprocess_to_device_events > receive_sync_changes that calls update_key_counts but this time with the info from the sync (that is 0).
As shown in logs Updated uploaded one-time key count 50 -> 0.

As a consequence the sdk thinks all the keys have been used