From 95624a6ec4feae1e8a419fe0f378bb26c711dc4c Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 5 Nov 2021 17:09:15 -0500 Subject: [PATCH 1/5] Mark historical state as historical internally Part of https://github.com/matrix-org/synapse/issues/11241 --- synapse/handlers/room_batch.py | 2 ++ synapse/handlers/room_member.py | 6 ++++++ 2 files changed, 8 insertions(+) diff --git a/synapse/handlers/room_batch.py b/synapse/handlers/room_batch.py index 072328638376..f880aa93d29a 100644 --- a/synapse/handlers/room_batch.py +++ b/synapse/handlers/room_batch.py @@ -221,6 +221,7 @@ async def persist_state_events_at_start( action=membership, content=event_dict["content"], outlier=True, + historical=True, prev_event_ids=[prev_event_id_for_state_chain], # Make sure to use a copy of this list because we modify it # later in the loop here. Otherwise it will be the same @@ -240,6 +241,7 @@ async def persist_state_events_at_start( ), event_dict, outlier=True, + historical=True, prev_event_ids=[prev_event_id_for_state_chain], # Make sure to use a copy of this list because we modify it # later in the loop here. Otherwise it will be the same diff --git a/synapse/handlers/room_member.py b/synapse/handlers/room_member.py index 08244b690d4c..aade0f711bab 100644 --- a/synapse/handlers/room_member.py +++ b/synapse/handlers/room_member.py @@ -268,6 +268,7 @@ async def _local_membership_update( content: Optional[dict] = None, require_consent: bool = True, outlier: bool = False, + historical: bool = False, ) -> Tuple[str, int]: """ Internal membership update function to get an existing event or create @@ -337,6 +338,7 @@ async def _local_membership_update( auth_event_ids=auth_event_ids, require_consent=require_consent, outlier=outlier, + historical=historical, ) prev_state_ids = await context.get_prev_state_ids() @@ -433,6 +435,7 @@ async def update_membership( new_room: bool = False, require_consent: bool = True, outlier: bool = False, + historical: bool = False, prev_event_ids: Optional[List[str]] = None, auth_event_ids: Optional[List[str]] = None, ) -> Tuple[str, int]: @@ -487,6 +490,7 @@ async def update_membership( new_room=new_room, require_consent=require_consent, outlier=outlier, + historical=historical, prev_event_ids=prev_event_ids, auth_event_ids=auth_event_ids, ) @@ -507,6 +511,7 @@ async def update_membership_locked( new_room: bool = False, require_consent: bool = True, outlier: bool = False, + historical: bool = False, prev_event_ids: Optional[List[str]] = None, auth_event_ids: Optional[List[str]] = None, ) -> Tuple[str, int]: @@ -657,6 +662,7 @@ async def update_membership_locked( content=content, require_consent=require_consent, outlier=outlier, + historical=historical, ) latest_event_ids = await self.store.get_prev_events_for_room(room_id) From c30a35bb49cbf49a6846a81b0543c875f52a553c Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Sat, 6 Nov 2021 00:40:10 -0500 Subject: [PATCH 2/5] Add useful debug logs while making a fake AS /transactions endpoint in Complement Complement tests: https://github.com/matrix-org/complement/pull/221 --- synapse/appservice/api.py | 17 +++++++++++++++-- 1 file changed, 15 insertions(+), 2 deletions(-) diff --git a/synapse/appservice/api.py b/synapse/appservice/api.py index d08f6bbd7f2e..c603b4403912 100644 --- a/synapse/appservice/api.py +++ b/synapse/appservice/api.py @@ -231,13 +231,26 @@ async def push_bulk( json_body=body, args={"access_token": service.hs_token}, ) + logger.debug( + "push_bulk to %s succeeded! events=%s", + uri, + [event.get("event_id") for event in events], + ) sent_transactions_counter.labels(service.id).inc() sent_events_counter.labels(service.id).inc(len(events)) return True except CodeMessageException as e: - logger.warning("push_bulk to %s received %s", uri, e.code) + logger.warning( + "push_bulk to %s received code=%s msg=%s", uri, e.code, e.msg + ) except Exception as ex: - logger.warning("push_bulk to %s threw exception %s", uri, ex) + logger.warning( + "push_bulk to %s threw exception(%s) %s args=%s", + uri, + type(ex).__name__, + ex, + ex.args, + ) failed_transactions_counter.labels(service.id).inc() return False From 64df8cda3f4e701a1d4a391ed426149493c6024f Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Sat, 6 Nov 2021 00:58:48 -0500 Subject: [PATCH 3/5] Add changelog --- changelog.d/11265.bugfix | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/11265.bugfix diff --git a/changelog.d/11265.bugfix b/changelog.d/11265.bugfix new file mode 100644 index 000000000000..b0e9dfac5309 --- /dev/null +++ b/changelog.d/11265.bugfix @@ -0,0 +1 @@ +Prevent [MSC2716](https://github.com/matrix-org/matrix-doc/pull/2716) historical state events from being pushed to an application service via `/transactions`. From e580d4714eda35077c54a76230c666af85bd3531 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Tue, 9 Nov 2021 17:33:21 -0600 Subject: [PATCH 4/5] Add exc_info to debug stack trace --- synapse/appservice/api.py | 18 ++++++++++++------ 1 file changed, 12 insertions(+), 6 deletions(-) diff --git a/synapse/appservice/api.py b/synapse/appservice/api.py index c603b4403912..f51b636417bb 100644 --- a/synapse/appservice/api.py +++ b/synapse/appservice/api.py @@ -231,17 +231,22 @@ async def push_bulk( json_body=body, args={"access_token": service.hs_token}, ) - logger.debug( - "push_bulk to %s succeeded! events=%s", - uri, - [event.get("event_id") for event in events], - ) + if logger.isEnabledFor(logging.DEBUG): + logger.debug( + "push_bulk to %s succeeded! events=%s", + uri, + [event.get("event_id") for event in events], + ) sent_transactions_counter.labels(service.id).inc() sent_events_counter.labels(service.id).inc(len(events)) return True except CodeMessageException as e: logger.warning( - "push_bulk to %s received code=%s msg=%s", uri, e.code, e.msg + "push_bulk to %s received code=%s msg=%s", + uri, + e.code, + e.msg, + exc_info=logger.isEnabledFor(logging.DEBUG), ) except Exception as ex: logger.warning( @@ -250,6 +255,7 @@ async def push_bulk( type(ex).__name__, ex, ex.args, + exc_info=logger.isEnabledFor(logging.DEBUG), ) failed_transactions_counter.labels(service.id).inc() return False From 15e32463023ed1134362718bfb5f52844253b486 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Thu, 11 Nov 2021 01:32:35 -0600 Subject: [PATCH 5/5] Add historical to commentdoc --- synapse/handlers/room_member.py | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/synapse/handlers/room_member.py b/synapse/handlers/room_member.py index aade0f711bab..a6dbff637f54 100644 --- a/synapse/handlers/room_member.py +++ b/synapse/handlers/room_member.py @@ -294,6 +294,9 @@ async def _local_membership_update( outlier: Indicates whether the event is an `outlier`, i.e. if it's from an arbitrary point and floating in the DAG as opposed to being inline with the current DAG. + historical: Indicates whether the message is being inserted + back in time around some existing events. This is used to skip + a few checks and mark the event as backfilled. Returns: Tuple of event ID and stream ordering position @@ -457,6 +460,9 @@ async def update_membership( outlier: Indicates whether the event is an `outlier`, i.e. if it's from an arbitrary point and floating in the DAG as opposed to being inline with the current DAG. + historical: Indicates whether the message is being inserted + back in time around some existing events. This is used to skip + a few checks and mark the event as backfilled. prev_event_ids: The event IDs to use as the prev events auth_event_ids: The event ids to use as the auth_events for the new event. @@ -535,6 +541,9 @@ async def update_membership_locked( outlier: Indicates whether the event is an `outlier`, i.e. if it's from an arbitrary point and floating in the DAG as opposed to being inline with the current DAG. + historical: Indicates whether the message is being inserted + back in time around some existing events. This is used to skip + a few checks and mark the event as backfilled. prev_event_ids: The event IDs to use as the prev events auth_event_ids: The event ids to use as the auth_events for the new event.