Remove sentinel logcontext in Clock utilities (looping_call, looping_call_now, call_later)

synapse/util/__init__.py

@@ -121,6 +121,8 @@ class Clock:
 
     async def sleep(self, seconds: float) -> None:
         d: defer.Deferred[float] = defer.Deferred()
+        # Start task in the `sentinel` logcontext, to avoid leaking the current context
+        # into the reactor once it finishes.
         with context.PreserveLoggingContext():
             self._reactor.callLater(seconds, d.callback, seconds)
             await d
@@ -149,8 +151,9 @@ def looping_call(
         this functionality thanks to this function being a thin wrapper around
         `twisted.internet.task.LoopingCall`.
 
-        Note that the function will be called with no logcontext, so if it is anything
-        other than trivial, you probably want to wrap it in run_as_background_process.
+        Note that the function will be called with generic `looping_call` logcontext, so
+        if it is anything other than a trivial task, you probably want to wrap it in
+        `run_as_background_process` to give it more specific label and track metrics.
 
         Args:
             f: The function to call repeatedly.
@@ -172,8 +175,9 @@ def looping_call_now(
         As with `looping_call`: subsequent calls are not scheduled until after the
         the Awaitable returned by a previous call has finished.
 
-        Also as with `looping_call`: the function is called with no logcontext and
-        you probably want to wrap it in `run_as_background_process`.
+        Note that the function will be called with generic `looping_call` logcontext, so
+        if it is anything other than a trivial task, you probably want to wrap it in
+        `run_as_background_process` to give it more specific label and track metrics.
 
         Args:
             f: The function to call repeatedly.
@@ -192,19 +196,37 @@ def _looping_call_common(
         **kwargs: P.kwargs,
     ) -> LoopingCall:
         """Common functionality for `looping_call` and `looping_call_now`"""
-        call = task.LoopingCall(f, *args, **kwargs)
-        call.clock = self._reactor
-        d = call.start(msec / 1000.0, now=now)
-        d.addErrback(log_failure, "Looping call died", consumeErrors=False)
-        return call
+
+        def wrapped_f(*args: P.args, **kwargs: P.kwargs) -> object:
+            # Because this is a callback from the reactor, we will be using the
+            # `sentinel` log context at this point. We want to log with some logcontext
+            # as we want to know which server the logs came from.
+            #
+            # This also ensures that we return to the `sentinel` context when we exit
+            # this function and yield control back to the reactor to avoid leaking the
+            # current logcontext to the reactor (which would then get picked up and
+            # associated with the next thing the reactor does)
+            with context.LoggingContext("looping_call"):
+                return f(*args, **kwargs)
+
+        # Start task in the `sentinel` logcontext, to avoid leaking the current context
+        # into the reactor if `d` ever finishes (perhaps someone cancels the looping
+        # call)
+        with context.PreserveLoggingContext():
+            call = task.LoopingCall(wrapped_f, *args, **kwargs)
+            call.clock = self._reactor
+            d = call.start(msec / 1000.0, now=now)
+            d.addErrback(log_failure, "Looping call died", consumeErrors=False)
+            return call
 
     def call_later(
         self, delay: float, callback: Callable, *args: Any, **kwargs: Any
     ) -> IDelayedCall:
         """Call something later
 
-        Note that the function will be called with no logcontext, so if it is anything
-        other than trivial, you probably want to wrap it in run_as_background_process.
+        Note that the function will be called with generic `looping_call` logcontext, so
+        if it is anything other than a trivial task, you probably want to wrap it in
+        `run_as_background_process` to give it more specific label and track metrics.
 
         Args:
             delay: How long to wait in seconds.
@@ -214,9 +236,19 @@ def call_later(
         """
 
         def wrapped_callback(*args: Any, **kwargs: Any) -> None:
-            with context.PreserveLoggingContext():
+            # Because this is a callback from the reactor, we will be using the
+            # `sentinel` log context at this point. We want to log with some logcontext
+            # as we want to know which server the logs came from.
+            #
+            # This also ensures that we return to the `sentinel` context when we exit
+            # this function and yield control back to the reactor to avoid leaking the
+            # current logcontext to the reactor (which would then get picked up and
+            # associated with the next thing the reactor does)
+            with context.LoggingContext("call_later"):
                 callback(*args, **kwargs)
 
+        # Start task in the `sentinel` logcontext, to avoid leaking the current context
+        # into the reactor once it finishes.
         with context.PreserveLoggingContext():
             return self._reactor.callLater(delay, wrapped_callback, *args, **kwargs)