From 715f779471acce1ca138737810fba0e5cc19d678 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 22 Apr 2020 21:16:20 +0100 Subject: [PATCH 1/6] add some debug to help debug racy test --- synapse/handlers/message.py | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/synapse/handlers/message.py b/synapse/handlers/message.py index 522271eed1..d73eef24f7 100644 --- a/synapse/handlers/message.py +++ b/synapse/handlers/message.py @@ -104,8 +104,18 @@ class MessageHandler(object): ) if membership == Membership.JOIN: + logger.info( + "Fetching current state %s/%s/%s", room_id, event_type, state_key + ) data = yield self.state.get_current_state(room_id, event_type, state_key) elif membership == Membership.LEAVE: + logger.info( + "Fetching historical state %s/%s/%s at %s", + room_id, + event_type, + state_key, + membership_event_id, + ) key = (event_type, state_key) room_state = yield self.state_store.get_state_for_events( [membership_event_id], StateFilter.from_types([key]) From 546ff51c9fc896491c159886c38bd43beea10835 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 22 Apr 2020 21:26:32 +0100 Subject: [PATCH 2/6] dummy newsfile --- changelog.d/1.test | 0 1 file changed, 0 insertions(+), 0 deletions(-) create mode 100644 changelog.d/1.test diff --git a/changelog.d/1.test b/changelog.d/1.test new file mode 100644 index 0000000000..e69de29bb2 From 873c5e6fe38ac6884ebcefb446357b2872f981d8 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 22 Apr 2020 21:34:55 +0100 Subject: [PATCH 3/6] Fix up newsfile --- changelog.d/{1.test => 1.misc} | 0 1 file changed, 0 insertions(+), 0 deletions(-) rename changelog.d/{1.test => 1.misc} (100%) diff --git a/changelog.d/1.test b/changelog.d/1.misc similarity index 100% rename from changelog.d/1.test rename to changelog.d/1.misc From 3930a96763be797d9f96328843cbe7a18064f7b7 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 22 Apr 2020 23:00:33 +0100 Subject: [PATCH 4/6] more testing for flaky test --- synapse/state/__init__.py | 1 + synapse/storage/data_stores/main/events.py | 8 +++++++- 2 files changed, 8 insertions(+), 1 deletion(-) diff --git a/synapse/state/__init__.py b/synapse/state/__init__.py index 4afefc6b1d..61fb379f01 100644 --- a/synapse/state/__init__.py +++ b/synapse/state/__init__.py @@ -131,6 +131,7 @@ class StateHandler(object): if not latest_event_ids: latest_event_ids = yield self.store.get_latest_event_ids_in_room(room_id) + logger.info("latest events in %s: %s", room_id, latest_event_ids) logger.debug("calling resolve_state_groups from get_current_state") ret = yield self.resolve_state_groups_for_events(room_id, latest_event_ids) state = ret.state diff --git a/synapse/storage/data_stores/main/events.py b/synapse/storage/data_stores/main/events.py index e71c23541d..a3ad22a56c 100644 --- a/synapse/storage/data_stores/main/events.py +++ b/synapse/storage/data_stores/main/events.py @@ -647,7 +647,12 @@ class EventsStore( self.db.simple_delete_txn( txn, table="event_forward_extremities", keyvalues={"room_id": room_id} ) - txn.call_after(self.get_latest_event_ids_in_room.invalidate, (room_id,)) + + def inv(*args): + logger.info("Invalidating get_latest_event_ids: %r", *args) + self.get_latest_event_ids_in_room.invalidate(*args) + + txn.call_after(inv, (room_id,)) self.db.simple_insert_many_txn( txn, @@ -658,6 +663,7 @@ class EventsStore( for ev_id in new_extrem ], ) + logger.info("new forward extremities: %s", new_forward_extremities) # We now insert into stream_ordering_to_exterm a mapping from room_id, # new stream_ordering to new forward extremeties in the room. # This allows us to later efficiently look up the forward extremeties From 79962da389bd8c95095f6f4b5915ca35d09588e2 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 22 Apr 2020 23:21:22 +0100 Subject: [PATCH 5/6] even more debugging. Perhaps the issue is in the join event? --- synapse/handlers/message.py | 2 ++ synapse/state/__init__.py | 4 ++++ 2 files changed, 6 insertions(+) diff --git a/synapse/handlers/message.py b/synapse/handlers/message.py index d73eef24f7..9e43c2b553 100644 --- a/synapse/handlers/message.py +++ b/synapse/handlers/message.py @@ -495,12 +495,14 @@ class EventCreationHandler(object): try: if "displayname" not in content: content["displayname"] = yield profile.get_displayname(target) + logger.info("Adding displayname to membership event") if "avatar_url" not in content: content["avatar_url"] = yield profile.get_avatar_url(target) except Exception as e: logger.info( "Failed to get profile information for %r: %s", target, e ) + logger.info("Membership event content: %s", content) is_exempt = yield self._is_exempt_from_privacy_policy(builder, requester) if require_consent and not is_exempt: diff --git a/synapse/state/__init__.py b/synapse/state/__init__.py index 61fb379f01..13ac6307db 100644 --- a/synapse/state/__init__.py +++ b/synapse/state/__init__.py @@ -136,6 +136,8 @@ class StateHandler(object): ret = yield self.resolve_state_groups_for_events(room_id, latest_event_ids) state = ret.state + logger.info("state at %s: %s", latest_event_ids, state) + if event_type: event_id = state.get((event_type, state_key)) event = None @@ -381,6 +383,8 @@ class StateHandler(object): room_id, event_ids ) + logger.info("state groups at %s: %s", event_ids, state_groups_ids) + if len(state_groups_ids) == 0: return _StateCacheEntry(state={}, state_group=None) elif len(state_groups_ids) == 1: From 92d9cf5457d86d11df7ec81906f178a8a2072ce2 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 22 Apr 2020 23:34:52 +0100 Subject: [PATCH 6/6] remove somewhat spurious debug --- synapse/handlers/message.py | 12 ------------ 1 file changed, 12 deletions(-) diff --git a/synapse/handlers/message.py b/synapse/handlers/message.py index 9e43c2b553..522271eed1 100644 --- a/synapse/handlers/message.py +++ b/synapse/handlers/message.py @@ -104,18 +104,8 @@ class MessageHandler(object): ) if membership == Membership.JOIN: - logger.info( - "Fetching current state %s/%s/%s", room_id, event_type, state_key - ) data = yield self.state.get_current_state(room_id, event_type, state_key) elif membership == Membership.LEAVE: - logger.info( - "Fetching historical state %s/%s/%s at %s", - room_id, - event_type, - state_key, - membership_event_id, - ) key = (event_type, state_key) room_state = yield self.state_store.get_state_for_events( [membership_event_id], StateFilter.from_types([key]) @@ -495,14 +485,12 @@ class EventCreationHandler(object): try: if "displayname" not in content: content["displayname"] = yield profile.get_displayname(target) - logger.info("Adding displayname to membership event") if "avatar_url" not in content: content["avatar_url"] = yield profile.get_avatar_url(target) except Exception as e: logger.info( "Failed to get profile information for %r: %s", target, e ) - logger.info("Membership event content: %s", content) is_exempt = yield self._is_exempt_from_privacy_policy(builder, requester) if require_consent and not is_exempt: