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

Author: devonh

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.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 @@
 
 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 @@ def _looping_call_common(
             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 @@ def wrapped_f(*args: P.args, **kwargs: P.kwargs) -> Deferred:
         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 @@ def call_later(
             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 @@ def wrapped_callback(*args: Any, **kwargs: Any) -> None:
             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 @@ def cancel_call_later(
         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 @@ def cancel_all_delayed_calls(self, ignore_errs: bool = True) -> None:
         # 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 @@ def call_when_running(
         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 @@ def wrapped_callback(*args: Any, **kwargs: Any) -> None:
         # 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 @@ def add_system_event_trigger(
         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 @@ def wrapped_callback(*args: Any, **kwargs: Any) -> None:
                 # 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,