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

changelog.d/18870.misc

@@ -0,0 +1 @@
+Remove `sentinel` logcontext usage where we log in `setup`, `start` and exit.

synapse/app/_base.py

@@ -72,7 +72,7 @@
 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.context import LoggingContext, 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
@@ -183,25 +183,23 @@ def run() -> None:
         if gc_thresholds:
             gc.set_threshold(*gc_thresholds)
         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
+        # Reset the logging context when we start the reactor (whenever we yield control
+        # to the reactor, the `sentinel` logging context needs to be set so we don't
+        # leak the current logging context and erroneously apply it to the next task the
+        # reactor event loop picks up)
+        with PreserveLoggingContext():
+            run_command()
+
+    if daemonize:
+        assert pid_file is not None
+
+        if print_pidfile:
+            print(pid_file)
 
-            if print_pidfile:
-                print(pid_file)
+        daemonize_process(pid_file, logger)
 
-            daemonize_process(pid_file, logger)
-        run()
+    run()
 
 
 def quit_with_error(error_string: str) -> NoReturn:
@@ -601,10 +599,12 @@ def run_sighup(*args: Any, **kwargs: Any) -> None:
     hs.get_datastores().main.db_pool.start_profiling()
     hs.get_pusherpool().start()
 
+    def log_shutdown() -> None:
+        with LoggingContext("log_shutdown"):
+            logger.info("Shutting down...")
+
     # Log when we start the shut down process.
-    hs.get_reactor().addSystemEventTrigger(
-        "before", "shutdown", logger.info, "Shutting down..."
-    )
+    hs.get_reactor().addSystemEventTrigger("before", "shutdown", log_shutdown)
 
     setup_sentry(hs)
     setup_sdnotify(hs)

synapse/app/generic_worker.py

@@ -355,7 +355,12 @@ def start(config_options: List[str]) -> None:
     except Exception as e:
         handle_startup_exception(e)
 
-    register_start(_base.start, hs)
+    async def start() -> None:
+        # Re-establish log context now that we're back from the reactor
+        with LoggingContext("start"):
+            await _base.start(hs)
+
+    register_start(start)
 
     # redirect stdio to the logs, if configured.
     if not hs.config.logging.no_redirect_stdio:

synapse/app/homeserver.py

@@ -377,15 +377,17 @@ def setup(config_options: List[str]) -> SynapseHomeServer:
         handle_startup_exception(e)
 
     async def start() -> None:
-        # Load the OIDC provider metadatas, if OIDC is enabled.
-        if hs.config.oidc.oidc_enabled:
-            oidc = hs.get_oidc_handler()
-            # Loading the provider metadata also ensures the provider config is valid.
-            await oidc.load_metadata()
+        # Re-establish log context now that we're back from the reactor
+        with LoggingContext("start"):
+            # Load the OIDC provider metadatas, if OIDC is enabled.
+            if hs.config.oidc.oidc_enabled:
+                oidc = hs.get_oidc_handler()
+                # Loading the provider metadata also ensures the provider config is valid.
+                await oidc.load_metadata()
 
-        await _base.start(hs)
+            await _base.start(hs)
 
-        hs.get_datastores().main.db_pool.updates.start_doing_background_updates()
+            hs.get_datastores().main.db_pool.updates.start_doing_background_updates()
 
     register_start(start)
 

synapse/util/daemonize.py

@@ -29,6 +29,11 @@
 from types import FrameType, TracebackType
 from typing import NoReturn, Optional, Type
 
+from synapse.logging.context import (
+    LoggingContext,
+    PreserveLoggingContext,
+)
+
 
 def daemonize_process(pid_file: str, logger: logging.Logger, chdir: str = "/") -> None:
     """daemonize the current process
@@ -64,8 +69,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():
+        # Fork, creating a new process for the child.
+        process_id = os.fork()
 
     if process_id != 0:
         # parent process: exit.
@@ -140,9 +151,10 @@ def sigterm(signum: int, frame: Optional[FrameType]) -> NoReturn:
 
     # Cleanup pid file at exit.
     def exit() -> None:
-        logger.warning("Stopping daemon.")
-        os.remove(pid_file)
-        sys.exit(0)
+        with LoggingContext("atexit"):
+            logger.warning("Stopping daemon.")
+            os.remove(pid_file)
+            sys.exit(0)
 
     atexit.register(exit)