From 9a6f4a684f6522be4745ce5e0b39e0268c5f0a01 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Wed, 15 Sep 2021 17:14:25 +0100 Subject: [PATCH 1/3] Cleanup opentracing logging for syncs (#10828) We added a bunch of spans in #10704, but this ended up adding a lot of redundant spans for rooms where nothing changed, so instead we only start the span if there might be something interesting going on. --- changelog.d/10828.bugfix | 1 + synapse/handlers/sync.py | 293 ++++++++++++++++++++------------------- 2 files changed, 155 insertions(+), 139 deletions(-) create mode 100644 changelog.d/10828.bugfix diff --git a/changelog.d/10828.bugfix b/changelog.d/10828.bugfix new file mode 100644 index 000000000..e00c10ec8 --- /dev/null +++ b/changelog.d/10828.bugfix @@ -0,0 +1 @@ +Added opentrace logging to help debug #9424. diff --git a/synapse/handlers/sync.py b/synapse/handlers/sync.py index e017b28cd..edfdb99cb 100644 --- a/synapse/handlers/sync.py +++ b/synapse/handlers/sync.py @@ -1533,21 +1533,18 @@ class SyncHandler: newly_left_rooms = room_changes.newly_left_rooms async def handle_room_entries(room_entry: "RoomSyncResultBuilder"): - with start_active_span("generate_room_entry"): - 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, - 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 + 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) @@ -1960,139 +1957,157 @@ 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, - sync_config, - now_token=upto_token, - since_token=since_token, - potential_recents=events, - newly_joined_room=newly_joined, - ) - log_kv( - { - "batch_events": len(batch.events), - "prev_batch": batch.prev_batch, - "batch_limited": batch.limited, - } - ) + with start_active_span("generate_room_entry"): + set_tag("room_id", room_id) + log_kv({"events": len(events or ())}) - # 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 - # (e.g. due to having ignored the sender of the last 50 events). + log_kv( + { + "since_token": since_token, + "upto_token": upto_token, + } + ) - if newly_joined: - # debug for https://github.com/matrix-org/synapse/issues/4422 - issue4422_logger.debug( - "Timeline events after filtering in newly-joined room %s: %r", + batch = await self._load_filtered_recents( + room_id, + sync_config, + now_token=upto_token, + since_token=since_token, + 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 + # (e.g. due to having ignored the sender of the last 50 events). + + if newly_joined: + # debug for https://github.com/matrix-org/synapse/issues/4422 + issue4422_logger.debug( + "Timeline events after filtering in newly-joined room %s: %r", + room_id, + batch, + ) + + # When we join the room (or the client requests full_state), we should + # send down any existing tags. Usually the user won't have tags in a + # newly joined room, unless either a) they've joined before or b) the + # tag was added by synapse e.g. for server notice rooms. + if full_state: + user_id = sync_result_builder.sync_config.user.to_string() + tags = await self.store.get_tags_for_room(user_id, room_id) + + # If there aren't any tags, don't send the empty tags list down + # sync + if not tags: + tags = None + + account_data_events = [] + if tags is not None: + account_data_events.append({"type": "m.tag", "content": {"tags": tags}}) + + for account_data_type, content in account_data.items(): + account_data_events.append( + {"type": account_data_type, "content": content} + ) + + account_data_events = ( + sync_config.filter_collection.filter_room_account_data( + account_data_events + ) + ) + + ephemeral = sync_config.filter_collection.filter_room_ephemeral(ephemeral) + + if not ( + always_include + or batch + or account_data_events + or ephemeral + or full_state + ): + return + + state = await self.compute_state_delta( room_id, batch, + sync_config, + since_token, + now_token, + full_state=full_state, ) - # When we join the room (or the client requests full_state), we should - # send down any existing tags. Usually the user won't have tags in a - # newly joined room, unless either a) they've joined before or b) the - # tag was added by synapse e.g. for server notice rooms. - if full_state: - user_id = sync_result_builder.sync_config.user.to_string() - tags = await self.store.get_tags_for_room(user_id, room_id) + summary: Optional[JsonDict] = {} - # If there aren't any tags, don't send the empty tags list down - # sync - if not tags: - tags = None - - account_data_events = [] - if tags is not None: - account_data_events.append({"type": "m.tag", "content": {"tags": tags}}) - - for account_data_type, content in account_data.items(): - account_data_events.append({"type": account_data_type, "content": content}) - - account_data_events = sync_config.filter_collection.filter_room_account_data( - account_data_events - ) - - ephemeral = sync_config.filter_collection.filter_room_ephemeral(ephemeral) - - if not ( - always_include or batch or account_data_events or ephemeral or full_state - ): - return - - state = await self.compute_state_delta( - room_id, batch, sync_config, since_token, now_token, full_state=full_state - ) - - summary: Optional[JsonDict] = {} - - # we include a summary in room responses when we're lazy loading - # members (as the client otherwise doesn't have enough info to form - # the name itself). - if sync_config.filter_collection.lazy_load_members() and ( - # we recalculate the summary: - # if there are membership changes in the timeline, or - # if membership has changed during a gappy sync, or - # if this is an initial sync. - any(ev.type == EventTypes.Member for ev in batch.events) - or ( - # XXX: this may include false positives in the form of LL - # members which have snuck into state - batch.limited - and any(t == EventTypes.Member for (t, k) in state) - ) - or since_token is None - ): - summary = await self.compute_summary( - room_id, sync_config, batch, state, now_token - ) - - if room_builder.rtype == "joined": - unread_notifications: Dict[str, int] = {} - room_sync = JoinedSyncResult( - room_id=room_id, - timeline=batch, - state=state, - ephemeral=ephemeral, - account_data=account_data_events, - unread_notifications=unread_notifications, - summary=summary, - unread_count=0, - ) - - if room_sync or always_include: - notifs = await self.unread_notifs_for_room_id(room_id, sync_config) - - unread_notifications["notification_count"] = notifs["notify_count"] - unread_notifications["highlight_count"] = notifs["highlight_count"] - - room_sync.unread_count = notifs["unread_count"] - - sync_result_builder.joined.append(room_sync) - - if batch.limited and since_token: - user_id = sync_result_builder.sync_config.user.to_string() - logger.debug( - "Incremental gappy sync of %s for user %s with %d state events" - % (room_id, user_id, len(state)) + # we include a summary in room responses when we're lazy loading + # members (as the client otherwise doesn't have enough info to form + # the name itself). + if sync_config.filter_collection.lazy_load_members() and ( + # we recalculate the summary: + # if there are membership changes in the timeline, or + # if membership has changed during a gappy sync, or + # if this is an initial sync. + any(ev.type == EventTypes.Member for ev in batch.events) + or ( + # XXX: this may include false positives in the form of LL + # members which have snuck into state + batch.limited + and any(t == EventTypes.Member for (t, k) in state) ) - elif room_builder.rtype == "archived": - archived_room_sync = ArchivedSyncResult( - room_id=room_id, - timeline=batch, - state=state, - account_data=account_data_events, - ) - if archived_room_sync or always_include: - sync_result_builder.archived.append(archived_room_sync) - else: - raise Exception("Unrecognized rtype: %r", room_builder.rtype) + or since_token is None + ): + summary = await self.compute_summary( + room_id, sync_config, batch, state, now_token + ) + + if room_builder.rtype == "joined": + unread_notifications: Dict[str, int] = {} + room_sync = JoinedSyncResult( + room_id=room_id, + timeline=batch, + state=state, + ephemeral=ephemeral, + account_data=account_data_events, + unread_notifications=unread_notifications, + summary=summary, + unread_count=0, + ) + + if room_sync or always_include: + notifs = await self.unread_notifs_for_room_id(room_id, sync_config) + + unread_notifications["notification_count"] = notifs["notify_count"] + unread_notifications["highlight_count"] = notifs["highlight_count"] + + room_sync.unread_count = notifs["unread_count"] + + sync_result_builder.joined.append(room_sync) + + if batch.limited and since_token: + user_id = sync_result_builder.sync_config.user.to_string() + logger.debug( + "Incremental gappy sync of %s for user %s with %d state events" + % (room_id, user_id, len(state)) + ) + elif room_builder.rtype == "archived": + archived_room_sync = ArchivedSyncResult( + room_id=room_id, + timeline=batch, + state=state, + account_data=account_data_events, + ) + if archived_room_sync or always_include: + sync_result_builder.archived.append(archived_room_sync) + else: + raise Exception("Unrecognized rtype: %r", room_builder.rtype) async def get_rooms_for_user_at( self, user_id: str, room_key: RoomStreamToken From daac1e645cc64a588b63cffd6e0078a479b96a74 Mon Sep 17 00:00:00 2001 From: David Robertson Date: Fri, 17 Sep 2021 10:43:51 +0100 Subject: [PATCH 2/3] 1.43.0rc2 --- CHANGES.md | 9 +++++++++ changelog.d/10828.bugfix | 1 - debian/changelog | 6 ++++++ synapse/__init__.py | 2 +- 4 files changed, 16 insertions(+), 2 deletions(-) delete mode 100644 changelog.d/10828.bugfix diff --git a/CHANGES.md b/CHANGES.md index 4e9cefe69..3b6e9a270 100644 --- a/CHANGES.md +++ b/CHANGES.md @@ -1,3 +1,12 @@ +Synapse 1.43.0rc2 (2021-09-17) +============================== + +Bugfixes +-------- + +- Added opentrace logging to help debug #9424. ([\#10828](https://github.com/matrix-org/synapse/issues/10828)) + + Synapse 1.43.0rc1 (2021-09-14) ============================== diff --git a/changelog.d/10828.bugfix b/changelog.d/10828.bugfix deleted file mode 100644 index e00c10ec8..000000000 --- a/changelog.d/10828.bugfix +++ /dev/null @@ -1 +0,0 @@ -Added opentrace logging to help debug #9424. diff --git a/debian/changelog b/debian/changelog index d3a6f6a4e..7774cad55 100644 --- a/debian/changelog +++ b/debian/changelog @@ -1,3 +1,9 @@ +matrix-synapse-py3 (1.43.0~rc2) stable; urgency=medium + + * New synapse release 1.43.0~rc2. + + -- Synapse Packaging team Fri, 17 Sep 2021 10:43:21 +0100 + matrix-synapse-py3 (1.43.0~rc1) stable; urgency=medium * New synapse release 1.43.0~rc1. diff --git a/synapse/__init__.py b/synapse/__init__.py index d62ccd1db..c9ef90cca 100644 --- a/synapse/__init__.py +++ b/synapse/__init__.py @@ -47,7 +47,7 @@ try: except ImportError: pass -__version__ = "1.43.0rc1" +__version__ = "1.43.0rc2" if bool(os.environ.get("SYNAPSE_TEST_PATCH_LOG_CONTEXTS", False)): # We import here so that we don't have to install a bunch of deps when From 4ed4ab0e93ea2b45d05fd803a4331d4278b47782 Mon Sep 17 00:00:00 2001 From: David Robertson Date: Fri, 17 Sep 2021 10:48:07 +0100 Subject: [PATCH 3/3] Add hyperlink to #9424 in changelog --- CHANGES.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGES.md b/CHANGES.md index 3b6e9a270..ce3b0adae 100644 --- a/CHANGES.md +++ b/CHANGES.md @@ -4,7 +4,7 @@ Synapse 1.43.0rc2 (2021-09-17) Bugfixes -------- -- Added opentrace logging to help debug #9424. ([\#10828](https://github.com/matrix-org/synapse/issues/10828)) +- Added opentracing logging to help debug [\#9424](https://github.com/matrix-org/synapse/issues/9424). ([\#10828](https://github.com/matrix-org/synapse/issues/10828)) Synapse 1.43.0rc1 (2021-09-14)