From 63a1c8051330541fffea00c1f70d7070d4d04417 Mon Sep 17 00:00:00 2001 From: Azrenbeth <7782548+Azrenbeth@users.noreply.github.com> Date: Thu, 26 Aug 2021 16:11:45 +0100 Subject: [PATCH 1/5] Added log_kv calls to sync and a span for each generate room entry --- synapse/handlers/sync.py | 71 ++++++++++++++++++++++++++++++++-------- 1 file changed, 58 insertions(+), 13 deletions(-) diff --git a/synapse/handlers/sync.py b/synapse/handlers/sync.py index 86c3c7f0df50..97b4018b1f8d 100644 --- a/synapse/handlers/sync.py +++ b/synapse/handlers/sync.py @@ -505,10 +505,13 @@ async def _load_filtered_recents( 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 @@ async def _load_filtered_recents( recents, always_include_ids=current_state_ids, ) + log_kv({"recents_after_visibility_filtering": len(recents)}) else: recents = [] @@ -566,10 +570,15 @@ async def _load_filtered_recents( 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 @@ async def _load_filtered_recents( 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 @@ async def generate_sync_result( 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 @@ async def generate_sync_result( issue4422_logger.debug( "Sync result for newly joined room %s: %r", room_id, joined_room ) + num_events += len(joined_room.timeline) + + 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 @@ async def _generate_sync_entry_for_rooms( 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,34 @@ async def _generate_sync_entry_for_rooms( 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): - logger.debug("Generating room entry for %s", room_entry.room_id) - res = await self._generate_room_entry( - sync_result_builder, - ignored_users, - room_entry, - ephemeral=ephemeral_by_room.get(room_entry.room_id, []), - tags=tags_by_room.get(room_entry.room_id), - 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 + async def handle_room_entries(room_entry: "RoomSyncResultBuilder"): + with start_active_span("generate_room_entry"): + log_kv( + { + "room_id": room_entry.room_id, + "events": len(room_entry.events), + } + ) + logger.debug("Generating room entry for %s", room_entry.room_id) + res = await self._generate_room_entry( + sync_result_builder, + ignored_users, + room_entry, + ephemeral=ephemeral_by_room.get(room_entry.room_id, []), + tags=tags_by_room.get(room_entry.room_id), + 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) @@ -1932,6 +1964,12 @@ async def _generate_room_entry( 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 +1979,13 @@ async def _generate_room_entry( 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 From 11dc0add4184a39136b07f581d0728d901936b02 Mon Sep 17 00:00:00 2001 From: Azrenbeth <7782548+Azrenbeth@users.noreply.github.com> Date: Thu, 26 Aug 2021 16:35:18 +0100 Subject: [PATCH 2/5] Fixed issues identified by mypy --- synapse/handlers/sync.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/synapse/handlers/sync.py b/synapse/handlers/sync.py index 97b4018b1f8d..b0590ca2af20 100644 --- a/synapse/handlers/sync.py +++ b/synapse/handlers/sync.py @@ -1137,7 +1137,7 @@ async def generate_sync_result( issue4422_logger.debug( "Sync result for newly joined room %s: %r", room_id, joined_room ) - num_events += len(joined_room.timeline) + num_events += len(joined_room.timeline.events) log_kv( { @@ -1537,7 +1537,7 @@ async def handle_room_entries(room_entry: "RoomSyncResultBuilder"): log_kv( { "room_id": room_entry.room_id, - "events": len(room_entry.events), + "events": len(room_entry.events or []), } ) logger.debug("Generating room entry for %s", room_entry.room_id) From daf013f755b8976e260bfa3e6ed0382ea41b2b77 Mon Sep 17 00:00:00 2001 From: Azrenbeth <7782548+Azrenbeth@users.noreply.github.com> Date: Fri, 27 Aug 2021 11:29:04 +0100 Subject: [PATCH 3/5] set room_id as span tag rather than logging it --- synapse/handlers/sync.py | 8 ++------ 1 file changed, 2 insertions(+), 6 deletions(-) diff --git a/synapse/handlers/sync.py b/synapse/handlers/sync.py index b0590ca2af20..fb2c4eac0679 100644 --- a/synapse/handlers/sync.py +++ b/synapse/handlers/sync.py @@ -1534,12 +1534,8 @@ async def _generate_sync_entry_for_rooms( async def handle_room_entries(room_entry: "RoomSyncResultBuilder"): with start_active_span("generate_room_entry"): - log_kv( - { - "room_id": room_entry.room_id, - "events": len(room_entry.events or []), - } - ) + set_tag({"room_id": room_entry.room_id}) + log_kv({"events": len(room_entry.events or [])}) logger.debug("Generating room entry for %s", room_entry.room_id) res = await self._generate_room_entry( sync_result_builder, From 9a4bb689b0811126e9acbee8c367fc357778cb73 Mon Sep 17 00:00:00 2001 From: Azrenbeth <7782548+Azrenbeth@users.noreply.github.com> Date: Fri, 27 Aug 2021 11:33:53 +0100 Subject: [PATCH 4/5] Added changelog --- changelog.d/10704.bugfix | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/10704.bugfix diff --git a/changelog.d/10704.bugfix b/changelog.d/10704.bugfix new file mode 100644 index 000000000000..4284cddc2b19 --- /dev/null +++ b/changelog.d/10704.bugfix @@ -0,0 +1 @@ +Added opentrace logging to help debug #9424. \ No newline at end of file From 2798a611fc2bc28350bb21df2219444a5ff60d46 Mon Sep 17 00:00:00 2001 From: Azrenbeth <7782548+Azrenbeth@users.noreply.github.com> Date: Fri, 27 Aug 2021 12:24:04 +0100 Subject: [PATCH 5/5] Fixed incorrect set_tag syntax --- synapse/handlers/sync.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/handlers/sync.py b/synapse/handlers/sync.py index fb2c4eac0679..e017b28cd20a 100644 --- a/synapse/handlers/sync.py +++ b/synapse/handlers/sync.py @@ -1534,7 +1534,7 @@ async def _generate_sync_entry_for_rooms( async def handle_room_entries(room_entry: "RoomSyncResultBuilder"): with start_active_span("generate_room_entry"): - set_tag({"room_id": room_entry.room_id}) + set_tag("room_id", room_entry.room_id) log_kv({"events": len(room_entry.events or [])}) logger.debug("Generating room entry for %s", room_entry.room_id) res = await self._generate_room_entry(