Debug logging

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.

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

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

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(

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

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(

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,