Explain logging context in run_as_background_process

Author: MadLittleMods

synapse/handlers/delayed_events.py

@@ -328,6 +328,9 @@ async def cancel(self, requester: Requester, delay_id: str) -> None:
             requester,
             (requester.user.to_string(), requester.device_id),
         )
+        # TODO: Because the deferred returned by `run_as_background_process` does not
+        # follow the synapse logcontext rules, this probably messes with log contexts.
+        # Use `make_deferred_yieldable`
         await self._initialized_from_db
 
         next_send_ts = await self._store.cancel_delayed_event(
@@ -354,6 +357,9 @@ async def restart(self, requester: Requester, delay_id: str) -> None:
             requester,
             (requester.user.to_string(), requester.device_id),
         )
+        # TODO: Because the deferred returned by `run_as_background_process` does not
+        # follow the synapse logcontext rules, this probably messes with log contexts.
+        # Use `make_deferred_yieldable`
         await self._initialized_from_db
 
         next_send_ts = await self._store.restart_delayed_event(
@@ -380,6 +386,9 @@ async def send(self, requester: Requester, delay_id: str) -> None:
         # Use standard request limiter for sending delayed events on-demand,
         # as an on-demand send is similar to sending a regular event.
         await self._request_ratelimiter.ratelimit(requester)
+        # TODO: Because the deferred returned by `run_as_background_process` does not
+        # follow the synapse logcontext rules, this probably messes with log contexts.
+        # Use `make_deferred_yieldable`
         await self._initialized_from_db
 
         event, next_send_ts = await self._store.process_target_delayed_event(

synapse/metrics/background_process_metrics.py

@@ -230,6 +230,11 @@ def run_as_background_process(
     clock.looping_call and friends (or for firing-and-forgetting in the middle of a
     normal synapse async function).
 
+    Because the returned Deferred does not follow the synapse logcontext rules, awaiting
+    the result of this function will result in the log context being cleared. In order
+    to properly await the result of this function and maintain the current log context,
+    use `make_deferred_yieldable`.
+
     Args:
         desc: a description for this background process type
         server_name: The homeserver name that this background process is being run for
@@ -285,7 +290,20 @@ async def run() -> Optional[R]:
                     name=desc, **{SERVER_NAME_LABEL: server_name}
                 ).dec()
 
+    # To explain how the log contexts work here:
+    #  - When this function is called, the current context is stored (using
+    #    `PreserveLoggingContext`), we kick off the background task, and we restore the
+    #    original context before returning (also part of `PreserveLoggingContext`).
+    #  - When the background task finishes, we don't want to leak our background context
+    #    into the reactor which would erroneously get attached to the next operation
+    #    picked up by the event loop. We use `PreserveLoggingContext` to set the
+    #    `sentinel` context and means the new `BackgroundProcessLoggingContext` will
+    #    remember the `sentinel` context as its previous context to return to when it
+    #    exits and yields control back to the reactor.
     with PreserveLoggingContext():
+        # The async `run` task is wrapped in a deferred, which will have the side effect
+        # of executing the coroutine.
+        #
         # Note that we return a Deferred here so that it can be used in a
         # looping_call and other places that expect a Deferred.
         return defer.ensureDeferred(run())