Remove sentinel logcontext where we log in setup, start and exit

synapse/app/_base.py

@@ -72,7 +72,6 @@
 from synapse.events.presence_router import load_legacy_presence_router
 from synapse.handlers.auth import load_legacy_password_auth_providers
 from synapse.http.site import SynapseSite
-from synapse.logging.context import PreserveLoggingContext
 from synapse.logging.opentracing import init_tracer
 from synapse.metrics import install_gc_manager, register_threadpool
 from synapse.metrics.background_process_metrics import run_as_background_process
@@ -185,23 +184,15 @@ def run() -> None:
         install_gc_manager()
         run_command()
 
-    # make sure that we run the reactor with the sentinel log context,
-    # otherwise other PreserveLoggingContext instances will get confused
-    # and complain when they see the logcontext arbitrarily swapping
-    # between the sentinel and `run` logcontexts.
-    #
-    # We also need to drop the logcontext before forking if we're daemonizing,
-    # otherwise the cputime metrics get confused about the per-thread resource usage
-    # appearing to go backwards.
-    with PreserveLoggingContext():
-        if daemonize:
-            assert pid_file is not None
-
-            if print_pidfile:
-                print(pid_file)
-
-            daemonize_process(pid_file, logger)
-        run()
+    if daemonize:
+        assert pid_file is not None
+
+        if print_pidfile:
+            print(pid_file)
+
+        daemonize_process(pid_file, logger)
+
+    run()
 
 
 def quit_with_error(error_string: str) -> NoReturn:

synapse/metrics/background_process_metrics.py

@@ -47,7 +47,7 @@
 from synapse.logging.context import (
     ContextResourceUsage,
     LoggingContext,
-    PreserveLoggingContext,
+    make_deferred_yieldable,
 )
 from synapse.logging.opentracing import SynapseTags, start_active_span
 from synapse.metrics import SERVER_NAME_LABEL
@@ -223,10 +223,9 @@ def run_as_background_process(
     This should be used to wrap processes which are fired off to run in the
     background, instead of being associated with a particular request.
 
-    It returns a Deferred which completes when the function completes, but it doesn't
-    follow the synapse logcontext rules, which makes it appropriate for passing to
-    clock.looping_call and friends (or for firing-and-forgetting in the middle of a
-    normal synapse async function).
+    It returns a Deferred which completes when the function completes, which makes it
+    appropriate for passing to clock.looping_call and friends (or for
+    firing-and-forgetting in the middle of a normal synapse async function).
 
     Args:
         desc: a description for this background process type
@@ -241,8 +240,6 @@ def run_as_background_process(
 
     Returns:
         Deferred which returns the result of func, or `None` if func raises.
-        Note that the returned Deferred does not follow the synapse logcontext
-        rules.
     """
 
     async def run() -> Optional[R]:
@@ -280,10 +277,9 @@ async def run() -> Optional[R]:
                     name=desc, **{SERVER_NAME_LABEL: server_name}
                 ).dec()
 
-    with PreserveLoggingContext():
         # 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())
+        return make_deferred_yieldable(defer.ensureDeferred(run()))
 
 
 P = ParamSpec("P")

synapse/util/daemonize.py

@@ -29,6 +29,12 @@
 from types import FrameType, TracebackType
 from typing import NoReturn, Optional, Type
 
+from synapse.logging.context import (
+    SENTINEL_CONTEXT,
+    LoggingContext,
+    PreserveLoggingContext,
+)
+
 
 def daemonize_process(pid_file: str, logger: logging.Logger, chdir: str = "/") -> None:
     """daemonize the current process
@@ -64,8 +70,14 @@ def daemonize_process(pid_file: str, logger: logging.Logger, chdir: str = "/") -
             pid_fh.write(old_pid)
         sys.exit(1)
 
-    # Fork, creating a new process for the child.
-    process_id = os.fork()
+    # Stop the existing context *before* we fork the process. Otherwise the cputime
+    # metrics get confused about the per-thread resource usage appearing to go backwards
+    # because we're comparing the resource usage from the original process to the forked
+    # process. `PreserveLoggingContext` already takes care of restarting the original
+    # context *after* the block.
+    with PreserveLoggingContext(SENTINEL_CONTEXT):
+        # Fork, creating a new process for the child.
+        process_id = os.fork()
 
     if process_id != 0:
         # parent process: exit.
@@ -138,11 +150,33 @@ def sigterm(signum: int, frame: Optional[FrameType]) -> NoReturn:
 
     signal.signal(signal.SIGTERM, sigterm)
 
+    # Create a logging context that we can use later as these `atexit` handlers will run
+    # after the `with LoggingContext("main")` context manager finishes and we still want
+    # some context here to know which server is logging.
+    #
+    # We're using `PreserveLoggingContext(SENTINEL_CONTEXT)` so our new `LoggingContext`
+    # ends up with `LoggingContext.previous_context = SENTINEL_CONTEXT` so that when the
+    # `LoggingContext` exits and restores the previous context, we don't leak some
+    # context into the reactor that would be erroneously be picked up by something else
+    # down the line.
+    with PreserveLoggingContext(SENTINEL_CONTEXT):
+        exit_logging_context = LoggingContext(
+            "atexit",
+            # TODO: In the future, we will want
+            # `server_name=calling_context.server_name` so we know which server this log
+            # pertains to, https://github.com/element-hq/synapse/pull/18868
+            #
+            # No parent_context as we don't want to attribute the metrics/traces to the
+            # calling context. `atexit` is completely out-of-band from our application
+            # so it doesn't make sense to associate it back.
+        )
+
     # Cleanup pid file at exit.
     def exit() -> None:
-        logger.warning("Stopping daemon.")
-        os.remove(pid_file)
-        sys.exit(0)
+        with PreserveLoggingContext(exit_logging_context):
+            logger.warning("Stopping daemon.")
+            os.remove(pid_file)
+            sys.exit(0)
 
     atexit.register(exit)