diff --git a/changelog.d/14213.misc b/changelog.d/14213.misc
new file mode 100644
index 0000000000..b0689f3d15
--- /dev/null
+++ b/changelog.d/14213.misc
@@ -0,0 +1 @@
+Log when events are (maybe unexpectedly) filtered out of responses in tests.
diff --git a/docker/README.md b/docker/README.md
index eda3221c23..08372e95c6 100644
--- a/docker/README.md
+++ b/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
diff --git a/docker/conf/log.config b/docker/conf/log.config
index 90b5179838..5772321202 100644
--- a/docker/conf/log.config
+++ b/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" }}
diff --git a/docker/configure_workers_and_start.py b/docker/configure_workers_and_start.py
index 79b5b87397..87a740e3d4 100755
--- a/docker/configure_workers_and_start.py
+++ b/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"
diff --git a/scripts-dev/complement.sh b/scripts-dev/complement.sh
index cba2799f15..131f26234e 100755
--- a/scripts-dev/complement.sh
+++ b/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"
diff --git a/synapse/visibility.py b/synapse/visibility.py
index 468e22f8f6..fc71dc92a4 100644
--- a/synapse/visibility.py
+++ b/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):
- logger.debug(
+ if filtered_event_logger.isEnabledFor(logging.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,
)
diff --git a/tests/test_utils/logging_setup.py b/tests/test_utils/logging_setup.py
index c37f205ed0..199bb06a81 100644
--- a/tests/test_utils/logging_setup.py
+++ b/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()
|
