From e8710e7c5e45ff511141ba17facda276ecb861b0 Mon Sep 17 00:00:00 2001 From: Devon Hudson Date: Thu, 4 Dec 2025 23:49:24 +0000 Subject: [PATCH] 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 * [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 | 1 + synapse/util/clock.py | 42 ++++++++++++++++++++++++++++++++---------- 2 files changed, 33 insertions(+), 10 deletions(-) create mode 100644 changelog.d/19278.misc diff --git a/changelog.d/19278.misc b/changelog.d/19278.misc new file mode 100644 index 0000000000..d1425ff38c --- /dev/null +++ b/changelog.d/19278.misc @@ -0,0 +1 @@ +Don't include debug logs in `Clock` unless explicitly enabled. diff --git a/synapse/util/clock.py b/synapse/util/clock.py index 6fd31864b7..4355704f8a 100644 --- a/synapse/util/clock.py +++ b/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,