Debug: Eliminate variables

Reproduction:

 1. `poetry run synapse_homeserver --config-path homeserver.yaml`
 1. Ctrl + C to stop the server
 1. Notice `LoggingContext: Expected logging context main was lost` in the logs

Author: MadLittleMods

synapse/handlers/federation.py

@@ -188,7 +188,8 @@ def __init__(self, hs: "HomeServer"):
         # were shut down.
         if not hs.config.worker.worker_app:
             run_as_background_process(
-                "resume_sync_partial_state_room",
+                # "resume_sync_partial_state_room",
+                "rspsr",
                 self.server_name,
                 self._resume_partial_state_room_sync,
             )
@@ -1788,15 +1789,17 @@ async def get_room_complexity(
 
     async def _resume_partial_state_room_sync(self) -> None:
         """Resumes resyncing of all partial-state rooms after a restart."""
+        logger.info("asdf->_resume_partial_state_room_sync")
         assert not self.config.worker.worker_app
 
         partial_state_rooms = await self.store.get_partial_state_room_resync_info()
-        for room_id, resync_info in partial_state_rooms.items():
-            self._start_partial_state_room_sync(
-                initial_destination=resync_info.joined_via,
-                other_destinations=resync_info.servers_in_room,
-                room_id=room_id,
-            )
+        # for room_id, resync_info in partial_state_rooms.items():
+        #     self._start_partial_state_room_sync(
+        #         initial_destination=resync_info.joined_via,
+        #         other_destinations=resync_info.servers_in_room,
+        #         room_id=room_id,
+        #     )
+        logger.info("asdf->_resume_partial_state_room_sync done")
 
     def _start_partial_state_room_sync(
         self,

synapse/logging/context.py

@@ -49,6 +49,8 @@
     overload,
 )
 
+import secrets
+import string
 import attr
 from typing_extensions import ParamSpec
 from traceback import format_stack
@@ -386,6 +388,10 @@ def __enter__(self) -> "LoggingContext":
             self.previous_context,
             format_stack()[-2]
             .replace("/home/eric/Documents/github/element/synapse/", "")
+            .replace(
+                "/home/eric/.cache/pypoetry/virtualenvs/matrix-synapse-xCtC9ulO-py3.13/lib/",
+                "",
+            )
             .replace("\n", "->"),
         )
         old_context = set_current_context(self)
@@ -416,6 +422,10 @@ def __exit__(
             self.previous_context,
             format_stack()[-2]
             .replace("/home/eric/Documents/github/element/synapse/", "")
+            .replace(
+                "/home/eric/.cache/pypoetry/virtualenvs/matrix-synapse-xCtC9ulO-py3.13/lib/",
+                "",
+            )
             .replace("\n", "->"),
         )
         current = set_current_context(self.previous_context)
@@ -635,25 +645,39 @@ def filter(self, record: logging.LogRecord) -> Literal[True]:
         return True
 
 
+def random_string(length: int) -> str:
+    """Generate a cryptographically secure string of random letters.
+
+    Drawn from the characters: `a-z` and `A-Z`
+    """
+    return "".join(secrets.choice(string.ascii_letters) for _ in range(length))
+
+
 class PreserveLoggingContext:
     """Context manager which replaces the logging context
 
     The previous logging context is restored on exit."""
 
-    __slots__ = ["_old_context", "_new_context"]
+    __slots__ = ["_old_context", "_new_context", "_instance_id"]
 
     def __init__(
         self, new_context: LoggingContextOrSentinel = SENTINEL_CONTEXT
     ) -> None:
         self._new_context = new_context
+        self._instance_id = random_string(5)
 
     def __enter__(self) -> None:
         logger.debug(
-            "PreserveLoggingContext(%s) enter (old_context=%s) (source: %s)",
+            "PreserveLoggingContext(%s) %s enter (old_context=%s) (source: %s)",
             self._new_context,
+            self._instance_id,
             current_context(),
             format_stack()[-2]
             .replace("/home/eric/Documents/github/element/synapse/", "")
+            .replace(
+                "/home/eric/.cache/pypoetry/virtualenvs/matrix-synapse-xCtC9ulO-py3.13/lib/",
+                "",
+            )
             .replace("\n", "->"),
         )
         self._old_context = set_current_context(self._new_context)
@@ -665,11 +689,16 @@ def __exit__(
         traceback: Optional[TracebackType],
     ) -> None:
         logger.debug(
-            "PreserveLoggingContext(%s) exit returning to old_context=%s (source: %s)",
+            "PreserveLoggingContext(%s) %s exit returning to old_context=%s (source: %s)",
             self._new_context,
+            self._instance_id,
             self._old_context,
             format_stack()[-2]
             .replace("/home/eric/Documents/github/element/synapse/", "")
+            .replace(
+                "/home/eric/.cache/pypoetry/virtualenvs/matrix-synapse-xCtC9ulO-py3.13/lib/",
+                "",
+            )
             .replace("\n", "->"),
         )
         context = set_current_context(self._old_context)
@@ -715,7 +744,16 @@ def set_current_context(context: LoggingContextOrSentinel) -> LoggingContextOrSe
     current = current_context()
 
     logger.debug(
-        "set_current_context(%s) old_context=%s - %s", context, current, format_stack()
+        "|    set_current_context(%s) old_context=%s - %s",
+        context,
+        current,
+        [
+            x.replace("/home/eric/Documents/github/element/synapse/", "").replace(
+                "/home/eric/.cache/pypoetry/virtualenvs/matrix-synapse-xCtC9ulO-py3.13/lib/",
+                "",
+            )
+            for x in format_stack()
+        ],
     )
 
     if current is not context:
@@ -837,7 +875,25 @@ def run_in_background(
     CRITICAL error about an unhandled error will be logged without much
     indication about where it came from.
     """
+    instance_id = random_string(5)
+    stack = (
+        format_stack()[-2]
+        .replace("/home/eric/Documents/github/element/synapse/", "")
+        .replace(
+            "/home/eric/.cache/pypoetry/virtualenvs/matrix-synapse-xCtC9ulO-py3.13/lib/",
+            "",
+        )
+        .replace("\n", "->")
+    )
+
     current = current_context()
+    logger.info(
+        "asdf run_in_background1 %s start context=%s - %s",
+        instance_id,
+        current,
+        stack,
+    )
+
     try:
         res = f(*args, **kwargs)
     except Exception:
@@ -868,6 +924,12 @@ def run_in_background(
 
     # The function may have reset the context before returning, so
     # we need to restore it now.
+    logger.info(
+        "asdf run_in_background2 %s restore log context=%s - %s",
+        instance_id,
+        current,
+        stack,
+    )
     ctx = set_current_context(current)
 
     # The original context will be restored when the deferred
@@ -882,7 +944,17 @@ def run_in_background(
     # which is supposed to have a single entry and exit point. But
     # by spawning off another deferred, we are effectively
     # adding a new exit point.)
-    d.addBoth(_set_context_cb, ctx)
+
+    def _asdf(result: ResultT, context: LoggingContextOrSentinel) -> ResultT:
+        logger.info(
+            "asdf run_in_background3 %s reset log context at end ctx=%s - %s",
+            instance_id,
+            ctx,
+            stack,
+        )
+        return _set_context_cb(result, context)
+
+    d.addBoth(_asdf, ctx)
     return d
 
 
@@ -901,6 +973,15 @@ def run_coroutine_in_background(
     do not run until called, and so calling an async function without awaiting
     cannot change the log contexts.
     """
+    stack = (
+        format_stack()[-2]
+        .replace("/home/eric/Documents/github/element/synapse/", "")
+        .replace(
+            "/home/eric/.cache/pypoetry/virtualenvs/matrix-synapse-xCtC9ulO-py3.13/lib/",
+            "",
+        )
+        .replace("\n", "->")
+    )
 
     current = current_context()
     d = defer.ensureDeferred(coroutine)
@@ -921,7 +1002,15 @@ def run_coroutine_in_background(
     # which is supposed to have a single entry and exit point. But
     # by spawning off another deferred, we are effectively
     # adding a new exit point.)
-    d.addBoth(_set_context_cb, ctx)
+    def _asdf(result: ResultT, context: LoggingContextOrSentinel) -> ResultT:
+        logger.info(
+            "asdf run_coroutine_in_background reset log context at end ctx=%s - %s",
+            ctx,
+            stack,
+        )
+        return _set_context_cb(result, context)
+
+    d.addBoth(_asdf, ctx)
     return d
 
 
@@ -940,15 +1029,56 @@ def make_deferred_yieldable(deferred: "defer.Deferred[T]") -> "defer.Deferred[T]
 
     (This is more-or-less the opposite operation to run_in_background.)
     """
+    instance_id = random_string(5)
+    stack = (
+        format_stack()[-2]
+        .replace("/home/eric/Documents/github/element/synapse/", "")
+        .replace(
+            "/home/eric/.cache/pypoetry/virtualenvs/matrix-synapse-xCtC9ulO-py3.13/lib/",
+            "",
+        )
+        .replace("\n", "->")
+    )
+    full_stack = [
+        x.replace("/home/eric/Documents/github/element/synapse/", "").replace(
+            "/home/eric/.cache/pypoetry/virtualenvs/matrix-synapse-xCtC9ulO-py3.13/lib/",
+            "",
+        )
+        for x in format_stack()
+    ]
+    logger.info(
+        "asdf make_deferred_yieldable1 %s start - %s - full stack=%s",
+        instance_id,
+        stack,
+        full_stack,
+    )
+
     if deferred.called and not deferred.paused:
         # it looks like this deferred is ready to run any callbacks we give it
         # immediately. We may as well optimise out the logcontext faffery.
         return deferred
 
     # ok, we can't be sure that a yield won't block, so let's reset the
     # logcontext, and add a callback to the deferred to restore it.
+    logger.info(
+        "asdf make_deferred_yieldable2 %s reset log context - %s - full stack=%s",
+        instance_id,
+        stack,
+        full_stack,
+    )
     prev_context = set_current_context(SENTINEL_CONTEXT)
-    deferred.addBoth(_set_context_cb, prev_context)
+
+    def _asdf(result: ResultT, context: LoggingContextOrSentinel) -> ResultT:
+        logger.info(
+            "asdf make_deferred_yieldable3 %s restore log context at end ctx=%s - %s - full stack=%s",
+            instance_id,
+            prev_context,
+            stack,
+            full_stack,
+        )
+        return _set_context_cb(result, context)
+
+    deferred.addBoth(_asdf, prev_context)
     return deferred
 
 

synapse/metrics/background_process_metrics.py

@@ -48,6 +48,7 @@
     ContextResourceUsage,
     LoggingContext,
     PreserveLoggingContext,
+    run_in_background,
 )
 from synapse.logging.opentracing import SynapseTags, start_active_span
 from synapse.metrics import SERVER_NAME_LABEL
@@ -244,6 +245,9 @@ def run_as_background_process(
         Note that the returned Deferred does not follow the synapse logcontext
         rules.
     """
+    # TODO: Remove
+    if desc != "rspsr":
+        return
 
     async def run() -> Optional[R]:
         with _bg_metrics_lock:
@@ -258,7 +262,7 @@ async def run() -> Optional[R]:
         ).inc()
 
         with BackgroundProcessLoggingContext(
-            name=desc, server_name=server_name, instance_id=count
+            name="bg-" + desc, server_name=server_name, instance_id=count
         ) as context:
             try:
                 if bg_start_span:
@@ -285,6 +289,8 @@ async def run() -> Optional[R]:
         # looping_call and other places that expect a Deferred.
         return defer.ensureDeferred(run())
 
+    # return run_in_background(run)
+
 
 P = ParamSpec("P")
 

synapse/storage/database.py

@@ -1049,7 +1049,7 @@ def inner_func(conn: _PoolConnection, *args: P.args, **kwargs: P.kwargs) -> R:
             assert not self.engine.in_transaction(conn)
 
             with LoggingContext(
-                str(curr_context), parent_context=parent_context
+                "db-" + str(curr_context), parent_context=parent_context
             ) as context:
                 with opentracing.start_active_span(
                     operation_name="db.connection",

synapse/storage/databases/main/room.py

@@ -1479,26 +1479,26 @@ async def get_partial_state_room_resync_info(
         for room_id, joined_via in rows:
             room_servers[room_id] = PartialStateResyncInfo(joined_via=joined_via)
 
-        rows = cast(
-            List[Tuple[str, str]],
-            await self.db_pool.simple_select_list(
-                "partial_state_rooms_servers",
-                keyvalues=None,
-                retcols=("room_id", "server_name"),
-                desc="get_partial_state_rooms",
-            ),
-        )
-
-        for room_id, server_name in rows:
-            entry = room_servers.get(room_id)
-            if entry is None:
-                # There is a foreign key constraint which enforces that every room_id in
-                # partial_state_rooms_servers appears in partial_state_rooms. So we
-                # expect `entry` to be non-null. (This reasoning fails if we've
-                # partial-joined between the two SELECTs, but this is unlikely to happen
-                # in practice.)
-                continue
-            entry.servers_in_room.add(server_name)
+        # rows = cast(
+        #     List[Tuple[str, str]],
+        #     await self.db_pool.simple_select_list(
+        #         "partial_state_rooms_servers",
+        #         keyvalues=None,
+        #         retcols=("room_id", "server_name"),
+        #         desc="get_partial_state_rooms",
+        #     ),
+        # )
+
+        # for room_id, server_name in rows:
+        #     entry = room_servers.get(room_id)
+        #     if entry is None:
+        #         # There is a foreign key constraint which enforces that every room_id in
+        #         # partial_state_rooms_servers appears in partial_state_rooms. So we
+        #         # expect `entry` to be non-null. (This reasoning fails if we've
+        #         # partial-joined between the two SELECTs, but this is unlikely to happen
+        #         # in practice.)
+        #         continue
+        #     entry.servers_in_room.add(server_name)
 
         return room_servers