DEBUG: lost main context after request

Reproduction instructions:

 1. `poetry run synapse_homeserver --config-path homeserver.yaml`
 1. `curl http://localhost:8008/_matrix/client/versions`
 1. Stop Synapse (`Ctrl + c`)

Notice the bad log:

```
synapse.logging.context - WARNING - sentinel - LoggingContext: Expected logging context main was lost
```

Author: MadLittleMods

synapse/app/homeserver.py

@@ -415,6 +415,7 @@ def main() -> None:
             redirect_stdio_to_logs()
 
         run(hs)
+    logger.info("asdf outside main")
 
 
 if __name__ == "__main__":

synapse/http/site.py

@@ -299,6 +299,7 @@ def get_authenticated_entity(self) -> Tuple[Optional[str], Optional[str]]:
         return None, None
 
     def render(self, resrc: Resource) -> None:
+        logger.info("asdf->SynapseRequest.render")
         # this is called once a Resource has been found to serve the request; in our
         # case the Resource in question will normally be a JsonResource.
 
@@ -319,6 +320,11 @@ def render(self, resrc: Resource) -> None:
                 user_agent=get_request_user_agent(self),
             ),
         )
+        logger.info(
+            "asdf request logcontext=%s logcontext.previous_context=%s",
+            self.logcontext,
+            self.logcontext.previous_context,
+        )
 
         # override the Server header which is set by twisted
         self.setHeader("Server", self.synapse_site.server_version_string)
@@ -342,6 +348,7 @@ def render(self, resrc: Resource) -> None:
                 servlet=self.request_metrics.name,
                 **{SERVER_NAME_LABEL: self.our_server_name},
             ).inc()
+        logger.info("asdf->SynapseRequest.render done")
 
     @contextlib.contextmanager
     def processing(self) -> Generator[None, None, None]:

synapse/logging/context.py

@@ -51,6 +51,7 @@
 
 import attr
 from typing_extensions import ParamSpec
+from traceback import format_stack
 
 from twisted.internet import defer, threads
 from twisted.python.threadpool import ThreadPool
@@ -379,6 +380,14 @@ def set_current_context(
 
     def __enter__(self) -> "LoggingContext":
         """Enters this logging context into thread local storage"""
+        logger.debug(
+            "LoggingContext(%s) enter (previous_context=%s) (source: %s)",
+            self,
+            self.previous_context,
+            format_stack()[-2]
+            .replace("/home/eric/Documents/github/element/synapse/", "")
+            .replace("\n", "->"),
+        )
         old_context = set_current_context(self)
         if self.previous_context != old_context:
             logcontext_error(
@@ -401,13 +410,24 @@ def __exit__(
         Returns:
             None to avoid suppressing any exceptions that were thrown.
         """
+        logger.debug(
+            "LoggingContext(%s) exit: returning to previous_context=%s  (source: %s)",
+            self,
+            self.previous_context,
+            format_stack()[-2]
+            .replace("/home/eric/Documents/github/element/synapse/", "")
+            .replace("\n", "->"),
+        )
         current = set_current_context(self.previous_context)
         if current is not self:
             if current is SENTINEL_CONTEXT:
-                logcontext_error("Expected logging context %s was lost" % (self,))
+                logcontext_error(
+                    "LoggingContext: Expected logging context %s was lost" % (self,)
+                )
             else:
                 logcontext_error(
-                    "Expected logging context %s but found %s" % (self, current)
+                    "LoggingContext: Expected logging context %s but found %s"
+                    % (self, current)
                 )
 
         # the fact that we are here suggests that the caller thinks that everything
@@ -628,6 +648,14 @@ def __init__(
         self._new_context = new_context
 
     def __enter__(self) -> None:
+        logger.debug(
+            "PreserveLoggingContext(%s) enter (old_context=%s) (source: %s)",
+            self._new_context,
+            current_context(),
+            format_stack()[-2]
+            .replace("/home/eric/Documents/github/element/synapse/", "")
+            .replace("\n", "->"),
+        )
         self._old_context = set_current_context(self._new_context)
 
     def __exit__(
@@ -636,16 +664,25 @@ def __exit__(
         value: Optional[BaseException],
         traceback: Optional[TracebackType],
     ) -> None:
+        logger.debug(
+            "PreserveLoggingContext(%s) exit returning to old_context=%s (source: %s)",
+            self._new_context,
+            self._old_context,
+            format_stack()[-2]
+            .replace("/home/eric/Documents/github/element/synapse/", "")
+            .replace("\n", "->"),
+        )
         context = set_current_context(self._old_context)
 
         if context != self._new_context:
             if not context:
                 logcontext_error(
-                    "Expected logging context %s was lost" % (self._new_context,)
+                    "PreserveLoggingContext: Expected logging context %s was lost"
+                    % (self._new_context,)
                 )
             else:
                 logcontext_error(
-                    "Expected logging context %s but found %s"
+                    "PreserveLoggingContext: Expected logging context %s but found %s"
                     % (
                         self._new_context,
                         context,
@@ -677,6 +714,10 @@ def set_current_context(context: LoggingContextOrSentinel) -> LoggingContextOrSe
 
     current = current_context()
 
+    logger.debug(
+        "set_current_context(%s) old_context=%s - %s", context, current, format_stack()
+    )
+
     if current is not context:
         rusage = get_thread_resource_usage()
         current.stop(rusage)