Add debugging to sync response generation I spent a while trying to figure out where my /sync requests were getting stuck.

changelog.d/7929.misc

@@ -0,0 +1 @@
+Add debugging to `/sync` response generation (disabled by default).

synapse/handlers/sync.py

@@ -283,6 +283,7 @@ async def wait_for_sync_for_user(
             timeout,
             full_state,
         )
+        logger.debug("Returning sync response for %s", user_id)
         return res
 
     async def _wait_for_sync_for_user(
@@ -990,10 +991,14 @@ async def generate_sync_result(
             joined_room_ids=joined_room_ids,
         )
 
+        logger.debug("Fetching account data")
+
         account_data_by_room = await self._generate_sync_entry_for_account_data(
             sync_result_builder
         )
 
+        logger.debug("Fetching room data")
+
         res = await self._generate_sync_entry_for_rooms(
             sync_result_builder, account_data_by_room
         )
@@ -1004,10 +1009,12 @@ async def generate_sync_result(
             since_token is None and sync_config.filter_collection.blocks_all_presence()
         )
         if self.hs_config.use_presence and not block_all_presence_data:
+            logger.debug("Fetching presence data")
             await self._generate_sync_entry_for_presence(
                 sync_result_builder, newly_joined_rooms, newly_joined_or_invited_users
             )
 
+        logger.debug("Fetching to-device data")
         await self._generate_sync_entry_for_to_device(sync_result_builder)
 
         device_lists = await self._generate_sync_entry_for_device_list(
@@ -1018,13 +1025,15 @@ async def generate_sync_result(
             newly_left_users=newly_left_users,
         )
 
+        logger.debug("Fetching OTK data")
         device_id = sync_config.device_id
         one_time_key_counts = {}  # type: JsonDict
         if device_id:
             one_time_key_counts = await self.store.count_e2e_one_time_keys(
                 user_id, device_id
             )
 
+        logger.debug("Fetching group data")
         await self._generate_sync_entry_for_groups(sync_result_builder)
 
         # debug for https://github.com/matrix-org/synapse/issues/4422
@@ -1035,6 +1044,7 @@ async def generate_sync_result(
                     "Sync result for newly joined room %s: %r", room_id, joined_room
                 )
 
+        logger.debug("Sync response calculation complete")
         return SyncResult(
             presence=sync_result_builder.presence,
             account_data=sync_result_builder.account_data,
@@ -1407,8 +1417,9 @@ async def _generate_sync_entry_for_rooms(
         newly_joined_rooms = room_changes.newly_joined_rooms
         newly_left_rooms = room_changes.newly_left_rooms
 
-        def handle_room_entries(room_entry):
-            return self._generate_room_entry(
+        async def handle_room_entries(room_entry):
+            logger.debug("Generating room entry for %s", room_entry.room_id)
+            res = await self._generate_room_entry(
                 sync_result_builder,
                 ignored_users,
                 room_entry,
@@ -1417,6 +1428,8 @@ def handle_room_entries(room_entry):
                 account_data=account_data_by_room.get(room_entry.room_id, {}),
                 always_include=sync_result_builder.full_state,
             )
+            logger.debug("Generated room entry for %s", room_entry.room_id)
+            return res
 
         await concurrently_execute(handle_room_entries, room_entries, 10)
 

synapse/rest/client/v2_alpha/sync.py

@@ -183,9 +183,11 @@ async def on_GET(self, request):
             time_now, sync_result, requester.access_token_id, filter_collection
         )
 
+        logger.debug("Event formatting complete")
         return 200, response_content
 
     async def encode_response(self, time_now, sync_result, access_token_id, filter):
+        logger.debug("Formatting events in sync response")
         if filter.event_format == "client":
             event_formatter = format_event_for_client_v2_without_room_id
         elif filter.event_format == "federation":
@@ -213,6 +215,7 @@ async def encode_response(self, time_now, sync_result, access_token_id, filter):
             event_formatter,
         )
 
+        logger.debug("building sync response dict")
         return {
             "account_data": {"events": sync_result.account_data},
             "to_device": {"events": sync_result.to_device},