Always use the name as the log ID.

changelog.d/9829.bugfix

@@ -0,0 +1 @@
+Fix the log lines of nested logging contexts.

synapse/logging/context.py

@@ -277,7 +277,7 @@ class LoggingContext:
 
     def __init__(
         self,
-        name: Optional[str] = None,
+        name: str,
         parent_context: "Optional[LoggingContext]" = None,
         request: Optional[ContextRequest] = None,
     ) -> None:
@@ -315,9 +315,7 @@ def __init__(
             self.request = request
 
     def __str__(self) -> str:
-        if self.request:
-            return self.request.request_id
-        return "%s@%x" % (self.name, id(self))
+        return self.name
 
     @classmethod
     def current_context(cls) -> LoggingContextOrSentinel:
@@ -695,16 +693,13 @@ def nested_logging_context(suffix: str) -> LoggingContext:
         )
         parent_context = None
         prefix = ""
-        request = None
     else:
         assert isinstance(curr_context, LoggingContext)
         parent_context = curr_context
-        prefix = str(parent_context.name)
-        request = parent_context.request
+        prefix = parent_context.name
     return LoggingContext(
         prefix + "-" + suffix,
         parent_context=parent_context,
-        request=request,
     )
 
 
@@ -890,12 +885,14 @@ def defer_to_threadpool(reactor, threadpool, f, *args, **kwargs):
             "Calling defer_to_threadpool from sentinel context: metrics will be lost"
         )
         parent_context = None
+        name = ""
     else:
         assert isinstance(curr_context, LoggingContext)
         parent_context = curr_context
+        name = parent_context.name
 
     def g():
-        with LoggingContext(parent_context=parent_context):
+        with LoggingContext(name, parent_context=parent_context):
             return f(*args, **kwargs)
 
     return make_deferred_yieldable(threads.deferToThreadPool(reactor, threadpool, g))

synapse/metrics/background_process_metrics.py

@@ -199,7 +199,7 @@ async def run():
         _background_process_start_count.labels(desc).inc()
         _background_process_in_flight_count.labels(desc).inc()
 
-        with BackgroundProcessLoggingContext(desc, count) as context:
+        with BackgroundProcessLoggingContext("%s-%s" % (desc, count)) as context:
             try:
                 ctx = noop_context_manager()
                 if bg_start_span:
@@ -242,19 +242,12 @@ class BackgroundProcessLoggingContext(LoggingContext):
     processes.
     """
 
-    __slots__ = ["_id", "_proc"]
+    __slots__ = ["_proc"]
 
-    def __init__(self, name: str, id: Optional[Union[int, str]] = None):
+    def __init__(self, name: str):
         super().__init__(name)
-        self._id = id
-
         self._proc = _BackgroundProcess(name, self)
 
-    def __str__(self) -> str:
-        if self._id is not None:
-            return "%s-%s" % (self.name, self._id)
-        return "%s@%x" % (self.name, id(self))
-
     def start(self, rusage: "Optional[resource._RUsage]"):
         """Log context has started running (again)."""
 

synapse/replication/tcp/protocol.py

@@ -185,7 +185,7 @@ def __init__(self, clock: Clock, handler: "ReplicationCommandHandler"):
         # a logcontext which we use for processing incoming commands. We declare it as a
         # background process so that the CPU stats get reported to prometheus.
         self._logging_context = BackgroundProcessLoggingContext(
-            "replication-conn", self.conn_id
+            "replication-conn-%s" % (self.conn_id,)
         )
 
     def connectionMade(self):

synapse/util/metrics.py

@@ -119,7 +119,7 @@ def __init__(self, clock, name):
             assert isinstance(curr_context, LoggingContext)
             parent_context = curr_context
         self._logging_context = LoggingContext(
-            "Measure[%s]" % (self.name,), parent_context
+            self.name, parent_context
         )
         self.start = None