diff --git a/changelog.d/18474.misc b/changelog.d/18474.misc new file mode 100644 index 000000000..b5897e136 --- /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. diff --git a/synapse/logging/loggers.py b/synapse/logging/loggers.py new file mode 100644 index 000000000..7f7bfef5d --- /dev/null +++ b/synapse/logging/loggers.py @@ -0,0 +1,25 @@ +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 isEnabledFor(self, level: int) -> bool: + # 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 + + # 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 level >= log_level diff --git a/synapse/rest/admin/users.py b/synapse/rest/admin/users.py index 80cdcdee7..c1955bf95 100644 --- a/synapse/rest/admin/users.py +++ b/synapse/rest/admin/users.py @@ -42,6 +42,7 @@ from synapse.http.servlet import ( 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, @@ -60,6 +61,25 @@ if TYPE_CHECKING: logger = logging.getLogger(__name__) +original_logger_class = logging.getLoggerClass() +# 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_sensitive_debug_logger = logging.getLogger( + "synapse.rest.admin.users.registration_debug" +) +""" +A logger for debugging the user registration process. + +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 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 +logging.setLoggerClass(original_logger_class) + + class UsersRestServletV2(RestServlet): PATTERNS = admin_patterns("/users$", "v2") @@ -635,6 +655,34 @@ class UserRegisterServlet(RestServlet): want_mac = want_mac_builder.hexdigest() if not hmac.compare_digest(want_mac.encode("ascii"), got_mac.encode("ascii")): + # 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) diff --git a/tests/logging/test_loggers.py b/tests/logging/test_loggers.py new file mode 100644 index 000000000..9a9bf1437 --- /dev/null +++ b/tests/logging/test_loggers.py @@ -0,0 +1,127 @@ +# +# 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: + """ + Test to make sure that nothing is logged when the logger is *not* explicitly + configured. + """ + root_logger = logging.getLogger() + root_logger.setLevel(logging.DEBUG) + + logger = self._create_explicitly_configured_logger() + + 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 + # fix) + logger.setLevel(logging.NOTSET) + + logger.debug("debug message") + logger.info("info message") + 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. + """ + 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.warning("warning message") + logger.error("error message") + + self.assertIncludes( + set(cm.output), + { + "DEBUG:test:debug 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))