Add debug log when HMAC incorrect

changelog.d/18474.misc

@@ -0,0 +1 @@
+Add debug logging for HMAC digest verification failures when using the admin API to register users.

synapse/logging/loggers.py

@@ -0,0 +1,28 @@
+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)
+
+    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

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,
@@ -60,6 +61,25 @@
 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 @@ 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")):
+            # 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)

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:
+# <https://www.gnu.org/licenses/agpl-3.0.html>.
+#
+#
+#
+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))