From c6aec967132ac96fccaa762f99c89f95eac2ccf7 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Mon, 17 Oct 2022 16:10:52 -0500 Subject: [PATCH 1/6] Log when events are filtered out of responses in tests See https://github.com/matrix-org/synapse/pull/14095#discussion_r990335492 --- synapse/visibility.py | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/synapse/visibility.py b/synapse/visibility.py index 40a9c5b53f83..d212661400b6 100644 --- a/synapse/visibility.py +++ b/synapse/visibility.py @@ -31,7 +31,7 @@ from synapse.util import Clock logger = logging.getLogger(__name__) - +filtered_event_logger = logging.getLogger("synapse.visibility.filtered_event_debug") VISIBILITY_PRIORITY = ( HistoryVisibility.WORLD_READABLE, @@ -87,8 +87,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], @@ -309,7 +309,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, ) @@ -331,7 +331,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, ) @@ -357,7 +357,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, @@ -368,7 +368,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, ) From aa64946326f36613475e6eee7d2e62fb9829d348 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 19 May 2023 19:52:51 -0500 Subject: [PATCH 2/6] Log in trial tests --- tests/test_utils/logging_setup.py | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/tests/test_utils/logging_setup.py b/tests/test_utils/logging_setup.py index b522163a3444..a96f1d8601de 100644 --- a/tests/test_utils/logging_setup.py +++ b/tests/test_utils/logging_setup.py @@ -54,4 +54,10 @@ def setup_logging() -> None: log_level = os.environ.get("SYNAPSE_TEST_LOG_LEVEL", "ERROR") root_logger.setLevel(log_level) + # 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() From 7168a2623897a9bd4915be550efc4edb80a8f646 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 19 May 2023 20:02:11 -0500 Subject: [PATCH 3/6] Log in complement --- docker/README.md | 3 ++- docker/conf/log.config | 30 ++++++++++++++++++++++++------ scripts-dev/complement.sh | 4 ++++ 3 files changed, 30 insertions(+), 7 deletions(-) diff --git a/docker/README.md b/docker/README.md index eda3221c2339..08372e95c647 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 90b5179838ca..577232120204 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/scripts-dev/complement.sh b/scripts-dev/complement.sh index cba2799f1589..40b38cc98490 100755 --- a/scripts-dev/complement.sh +++ b/scripts-dev/complement.sh @@ -267,6 +267,10 @@ if [[ -n "$SYNAPSE_TEST_LOG_LEVEL" ]]; then # Since this is just a test suite, this is fine and won't reveal anyone's # personal information export PASS_SYNAPSE_LOG_SENSITIVE=1 + + # Log a few more useful things for a developer attempting to debug something + # particularly tricky. + export PASS_SYNAPSE_TEST_LOG_LEVEL=1 fi # Run the tests! From bdd8f83ce683f7e81ae9b8d8f4f1f0e489838d82 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 19 May 2023 20:15:13 -0500 Subject: [PATCH 4/6] Add changelog --- changelog.d/14213.misc | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/14213.misc diff --git a/changelog.d/14213.misc b/changelog.d/14213.misc new file mode 100644 index 000000000000..b0689f3d1574 --- /dev/null +++ b/changelog.d/14213.misc @@ -0,0 +1 @@ +Log when events are (maybe unexpectedly) filtered out of responses in tests. From 0e0cefbcfb83d189cb192b9e13dc0ada15d0257d Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 19 May 2023 23:04:21 -0500 Subject: [PATCH 5/6] Fix logs in complement --- docker/configure_workers_and_start.py | 3 +++ scripts-dev/complement.sh | 8 ++++---- 2 files changed, 7 insertions(+), 4 deletions(-) diff --git a/docker/configure_workers_and_start.py b/docker/configure_workers_and_start.py index 79b5b8739764..87a740e3d433 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 40b38cc98490..131f26234ece 100755 --- a/scripts-dev/complement.sh +++ b/scripts-dev/complement.sh @@ -267,12 +267,12 @@ if [[ -n "$SYNAPSE_TEST_LOG_LEVEL" ]]; then # Since this is just a test suite, this is fine and won't reveal anyone's # personal information export PASS_SYNAPSE_LOG_SENSITIVE=1 - - # Log a few more useful things for a developer attempting to debug something - # particularly tricky. - export PASS_SYNAPSE_TEST_LOG_LEVEL=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" From 3f37966cab2c6fccd2bd3779edf9248538b0fc3c Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Thu, 1 Jun 2023 17:53:03 -0500 Subject: [PATCH 6/6] Only enable extra logs for developers looking for more INFO See https://github.com/matrix-org/synapse/pull/14213#discussion_r1210664455 --- tests/test_utils/logging_setup.py | 14 ++++++++++---- 1 file changed, 10 insertions(+), 4 deletions(-) diff --git a/tests/test_utils/logging_setup.py b/tests/test_utils/logging_setup.py index 6387373cb537..199bb06a81a8 100644 --- a/tests/test_utils/logging_setup.py +++ b/tests/test_utils/logging_setup.py @@ -53,10 +53,16 @@ def setup_logging() -> None: log_level = os.environ.get("SYNAPSE_TEST_LOG_LEVEL", "ERROR") root_logger.setLevel(log_level) - # 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) + # 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()