Log when events are (unexpectedly) filtered out of responses in tests (#14213)

See https://github.com/matrix-org/synapse/pull/14095#discussion_r990335492

This is useful because when see that a relevant event is an `outlier` or `soft-failed`, then that's a good unexpected indicator explaining why it's not showing up. `filter_events_for_client` is used in `/sync`, `/messages`, `/context` which are all common end-to-end assertion touch points (also notifications, relations).

changelog.d/14213.misc

@@ -0,0 +1 @@
+Log when events are (maybe unexpectedly) filtered out of responses in tests.

docker/README.md

@@ -73,7 +73,8 @@ The following environment variables are supported in `generate` mode:
   will log sensitive information such as access tokens.
   This should not be needed unless you are a developer attempting to debug something
   particularly tricky.
-
+* `SYNAPSE_LOG_TESTING`: if set, Synapse will log additional information useful
+  for testing.
 
 ## Postgres
 

docker/conf/log.config

@@ -49,17 +49,35 @@ handlers:
     class: logging.StreamHandler
     formatter: precise
 
-{% if not SYNAPSE_LOG_SENSITIVE %}
-{#
-  If SYNAPSE_LOG_SENSITIVE is unset, then override synapse.storage.SQL to INFO
-  so that DEBUG entries (containing sensitive information) are not emitted.
-#}
 loggers:
+    # This is just here so we can leave `loggers` in the config regardless of whether
+    # we configure other loggers below (avoid empty yaml dict error).
+    _placeholder:
+        level: "INFO"
+
+    {% if not SYNAPSE_LOG_SENSITIVE %}
+    {#
+      If SYNAPSE_LOG_SENSITIVE is unset, then override synapse.storage.SQL to INFO
+      so that DEBUG entries (containing sensitive information) are not emitted.
+    #}
     synapse.storage.SQL:
         # beware: increasing this to DEBUG will make synapse log sensitive
         # information such as access tokens.
         level: INFO
-{% endif %}
+    {% endif %}
+
+    {% if SYNAPSE_LOG_TESTING %}
+    {#
+      If Synapse is under test, log a few more useful things for a developer
+      attempting to debug something particularly tricky.
+
+      With `synapse.visibility.filtered_event_debug`, it logs when events are (maybe
+      unexpectedly) filtered out of responses in tests. It's just nice to be able to
+      look at the CI log and figure out why an event isn't being returned.
+    #}
+    synapse.visibility.filtered_event_debug:
+        level: DEBUG
+    {% endif %}
 
 root:
     level: {{ SYNAPSE_LOG_LEVEL or "INFO" }}

docker/configure_workers_and_start.py

@@ -40,6 +40,8 @@
 #         log level. INFO is the default.
 #   * SYNAPSE_LOG_SENSITIVE: If unset, SQL and SQL values won't be logged,
 #         regardless of the SYNAPSE_LOG_LEVEL setting.
+#   * SYNAPSE_LOG_TESTING: if set, Synapse will log additional information useful
+#     for testing.
 #
 # NOTE: According to Complement's ENTRYPOINT expectations for a homeserver image (as defined
 # in the project's README), this script may be run multiple times, and functionality should
@@ -947,6 +949,7 @@ def generate_worker_log_config(
     extra_log_template_args["SYNAPSE_LOG_SENSITIVE"] = environ.get(
         "SYNAPSE_LOG_SENSITIVE"
     )
+    extra_log_template_args["SYNAPSE_LOG_TESTING"] = environ.get("SYNAPSE_LOG_TESTING")
 
     # Render and write the file
     log_config_filepath = f"/conf/workers/{worker_name}.log.config"

scripts-dev/complement.sh

@@ -269,6 +269,10 @@ if [[ -n "$SYNAPSE_TEST_LOG_LEVEL" ]]; then
   export PASS_SYNAPSE_LOG_SENSITIVE=1
 fi
 
+# Log a few more useful things for a developer attempting to debug something
+# particularly tricky.
+export PASS_SYNAPSE_LOG_TESTING=1
+
 # Run the tests!
 echo "Images built; running complement"
 cd "$COMPLEMENT_DIR"

synapse/visibility.py

@@ -41,7 +41,7 @@ from synapse.types.state import StateFilter
 from synapse.util import Clock
 
 logger = logging.getLogger(__name__)
-
+filtered_event_logger = logging.getLogger("synapse.visibility.filtered_event_debug")
 
 VISIBILITY_PRIORITY = (
     HistoryVisibility.WORLD_READABLE,
@@ -97,8 +97,8 @@ async def filter_events_for_client(
     events_before_filtering = events
     events = [e for e in events if not e.internal_metadata.is_soft_failed()]
     if len(events_before_filtering) != len(events):
-        if logger.isEnabledFor(logging.DEBUG):
+        if filtered_event_logger.isEnabledFor(logging.DEBUG):
-            logger.debug(
+            filtered_event_logger.debug(
                 "filter_events_for_client: Filtered out soft-failed events: Before=%s, After=%s",
                 [event.event_id for event in events_before_filtering],
                 [event.event_id for event in events],
@@ -319,7 +319,7 @@ def _check_client_allowed_to_see_event(
             _check_filter_send_to_client(event, clock, retention_policy, sender_ignored)
             == _CheckFilter.DENIED
         ):
-            logger.debug(
+            filtered_event_logger.debug(
                 "_check_client_allowed_to_see_event(event=%s): Filtered out event because `_check_filter_send_to_client` returned `_CheckFilter.DENIED`",
                 event.event_id,
             )
@@ -341,7 +341,7 @@ def _check_client_allowed_to_see_event(
             )
             return event
 
-        logger.debug(
+        filtered_event_logger.debug(
             "_check_client_allowed_to_see_event(event=%s): Filtered out event because it's an outlier",
             event.event_id,
         )
@@ -367,7 +367,7 @@ def _check_client_allowed_to_see_event(
 
     membership_result = _check_membership(user_id, event, visibility, state, is_peeking)
     if not membership_result.allowed:
-        logger.debug(
+        filtered_event_logger.debug(
             "_check_client_allowed_to_see_event(event=%s): Filtered out event because the user can't see the event because of their membership, membership_result.allowed=%s membership_result.joined=%s",
             event.event_id,
             membership_result.allowed,
@@ -378,7 +378,7 @@ def _check_client_allowed_to_see_event(
     # If the sender has been erased and the user was not joined at the time, we
     # must only return the redacted form.
     if sender_erased and not membership_result.joined:
-        logger.debug(
+        filtered_event_logger.debug(
             "_check_client_allowed_to_see_event(event=%s): Returning pruned event because `sender_erased` and the user was not joined at the time",
             event.event_id,
         )

tests/test_utils/logging_setup.py

@@ -53,4 +53,16 @@ def setup_logging() -> None:
     log_level = os.environ.get("SYNAPSE_TEST_LOG_LEVEL", "ERROR")
     root_logger.setLevel(log_level)
 
+    # In order to not add noise by default (since we only log ERROR messages for trial
+    # tests as configured above), we only enable this for developers for looking for
+    # more INFO or DEBUG.
+    if root_logger.isEnabledFor(logging.INFO):
+        # Log when events are (maybe unexpectedly) filtered out of responses in tests. It's
+        # just nice to be able to look at the CI log and figure out why an event isn't being
+        # returned.
+        logging.getLogger("synapse.visibility.filtered_event_debug").setLevel(
+            logging.DEBUG
+        )
+
+    # Blow away the pyo3-log cache so that it reloads the configuration.
     reset_logging_config()