From b076bc276e881b262048307b6a226061d96c4a8d Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Tue, 20 Apr 2021 09:19:00 -0400 Subject: 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). --- synapse/logging/context.py | 14 ++++---------- synapse/metrics/background_process_metrics.py | 15 ++++----------- synapse/replication/tcp/protocol.py | 2 +- synapse/util/metrics.py | 14 +++++++++----- 4 files changed, 18 insertions(+), 27 deletions(-) (limited to 'synapse') 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: -- cgit 1.4.1