Sliding Sync 'encryption' loop seems to wake up despite nothing of interest having happened

[reivilibre]

Description

Clients (at least the Rust SDK) use two separate Sliding Sync loops, one of them for room content and one for 'encryption'.

I'm noticing that both loops always seem to wake up at the same time, even though the encryption loop has no interesting data to return.

This seems unnecessarily chatty, particularly as it can happen dozens of time per second. We also appear to have logic intended to suppress wakeups for empty responses, but presumably this isn't succeeding here.

Steps to reproduce

• add a log line (see below)
• open multiverse or other Rust SDK client
• cause some activity, like typing notifications, sending messages, etc
• notice that the 'encryption' sync loop wakes up when the only change is a change in the pos token

example logs in section below.
Empirically it feels like it wakes up A LOT when I'm sending typing notifications from another user (that's how I generated the log in the section below).

patch for log line:

diff --git a/synapse/rest/client/sync.py b/synapse/rest/client/sync.py
index 5e0596d1bc..d8b08f89b5 100644
--- a/synapse/rest/client/sync.py
+++ b/synapse/rest/client/sync.py
@@ -1014,7 +1014,7 @@ class SlidingSyncRestServlet(RestServlet):
             return 200, {}
 
         response_content = await self.encode_response(requester, sliding_sync_results)
-
+        logger.info("SSS=%r", response_content)
         return 200, response_content
 
     @trace_with_opname("sliding_sync.encode_response")

Homeserver

local testing homeserver

Synapse Version

1.138.0rc1 (b=develop,b2997a8f20,dirty) = b2997a8

Installation Method

Other (please mention below)

Database

SQLite

Workers

Single process

Platform

poetry dev install

Configuration

No response

Relevant log output

2025-09-03 11:22:17,167 - synapse.rest.client.sync - 1017 - INFO - POST-1034 - SSS=defaultdict(<class 'dict'>, {'pos': '0/s42_101_17_16_28_1_1_18_0_1', 'rooms': {}, 'extensions': {'to_device': {'next_batch': '1', 'events': []}, 'e2ee': {'device_one_time_keys_count': {'signed_curve25519': 100}, 'device_unused_fallback_key_types': ['signed_curve25519'], 'device_lists': {'changed': [], 'left': []}}}})
2025-09-03 11:22:17,337 - synapse.rest.client.sync - 1017 - INFO - POST-1043 - SSS=defaultdict(<class 'dict'>, {'pos': '0/s42_101_18_16_28_1_1_18_0_1', 'rooms': {}, 'extensions': {'to_device': {'next_batch': '1', 'events': []}, 'e2ee': {'device_one_time_keys_count': {'signed_curve25519': 100}, 'device_unused_fallback_key_types': ['signed_curve25519'], 'device_lists': {'changed': [], 'left': []}}}})
2025-09-03 11:22:17,425 - synapse.rest.client.sync - 1017 - INFO - POST-1043 - SSS=defaultdict(<class 'dict'>, {'pos': '0/s43_101_18_16_28_1_1_18_0_1', 'rooms': {}, 'extensions': {'to_device': {'next_batch': '1', 'events': []}, 'e2ee': {'device_one_time_keys_count': {'signed_curve25519': 100}, 'device_unused_fallback_key_types': ['signed_curve25519'], 'device_lists': {'changed': [], 'left': []}}}})
2025-09-03 11:22:17,702 - synapse.rest.client.sync - 1017 - INFO - POST-1048 - SSS=defaultdict(<class 'dict'>, {'pos': '0/s43_101_19_16_28_1_1_18_0_1', 'rooms': {}, 'extensions': {'to_device': {'next_batch': '1', 'events': []}, 'e2ee': {'device_one_time_keys_count': {'signed_curve25519': 100}, 'device_unused_fallback_key_types': ['signed_curve25519'], 'device_lists': {'changed': [], 'left': []}}}})
2025-09-03 11:22:18,403 - synapse.rest.client.sync - 1017 - INFO - POST-1052 - SSS=defaultdict(<class 'dict'>, {'pos': '0/s43_101_20_16_28_1_1_18_0_1', 'rooms': {}, 'extensions': {'to_device': {'next_batch': '1', 'events': []}, 'e2ee': {'device_one_time_keys_count': {'signed_curve25519': 100}, 'device_unused_fallback_key_types': ['signed_curve25519'], 'device_lists': {'changed': [], 'left': []}}}})
2025-09-03 11:22:18,486 - synapse.rest.client.sync - 1017 - INFO - POST-1060 - SSS=defaultdict(<class 'dict'>, {'pos': '0/s44_101_20_16_28_1_1_18_0_1', 'rooms': {}, 'extensions': {'to_device': {'next_batch': '1', 'events': []}, 'e2ee': {'device_one_time_keys_count': {'signed_curve25519': 100}, 'device_unused_fallback_key_types': ['signed_curve25519'], 'device_lists': {'changed': [], 'left': []}}}})
2025-09-03 11:22:18,511 - synapse.rest.client.sync - 1017 - INFO - POST-1068 - SSS=defaultdict(<class 'dict'>, {'pos': '0/s44_101_21_16_28_1_1_18_0_1', 'rooms': {}, 'extensions': {'to_device': {'next_batch': '1', 'events': []}, 'e2ee': {'device_one_time_keys_count': {'signed_curve25519': 100}, 'device_unused_fallback_key_types': ['signed_curve25519'], 'device_lists': {'changed': [], 'left': []}}}})
2025-09-03 11:22:18,938 - synapse.rest.client.sync - 1017 - INFO - POST-1068 - SSS=defaultdict(<class 'dict'>, {'pos': '0/s44_101_22_16_28_1_1_18_0_1', 'rooms': {}, 'extensions': {'to_device': {'next_batch': '1', 'events': []}, 'e2ee': {'device_one_time_keys_count': {'signed_curve25519': 100}, 'device_unused_fallback_key_types': ['signed_curve25519'], 'device_lists': {'changed': [], 'left': []}}}})
2025-09-03 11:22:19,018 - synapse.rest.client.sync - 1017 - INFO - POST-1072 - SSS=defaultdict(<class 'dict'>, {'pos': '0/s45_101_22_16_28_1_1_18_0_1', 'rooms': {}, 'extensions': {'to_device': {'next_batch': '1', 'events': []}, 'e2ee': {'device_one_time_keys_count': {'signed_curve25519': 100}, 'device_unused_fallback_key_types': ['signed_curve25519'], 'device_lists': {'changed': [], 'left': []}}}})
2025-09-03 11:22:19,062 - synapse.rest.client.sync - 1017 - INFO - POST-1079 - SSS=defaultdict(<class 'dict'>, {'pos': '0/s45_101_23_16_28_1_1_18_0_1', 'rooms': {}, 'extensions': {'to_device': {'next_batch': '1', 'events': []}, 'e2ee': {'device_one_time_keys_count': {'signed_curve25519': 100}, 'device_unused_fallback_key_types': ['signed_curve25519'], 'device_lists': {'changed': [], 'left': []}}}})
2025-09-03 11:22:19,480 - synapse.rest.client.sync - 1017 - INFO - POST-1079 - SSS=defaultdict(<class 'dict'>, {'pos': '0/s45_101_24_16_28_1_1_18_0_1', 'rooms': {}, 'extensions': {'to_device': {'next_batch': '1', 'events': []}, 'e2ee': {'device_one_time_keys_count': {'signed_curve25519': 100}, 'device_unused_fallback_key_types': ['signed_curve25519'], 'device_lists': {'changed': [], 'left': []}}}})
2025-09-03 11:22:19,550 - synapse.rest.client.sync - 1017 - INFO - POST-1083 - SSS=defaultdict(<class 'dict'>, {'pos': '0/s46_101_24_16_28_1_1_18_0_1', 'rooms': {}, 'extensions': {'to_device': {'next_batch': '1', 'events': []}, 'e2ee': {'device_one_time_keys_count': {'signed_curve25519': 100}, 'device_unused_fallback_key_types': ['signed_curve25519'], 'device_lists': {'changed': [], 'left': []}}}})
2025-09-03 11:22:19,589 - synapse.rest.client.sync - 1017 - INFO - POST-1092 - SSS=defaultdict(<class 'dict'>, {'pos': '0/s46_101_25_16_28_1_1_18_0_1', 'rooms': {}, 'extensions': {'to_device': {'next_batch': '1', 'events': []}, 'e2ee': {'device_one_time_keys_count': {'signed_curve25519': 100}, 'device_unused_fallback_key_types': ['signed_curve25519'], 'device_lists': {'changed': [], 'left': []}}}})
2025-09-03 11:22:19,871 - synapse.rest.client.sync - 1017 - INFO - POST-1092 - SSS=defaultdict(<class 'dict'>, {'pos': '0/s46_101_26_16_28_1_1_18_0_1', 'rooms': {}, 'extensions': {'to_device': {'next_batch': '1', 'events': []}, 'e2ee': {'device_one_time_keys_count': {'signed_curve25519': 100}, 'device_unused_fallback_key_types': ['signed_curve25519'], 'device_lists': {'changed': [], 'left': []}}}})
2025-09-03 11:22:19,954 - synapse.rest.client.sync - 1017 - INFO - PUT-1100 - SSS=defaultdict(<class 'dict'>, {'pos': '0/s47_101_26_16_28_1_1_18_0_1', 'rooms': {}, 'extensions': {'to_device': {'next_batch': '1', 'events': []}, 'e2ee': {'device_one_time_keys_count': {'signed_curve25519': 100}, 'device_unused_fallback_key_types': ['signed_curve25519'], 'device_lists': {'changed': [], 'left': []}}}})
2025-09-03 11:22:19,974 - synapse.rest.client.sync - 1017 - INFO - PUT-1106 - SSS=defaultdict(<class 'dict'>, {'pos': '0/s47_101_27_16_28_1_1_18_0_1', 'rooms': {}, 'extensions': {'to_device': {'next_batch': '1', 'events': []}, 'e2ee': {'device_one_time_keys_count': {'signed_curve25519': 100}, 'device_unused_fallback_key_types': ['signed_curve25519'], 'device_lists': {'changed': [], 'left': []}}}})
2025-09-03 11:22:20,254 - synapse.rest.client.sync - 1017 - INFO - PUT-1106 - SSS=defaultdict(<class 'dict'>, {'pos': '0/s47_101_28_16_28_1_1_18_0_1', 'rooms': {}, 'extensions': {'to_device': {'next_batch': '1', 'events': []}, 'e2ee': {'device_one_time_keys_count': {'signed_curve25519': 100}, 'device_unused_fallback_key_types': ['signed_curve25519'], 'device_lists': {'changed': [], 'left': []}}}})
2025-09-03 11:22:20,333 - synapse.rest.client.sync - 1017 - INFO - POST-1107 - SSS=defaultdict(<class 'dict'>, {'pos': '0/s48_101_28_16_28_1_1_18_0_1', 'rooms': {}, 'extensions': {'to_device': {'next_batch': '1', 'events': []}, 'e2ee': {'device_one_time_keys_count': {'signed_curve25519': 100}, 'device_unused_fallback_key_types': ['signed_curve25519'], 'device_lists': {'changed': [], 'left': []}}}})
2025-09-03 11:22:20,374 - synapse.rest.client.sync - 1017 - INFO - POST-1116 - SSS=defaultdict(<class 'dict'>, {'pos': '0/s48_101_29_16_28_1_1_18_0_1', 'rooms': {}, 'extensions': {'to_device': {'next_batch': '1', 'events': []}, 'e2ee': {'device_one_time_keys_count': {'signed_curve25519': 100}, 'device_unused_fallback_key_types': ['signed_curve25519'], 'device_lists': {'changed': [], 'left': []}}}})
2025-09-03 11:22:20,653 - synapse.rest.client.sync - 1017 - INFO - POST-1116 - SSS=defaultdict(<class 'dict'>, {'pos': '0/s48_101_30_16_28_1_1_18_0_1', 'rooms': {}, 'extensions': {'to_device': {'next_batch': '1', 'events': []}, 'e2ee': {'device_one_time_keys_count': {'signed_curve25519': 100}, 'device_unused_fallback_key_types': ['signed_curve25519'], 'device_lists': {'changed': [], 'left': []}}}})

Anything else that would be useful to know?

No response

[kegsay]

Please actually detail the problem this is causing.

[reivilibre]

Please actually detail the problem this is causing.

The waste of bandwidth and general overhead by sending back redundant responses in rapidfire succession (e.g. dozens of empty responses within 1 second).

Not a problem so much as the protocol 'shouldn't' be so chatty when there's nothing to report.

From a brief read, the code is supposed to avoid this happening, so in that case it's a concrete bug as well

[MadLittleMods]

The relevant logic is in SlidingSyncResult.Extensions.E2eeExtension

synapse/synapse/types/handlers/sliding_sync.py

Lines 295 to 312 in 84d6425

	def __bool__(self) -> bool:
	# Note that "signed_curve25519" is always returned in key count responses
	# regardless of whether we uploaded any keys for it. This is necessary until
	# https://github.com/matrix-org/matrix-doc/issues/3298 is fixed.
	#
	# Also related:
	# https://github.com/element-hq/element-android/issues/3725 and
	# https://github.com/matrix-org/synapse/issues/10456
	default_otk = self.device_one_time_keys_count.get("signed_curve25519")
	more_than_default_otk = len(self.device_one_time_keys_count) > 1 or (
	default_otk is not None and default_otk > 0
	)
	return bool(
	more_than_default_otk
	or self.device_list_updates
	or self.device_unused_fallback_key_types
	)

And we have a test to make sure the default empty response is falsey.

But there are some flaws in that logic given it will be truthy for any non-zero 'device_one_time_keys_count': {'signed_curve25519': 100} which we see in your responses. So it looks like it hot-loops as fast as possible once some one-time keys are uploaded and it's non-zero.

What we really want to know is when the count changes.

Also related to #17474