From 30a5076da8ad776c150ad2745b5f34b4446012e0 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Thu, 1 Jun 2023 21:27:18 -0500 Subject: 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). --- docker/README.md | 3 ++- docker/conf/log.config | 30 ++++++++++++++++++++++++------ docker/configure_workers_and_start.py | 3 +++ 3 files changed, 29 insertions(+), 7 deletions(-) (limited to 'docker') 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" -- cgit 1.4.1