From b076bc276e881b262048307b6a226061d96c4a8d Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Tue, 20 Apr 2021 09:19:00 -0400 Subject: [PATCH] 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 | 1 + synapse/logging/context.py | 14 ++++---------- synapse/metrics/background_process_metrics.py | 15 ++++----------- synapse/replication/tcp/protocol.py | 2 +- synapse/util/metrics.py | 14 +++++++++----- tests/logging/test_terse_json.py | 6 ++++-- tests/test_federation.py | 2 +- tests/util/caches/test_descriptors.py | 6 ++---- 8 files changed, 26 insertions(+), 34 deletions(-) create mode 100644 changelog.d/9829.bugfix diff --git a/changelog.d/9829.bugfix b/changelog.d/9829.bugfix new file mode 100644 index 0000000000..d0c1e49fd8 --- /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 e78343f554..dbd7d3a33a 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 e8a9096c03..78e9cfbc26 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 d10d574246..ba753318bd 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 1023c856d1..019cfa17cc 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 215fd8b0f9..ecf873e2ab 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 8928597d17..382cedbd5d 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 2d1f9360e0..8c082e7432 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(