From 4be4ea06adb0840977b7d319d1df2af990359717 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 23 May 2025 15:59:55 -0500 Subject: [PATCH 01/21] Add debug log when `HMAC incorrect` --- synapse/rest/admin/users.py | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/synapse/rest/admin/users.py b/synapse/rest/admin/users.py index 7b8f1d1b2a9..f18cca49366 100644 --- a/synapse/rest/admin/users.py +++ b/synapse/rest/admin/users.py @@ -59,6 +59,14 @@ logger = logging.getLogger(__name__) +user_registration_debug_logger = logging.getLogger( + "synapse.rest.admin.users.registration_debug" +) +""" +A logger for debugging the user registration process. This is separate from the main +logger as it logs sensitive information such as passwords and `registration_shared_secret`. +""" + class UsersRestServletV2(RestServlet): PATTERNS = admin_patterns("/users$", "v2") @@ -633,6 +641,13 @@ async def on_POST(self, request: SynapseRequest) -> Tuple[int, JsonDict]: want_mac = want_mac_builder.hexdigest() if not hmac.compare_digest(want_mac.encode("ascii"), got_mac.encode("ascii")): + user_registration_debug_logger.debug( + "UserRegisterServlet: Incorrect HMAC digest: actual=%s, expected=%s, registration_shared_secret=%s, body=%s", + want_mac, + got_mac, + self.hs.config.registration.registration_shared_secret, + body, + ) raise SynapseError(HTTPStatus.FORBIDDEN, "HMAC incorrect") should_issue_refresh_token = body.get("refresh_token", False) From 7feedb9fd7383835b14656211306350a1c04d80f Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 23 May 2025 16:16:49 -0500 Subject: [PATCH 02/21] Fix order --- synapse/rest/admin/users.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/synapse/rest/admin/users.py b/synapse/rest/admin/users.py index f18cca49366..c9b3981c978 100644 --- a/synapse/rest/admin/users.py +++ b/synapse/rest/admin/users.py @@ -640,11 +640,13 @@ async def on_POST(self, request: SynapseRequest) -> Tuple[int, JsonDict]: want_mac = want_mac_builder.hexdigest() + user_registration_debug_logger.debug("asdf") + if not hmac.compare_digest(want_mac.encode("ascii"), got_mac.encode("ascii")): user_registration_debug_logger.debug( "UserRegisterServlet: Incorrect HMAC digest: actual=%s, expected=%s, registration_shared_secret=%s, body=%s", - want_mac, got_mac, + want_mac, self.hs.config.registration.registration_shared_secret, body, ) From 944800d4e2ca0a922dc45032a6c638b0f62ed24a Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 23 May 2025 16:19:06 -0500 Subject: [PATCH 03/21] Remove extra testing log --- synapse/rest/admin/users.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/synapse/rest/admin/users.py b/synapse/rest/admin/users.py index c9b3981c978..d7906c1af44 100644 --- a/synapse/rest/admin/users.py +++ b/synapse/rest/admin/users.py @@ -640,8 +640,6 @@ async def on_POST(self, request: SynapseRequest) -> Tuple[int, JsonDict]: want_mac = want_mac_builder.hexdigest() - user_registration_debug_logger.debug("asdf") - if not hmac.compare_digest(want_mac.encode("ascii"), got_mac.encode("ascii")): user_registration_debug_logger.debug( "UserRegisterServlet: Incorrect HMAC digest: actual=%s, expected=%s, registration_shared_secret=%s, body=%s", From 8e45c6fe5f2e74e093b3511924a90062760ec13e Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 23 May 2025 16:49:55 -0500 Subject: [PATCH 04/21] Add changelog --- changelog.d/18474.misc | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/18474.misc diff --git a/changelog.d/18474.misc b/changelog.d/18474.misc new file mode 100644 index 00000000000..b5897e13608 --- /dev/null +++ b/changelog.d/18474.misc @@ -0,0 +1 @@ +Add debug logging for HMAC digest verification failures when using the admin API to register users. From 95a084e6975a1017a8c9fa6346736674c835cb79 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 23 May 2025 17:24:04 -0500 Subject: [PATCH 05/21] Add to sensitive part of logging template for Docker --- docker/conf/log.config | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/docker/conf/log.config b/docker/conf/log.config index 57723212020..bf632a93e3f 100644 --- a/docker/conf/log.config +++ b/docker/conf/log.config @@ -64,6 +64,10 @@ loggers: # beware: increasing this to DEBUG will make synapse log sensitive # information such as access tokens. level: INFO + synapse.rest.admin.users.registration_debug: + # beware: increasing this to DEBUG will make synapse log sensitive + # information such as passwords and `registration_shared_secret`. + level: INFO {% endif %} {% if SYNAPSE_LOG_TESTING %} From e07910486a447ee3f5f9c294da9a0ef9dcfa2e9e Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 23 May 2025 17:31:04 -0500 Subject: [PATCH 06/21] Document dangers of `DEBUG` level logging --- docs/usage/configuration/logging_sample_config.md | 3 +++ 1 file changed, 3 insertions(+) diff --git a/docs/usage/configuration/logging_sample_config.md b/docs/usage/configuration/logging_sample_config.md index 23a55abdccd..2712dff44e9 100644 --- a/docs/usage/configuration/logging_sample_config.md +++ b/docs/usage/configuration/logging_sample_config.md @@ -14,6 +14,9 @@ It should be named `.log.config` by default. Hint: If you're looking for a guide on what each of the fields in the "Processed request" log lines mean, see [Request log format](../administration/request_log.md). +Warn: Logging at the `DEBUG` level is very verbose and will include sensitive +information such as access tokens, passwords, and secrets. + ```yaml {{#include ../../sample_log_config.yaml}} ``` From 1aac00fc62be6f56eda57d206d42e48a09408025 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 6 Jun 2025 16:58:32 -0500 Subject: [PATCH 07/21] Not fully working correctly: `ExplicitlyConfiguredLogger` via filters --- synapse/rest/admin/users.py | 46 +++++++++++++++++++++++++++++++++++-- 1 file changed, 44 insertions(+), 2 deletions(-) diff --git a/synapse/rest/admin/users.py b/synapse/rest/admin/users.py index 5a0e30debc9..409c6e90c35 100644 --- a/synapse/rest/admin/users.py +++ b/synapse/rest/admin/users.py @@ -59,12 +59,51 @@ logger = logging.getLogger(__name__) -user_registration_debug_logger = logging.getLogger( + +class ExplicitlyConfiguredLogger(logging.Logger): + """ + A custom logger class that only allows logging if the logger is explicitly + configured (does not inherit log level from parent). + """ + + def __init__(self, name, level=logging.NOTSET): + super().__init__(name, level) + + self.addFilter(self._filter) + + def _filter(self, record: logging.LogRecord) -> bool: + """ + Only allow logging if the logger is explicitly configured. + """ + # Check if the logger is explicitly configured + explicitly_configured_logger = self.manager.loggerDict.get(self.name) + + log_level = logging.NOTSET + if isinstance(explicitly_configured_logger, logging.Logger): + log_level = explicitly_configured_logger.level + + print( + "asdf log_level=%s record_level=%s -> %s", + log_level, + record.levelno, + record.levelno >= log_level, + ) + + # If the logger is not configured, we don't log anything + if log_level == logging.NOTSET: + return False + + # Otherwise, follow the normal logging behavior + return record.levelno >= log_level + + +user_registration_debug_logger = ExplicitlyConfiguredLogger( "synapse.rest.admin.users.registration_debug" ) """ A logger for debugging the user registration process. This is separate from the main -logger as it logs sensitive information such as passwords and `registration_shared_secret`. +logger as it logs sensitive information such as passwords and +`registration_shared_secret`. """ @@ -99,6 +138,9 @@ def __init__(self, hs: "HomeServer"): self._msc3866_enabled = hs.config.experimental.msc3866.enabled self._msc3861_enabled = hs.config.experimental.msc3861.enabled + user_registration_debug_logger.warning("asdf warn test") + user_registration_debug_logger.debug("asdf debug test") + async def on_GET(self, request: SynapseRequest) -> Tuple[int, JsonDict]: await assert_requester_is_admin(self.auth, request) From 7e5ef26d0f473a36c50f14e4ac39cf13ca717dce Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 6 Jun 2025 17:31:27 -0500 Subject: [PATCH 08/21] Working `ExplicitlyConfiguredLogger` but not a great setup experience --- synapse/logging/filter.py | 2 ++ synapse/logging/loggers.py | 40 +++++++++++++++++++++++++++++ synapse/rest/admin/users.py | 51 +++++++++---------------------------- 3 files changed, 54 insertions(+), 39 deletions(-) create mode 100644 synapse/logging/loggers.py diff --git a/synapse/logging/filter.py b/synapse/logging/filter.py index 16de488dbca..7dd046d571b 100644 --- a/synapse/logging/filter.py +++ b/synapse/logging/filter.py @@ -21,6 +21,8 @@ import logging from typing import Literal +root_logger = logging.getLogger() + class MetadataFilter(logging.Filter): """Logging filter that adds constant values to each record. diff --git a/synapse/logging/loggers.py b/synapse/logging/loggers.py new file mode 100644 index 00000000000..8e1cbfd6773 --- /dev/null +++ b/synapse/logging/loggers.py @@ -0,0 +1,40 @@ +import logging + +root_logger = logging.getLogger() + + +class ExplicitlyConfiguredLogger(logging.Logger): + """ + A custom logger class that only allows logging if the logger is explicitly + configured (does not inherit log level from parent). + """ + + def __init__(self, name: str, level: int = logging.NOTSET) -> None: + super().__init__(name, level) + + self.addFilter(self._filter) + + def _filter(self, record: logging.LogRecord) -> bool: + """ + Only allow logging if the logger is explicitly configured. + """ + # Check if the logger is explicitly configured + explicitly_configured_logger = self.manager.loggerDict.get(self.name) + + log_level = logging.NOTSET + if isinstance(explicitly_configured_logger, logging.Logger): + log_level = explicitly_configured_logger.level + + print( + "asdf log_level=%s record_level=%s -> %s", + log_level, + record.levelno, + record.levelno >= log_level, + ) + + # If the logger is not configured, we don't log anything + if log_level == logging.NOTSET: + return False + + # Otherwise, follow the normal logging behavior + return record.levelno >= log_level diff --git a/synapse/rest/admin/users.py b/synapse/rest/admin/users.py index 409c6e90c35..60b6de55665 100644 --- a/synapse/rest/admin/users.py +++ b/synapse/rest/admin/users.py @@ -52,6 +52,7 @@ from synapse.storage.databases.main.stats import UserSortOrder from synapse.types import JsonDict, JsonMapping, TaskStatus, UserID from synapse.types.rest import RequestBodyModel +from synapse.logging.loggers import ExplicitlyConfiguredLogger if TYPE_CHECKING: from synapse.server import HomeServer @@ -60,51 +61,23 @@ logger = logging.getLogger(__name__) -class ExplicitlyConfiguredLogger(logging.Logger): - """ - A custom logger class that only allows logging if the logger is explicitly - configured (does not inherit log level from parent). - """ - - def __init__(self, name, level=logging.NOTSET): - super().__init__(name, level) - - self.addFilter(self._filter) - - def _filter(self, record: logging.LogRecord) -> bool: - """ - Only allow logging if the logger is explicitly configured. - """ - # Check if the logger is explicitly configured - explicitly_configured_logger = self.manager.loggerDict.get(self.name) - - log_level = logging.NOTSET - if isinstance(explicitly_configured_logger, logging.Logger): - log_level = explicitly_configured_logger.level - - print( - "asdf log_level=%s record_level=%s -> %s", - log_level, - record.levelno, - record.levelno >= log_level, - ) - - # If the logger is not configured, we don't log anything - if log_level == logging.NOTSET: - return False - - # Otherwise, follow the normal logging behavior - return record.levelno >= log_level - - -user_registration_debug_logger = ExplicitlyConfiguredLogger( +original_logger_class = logging.getLoggerClass() +# Use the custom logger class that only allows logging if the logger is explicitly +# configured. +logging.setLoggerClass(ExplicitlyConfiguredLogger) +user_registration_debug_logger = logging.getLogger( "synapse.rest.admin.users.registration_debug" ) """ A logger for debugging the user registration process. This is separate from the main logger as it logs sensitive information such as passwords and -`registration_shared_secret`. +`registration_shared_secret` + +Can only be enabled by explicitly setting `synapse.rest.admin.users.registration_debug` +in the logging configuration. """ +# Restore the original logger class +logging.setLoggerClass(original_logger_class) class UsersRestServletV2(RestServlet): From fea75ae79062ae5f7cd8a77ffda9af87e71a669f Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 6 Jun 2025 17:37:38 -0500 Subject: [PATCH 09/21] Better comments --- synapse/rest/admin/users.py | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/synapse/rest/admin/users.py b/synapse/rest/admin/users.py index 60b6de55665..f4b2817348e 100644 --- a/synapse/rest/admin/users.py +++ b/synapse/rest/admin/users.py @@ -62,19 +62,19 @@ original_logger_class = logging.getLoggerClass() -# Use the custom logger class that only allows logging if the logger is explicitly -# configured. +# Because this can log sensitive information, use a custom logger class that only allows +# logging if the logger is explicitly configured. logging.setLoggerClass(ExplicitlyConfiguredLogger) user_registration_debug_logger = logging.getLogger( "synapse.rest.admin.users.registration_debug" ) """ -A logger for debugging the user registration process. This is separate from the main -logger as it logs sensitive information such as passwords and -`registration_shared_secret` +A logger for debugging the user registration process. -Can only be enabled by explicitly setting `synapse.rest.admin.users.registration_debug` -in the logging configuration. +Because this can log sensitive information (such as passwords and +`registration_shared_secret`), we want people to explictly opt-in before seeing anything +in the logs. Requires explicitely setting `synapse.rest.admin.users.registration_debug` +in the logging configuration and does not inherit the log level from the parent logger. """ # Restore the original logger class logging.setLoggerClass(original_logger_class) From 7f4a06bf7e6ebd650d10f8d5aeb316daa0b5144b Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 6 Jun 2025 17:38:57 -0500 Subject: [PATCH 10/21] Revert "Document dangers of `DEBUG` level logging" This reverts commit e07910486a447ee3f5f9c294da9a0ef9dcfa2e9e. --- docs/usage/configuration/logging_sample_config.md | 3 --- 1 file changed, 3 deletions(-) diff --git a/docs/usage/configuration/logging_sample_config.md b/docs/usage/configuration/logging_sample_config.md index 2712dff44e9..23a55abdccd 100644 --- a/docs/usage/configuration/logging_sample_config.md +++ b/docs/usage/configuration/logging_sample_config.md @@ -14,9 +14,6 @@ It should be named `.log.config` by default. Hint: If you're looking for a guide on what each of the fields in the "Processed request" log lines mean, see [Request log format](../administration/request_log.md). -Warn: Logging at the `DEBUG` level is very verbose and will include sensitive -information such as access tokens, passwords, and secrets. - ```yaml {{#include ../../sample_log_config.yaml}} ``` From 6b13fbdc24577884a0c3cdf935bc14bb5846f685 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 6 Jun 2025 17:41:06 -0500 Subject: [PATCH 11/21] Revert "Add to sensitive part of logging template for Docker" This reverts commit 95a084e6975a1017a8c9fa6346736674c835cb79. --- docker/conf/log.config | 4 ---- 1 file changed, 4 deletions(-) diff --git a/docker/conf/log.config b/docker/conf/log.config index bf632a93e3f..57723212020 100644 --- a/docker/conf/log.config +++ b/docker/conf/log.config @@ -64,10 +64,6 @@ loggers: # beware: increasing this to DEBUG will make synapse log sensitive # information such as access tokens. level: INFO - synapse.rest.admin.users.registration_debug: - # beware: increasing this to DEBUG will make synapse log sensitive - # information such as passwords and `registration_shared_secret`. - level: INFO {% endif %} {% if SYNAPSE_LOG_TESTING %} From b44e5d7346912adda0cd74557a29cc6d114a8409 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 6 Jun 2025 17:51:00 -0500 Subject: [PATCH 12/21] Remove debug logs --- synapse/logging/loggers.py | 7 ------- synapse/rest/admin/users.py | 5 +---- 2 files changed, 1 insertion(+), 11 deletions(-) diff --git a/synapse/logging/loggers.py b/synapse/logging/loggers.py index 8e1cbfd6773..808702a85f8 100644 --- a/synapse/logging/loggers.py +++ b/synapse/logging/loggers.py @@ -25,13 +25,6 @@ def _filter(self, record: logging.LogRecord) -> bool: if isinstance(explicitly_configured_logger, logging.Logger): log_level = explicitly_configured_logger.level - print( - "asdf log_level=%s record_level=%s -> %s", - log_level, - record.levelno, - record.levelno >= log_level, - ) - # If the logger is not configured, we don't log anything if log_level == logging.NOTSET: return False diff --git a/synapse/rest/admin/users.py b/synapse/rest/admin/users.py index f4b2817348e..55e2a89d257 100644 --- a/synapse/rest/admin/users.py +++ b/synapse/rest/admin/users.py @@ -42,6 +42,7 @@ parse_strings_from_args, ) from synapse.http.site import SynapseRequest +from synapse.logging.loggers import ExplicitlyConfiguredLogger from synapse.rest.admin._base import ( admin_patterns, assert_requester_is_admin, @@ -52,7 +53,6 @@ from synapse.storage.databases.main.stats import UserSortOrder from synapse.types import JsonDict, JsonMapping, TaskStatus, UserID from synapse.types.rest import RequestBodyModel -from synapse.logging.loggers import ExplicitlyConfiguredLogger if TYPE_CHECKING: from synapse.server import HomeServer @@ -111,9 +111,6 @@ def __init__(self, hs: "HomeServer"): self._msc3866_enabled = hs.config.experimental.msc3866.enabled self._msc3861_enabled = hs.config.experimental.msc3861.enabled - user_registration_debug_logger.warning("asdf warn test") - user_registration_debug_logger.debug("asdf debug test") - async def on_GET(self, request: SynapseRequest) -> Tuple[int, JsonDict]: await assert_requester_is_admin(self.auth, request) From 57da8ba457d9becb45e95a2d29598648d813111f Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 6 Jun 2025 17:51:58 -0500 Subject: [PATCH 13/21] Fix typo --- synapse/rest/admin/users.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/rest/admin/users.py b/synapse/rest/admin/users.py index 55e2a89d257..2773c68f03a 100644 --- a/synapse/rest/admin/users.py +++ b/synapse/rest/admin/users.py @@ -73,7 +73,7 @@ Because this can log sensitive information (such as passwords and `registration_shared_secret`), we want people to explictly opt-in before seeing anything -in the logs. Requires explicitely setting `synapse.rest.admin.users.registration_debug` +in the logs. Requires explicitly setting `synapse.rest.admin.users.registration_debug` in the logging configuration and does not inherit the log level from the parent logger. """ # Restore the original logger class From b1e96ae39615c7c8af0d48346be8402bd1dffc10 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Mon, 21 Jul 2025 19:49:04 -0500 Subject: [PATCH 14/21] Override `isEnabledFor` so that we can use it accurately --- synapse/logging/loggers.py | 13 ++++++++----- synapse/rest/admin/users.py | 37 +++++++++++++++++++++++++++++-------- 2 files changed, 37 insertions(+), 13 deletions(-) diff --git a/synapse/logging/loggers.py b/synapse/logging/loggers.py index 808702a85f8..63da22a115d 100644 --- a/synapse/logging/loggers.py +++ b/synapse/logging/loggers.py @@ -14,10 +14,7 @@ def __init__(self, name: str, level: int = logging.NOTSET) -> None: self.addFilter(self._filter) - def _filter(self, record: logging.LogRecord) -> bool: - """ - Only allow logging if the logger is explicitly configured. - """ + def isEnabledFor(self, level: int) -> bool: # Check if the logger is explicitly configured explicitly_configured_logger = self.manager.loggerDict.get(self.name) @@ -30,4 +27,10 @@ def _filter(self, record: logging.LogRecord) -> bool: return False # Otherwise, follow the normal logging behavior - return record.levelno >= log_level + return level >= log_level + + def _filter(self, record: logging.LogRecord) -> bool: + """ + Only allow logging if the logger is explicitly configured. + """ + return self.isEnabledFor(record.levelno) diff --git a/synapse/rest/admin/users.py b/synapse/rest/admin/users.py index 30bdc83e98d..c1955bf9593 100644 --- a/synapse/rest/admin/users.py +++ b/synapse/rest/admin/users.py @@ -65,7 +65,7 @@ # Because this can log sensitive information, use a custom logger class that only allows # logging if the logger is explicitly configured. logging.setLoggerClass(ExplicitlyConfiguredLogger) -user_registration_debug_logger = logging.getLogger( +user_registration_sensitive_debug_logger = logging.getLogger( "synapse.rest.admin.users.registration_debug" ) """ @@ -655,13 +655,34 @@ async def on_POST(self, request: SynapseRequest) -> Tuple[int, JsonDict]: want_mac = want_mac_builder.hexdigest() if not hmac.compare_digest(want_mac.encode("ascii"), got_mac.encode("ascii")): - user_registration_debug_logger.debug( - "UserRegisterServlet: Incorrect HMAC digest: actual=%s, expected=%s, registration_shared_secret=%s, body=%s", - got_mac, - want_mac, - self.hs.config.registration.registration_shared_secret, - body, - ) + # If the sensitive debug logger is enabled, log the full details. + # + # For reference, the `user_registration_sensitive_debug_logger.debug(...)` + # call is enough to gate the logging of sensitive information unless + # explicitly enabled. We only have this if-statement to avoid logging the + # suggestion to enable the debug logger if you already have it enabled. + if user_registration_sensitive_debug_logger.isEnabledFor(logging.DEBUG): + user_registration_sensitive_debug_logger.debug( + "UserRegisterServlet: Incorrect HMAC digest: actual=%s, expected=%s, registration_shared_secret=%s, body=%s", + got_mac, + want_mac, + self.hs.config.registration.registration_shared_secret, + body, + ) + else: + # Otherwise, just log the non-sensitive essentials and advertise the + # debug logger for sensitive information. + logger.debug( + ( + "UserRegisterServlet: HMAC incorrect (username=%s): actual=%s, expected=%s - " + "If you need more information, explicitly enable the `synapse.rest.admin.users.registration_debug` " + "logger at the `DEBUG` level to log things like the full request body and " + "`registration_shared_secret` used to calculate the HMAC." + ), + username, + got_mac, + want_mac, + ) raise SynapseError(HTTPStatus.FORBIDDEN, "HMAC incorrect") should_issue_refresh_token = body.get("refresh_token", False) From 19aeeeec356bf1e28dcd29538dd9bef494c0442c Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Mon, 21 Jul 2025 19:51:11 -0500 Subject: [PATCH 15/21] No need to add a filter with `isEnabledFor` --- synapse/logging/loggers.py | 8 -------- 1 file changed, 8 deletions(-) diff --git a/synapse/logging/loggers.py b/synapse/logging/loggers.py index 63da22a115d..2617d89596c 100644 --- a/synapse/logging/loggers.py +++ b/synapse/logging/loggers.py @@ -12,8 +12,6 @@ class ExplicitlyConfiguredLogger(logging.Logger): def __init__(self, name: str, level: int = logging.NOTSET) -> None: super().__init__(name, level) - self.addFilter(self._filter) - def isEnabledFor(self, level: int) -> bool: # Check if the logger is explicitly configured explicitly_configured_logger = self.manager.loggerDict.get(self.name) @@ -28,9 +26,3 @@ def isEnabledFor(self, level: int) -> bool: # Otherwise, follow the normal logging behavior return level >= log_level - - def _filter(self, record: logging.LogRecord) -> bool: - """ - Only allow logging if the logger is explicitly configured. - """ - return self.isEnabledFor(record.levelno) From b8bc1e3f316ae4285f9afee8d27726adc6398852 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Mon, 21 Jul 2025 21:20:12 -0500 Subject: [PATCH 16/21] Add `ExplicitlyConfiguredLoggerTestCase` --- tests/logging/test_loggers.py | 69 +++++++++++++++++++++++++++++++++++ 1 file changed, 69 insertions(+) create mode 100644 tests/logging/test_loggers.py diff --git a/tests/logging/test_loggers.py b/tests/logging/test_loggers.py new file mode 100644 index 00000000000..f3958e19afb --- /dev/null +++ b/tests/logging/test_loggers.py @@ -0,0 +1,69 @@ +# +# This file is licensed under the Affero General Public License (AGPL) version 3. +# +# Copyright (C) 2025 New Vector, Ltd +# +# This program is free software: you can redistribute it and/or modify +# it under the terms of the GNU Affero General Public License as +# published by the Free Software Foundation, either version 3 of the +# License, or (at your option) any later version. +# +# See the GNU Affero General Public License for more details: +# . +# +# +# +import logging + +from synapse.logging.loggers import ExplicitlyConfiguredLogger + +from tests.unittest import TestCase + + +class ExplicitlyConfiguredLoggerTestCase(TestCase): + def _create_explicitly_configured_logger(self) -> logging.Logger: + original_logger_class = logging.getLoggerClass() + logging.setLoggerClass(ExplicitlyConfiguredLogger) + logger = logging.getLogger("test") + # Restore the original logger class + logging.setLoggerClass(original_logger_class) + + return logger + + def test_no_logs_when_not_set(self) -> None: + root_logger = logging.getLogger() + root_logger.setLevel(logging.INFO) + + logger = self._create_explicitly_configured_logger() + + with self.assertNoLogs(logger=logger, level=logging.NOTSET): + # XXX: We have to set this again because of a Python bug: + # https://github.com/python/cpython/issues/136958 (feel free to remove once + # that is resolved and we update to a newer Python version that includes the + # fix) + logger.setLevel(logging.NOTSET) + + logger.debug("debug message") + logger.info("info message") + logger.error("error message") + + def test_logs_when_explicitly_configured(self) -> None: + root_logger = logging.getLogger() + root_logger.setLevel(logging.INFO) + + logger = self._create_explicitly_configured_logger() + + with self.assertLogs(logger=logger, level=logging.DEBUG) as cm: + logger.debug("debug message") + logger.info("info message") + logger.error("error message") + + self.assertIncludes( + set(cm.output), + { + "DEBUG:test:debug message", + "ERROR:test:error message", + "INFO:test:info message", + }, + exact=True, + ) From 37073742cb5916048733a53134c4d3be41ce4010 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Mon, 21 Jul 2025 21:27:12 -0500 Subject: [PATCH 17/21] Add tests for `isEnabledFor` --- tests/logging/test_loggers.py | 48 +++++++++++++++++++++++++++++++++-- 1 file changed, 46 insertions(+), 2 deletions(-) diff --git a/tests/logging/test_loggers.py b/tests/logging/test_loggers.py index f3958e19afb..18ed32f43b0 100644 --- a/tests/logging/test_loggers.py +++ b/tests/logging/test_loggers.py @@ -31,8 +31,12 @@ def _create_explicitly_configured_logger(self) -> logging.Logger: return logger def test_no_logs_when_not_set(self) -> None: + """ + Test to make sure that nothing is logged when the logger is not explicitly + configured. + """ root_logger = logging.getLogger() - root_logger.setLevel(logging.INFO) + root_logger.setLevel(logging.DEBUG) logger = self._create_explicitly_configured_logger() @@ -45,9 +49,13 @@ def test_no_logs_when_not_set(self) -> None: logger.debug("debug message") logger.info("info message") + logger.warning("warning message") logger.error("error message") def test_logs_when_explicitly_configured(self) -> None: + """ + Test to make sure that logs are emitted when the logger is explicitly configured. + """ root_logger = logging.getLogger() root_logger.setLevel(logging.INFO) @@ -56,14 +64,50 @@ def test_logs_when_explicitly_configured(self) -> None: with self.assertLogs(logger=logger, level=logging.DEBUG) as cm: logger.debug("debug message") logger.info("info message") + logger.warning("warning message") logger.error("error message") self.assertIncludes( set(cm.output), { "DEBUG:test:debug message", - "ERROR:test:error message", "INFO:test:info message", + "WARNING:test:warning message", + "ERROR:test:error message", }, exact=True, ) + + def test_is_enabled_for_not_set(self) -> None: + """ + Test to make sure `logger.isEnabledFor(...)` returns False when the logger is + not explicitly configured. + """ + + logger = self._create_explicitly_configured_logger() + + # Unset the logger (not configured) + logger.setLevel(logging.NOTSET) + + # The logger shouldn't be enabled for any level + self.assertFalse(logger.isEnabledFor(logging.DEBUG)) + self.assertFalse(logger.isEnabledFor(logging.INFO)) + self.assertFalse(logger.isEnabledFor(logging.WARNING)) + self.assertFalse(logger.isEnabledFor(logging.ERROR)) + + def test_is_enabled_for_info(self) -> None: + """ + Test to make sure `logger.isEnabledFor(...)` returns True any levels above the + explicitly configured level. + """ + + logger = self._create_explicitly_configured_logger() + + # Explicitly configure the logger to `INFO` level + logger.setLevel(logging.INFO) + + # The logger should be enabled for INFO and above once explicitly configured + self.assertFalse(logger.isEnabledFor(logging.DEBUG)) + self.assertTrue(logger.isEnabledFor(logging.INFO)) + self.assertTrue(logger.isEnabledFor(logging.WARNING)) + self.assertTrue(logger.isEnabledFor(logging.ERROR)) From 5b1020cb57371283c1567c294dd15b76df788421 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Mon, 21 Jul 2025 21:42:41 -0500 Subject: [PATCH 18/21] Workaround `assertNoLogs` not beinga available See https://github.com/element-hq/synapse/pull/18474#discussion_r2220864325 --- tests/logging/test_loggers.py | 18 ++++++++++++++++-- 1 file changed, 16 insertions(+), 2 deletions(-) diff --git a/tests/logging/test_loggers.py b/tests/logging/test_loggers.py index 18ed32f43b0..2abacec77b1 100644 --- a/tests/logging/test_loggers.py +++ b/tests/logging/test_loggers.py @@ -32,7 +32,7 @@ def _create_explicitly_configured_logger(self) -> logging.Logger: def test_no_logs_when_not_set(self) -> None: """ - Test to make sure that nothing is logged when the logger is not explicitly + Test to make sure that nothing is logged when the logger is *not* explicitly configured. """ root_logger = logging.getLogger() @@ -40,7 +40,7 @@ def test_no_logs_when_not_set(self) -> None: logger = self._create_explicitly_configured_logger() - with self.assertNoLogs(logger=logger, level=logging.NOTSET): + with self.assertLogs(logger=logger, level=logging.NOTSET) as cm: # XXX: We have to set this again because of a Python bug: # https://github.com/python/cpython/issues/136958 (feel free to remove once # that is resolved and we update to a newer Python version that includes the @@ -52,6 +52,20 @@ def test_no_logs_when_not_set(self) -> None: logger.warning("warning message") logger.error("error message") + # Nothing should be logged since the logger is *not* explicitly configured + # + # FIXME: Remove this whole block once we update to Python 3.10 or later and + # have access to `assertNoLogs` (replace `assertLogs` with `assertNoLogs`) + self.assertIncludes( + set(cm.output), + set(), + exact=True, + ) + # Stub log message to avoid `assertLogs` failing since it expects at least + # one log message to be logged. + logger.setLevel(logging.INFO) + logger.info("stub message so assertLogs` doesn't fail") + def test_logs_when_explicitly_configured(self) -> None: """ Test to make sure that logs are emitted when the logger is explicitly configured. From 78e29dc665da3ef633bdccbfd8c0d3afb3d321c3 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Mon, 21 Jul 2025 21:58:14 -0500 Subject: [PATCH 19/21] Remove unused change --- synapse/logging/filter.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/synapse/logging/filter.py b/synapse/logging/filter.py index 7dd046d571b..16de488dbca 100644 --- a/synapse/logging/filter.py +++ b/synapse/logging/filter.py @@ -21,8 +21,6 @@ import logging from typing import Literal -root_logger = logging.getLogger() - class MetadataFilter(logging.Filter): """Logging filter that adds constant values to each record. From c00a3e70ce19fb0dd6e0e5f534d8e4510010e3a1 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Mon, 21 Jul 2025 22:29:05 -0500 Subject: [PATCH 20/21] Remove unused boilerplate --- synapse/logging/loggers.py | 3 --- 1 file changed, 3 deletions(-) diff --git a/synapse/logging/loggers.py b/synapse/logging/loggers.py index 2617d89596c..7f7bfef5d40 100644 --- a/synapse/logging/loggers.py +++ b/synapse/logging/loggers.py @@ -9,9 +9,6 @@ class ExplicitlyConfiguredLogger(logging.Logger): configured (does not inherit log level from parent). """ - def __init__(self, name: str, level: int = logging.NOTSET) -> None: - super().__init__(name, level) - def isEnabledFor(self, level: int) -> bool: # Check if the logger is explicitly configured explicitly_configured_logger = self.manager.loggerDict.get(self.name) From e2e0e0ceaf49a84fb1e9cb155ce5725b008cc782 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Tue, 22 Jul 2025 09:44:10 -0500 Subject: [PATCH 21/21] Fix matching pair back-ticks typo in test log See https://github.com/element-hq/synapse/pull/18474#discussion_r2222703940 --- tests/logging/test_loggers.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/logging/test_loggers.py b/tests/logging/test_loggers.py index 2abacec77b1..9a9bf14376d 100644 --- a/tests/logging/test_loggers.py +++ b/tests/logging/test_loggers.py @@ -64,7 +64,7 @@ def test_no_logs_when_not_set(self) -> None: # Stub log message to avoid `assertLogs` failing since it expects at least # one log message to be logged. logger.setLevel(logging.INFO) - logger.info("stub message so assertLogs` doesn't fail") + logger.info("stub message so `assertLogs` doesn't fail") def test_logs_when_explicitly_configured(self) -> None: """