From d31ff534954469a4b79011854e8ce9ba093cfd94 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 10 Jan 2025 15:15:45 -0600 Subject: [PATCH] Debug logging --- scripts-dev/complement.sh | 18 +++++++++--------- synapse/event_auth.py | 6 ++++-- synapse/federation/federation_server.py | 5 ++++- synapse/handlers/federation.py | 3 +++ synapse/handlers/federation_event.py | 13 ++++++++++++- synapse/handlers/message.py | 6 +++++- synapse/notifier.py | 1 + 7 files changed, 38 insertions(+), 14 deletions(-) diff --git a/scripts-dev/complement.sh b/scripts-dev/complement.sh index 6be9177f110..8c4008b1306 100755 --- a/scripts-dev/complement.sh +++ b/scripts-dev/complement.sh @@ -220,15 +220,15 @@ extra_test_args=() test_packages=( ./tests/csapi - ./tests - ./tests/msc3874 - ./tests/msc3890 - ./tests/msc3391 - ./tests/msc3757 - ./tests/msc3930 - ./tests/msc3902 - ./tests/msc3967 - ./tests/msc4140 + # ./tests + # ./tests/msc3874 + # ./tests/msc3890 + # ./tests/msc3391 + # ./tests/msc3757 + # ./tests/msc3930 + # ./tests/msc3902 + # ./tests/msc3967 + # ./tests/msc4140 ) # Enable dirty runs, so tests will reuse the same container where possible. diff --git a/synapse/event_auth.py b/synapse/event_auth.py index c208b900c53..ea3b6a0e2e6 100644 --- a/synapse/event_auth.py +++ b/synapse/event_auth.py @@ -563,9 +563,10 @@ def _is_membership_change_allowed( invite_level = get_named_level(auth_events, "invite", 0) ban_level = get_named_level(auth_events, "ban", 50) - logger.debug( + logger.info( "_is_membership_change_allowed: %s", { + "caller_membership": caller.membership if caller else None, "caller_in_room": caller_in_room, "caller_invited": caller_invited, "caller_knocked": caller_knocked, @@ -677,7 +678,8 @@ def _is_membership_change_allowed( and join_rule == JoinRules.KNOCK_RESTRICTED ) ): - if not caller_in_room and not caller_invited: + # You can only join the room if you are invited or are already in the room. + if not (caller_in_room or caller_invited): raise AuthError(403, "You are not invited to this room.") else: # TODO (erikj): may_join list diff --git a/synapse/federation/federation_server.py b/synapse/federation/federation_server.py index 1932fa82a4a..ec34e282d65 100644 --- a/synapse/federation/federation_server.py +++ b/synapse/federation/federation_server.py @@ -1256,7 +1256,7 @@ async def _process_incoming_pdus_in_room_inner( # has started processing). while True: async with lock: - logger.info("handling received PDU in room %s: %s", room_id, event) + logger.info("📬 handling received PDU in room %s: %s", room_id, event) try: with nested_logging_context(event.event_id): # We're taking out a lock within a lock, which could @@ -1271,6 +1271,9 @@ async def _process_incoming_pdus_in_room_inner( await self._federation_event_handler.on_receive_pdu( origin, event ) + logger.info( + "✅ handled received PDU in room %s: %s", room_id, event + ) except FederationError as e: # XXX: Ideally we'd inform the remote we failed to process # the event, but we can't return an error in the transaction diff --git a/synapse/handlers/federation.py b/synapse/handlers/federation.py index 17dd4af13ed..4ee6f19c8bd 100644 --- a/synapse/handlers/federation.py +++ b/synapse/handlers/federation.py @@ -1051,6 +1051,8 @@ async def on_invite_request( Respond with the now signed event. """ + logger.info("🗳️ on_invite_request: handling event %s", event) + if event.state_key is None: raise SynapseError(400, "The invite event did not have a state key") @@ -1127,6 +1129,7 @@ async def on_invite_request( await self.store.remove_push_actions_from_staging(event.event_id) raise + logger.info("✅ on_invite_request: handled event %s", event) return event async def do_remotely_reject_invite( diff --git a/synapse/handlers/federation_event.py b/synapse/handlers/federation_event.py index c85deaed562..d0ef43a753c 100644 --- a/synapse/handlers/federation_event.py +++ b/synapse/handlers/federation_event.py @@ -382,6 +382,10 @@ async def on_send_membership_event( event.event_id, event.signatures, ) + # logger.info( + # "📮 on_send_membership_event: received event: %s", + # event, + # ) if get_domain_from_id(event.sender) != origin: logger.info( @@ -436,6 +440,10 @@ async def on_send_membership_event( await self._check_for_soft_fail(event, context=context, origin=origin) await self._run_push_actions_and_persist_event(event, context) + # logger.info( + # "✅ on_send_membership_event: handled event: %s", + # event, + # ) return event, context async def check_join_restrictions( @@ -2274,7 +2282,8 @@ async def persist_events_and_notify( # After persistence we always need to notify replication there may # be new data. - self._notifier.notify_replication() + # XXX: This already happens in `_notify_persisted_event` -> `on_new_room_events` -> `notify_new_room_events` -> `notify_replication` + # self._notifier.notify_replication() if self._ephemeral_messages_enabled: for event in events: @@ -2292,6 +2301,8 @@ async def persist_events_and_notify( str(len(events)), ) for event in events: + # TODO: Is this correct? + # if not event.internal_metadata.is_outlier(): await self._notify_persisted_event(event, max_stream_token) return max_stream_token.stream diff --git a/synapse/handlers/message.py b/synapse/handlers/message.py index df3010ecf68..99766b3f23d 100644 --- a/synapse/handlers/message.py +++ b/synapse/handlers/message.py @@ -1415,6 +1415,9 @@ async def handle_new_client_event( PartialStateConflictError if attempting to persist a partial state event in a room that has been un-partial stated. """ + for event, _ in events_and_context: + logger.info("📮 handle_new_client_event: handling %s", event) + extra_users = extra_users or [] for event, context in events_and_context: @@ -1460,7 +1463,7 @@ async def handle_new_client_event( event, batched_auth_events ) except AuthError as err: - logger.warning("Denying new event %r because %s", event, err) + logger.warning("❌ Denying new event %r because %s", event, err) raise err # Ensure that we can round trip before trying to persist in db @@ -1492,6 +1495,7 @@ async def handle_new_client_event( gather_results(deferreds, consumeErrors=True) ).addErrback(unwrapFirstError) + logger.info("✅ handle_new_client_event: handled %s", event) return result async def _persist_events( diff --git a/synapse/notifier.py b/synapse/notifier.py index 88f531182a0..b129bf49528 100644 --- a/synapse/notifier.py +++ b/synapse/notifier.py @@ -308,6 +308,7 @@ async def on_new_room_events( notify_new_room_events with the results.""" event_entries = [] for event, pos in events_and_pos: + logger.info("📨 Notifying about new event %s", event, exc_info=True) entry = self.create_pending_room_event_entry( pos, extra_users,