Always use the name as the log ID. (#9829)

As far as I can tell our logging contexts are meant to log the request ID, or sometimes the request ID followed by a suffix (this is generally stored in the name field of LoggingContext). There's also code to log the name@memory location, but I'm not sure this is ever used.

This simplifies the code paths to require every logging context to have a name and use that in logging. For sub-contexts (created via nested_logging_contexts, defer_to_threadpool, Measure) we use the current context's str (which becomes their name or the string "sentinel") and then potentially modify that (e.g. add a suffix).

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 @@ class LoggingContext:
             self.request = request
 
     def __str__(self) -> str:
-        if self.request:
+        return self.name
-            return self.request.request_id
-        return "%s@%x" % (self.name, id(self))
 
     @classmethod
     def current_context(cls) -> LoggingContextOrSentinel:
@@ -694,17 +692,13 @@ def nested_logging_context(suffix: str) -> LoggingContext:
             "Starting nested logging context from sentinel context: metrics will be lost"
         )
         parent_context = None
-        prefix = ""
-        request = None
     else:
         assert isinstance(curr_context, LoggingContext)
         parent_context = curr_context
-        prefix = str(parent_context.name)
+    prefix = str(curr_context)
-        request = parent_context.request
     return LoggingContext(
         prefix + "-" + suffix,
         parent_context=parent_context,
-        request=request,
     )
 
 
@@ -895,7 +889,7 @@ def defer_to_threadpool(reactor, threadpool, f, *args, **kwargs):
         parent_context = curr_context
 
     def g():
-        with LoggingContext(parent_context=parent_context):
+        with LoggingContext(str(curr_context), parent_context=parent_context):
             return f(*args, **kwargs)
 
     return make_deferred_yieldable(threads.deferToThreadPool(reactor, threadpool, g))

synapse/metrics/background_process_metrics.py

@@ -16,7 +16,7 @@
 import logging
 import threading
 from functools import wraps
-from typing import TYPE_CHECKING, Dict, Optional, Set, Union
+from typing import TYPE_CHECKING, Dict, Optional, Set
 
 from prometheus_client.core import REGISTRY, Counter, Gauge
 
@@ -199,7 +199,7 @@ def run_as_background_process(desc: str, func, *args, bg_start_span=True, **kwar
         _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 @@ class BaseReplicationStreamProtocol(LineOnlyReceiver):
         # 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

@@ -105,7 +105,13 @@ class Measure:
         "start",
     ]
 
-    def __init__(self, clock, name):
+    def __init__(self, clock, name: str):
+        """
+        Args:
+            clock: A n object with a "time()" method, which returns the current
+                time in seconds.
+            name: The name of the metric to report.
+        """
         self.clock = clock
         self.name = name
         curr_context = current_context()
@@ -118,10 +124,8 @@ class Measure:
         else:
             assert isinstance(curr_context, LoggingContext)
             parent_context = curr_context
-        self._logging_context = LoggingContext(
+        self._logging_context = LoggingContext(str(curr_context), parent_context)
-            "Measure[%s]" % (self.name,), parent_context
+        self.start = None  # type: Optional[int]
-        )
-        self.start = None
 
     def __enter__(self) -> "Measure":
         if self.start is not None:

tests/logging/test_terse_json.py

@@ -138,7 +138,7 @@ class TerseJsonTestCase(LoggerCleanupMixin, TestCase):
         ]
         self.assertCountEqual(log.keys(), expected_log_keys)
         self.assertEqual(log["log"], "Hello there, wally!")
-        self.assertTrue(log["request"].startswith("name@"))
+        self.assertEqual(log["request"], "name")
 
     def test_with_request_context(self):
         """
@@ -165,7 +165,9 @@ class TerseJsonTestCase(LoggerCleanupMixin, TestCase):
         # Also set the requester to ensure the processing works.
         request.requester = "@foo:test"
 
-        with LoggingContext(parent_context=request.logcontext):
+        with LoggingContext(
+            request.get_request_id(), parent_context=request.logcontext
+        ):
             logger.info("Hello there, %s!", "wally")
 
         log = self.get_log_line()

tests/test_federation.py

@@ -134,7 +134,7 @@ class MessageAcceptTests(unittest.HomeserverTestCase):
             }
         )
 
-        with LoggingContext():
+        with LoggingContext("test-context"):
             failure = self.get_failure(
                 self.handler.on_receive_pdu(
                     "test.serv", lying_event, sent_to_us_directly=True

tests/util/caches/test_descriptors.py

@@ -231,8 +231,7 @@ class DescriptorTestCase(unittest.TestCase):
 
         @defer.inlineCallbacks
         def do_lookup():
-            with LoggingContext() as c1:
+            with LoggingContext("c1") as c1:
-                c1.name = "c1"
                 r = yield obj.fn(1)
                 self.assertEqual(current_context(), c1)
             return r
@@ -274,8 +273,7 @@ class DescriptorTestCase(unittest.TestCase):
 
         @defer.inlineCallbacks
         def do_lookup():
-            with LoggingContext() as c1:
+            with LoggingContext("c1") as c1:
-                c1.name = "c1"
                 try:
                     d = obj.fn(1)
                     self.assertEqual(