From 2db287e6b0299e34a26ce793d620e25f169c91c8 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Tue, 20 Jul 2021 23:14:00 -0500 Subject: [PATCH 01/14] Fix backfilled events being rejected for none state_groups Reproducible on a federated homeserver when there is a membership auth event as a floating outlier. Then when we try to backfill one of that persons messages, it has missing membership auth to fetch which caused us to mistakenly replace the `context` for the message with that of the floating membership `outlier` event. Since `outliers` have no `state` or `state_group`, the error bubbles up when we continue down the persisting route: `sqlite3.IntegrityError: NOT NULL constraint failed: event_to_state_groups.state_group` Call stack: ``` backfill _auth_and_persist_event _check_event_auth _update_auth_events_and_context_for_auth ``` --- synapse/event_auth.py | 1 + synapse/handlers/federation.py | 8 ++- tests/handlers/test_federation.py | 106 +++++++++++++++++++++++++++++- 3 files changed, 112 insertions(+), 3 deletions(-) diff --git a/synapse/event_auth.py b/synapse/event_auth.py index a3df6cfcc1dc..042c6974acf4 100644 --- a/synapse/event_auth.py +++ b/synapse/event_auth.py @@ -131,6 +131,7 @@ def check( return # 3. If event does not have a m.room.create in its auth_events, reject. + logger.info("event_auth: event_id=%s auth_events=%s", event.event_id, auth_events) creation_event = auth_events.get((EventTypes.Create, ""), None) if not creation_event: raise AuthError(403, "No create event in auth events") diff --git a/synapse/handlers/federation.py b/synapse/handlers/federation.py index 991ec9919a95..1956607bd86a 100644 --- a/synapse/handlers/federation.py +++ b/synapse/handlers/federation.py @@ -2680,6 +2680,8 @@ async def _update_auth_events_and_context_for_auth( remote_auth_chain = await self.federation_client.get_event_auth( origin, event.room_id, event.event_id ) + logger.info("remote_auth_chain %s", remote_auth_chain) + logger.info("asdf %s", remote_auth_chain[0].auth_events) except RequestSendFailed as e1: # The other side isn't around or doesn't implement the # endpoint, so lets just bail out. @@ -2711,9 +2713,11 @@ async def _update_auth_events_and_context_for_auth( event.event_id, e.event_id, ) - context = await self.state_handler.compute_event_context(e) + missing_auth_context = ( + await self.state_handler.compute_event_context(e) + ) await self._auth_and_persist_event( - origin, e, context, auth_events=auth + origin, e, missing_auth_context, auth_events=auth ) if e.event_id in event_auth_events: diff --git a/tests/handlers/test_federation.py b/tests/handlers/test_federation.py index ba8cf44f4626..ca316c9624f4 100644 --- a/tests/handlers/test_federation.py +++ b/tests/handlers/test_federation.py @@ -13,15 +13,19 @@ # limitations under the License. import logging from unittest import TestCase +from unittest.mock import Mock +from twisted.internet import defer from synapse.api.constants import EventTypes from synapse.api.errors import AuthError, Codes, LimitExceededError, SynapseError from synapse.api.room_versions import RoomVersions from synapse.events import EventBase from synapse.federation.federation_base import event_from_pdu_json +from synapse.federation.units import Transaction from synapse.logging.context import LoggingContext, run_in_background from synapse.rest import admin from synapse.rest.client.v1 import login, room +from synapse.util.stringutils import random_string from tests import unittest @@ -36,9 +40,14 @@ class FederationTestCase(unittest.HomeserverTestCase): ] def make_homeserver(self, reactor, clock): - hs = self.setup_test_homeserver(federation_http_client=None) + # we mock out the federation client too + self.mock_federation_client = Mock() + hs = self.setup_test_homeserver( + federation_http_client=self.mock_federation_client + ) self.handler = hs.get_federation_handler() self.store = hs.get_datastore() + self.state_store = hs.get_storage().state return hs def test_exchange_revoked_invite(self): @@ -190,6 +199,101 @@ def test_rejected_state_event_state(self): self.assertEqual(sg, sg2) + def test_floating_outlier_membership_auth(self): + """ + Check that we can properly process an event with auth_events that + include a floating membership event. + + Regression test for #TODO(PR). + """ + OTHER_SERVER = "otherserver" + OTHER_USER = "@otheruser:" + OTHER_SERVER + + # create the room + user_id = self.register_user("kermit", "test") + tok = self.login("kermit", "test") + room_id = self.helper.create_room_as(room_creator=user_id, tok=tok) + room_version = self.get_success(self.store.get_room_version(room_id)) + + prev_event_ids = self.get_success(self.store.get_prev_events_for_room(room_id)) + ( + most_recent_prev_event_id, + most_recent_prev_event_depth, + ) = self.get_success(self.store.get_max_depth_of(prev_event_ids)) + # mapping from (type, state_key) -> state_event_id + prev_state_map = self.get_success( + self.state_store.get_state_ids_for_event(most_recent_prev_event_id) + ) + # List of state event ID's + prev_state_ids = list(prev_state_map.values()) + auth_event_ids = prev_state_ids + + auth_events = self.get_success(self.store.get_events(auth_event_ids)) + logger.info("auth_event_ids %s\nauth_events=%s", auth_event_ids, auth_events) + + # build a floating outlier member state event + fake_prev_event_id = "$" + random_string(43) + member_event = event_from_pdu_json( + { + "type": EventTypes.Member, + "content": { + "membership": "join", + }, + "state_key": OTHER_USER, + "room_id": room_id, + "sender": OTHER_USER, + "depth": most_recent_prev_event_depth, + "prev_events": [fake_prev_event_id], + "auth_events": auth_event_ids.copy(), + "origin_server_ts": self.clock.time_msec(), + "signatures": { + OTHER_SERVER: {"ed25519:key_version": "SomeSignatureHere"} + }, + }, + room_version, + ) + + # build and send an event authed based on the member event + ev = event_from_pdu_json( + { + "type": EventTypes.Message, + "content": {}, + "room_id": room_id, + "sender": OTHER_USER, + "depth": most_recent_prev_event_depth, + "prev_events": prev_event_ids.copy(), + "auth_events": auth_event_ids.copy() + [member_event.event_id], + "origin_server_ts": self.clock.time_msec(), + "signatures": { + OTHER_SERVER: {"ed25519:key_version": "SomeSignatureHere"} + }, + }, + room_version, + ) + + # Stub the event_auth responds from the OTHER_SERVER + self.handler.federation_client.get_event_auth = ( + lambda destination, room_id, event_id: defer.succeed([member_event]) + ) + # self.handler.federation_client.get_event_auth = Mock( + # return_value=defer.succeed(None) + # ) + res = Transaction( + origin=OTHER_SERVER, + pdus=[member_event], + origin_server_ts=self.clock.time_msec(), + destination=None, + ).get_dict() + self.mock_federation_client.get_json.return_value = defer.succeed((200, res)) + + # TODO: need to do backfill request instead + d = run_in_background(self.handler.on_receive_pdu, OTHER_SERVER, ev) + self.get_success(d) + + # Try and get the events + stored_event = self.get_success(self.store.get_event(ev.event_id)) + self.assertEqual(stored_event.event_id, ev.event_id) + @unittest.override_config( {"rc_invites": {"per_user": {"per_second": 0.5, "burst_count": 3}}} ) From 28a5e6a8cf293a400e46c6da3e9541ed787d1569 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Tue, 20 Jul 2021 23:31:14 -0500 Subject: [PATCH 02/14] Fix 403 --- synapse/event_auth.py | 1 - synapse/handlers/federation.py | 2 -- tests/handlers/test_federation.py | 17 +++++++++++------ 3 files changed, 11 insertions(+), 9 deletions(-) diff --git a/synapse/event_auth.py b/synapse/event_auth.py index 042c6974acf4..a3df6cfcc1dc 100644 --- a/synapse/event_auth.py +++ b/synapse/event_auth.py @@ -131,7 +131,6 @@ def check( return # 3. If event does not have a m.room.create in its auth_events, reject. - logger.info("event_auth: event_id=%s auth_events=%s", event.event_id, auth_events) creation_event = auth_events.get((EventTypes.Create, ""), None) if not creation_event: raise AuthError(403, "No create event in auth events") diff --git a/synapse/handlers/federation.py b/synapse/handlers/federation.py index 1956607bd86a..daff5803e3e4 100644 --- a/synapse/handlers/federation.py +++ b/synapse/handlers/federation.py @@ -2680,8 +2680,6 @@ async def _update_auth_events_and_context_for_auth( remote_auth_chain = await self.federation_client.get_event_auth( origin, event.room_id, event.event_id ) - logger.info("remote_auth_chain %s", remote_auth_chain) - logger.info("asdf %s", remote_auth_chain[0].auth_events) except RequestSendFailed as e1: # The other side isn't around or doesn't implement the # endpoint, so lets just bail out. diff --git a/tests/handlers/test_federation.py b/tests/handlers/test_federation.py index ca316c9624f4..568d5a6b43bb 100644 --- a/tests/handlers/test_federation.py +++ b/tests/handlers/test_federation.py @@ -227,9 +227,9 @@ def test_floating_outlier_membership_auth(self): # List of state event ID's prev_state_ids = list(prev_state_map.values()) auth_event_ids = prev_state_ids - - auth_events = self.get_success(self.store.get_events(auth_event_ids)) - logger.info("auth_event_ids %s\nauth_events=%s", auth_event_ids, auth_events) + auth_events = list( + self.get_success(self.store.get_events(auth_event_ids)).values() + ) # build a floating outlier member state event fake_prev_event_id = "$" + random_string(43) @@ -251,6 +251,7 @@ def test_floating_outlier_membership_auth(self): }, }, room_version, + outlier=True, ) # build and send an event authed based on the member event @@ -273,7 +274,9 @@ def test_floating_outlier_membership_auth(self): # Stub the event_auth responds from the OTHER_SERVER self.handler.federation_client.get_event_auth = ( - lambda destination, room_id, event_id: defer.succeed([member_event]) + lambda destination, room_id, event_id: defer.succeed( + auth_events + [member_event] + ) ) # self.handler.federation_client.get_event_auth = Mock( # return_value=defer.succeed(None) @@ -291,8 +294,10 @@ def test_floating_outlier_membership_auth(self): self.get_success(d) # Try and get the events - stored_event = self.get_success(self.store.get_event(ev.event_id)) - self.assertEqual(stored_event.event_id, ev.event_id) + stored_event = self.get_success( + self.store.get_event(ev.event_id, allow_none=True) + ) + self.assertTrue(stored_event is not None) @unittest.override_config( {"rc_invites": {"per_user": {"per_second": 0.5, "burst_count": 3}}} From 64c8e5ef352088a336eb7c6dccee7358e16a8aa3 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 21 Jul 2021 00:02:05 -0500 Subject: [PATCH 03/14] Some more cleanup and try backfill --- tests/handlers/test_federation.py | 24 +++++++++++++----------- 1 file changed, 13 insertions(+), 11 deletions(-) diff --git a/tests/handlers/test_federation.py b/tests/handlers/test_federation.py index 568d5a6b43bb..ee55c2ace75f 100644 --- a/tests/handlers/test_federation.py +++ b/tests/handlers/test_federation.py @@ -199,12 +199,13 @@ def test_rejected_state_event_state(self): self.assertEqual(sg, sg2) - def test_floating_outlier_membership_auth(self): + def test_backfill_floating_outlier_membership_auth(self): """ - Check that we can properly process an event with auth_events that - include a floating membership event. + As the remote federated homeserver, check that we can properly process + an event with auth_events that include a floating membership event from + the OTHER_SERVER. - Regression test for #TODO(PR). + Regression test, see #10439. """ OTHER_SERVER = "otherserver" OTHER_USER = "@otheruser:" + OTHER_SERVER @@ -272,15 +273,13 @@ def test_floating_outlier_membership_auth(self): room_version, ) - # Stub the event_auth responds from the OTHER_SERVER + # Stub the /event_auth response from the OTHER_SERVER self.handler.federation_client.get_event_auth = ( lambda destination, room_id, event_id: defer.succeed( auth_events + [member_event] ) ) - # self.handler.federation_client.get_event_auth = Mock( - # return_value=defer.succeed(None) - # ) + # Stub the /backfill response from the OTHER_SERVER res = Transaction( origin=OTHER_SERVER, pdus=[member_event], @@ -289,9 +288,12 @@ def test_floating_outlier_membership_auth(self): ).get_dict() self.mock_federation_client.get_json.return_value = defer.succeed((200, res)) - # TODO: need to do backfill request instead - d = run_in_background(self.handler.on_receive_pdu, OTHER_SERVER, ev) - self.get_success(d) + with LoggingContext("backfill"): + d = run_in_background( + self.handler.maybe_backfill, room_id, most_recent_prev_event_depth, 100 + ) + did_backfill = self.get_success(d) + self.assertTrue(did_backfill) # Try and get the events stored_event = self.get_success( From e9f3e9d864f4ec6384ae4ff707d2f3bdac2a4c2f Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 21 Jul 2021 02:39:44 -0500 Subject: [PATCH 04/14] Reproduce problem --- synapse/event_auth.py | 5 +++ synapse/handlers/federation.py | 44 +++++++++++++++++-- tests/handlers/test_federation.py | 72 ++++++++++++++++++++++--------- 3 files changed, 97 insertions(+), 24 deletions(-) diff --git a/synapse/event_auth.py b/synapse/event_auth.py index a3df6cfcc1dc..90bb8a3cb588 100644 --- a/synapse/event_auth.py +++ b/synapse/event_auth.py @@ -277,11 +277,15 @@ def _is_membership_change_allowed( key = (EventTypes.JoinRules, "") join_rule_event = auth_events.get(key) + logger.error("join_rule_event ggre %s", join_rule_event) if join_rule_event: join_rule = join_rule_event.content.get("join_rule", JoinRules.INVITE) else: join_rule = JoinRules.INVITE + # TODO: remove. The auth_rules don't have the join_rules for the given even we're trying auth + join_rule = JoinRules.PUBLIC + user_level = get_user_power_level(event.user_id, auth_events) target_level = get_user_power_level(target_user_id, auth_events) @@ -341,6 +345,7 @@ def _is_membership_change_allowed( if user_level < invite_level: raise AuthError(403, "You don't have permission to invite users") elif Membership.JOIN == membership: + logger.error("join_rule fefefeafw %s", join_rule) # Joins are valid iff caller == target and: # * They are not banned. # * They are accepting a previously sent invitation. diff --git a/synapse/handlers/federation.py b/synapse/handlers/federation.py index daff5803e3e4..8dccbddad6e8 100644 --- a/synapse/handlers/federation.py +++ b/synapse/handlers/federation.py @@ -2711,11 +2711,24 @@ async def _update_auth_events_and_context_for_auth( event.event_id, e.event_id, ) - missing_auth_context = ( - await self.state_handler.compute_event_context(e) + logger.error( + "_update_auth_events_and_context_for_auth before event_id=%s state_group=%s", + event.event_id, + context.state_group, + ) + context = await self.state_handler.compute_event_context(e) + logger.error( + "_update_auth_events_and_context_for_auth after1 event_id=%s state_group=%s", + event.event_id, + context.state_group, ) await self._auth_and_persist_event( - origin, e, missing_auth_context, auth_events=auth + origin, e, context, auth_events=auth + ) + logger.error( + "_update_auth_events_and_context_for_auth after2 event_id=%s state_group=%s", + event.event_id, + context.state_group, ) if e.event_id in event_auth_events: @@ -2727,6 +2740,11 @@ async def _update_auth_events_and_context_for_auth( logger.exception("Failed to get auth chain") if event.internal_metadata.is_outlier(): + logger.error( + "_update_auth_events_and_context_for_auth is outlier event_id=%s state_group=%s", + event.event_id, + context.state_group, + ) # XXX: given that, for an outlier, we'll be working with the # event's *claimed* auth events rather than those we calculated: # (a) is there any point in this test, since different_auth below will @@ -2739,7 +2757,22 @@ async def _update_auth_events_and_context_for_auth( e.event_id for e in auth_events.values() ) + if different_auth: + logger.error( + "_update_auth_events_and_context_for_auth different_auth! event_id=%s state_group=%s\ndifferent_auth=%s\nevent_auth_events=%s\nauth_events=%s", + event.event_id, + context.state_group, + different_auth, + event_auth_events, + auth_events, + ) + if not different_auth: + logger.error( + "_update_auth_events_and_context_for_auth no different_auth event_id=%s state_group=%s", + event.event_id, + context.state_group, + ) return context logger.info( @@ -2795,6 +2828,11 @@ async def _update_auth_events_and_context_for_auth( context = await self._update_context_for_auth_events( event, context, auth_events ) + logger.error( + "_update_auth_events_and_context_for_auth after3 event_id=%s state_group=%s", + event.event_id, + context.state_group, + ) return context diff --git a/tests/handlers/test_federation.py b/tests/handlers/test_federation.py index ee55c2ace75f..b135e721b332 100644 --- a/tests/handlers/test_federation.py +++ b/tests/handlers/test_federation.py @@ -15,6 +15,9 @@ from unittest import TestCase from unittest.mock import Mock from twisted.internet import defer +from typing import ( + List, +) from synapse.api.constants import EventTypes from synapse.api.errors import AuthError, Codes, LimitExceededError, SynapseError @@ -48,6 +51,7 @@ def make_homeserver(self, reactor, clock): self.handler = hs.get_federation_handler() self.store = hs.get_datastore() self.state_store = hs.get_storage().state + self._event_auth_handler = hs.get_event_auth_handler() return hs def test_exchange_revoked_invite(self): @@ -207,13 +211,36 @@ def test_backfill_floating_outlier_membership_auth(self): Regression test, see #10439. """ + + def filter_auth_events_on_event(event: EventBase, auth_events: List[EventBase]): + # Create a StateMap[str] + auth_event_state_map = { + (e.type, e.state_key): e.event_id for e in auth_events + } + # Actually strip down and use the necessary auth events + auth_event_ids = self._event_auth_handler.compute_auth_events( + event=event, + current_state_ids=auth_event_state_map, + for_verification=False, + ) + + # Replace the auth_events with the stripped down ones + event.auth_events = auth_event_ids + OTHER_SERVER = "otherserver" OTHER_USER = "@otheruser:" + OTHER_SERVER # create the room user_id = self.register_user("kermit", "test") tok = self.login("kermit", "test") - room_id = self.helper.create_room_as(room_creator=user_id, tok=tok) + room_id = self.helper.create_room_as( + room_creator=user_id, + is_public=True, + tok=tok, + extra_content={ + "preset": "public_chat", + }, + ) room_version = self.get_success(self.store.get_room_version(room_id)) prev_event_ids = self.get_success(self.store.get_prev_events_for_room(room_id)) @@ -231,6 +258,7 @@ def test_backfill_floating_outlier_membership_auth(self): auth_events = list( self.get_success(self.store.get_events(auth_event_ids)).values() ) + logger.error("auth_events gresegrsegrb %s", auth_events) # build a floating outlier member state event fake_prev_event_id = "$" + random_string(43) @@ -254,9 +282,13 @@ def test_backfill_floating_outlier_membership_auth(self): room_version, outlier=True, ) + logger.error("member_event before auth_events=%s", member_event.auth_events) + filter_auth_events_on_event(member_event, auth_events) + logger.error("member_event after auth_events=%s", member_event.auth_events) # build and send an event authed based on the member event - ev = event_from_pdu_json( + raw_auth_events = auth_events + [member_event] + message_event = event_from_pdu_json( { "type": EventTypes.Message, "content": {}, @@ -264,7 +296,7 @@ def test_backfill_floating_outlier_membership_auth(self): "sender": OTHER_USER, "depth": most_recent_prev_event_depth, "prev_events": prev_event_ids.copy(), - "auth_events": auth_event_ids.copy() + [member_event.event_id], + "auth_events": [ev.event_id for ev in raw_auth_events], "origin_server_ts": self.clock.time_msec(), "signatures": { OTHER_SERVER: {"ed25519:key_version": "SomeSignatureHere"} @@ -272,32 +304,30 @@ def test_backfill_floating_outlier_membership_auth(self): }, room_version, ) + logger.error("message_event before auth_events=%s", message_event.auth_events) + filter_auth_events_on_event(message_event, raw_auth_events) + logger.error("message_event after auth_events=%s", message_event.auth_events) # Stub the /event_auth response from the OTHER_SERVER - self.handler.federation_client.get_event_auth = ( - lambda destination, room_id, event_id: defer.succeed( - auth_events + [member_event] - ) + self.handler.federation_client.get_event_auth = lambda destination, room_id, event_id: defer.succeed( + # After we filtered the auth events, convert the message auth event + # ID's back into full fledged EventBases + [ + auth_event + for auth_event in raw_auth_events + if auth_event.event_id in message_event.auth_events + ] ) - # Stub the /backfill response from the OTHER_SERVER - res = Transaction( - origin=OTHER_SERVER, - pdus=[member_event], - origin_server_ts=self.clock.time_msec(), - destination=None, - ).get_dict() - self.mock_federation_client.get_json.return_value = defer.succeed((200, res)) - - with LoggingContext("backfill"): + + with LoggingContext("receive_pdu"): d = run_in_background( - self.handler.maybe_backfill, room_id, most_recent_prev_event_depth, 100 + self.handler.on_receive_pdu, OTHER_SERVER, message_event ) - did_backfill = self.get_success(d) - self.assertTrue(did_backfill) + self.get_success(d) # Try and get the events stored_event = self.get_success( - self.store.get_event(ev.event_id, allow_none=True) + self.store.get_event(message_event.event_id, allow_none=True) ) self.assertTrue(stored_event is not None) From 487247f4d4ad58cd4cf44f9a56a195129e1721a1 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 21 Jul 2021 04:16:31 -0500 Subject: [PATCH 05/14] Reproduce without join_rule cheat --- synapse/event_auth.py | 11 +++++++++-- synapse/handlers/federation.py | 17 +++++++++++++++++ tests/handlers/test_federation.py | 27 +++++++++++++++++++-------- 3 files changed, 45 insertions(+), 10 deletions(-) diff --git a/synapse/event_auth.py b/synapse/event_auth.py index 90bb8a3cb588..a15135a3f805 100644 --- a/synapse/event_auth.py +++ b/synapse/event_auth.py @@ -277,14 +277,21 @@ def _is_membership_change_allowed( key = (EventTypes.JoinRules, "") join_rule_event = auth_events.get(key) - logger.error("join_rule_event ggre %s", join_rule_event) + logger.error( + "_is_membership_change_allowed: event_id=%s join_rule_event=%s event=%s event.auth_events=%s auth_events=%s", + event.event_id, + join_rule_event, + event, + event.auth_events, + auth_events, + ) if join_rule_event: join_rule = join_rule_event.content.get("join_rule", JoinRules.INVITE) else: join_rule = JoinRules.INVITE # TODO: remove. The auth_rules don't have the join_rules for the given even we're trying auth - join_rule = JoinRules.PUBLIC + # join_rule = JoinRules.PUBLIC user_level = get_user_power_level(event.user_id, auth_events) target_level = get_user_power_level(target_user_id, auth_events) diff --git a/synapse/handlers/federation.py b/synapse/handlers/federation.py index 8dccbddad6e8..97c06a21b01b 100644 --- a/synapse/handlers/federation.py +++ b/synapse/handlers/federation.py @@ -2566,6 +2566,11 @@ async def _check_event_auth( room_version = await self.store.get_room_version_id(event.room_id) room_version_obj = KNOWN_ROOM_VERSIONS[room_version] + logger.error( + "_check_event_auth before event_id=%s auth_events=%s", + event.event_id, + auth_events, + ) if not auth_events: prev_state_ids = await context.get_prev_state_ids() auth_events_ids = self._event_auth_handler.compute_auth_events( @@ -2573,6 +2578,11 @@ async def _check_event_auth( ) auth_events_x = await self.store.get_events(auth_events_ids) auth_events = {(e.type, e.state_key): e for e in auth_events_x.values()} + logger.error( + "_check_event_auth after event_id=%s auth_events=%s", + event.event_id, + auth_events, + ) # This is a hack to fix some old rooms where the initial join event # didn't reference the create event in its auth events. @@ -2704,6 +2714,13 @@ async def _update_auth_events_and_context_for_auth( for e in remote_auth_chain if e.event_id in auth_ids or e.type == EventTypes.Create } + logger.error( + "_check_event_auth cvcxvxcbs event_id=%s e.event_id=%s auth_ids=%s auth=%s", + event.event_id, + e.event_id, + auth_ids, + auth, + ) e.internal_metadata.outlier = True logger.debug( diff --git a/tests/handlers/test_federation.py b/tests/handlers/test_federation.py index b135e721b332..c69beb5274d0 100644 --- a/tests/handlers/test_federation.py +++ b/tests/handlers/test_federation.py @@ -282,7 +282,12 @@ def filter_auth_events_on_event(event: EventBase, auth_events: List[EventBase]): room_version, outlier=True, ) - logger.error("member_event before auth_events=%s", member_event.auth_events) + logger.error("member_event event_id=%s", member_event.event_id) + logger.error( + "member_event before event_id=%s auth_events=%s", + member_event.event_id, + member_event.auth_events, + ) filter_auth_events_on_event(member_event, auth_events) logger.error("member_event after auth_events=%s", member_event.auth_events) @@ -304,20 +309,26 @@ def filter_auth_events_on_event(event: EventBase, auth_events: List[EventBase]): }, room_version, ) + logger.error("message_event event_id=%s", message_event.event_id) logger.error("message_event before auth_events=%s", message_event.auth_events) - filter_auth_events_on_event(message_event, raw_auth_events) + filter_auth_events_on_event(message_event, raw_auth_events.copy()) logger.error("message_event after auth_events=%s", message_event.auth_events) # Stub the /event_auth response from the OTHER_SERVER - self.handler.federation_client.get_event_auth = lambda destination, room_id, event_id: defer.succeed( - # After we filtered the auth events, convert the message auth event - # ID's back into full fledged EventBases - [ + async def get_event_auth(destination, room_id, event_id): + return [ auth_event for auth_event in raw_auth_events - if auth_event.event_id in message_event.auth_events + if auth_event.type is EventTypes.Create + or auth_event.type is EventTypes.PowerLevels + or auth_event.type is EventTypes.JoinRules + or ( + auth_event.type is EventTypes.Member + and auth_event.state_key == message_event.sender + ) ] - ) + + self.handler.federation_client.get_event_auth = get_event_auth with LoggingContext("receive_pdu"): d = run_in_background( From b1ce3afbdb7b518584fa94ca104a4f73defadecb Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 21 Jul 2021 04:17:36 -0500 Subject: [PATCH 06/14] Add fix back --- synapse/handlers/federation.py | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/synapse/handlers/federation.py b/synapse/handlers/federation.py index 97c06a21b01b..f1fc2216e002 100644 --- a/synapse/handlers/federation.py +++ b/synapse/handlers/federation.py @@ -2733,14 +2733,16 @@ async def _update_auth_events_and_context_for_auth( event.event_id, context.state_group, ) - context = await self.state_handler.compute_event_context(e) + missing_auth_event_context = ( + await self.state_handler.compute_event_context(e) + ) logger.error( "_update_auth_events_and_context_for_auth after1 event_id=%s state_group=%s", event.event_id, context.state_group, ) await self._auth_and_persist_event( - origin, e, context, auth_events=auth + origin, e, missing_auth_event_context, auth_events=auth ) logger.error( "_update_auth_events_and_context_for_auth after2 event_id=%s state_group=%s", From 005382fb92ef76eab29446055a5ec783b0672261 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 21 Jul 2021 04:27:19 -0500 Subject: [PATCH 07/14] Clean up all the debug logs --- synapse/event_auth.py | 12 ------- synapse/handlers/federation.py | 57 ---------------------------------- 2 files changed, 69 deletions(-) diff --git a/synapse/event_auth.py b/synapse/event_auth.py index a15135a3f805..a3df6cfcc1dc 100644 --- a/synapse/event_auth.py +++ b/synapse/event_auth.py @@ -277,22 +277,11 @@ def _is_membership_change_allowed( key = (EventTypes.JoinRules, "") join_rule_event = auth_events.get(key) - logger.error( - "_is_membership_change_allowed: event_id=%s join_rule_event=%s event=%s event.auth_events=%s auth_events=%s", - event.event_id, - join_rule_event, - event, - event.auth_events, - auth_events, - ) if join_rule_event: join_rule = join_rule_event.content.get("join_rule", JoinRules.INVITE) else: join_rule = JoinRules.INVITE - # TODO: remove. The auth_rules don't have the join_rules for the given even we're trying auth - # join_rule = JoinRules.PUBLIC - user_level = get_user_power_level(event.user_id, auth_events) target_level = get_user_power_level(target_user_id, auth_events) @@ -352,7 +341,6 @@ def _is_membership_change_allowed( if user_level < invite_level: raise AuthError(403, "You don't have permission to invite users") elif Membership.JOIN == membership: - logger.error("join_rule fefefeafw %s", join_rule) # Joins are valid iff caller == target and: # * They are not banned. # * They are accepting a previously sent invitation. diff --git a/synapse/handlers/federation.py b/synapse/handlers/federation.py index f1fc2216e002..827853db3937 100644 --- a/synapse/handlers/federation.py +++ b/synapse/handlers/federation.py @@ -2566,11 +2566,6 @@ async def _check_event_auth( room_version = await self.store.get_room_version_id(event.room_id) room_version_obj = KNOWN_ROOM_VERSIONS[room_version] - logger.error( - "_check_event_auth before event_id=%s auth_events=%s", - event.event_id, - auth_events, - ) if not auth_events: prev_state_ids = await context.get_prev_state_ids() auth_events_ids = self._event_auth_handler.compute_auth_events( @@ -2578,11 +2573,6 @@ async def _check_event_auth( ) auth_events_x = await self.store.get_events(auth_events_ids) auth_events = {(e.type, e.state_key): e for e in auth_events_x.values()} - logger.error( - "_check_event_auth after event_id=%s auth_events=%s", - event.event_id, - auth_events, - ) # This is a hack to fix some old rooms where the initial join event # didn't reference the create event in its auth events. @@ -2714,13 +2704,6 @@ async def _update_auth_events_and_context_for_auth( for e in remote_auth_chain if e.event_id in auth_ids or e.type == EventTypes.Create } - logger.error( - "_check_event_auth cvcxvxcbs event_id=%s e.event_id=%s auth_ids=%s auth=%s", - event.event_id, - e.event_id, - auth_ids, - auth, - ) e.internal_metadata.outlier = True logger.debug( @@ -2728,27 +2711,12 @@ async def _update_auth_events_and_context_for_auth( event.event_id, e.event_id, ) - logger.error( - "_update_auth_events_and_context_for_auth before event_id=%s state_group=%s", - event.event_id, - context.state_group, - ) missing_auth_event_context = ( await self.state_handler.compute_event_context(e) ) - logger.error( - "_update_auth_events_and_context_for_auth after1 event_id=%s state_group=%s", - event.event_id, - context.state_group, - ) await self._auth_and_persist_event( origin, e, missing_auth_event_context, auth_events=auth ) - logger.error( - "_update_auth_events_and_context_for_auth after2 event_id=%s state_group=%s", - event.event_id, - context.state_group, - ) if e.event_id in event_auth_events: auth_events[(e.type, e.state_key)] = e @@ -2759,11 +2727,6 @@ async def _update_auth_events_and_context_for_auth( logger.exception("Failed to get auth chain") if event.internal_metadata.is_outlier(): - logger.error( - "_update_auth_events_and_context_for_auth is outlier event_id=%s state_group=%s", - event.event_id, - context.state_group, - ) # XXX: given that, for an outlier, we'll be working with the # event's *claimed* auth events rather than those we calculated: # (a) is there any point in this test, since different_auth below will @@ -2776,22 +2739,7 @@ async def _update_auth_events_and_context_for_auth( e.event_id for e in auth_events.values() ) - if different_auth: - logger.error( - "_update_auth_events_and_context_for_auth different_auth! event_id=%s state_group=%s\ndifferent_auth=%s\nevent_auth_events=%s\nauth_events=%s", - event.event_id, - context.state_group, - different_auth, - event_auth_events, - auth_events, - ) - if not different_auth: - logger.error( - "_update_auth_events_and_context_for_auth no different_auth event_id=%s state_group=%s", - event.event_id, - context.state_group, - ) return context logger.info( @@ -2847,11 +2795,6 @@ async def _update_auth_events_and_context_for_auth( context = await self._update_context_for_auth_events( event, context, auth_events ) - logger.error( - "_update_auth_events_and_context_for_auth after3 event_id=%s state_group=%s", - event.event_id, - context.state_group, - ) return context From 87b7fb93c2926baac097e46973bf3e01a1ab13c5 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 21 Jul 2021 04:31:06 -0500 Subject: [PATCH 08/14] Remove logs from tests --- tests/handlers/test_federation.py | 11 ----------- 1 file changed, 11 deletions(-) diff --git a/tests/handlers/test_federation.py b/tests/handlers/test_federation.py index c69beb5274d0..cce7104136a8 100644 --- a/tests/handlers/test_federation.py +++ b/tests/handlers/test_federation.py @@ -258,7 +258,6 @@ def filter_auth_events_on_event(event: EventBase, auth_events: List[EventBase]): auth_events = list( self.get_success(self.store.get_events(auth_event_ids)).values() ) - logger.error("auth_events gresegrsegrb %s", auth_events) # build a floating outlier member state event fake_prev_event_id = "$" + random_string(43) @@ -282,14 +281,7 @@ def filter_auth_events_on_event(event: EventBase, auth_events: List[EventBase]): room_version, outlier=True, ) - logger.error("member_event event_id=%s", member_event.event_id) - logger.error( - "member_event before event_id=%s auth_events=%s", - member_event.event_id, - member_event.auth_events, - ) filter_auth_events_on_event(member_event, auth_events) - logger.error("member_event after auth_events=%s", member_event.auth_events) # build and send an event authed based on the member event raw_auth_events = auth_events + [member_event] @@ -309,10 +301,7 @@ def filter_auth_events_on_event(event: EventBase, auth_events: List[EventBase]): }, room_version, ) - logger.error("message_event event_id=%s", message_event.event_id) - logger.error("message_event before auth_events=%s", message_event.auth_events) filter_auth_events_on_event(message_event, raw_auth_events.copy()) - logger.error("message_event after auth_events=%s", message_event.auth_events) # Stub the /event_auth response from the OTHER_SERVER async def get_event_auth(destination, room_id, event_id): From a94217ee34840237867d037cf1133f3a9bf6b95a Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 21 Jul 2021 04:34:51 -0500 Subject: [PATCH 09/14] Add changelog --- changelog.d/10439.bugfix | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/10439.bugfix diff --git a/changelog.d/10439.bugfix b/changelog.d/10439.bugfix new file mode 100644 index 000000000000..74e5a25126d9 --- /dev/null +++ b/changelog.d/10439.bugfix @@ -0,0 +1 @@ +Fix events with floating outlier state being rejected over federation. From b2e26b96eb51c17c5bbffcc8329d571f34e6d31f Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 21 Jul 2021 04:41:14 -0500 Subject: [PATCH 10/14] Remove unused mock --- tests/handlers/test_federation.py | 6 +----- 1 file changed, 1 insertion(+), 5 deletions(-) diff --git a/tests/handlers/test_federation.py b/tests/handlers/test_federation.py index cce7104136a8..e74fddd10f79 100644 --- a/tests/handlers/test_federation.py +++ b/tests/handlers/test_federation.py @@ -43,11 +43,7 @@ class FederationTestCase(unittest.HomeserverTestCase): ] def make_homeserver(self, reactor, clock): - # we mock out the federation client too - self.mock_federation_client = Mock() - hs = self.setup_test_homeserver( - federation_http_client=self.mock_federation_client - ) + hs = self.setup_test_homeserver(federation_http_client=None) self.handler = hs.get_federation_handler() self.store = hs.get_datastore() self.state_store = hs.get_storage().state From b0886f84dc3dafd548b45ee5edc9382428dba59d Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 21 Jul 2021 04:43:47 -0500 Subject: [PATCH 11/14] Run linters --- tests/handlers/test_federation.py | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/tests/handlers/test_federation.py b/tests/handlers/test_federation.py index e74fddd10f79..de8fe388b77b 100644 --- a/tests/handlers/test_federation.py +++ b/tests/handlers/test_federation.py @@ -12,12 +12,11 @@ # See the License for the specific language governing permissions and # limitations under the License. import logging +from typing import List from unittest import TestCase from unittest.mock import Mock + from twisted.internet import defer -from typing import ( - List, -) from synapse.api.constants import EventTypes from synapse.api.errors import AuthError, Codes, LimitExceededError, SynapseError From eb32018cb3d9e048fa4b3523a6fb29b1e2b36faf Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 21 Jul 2021 05:06:44 -0500 Subject: [PATCH 12/14] Fix lints --- tests/handlers/test_federation.py | 4 ---- 1 file changed, 4 deletions(-) diff --git a/tests/handlers/test_federation.py b/tests/handlers/test_federation.py index de8fe388b77b..eb608436604e 100644 --- a/tests/handlers/test_federation.py +++ b/tests/handlers/test_federation.py @@ -14,16 +14,12 @@ import logging from typing import List from unittest import TestCase -from unittest.mock import Mock - -from twisted.internet import defer from synapse.api.constants import EventTypes from synapse.api.errors import AuthError, Codes, LimitExceededError, SynapseError from synapse.api.room_versions import RoomVersions from synapse.events import EventBase from synapse.federation.federation_base import event_from_pdu_json -from synapse.federation.units import Transaction from synapse.logging.context import LoggingContext, run_in_background from synapse.rest import admin from synapse.rest.client.v1 import login, room From 16b113b7affe4dc4814a499bd8fb3b8e41c8dc87 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 28 Jul 2021 12:24:48 -0500 Subject: [PATCH 13/14] Create test events with an event builder --- tests/handlers/test_federation.py | 129 +++++++++++++++--------------- 1 file changed, 64 insertions(+), 65 deletions(-) diff --git a/tests/handlers/test_federation.py b/tests/handlers/test_federation.py index eb608436604e..9064a4bc3f2a 100644 --- a/tests/handlers/test_federation.py +++ b/tests/handlers/test_federation.py @@ -202,22 +202,6 @@ def test_backfill_floating_outlier_membership_auth(self): Regression test, see #10439. """ - - def filter_auth_events_on_event(event: EventBase, auth_events: List[EventBase]): - # Create a StateMap[str] - auth_event_state_map = { - (e.type, e.state_key): e.event_id for e in auth_events - } - # Actually strip down and use the necessary auth events - auth_event_ids = self._event_auth_handler.compute_auth_events( - event=event, - current_state_ids=auth_event_state_map, - for_verification=False, - ) - - # Replace the auth_events with the stripped down ones - event.auth_events = auth_event_ids - OTHER_SERVER = "otherserver" OTHER_USER = "@otheruser:" + OTHER_SERVER @@ -252,71 +236,86 @@ def filter_auth_events_on_event(event: EventBase, auth_events: List[EventBase]): # build a floating outlier member state event fake_prev_event_id = "$" + random_string(43) - member_event = event_from_pdu_json( - { - "type": EventTypes.Member, - "content": { - "membership": "join", - }, - "state_key": OTHER_USER, - "room_id": room_id, - "sender": OTHER_USER, - "depth": most_recent_prev_event_depth, - "prev_events": [fake_prev_event_id], - "auth_events": auth_event_ids.copy(), - "origin_server_ts": self.clock.time_msec(), - "signatures": { - OTHER_SERVER: {"ed25519:key_version": "SomeSignatureHere"} - }, + member_event_dict = { + "type": EventTypes.Member, + "content": { + "membership": "join", }, - room_version, - outlier=True, + "state_key": OTHER_USER, + "room_id": room_id, + "sender": OTHER_USER, + "depth": most_recent_prev_event_depth, + "prev_events": [fake_prev_event_id], + "origin_server_ts": self.clock.time_msec(), + "signatures": {OTHER_SERVER: {"ed25519:key_version": "SomeSignatureHere"}}, + } + builder = self.hs.get_event_builder_factory().for_room_version( + room_version, member_event_dict + ) + member_event = self.get_success( + builder.build( + prev_event_ids=member_event_dict["prev_events"], + auth_event_ids=self._event_auth_handler.compute_auth_events( + builder, + prev_state_map, + for_verification=False, + ), + depth=member_event_dict["depth"], + ) ) - filter_auth_events_on_event(member_event, auth_events) + # Override the signature added from "test" homeserver that we created the event with + member_event.signatures = member_event_dict["signatures"] + + # Add the new member_event to the StateMap + prev_state_map[ + (member_event.type, member_event.state_key) + ] = member_event.event_id + auth_events.append(member_event) # build and send an event authed based on the member event - raw_auth_events = auth_events + [member_event] - message_event = event_from_pdu_json( - { - "type": EventTypes.Message, - "content": {}, - "room_id": room_id, - "sender": OTHER_USER, - "depth": most_recent_prev_event_depth, - "prev_events": prev_event_ids.copy(), - "auth_events": [ev.event_id for ev in raw_auth_events], - "origin_server_ts": self.clock.time_msec(), - "signatures": { - OTHER_SERVER: {"ed25519:key_version": "SomeSignatureHere"} - }, - }, - room_version, + message_event_dict = { + "type": EventTypes.Message, + "content": {}, + "room_id": room_id, + "sender": OTHER_USER, + "depth": most_recent_prev_event_depth, + "prev_events": prev_event_ids.copy(), + "origin_server_ts": self.clock.time_msec(), + "signatures": {OTHER_SERVER: {"ed25519:key_version": "SomeSignatureHere"}}, + } + builder = self.hs.get_event_builder_factory().for_room_version( + room_version, message_event_dict ) - filter_auth_events_on_event(message_event, raw_auth_events.copy()) + message_event = self.get_success( + builder.build( + prev_event_ids=message_event_dict["prev_events"], + auth_event_ids=self._event_auth_handler.compute_auth_events( + builder, + prev_state_map, + for_verification=False, + ), + depth=message_event_dict["depth"], + ) + ) + # Override the signature added from "test" homeserver that we created the event with + message_event.signatures = message_event_dict["signatures"] # Stub the /event_auth response from the OTHER_SERVER - async def get_event_auth(destination, room_id, event_id): - return [ - auth_event - for auth_event in raw_auth_events - if auth_event.type is EventTypes.Create - or auth_event.type is EventTypes.PowerLevels - or auth_event.type is EventTypes.JoinRules - or ( - auth_event.type is EventTypes.Member - and auth_event.state_key == message_event.sender - ) - ] + async def get_event_auth( + destination: str, room_id: str, event_id: str + ) -> List[EventBase]: + return auth_events self.handler.federation_client.get_event_auth = get_event_auth with LoggingContext("receive_pdu"): + # Fake the OTHER_SERVER federating the message event over to our local homeserver d = run_in_background( self.handler.on_receive_pdu, OTHER_SERVER, message_event ) self.get_success(d) - # Try and get the events + # Now try and get the events on our local homeserver stored_event = self.get_success( self.store.get_event(message_event.event_id, allow_none=True) ) From a89a95fadb896d0d0550699ef56bd2393f67922e Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 28 Jul 2021 12:43:47 -0500 Subject: [PATCH 14/14] Clarify what the test is actually doing --- tests/handlers/test_federation.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/tests/handlers/test_federation.py b/tests/handlers/test_federation.py index 9064a4bc3f2a..4140fcefc2c4 100644 --- a/tests/handlers/test_federation.py +++ b/tests/handlers/test_federation.py @@ -196,9 +196,9 @@ def test_rejected_state_event_state(self): def test_backfill_floating_outlier_membership_auth(self): """ - As the remote federated homeserver, check that we can properly process - an event with auth_events that include a floating membership event from - the OTHER_SERVER. + As the local homeserver, check that we can properly process a federated + event from the OTHER_SERVER with auth_events that include a floating + membership event from the OTHER_SERVER. Regression test, see #10439. """