diff --git a/changelog.d/9829.bugfix b/changelog.d/9829.bugfix
new file mode 100644
index 0000000000000000000000000000000000000000..d0c1e49fd8b8ee8e3682c025658ccc38788d956c
--- /dev/null
+++ b/changelog.d/9829.bugfix
@@ -0,0 +1 @@
+Fix the log lines of nested logging contexts.
diff --git a/synapse/logging/context.py b/synapse/logging/context.py
index e78343f5545b74e89b54fab75b75d09e590a39e7..dbd7d3a33a6eb575c19bb80b0910064d093c0077 100644
--- a/synapse/logging/context.py
+++ b/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.request.request_id
- return "%s@%x" % (self.name, id(self))
+ return self.name
@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)
- request = parent_context.request
+ prefix = str(curr_context)
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))
diff --git a/synapse/metrics/background_process_metrics.py b/synapse/metrics/background_process_metrics.py
index e8a9096c039eb0778b6df6a72c430339f250cd11..78e9cfbc26ee7f6d0f68597c16e12231c0b282d1 100644
--- a/synapse/metrics/background_process_metrics.py
+++ b/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)."""
diff --git a/synapse/replication/tcp/protocol.py b/synapse/replication/tcp/protocol.py
index d10d574246180b7701b39fd9951a465a6bb868b2..ba753318bd816fd7f9788c54bbedbb2fdce0660e 100644
--- a/synapse/replication/tcp/protocol.py
+++ b/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):
diff --git a/synapse/util/metrics.py b/synapse/util/metrics.py
index 1023c856d14363cbb4aef24821710d65d1dca6bd..019cfa17cc934c2c52b693fd63b128ecff9241b7 100644
--- a/synapse/util/metrics.py
+++ b/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(
- "Measure[%s]" % (self.name,), parent_context
- )
- self.start = None
+ self._logging_context = LoggingContext(str(curr_context), parent_context)
+ self.start = None # type: Optional[int]
def __enter__(self) -> "Measure":
if self.start is not None:
diff --git a/tests/logging/test_terse_json.py b/tests/logging/test_terse_json.py
index 215fd8b0f9e3297f5e323b906332037925af36b6..ecf873e2ab06be406de78f899ef9b39f757fa582 100644
--- a/tests/logging/test_terse_json.py
+++ b/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()
diff --git a/tests/test_federation.py b/tests/test_federation.py
index 8928597d17dbb1741d397f12cd03c093b8c76675..382cedbd5db953ec62ae96391f6c1d3967112f7a 100644
--- a/tests/test_federation.py
+++ b/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
diff --git a/tests/util/caches/test_descriptors.py b/tests/util/caches/test_descriptors.py
index 2d1f9360e0b02abf576b0826d6cc4c116d1e10e4..8c082e74326066284fac4e6b6bcfc639ddc0f771 100644
--- a/tests/util/caches/test_descriptors.py
+++ b/tests/util/caches/test_descriptors.py
@@ -231,8 +231,7 @@ class DescriptorTestCase(unittest.TestCase):
@defer.inlineCallbacks
def do_lookup():
- with LoggingContext() as c1:
- c1.name = "c1"
+ with LoggingContext("c1") as 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:
- c1.name = "c1"
+ with LoggingContext("c1") as c1:
try:
d = obj.fn(1)
self.assertEqual(