Don't include debug logs in Clock unless explicitly enabled (#19278)

Fixes #19276

This log with stack traces results in a ton of noise in the logs and is
confusing to users since it looks like it's an error in the logs.
This PR removes the stack trace from the log. This can be re-enabled on
demand if it is deemed necessary in the future.

### Pull Request Checklist

<!-- Please read
https://element-hq.github.io/synapse/latest/development/contributing_guide.html
before submitting your pull request -->

* [X] Pull request is based on the develop branch
* [X] Pull request includes a [changelog
file](https://element-hq.github.io/synapse/latest/development/contributing_guide.html#changelog).
The entry should:
- Be a short description of your change which makes sense to users.
"Fixed a bug that prevented receiving messages from other servers."
instead of "Moved X method from `EventStore` to `EventWorkerStore`.".
  - Use markdown where necessary, mostly for `code blocks`.
  - End with either a period (.) or an exclamation mark (!).
  - Start with a capital letter.
- Feel free to credit yourself, by adding a sentence "Contributed by
@github_username." or "Contributed by [Your Name]." to the end of the
entry.
* [X] [Code
style](https://element-hq.github.io/synapse/latest/code_style.html) is
correct (run the
[linters](https://element-hq.github.io/synapse/latest/development/contributing_guide.html#run-the-linters))

changelog.d/19278.misc

@@ -0,0 +1 @@
+Don't include debug logs in `Clock` unless explicitly enabled.

synapse/util/clock.py

@@ -29,6 +29,7 @@ from twisted.internet.interfaces import IDelayedCall
 from twisted.internet.task import LoopingCall
 
 from synapse.logging import context
+from synapse.logging.loggers import ExplicitlyConfiguredLogger
 from synapse.types import ISynapseThreadlessReactor
 from synapse.util import log_failure
 from synapse.util.duration import Duration
@@ -39,6 +40,25 @@ P = ParamSpec("P")
 
 logger = logging.getLogger(__name__)
 
+original_logger_class = logging.getLoggerClass()
+logging.setLoggerClass(ExplicitlyConfiguredLogger)
+clock_debug_logger = logging.getLogger("synapse.util.clock.debug")
+"""
+A logger for debugging what is scheduling calls.
+
+Ideally, these wouldn't be gated behind an `ExplicitlyConfiguredLogger` as including logs
+from this logger would be helpful to track when things are being scheduled. However, for
+these logs to be meaningful, they need to include a stack trace to show what initiated the
+call in the first place.
+
+Since the stack traces can create a lot of noise and make the logs hard to read (unless you're
+specifically debugging scheduling issues) we want users to opt-in to seeing these logs. To enable
+this, they must explicitly set `synapse.util.clock.debug` in the logging configuration. Note that
+this setting won't inherit the log level from the parent logger.
+"""
+# Restore the original logger class
+logging.setLoggerClass(original_logger_class)
+
 
 class Clock:
     """
@@ -174,7 +194,7 @@ class Clock:
             looping_call_context_string = "looping_call_now"
 
         def wrapped_f(*args: P.args, **kwargs: P.kwargs) -> Deferred:
-            logger.debug(
+            clock_debug_logger.debug(
                 "%s(%s): Executing callback", looping_call_context_string, instance_id
             )
 
@@ -222,7 +242,7 @@ class Clock:
         d.addErrback(log_failure, "Looping call died", consumeErrors=False)
         self._looping_calls.append(call)
 
-        logger.debug(
+        clock_debug_logger.debug(
             "%s(%s): Scheduled looping call every %sms later",
             looping_call_context_string,
             instance_id,
@@ -283,7 +303,7 @@ class Clock:
             raise Exception("Cannot start delayed call. Clock has been shutdown")
 
         def wrapped_callback(*args: Any, **kwargs: Any) -> None:
-            logger.debug("call_later(%s): Executing callback", call_id)
+            clock_debug_logger.debug("call_later(%s): Executing callback", call_id)
 
             assert context.current_context() is context.SENTINEL_CONTEXT, (
                 "Expected `call_later` callback from the reactor to start with the sentinel logcontext "
@@ -327,7 +347,7 @@ class Clock:
             delay.as_secs(), wrapped_callback, *args, **kwargs
         )  # type: ignore[call-later-not-tracked]
 
-        logger.debug(
+        clock_debug_logger.debug(
             "call_later(%s): Scheduled call for %ss later (tracked for shutdown: %s)",
             call_id,
             delay,
@@ -347,7 +367,7 @@ class Clock:
         self, wrapped_call: "DelayedCallWrapper", ignore_errs: bool = False
     ) -> None:
         try:
-            logger.debug(
+            clock_debug_logger.debug(
                 "cancel_call_later: cancelling scheduled call %s", wrapped_call.call_id
             )
             wrapped_call.delayed_call.cancel()
@@ -367,7 +387,7 @@ class Clock:
         # will result in the call removing itself from the map mid-iteration.
         for call_id, call in list(self._call_id_to_delayed_call.items()):
             try:
-                logger.debug(
+                clock_debug_logger.debug(
                     "cancel_all_delayed_calls: cancelling scheduled call %s", call_id
                 )
                 call.cancel()
@@ -396,7 +416,9 @@ class Clock:
         instance_id = random_string_insecure_fast(5)
 
         def wrapped_callback(*args: Any, **kwargs: Any) -> None:
-            logger.debug("call_when_running(%s): Executing callback", instance_id)
+            clock_debug_logger.debug(
+                "call_when_running(%s): Executing callback", instance_id
+            )
 
             # Since this callback can be invoked immediately if the reactor is already
             # running, we can't always assume that we're running in the sentinel
@@ -436,7 +458,7 @@ class Clock:
         # callWhenRunning should be called.
         self._reactor.callWhenRunning(wrapped_callback, *args, **kwargs)  # type: ignore[prefer-synapse-clock-call-when-running]
 
-        logger.debug(
+        clock_debug_logger.debug(
             "call_when_running(%s): Scheduled call",
             instance_id,
             # Find out who is scheduling the call which makes it easy to follow in the
@@ -472,7 +494,7 @@ class Clock:
         instance_id = random_string_insecure_fast(5)
 
         def wrapped_callback(*args: Any, **kwargs: Any) -> None:
-            logger.debug(
+            clock_debug_logger.debug(
                 "add_system_event_trigger(%s): Executing %s %s callback",
                 instance_id,
                 phase,
@@ -509,7 +531,7 @@ class Clock:
                 # logcontext to the reactor
                 context.run_in_background(callback, *args, **kwargs)
 
-        logger.debug(
+        clock_debug_logger.debug(
             "add_system_event_trigger(%s) for %s %s",
             instance_id,
             phase,