Add logging to help debug #9424 (#10704)

changelog.d/10704.bugfix

@@ -0,0 +1 @@
+Added opentrace logging to help debug #9424.

synapse/handlers/sync.py

@@ -505,10 +505,13 @@ class SyncHandler:
             else:
                 limited = False
 
+            log_kv({"limited": limited})
+
             if potential_recents:
                 recents = sync_config.filter_collection.filter_room_timeline(
                     potential_recents
                 )
+                log_kv({"recents_after_sync_filtering": len(recents)})
 
                 # We check if there are any state events, if there are then we pass
                 # all current state events to the filter_events function. This is to
@@ -526,6 +529,7 @@ class SyncHandler:
                     recents,
                     always_include_ids=current_state_ids,
                 )
+                log_kv({"recents_after_visibility_filtering": len(recents)})
             else:
                 recents = []
 
@@ -566,10 +570,15 @@ class SyncHandler:
                     events, end_key = await self.store.get_recent_events_for_room(
                         room_id, limit=load_limit + 1, end_token=end_key
                     )
+
+                log_kv({"loaded_recents": len(events)})
+
                 loaded_recents = sync_config.filter_collection.filter_room_timeline(
                     events
                 )
 
+                log_kv({"loaded_recents_after_sync_filtering": len(loaded_recents)})
+
                 # We check if there are any state events, if there are then we pass
                 # all current state events to the filter_events function. This is to
                 # ensure that we always include current state in the timeline
@@ -586,6 +595,9 @@ class SyncHandler:
                     loaded_recents,
                     always_include_ids=current_state_ids,
                 )
+
+                log_kv({"loaded_recents_after_client_filtering": len(loaded_recents)})
+
                 loaded_recents.extend(recents)
                 recents = loaded_recents
 
@@ -1116,6 +1128,8 @@ class SyncHandler:
         logger.debug("Fetching group data")
         await self._generate_sync_entry_for_groups(sync_result_builder)
 
+        num_events = 0
+
         # debug for https://github.com/matrix-org/synapse/issues/4422
         for joined_room in sync_result_builder.joined:
             room_id = joined_room.room_id
@@ -1123,6 +1137,14 @@ class SyncHandler:
                 issue4422_logger.debug(
                     "Sync result for newly joined room %s: %r", room_id, joined_room
                 )
+            num_events += len(joined_room.timeline.events)
+
+        log_kv(
+            {
+                "joined_rooms_in_result": len(sync_result_builder.joined),
+                "events_in_result": num_events,
+            }
+        )
 
         logger.debug("Sync response calculation complete")
         return SyncResult(
@@ -1467,6 +1489,7 @@ class SyncHandler:
         if not sync_result_builder.full_state:
             if since_token and not ephemeral_by_room and not account_data_by_room:
                 have_changed = await self._have_rooms_changed(sync_result_builder)
+                log_kv({"rooms_have_changed": have_changed})
                 if not have_changed:
                     tags_by_room = await self.store.get_updated_tags(
                         user_id, since_token.account_data_key
@@ -1501,25 +1524,30 @@ class SyncHandler:
 
             tags_by_room = await self.store.get_tags_for_user(user_id)
 
+        log_kv({"rooms_changed": len(room_changes.room_entries)})
+
         room_entries = room_changes.room_entries
         invited = room_changes.invited
         knocked = room_changes.knocked
         newly_joined_rooms = room_changes.newly_joined_rooms
         newly_left_rooms = room_changes.newly_left_rooms
 
-        async def handle_room_entries(room_entry):
+        async def handle_room_entries(room_entry: "RoomSyncResultBuilder"):
-            logger.debug("Generating room entry for %s", room_entry.room_id)
+            with start_active_span("generate_room_entry"):
-            res = await self._generate_room_entry(
+                set_tag("room_id", room_entry.room_id)
-                sync_result_builder,
+                log_kv({"events": len(room_entry.events or [])})
-                ignored_users,
+                logger.debug("Generating room entry for %s", room_entry.room_id)
-                room_entry,
+                res = await self._generate_room_entry(
-                ephemeral=ephemeral_by_room.get(room_entry.room_id, []),
+                    sync_result_builder,
-                tags=tags_by_room.get(room_entry.room_id),
+                    ignored_users,
-                account_data=account_data_by_room.get(room_entry.room_id, {}),
+                    room_entry,
-                always_include=sync_result_builder.full_state,
+                    ephemeral=ephemeral_by_room.get(room_entry.room_id, []),
-            )
+                    tags=tags_by_room.get(room_entry.room_id),
-            logger.debug("Generated room entry for %s", room_entry.room_id)
+                    account_data=account_data_by_room.get(room_entry.room_id, {}),
-            return res
+                    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)
 
@@ -1932,6 +1960,12 @@ class SyncHandler:
         room_id = room_builder.room_id
         since_token = room_builder.since_token
         upto_token = room_builder.upto_token
+        log_kv(
+            {
+                "since_token": since_token,
+                "upto_token": upto_token,
+            }
+        )
 
         batch = await self._load_filtered_recents(
             room_id,
@@ -1941,6 +1975,13 @@ class SyncHandler:
             potential_recents=events,
             newly_joined_room=newly_joined,
         )
+        log_kv(
+            {
+                "batch_events": len(batch.events),
+                "prev_batch": batch.prev_batch,
+                "batch_limited": batch.limited,
+            }
+        )
 
         # Note: `batch` can be both empty and limited here in the case where
         # `_load_filtered_recents` can't find any events the user should see