Add debug log when HMAC incorrect (#18474)

Spawning from getting `HMAC incorrect` errors that seem unexplainable
except for the `registration_shared_secret` being misconfigured. It's
also possible my HMAC calculation is incorrect but every time I
double-check the result with the [known-good Python
example](553e124f76/docs/admin_api/register_api.md)
(which matches [Synapse's
source](24e849e483/synapse/rest/admin/users.py (L618-L633))),
it's as expected.

With these logs, we can actually debug whether
`registration_shared_secret` is being configured correctly or not.

It also helps specifically when using `registration_shared_secret_path`
since the default Synapse behavior (of creating the file and secret if
it doesn't exist) can mask deployment race condition where we would
start up Synapse before the `registration_shared_secret_path` file was
put in place:

> **`registration_shared_secret_path`**
>
> [...]
>
> If this file does not exist, Synapse will create a new shared secret
on startup and store it in this file.
>
> *-- [Synapse config
docs](6521406a37/docs/usage/configuration/config_documentation.md (registration_shared_secret_path))*


This only applies to the [`POST
/_synapse/admin/v1/register`](553e124f76/docs/admin_api/register_api.md)
endpoint but does log very sensitive information so we've made it so you
have to explicitly enable the logs by configuring
`synapse.rest.admin.users.registration_debug` (does not inherit root log
level) (via our new `ExplicitlyConfiguredLogger`)


`homeserver.yaml`
```yaml
log_config: "/myserver.log.config.yaml"
```

`myserver.log.config.yaml`
```yaml
version: 1

formatters:
    precise:
        format: '%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(request)s - %(message)s'
        

handlers:
    # ... file/buffer handler (see `sample_log_config.yaml`)

    # A handler that writes logs to stderr. Unused by default, but can be used
    # instead of "buffer" and "file" in the logger handlers.
    console:
        class: logging.StreamHandler
        formatter: precise

loggers:
    synapse.storage.SQL:
        # beware: increasing this to DEBUG will make synapse log sensitive
        # information such as access tokens.
        level: INFO

    # Has to be explicitly configured as such. Will not inherit from the root level even if it's set to DEBUG
    synapse.rest.admin.users.registration_debug:
        level: DEBUG

root:
    level: INFO

    handlers: [console]

disable_existing_loggers: false
```

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,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

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)

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))