From cfda81dfbe928902342898f68010e8117d6a361e Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Thu, 10 Dec 2020 13:26:59 -0500 Subject: [PATCH 1/4] It does not make sense to nest a logging context in the sentinel context. --- synapse/logging/context.py | 15 +++++---------- 1 file changed, 5 insertions(+), 10 deletions(-) diff --git a/synapse/logging/context.py b/synapse/logging/context.py index a507a83e933c..07404fc59d59 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -616,9 +616,7 @@ def set_current_context(context: LoggingContextOrSentinel) -> LoggingContextOrSe return current -def nested_logging_context( - suffix: str, parent_context: Optional[LoggingContext] = None -) -> LoggingContext: +def nested_logging_context(suffix: str) -> LoggingContext: """Creates a new logging context as a child of another. The nested logging context will have a 'request' made up of the parent context's @@ -632,17 +630,14 @@ def nested_logging_context( # ... do stuff Args: - suffix (str): suffix to add to the parent context's 'request'. - parent_context (LoggingContext|None): parent context. Will use the current context - if None. + suffix: suffix to add to the parent context's 'request'. Returns: LoggingContext: new logging context. """ - if parent_context is not None: - context = parent_context # type: LoggingContextOrSentinel - else: - context = current_context() + context = current_context() + # It is not expected that a nested context would be created in the sentinel context. + assert isinstance(context, LoggingContext) return LoggingContext( parent_context=context, request=str(context.request) + "-" + suffix ) From db9d9656d4179097b053e67021ec37891ac82c14 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Thu, 10 Dec 2020 13:35:13 -0500 Subject: [PATCH 2/4] Add additional type hints. --- changelog.d/8939.misc | 1 + synapse/logging/context.py | 15 +++++++++++---- synapse/storage/database.py | 8 +++++--- synapse/util/metrics.py | 7 ++++++- 4 files changed, 23 insertions(+), 8 deletions(-) create mode 100644 changelog.d/8939.misc diff --git a/changelog.d/8939.misc b/changelog.d/8939.misc new file mode 100644 index 000000000000..bf94135fd5b4 --- /dev/null +++ b/changelog.d/8939.misc @@ -0,0 +1 @@ +Various clean-ups to the structured logging and logging context code. diff --git a/synapse/logging/context.py b/synapse/logging/context.py index 07404fc59d59..c7a6582a396c 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -252,7 +252,12 @@ class LoggingContext: "scope", ] - def __init__(self, name=None, parent_context=None, request=None) -> None: + def __init__( + self, + name: Optional[str] = None, + parent_context: "Optional[LoggingContext]" = None, + request: Optional[str] = None, + ) -> None: self.previous_context = current_context() self.name = name @@ -536,20 +541,20 @@ class LoggingContextFilter(logging.Filter): def __init__(self, request: str = ""): self._default_request = request - def filter(self, record) -> Literal[True]: + def filter(self, record: logging.LogRecord) -> Literal[True]: """Add each fields from the logging contexts to the record. Returns: True to include the record in the log output. """ context = current_context() - record.request = self._default_request + record.request = self._default_request # type: ignore # context should never be None, but if it somehow ends up being, then # we end up in a death spiral of infinite loops, so let's check, for # robustness' sake. if context is not None: # Logging is interested in the request. - record.request = context.request + record.request = context.request # type: ignore return True @@ -820,6 +825,8 @@ def defer_to_threadpool(reactor, threadpool, f, *args, **kwargs): logcontext = current_context() def g(): + # It is not expected that this gets called from the sentinel context. + assert isinstance(logcontext, LoggingContext) with LoggingContext(parent_context=logcontext): return f(*args, **kwargs) diff --git a/synapse/storage/database.py b/synapse/storage/database.py index d1b5760c2c09..b70ca3087bc0 100644 --- a/synapse/storage/database.py +++ b/synapse/storage/database.py @@ -42,7 +42,6 @@ from synapse.config.database import DatabaseConnectionConfig from synapse.logging.context import ( LoggingContext, - LoggingContextOrSentinel, current_context, make_deferred_yieldable, ) @@ -671,12 +670,15 @@ async def runWithConnection( Returns: The result of func """ - parent_context = current_context() # type: Optional[LoggingContextOrSentinel] - if not parent_context: + curr_context = current_context() + if not curr_context: logger.warning( "Starting db connection from sentinel context: metrics will be lost" ) parent_context = None + else: + assert isinstance(curr_context, LoggingContext) + parent_context = curr_context start_time = monotonic_time() diff --git a/synapse/util/metrics.py b/synapse/util/metrics.py index ffdea0de8d56..e06bf9fae924 100644 --- a/synapse/util/metrics.py +++ b/synapse/util/metrics.py @@ -108,7 +108,12 @@ class Measure: def __init__(self, clock, name): self.clock = clock self.name = name - parent_context = current_context() + curr_context = current_context() + if not curr_context: + parent_context = None + else: + assert isinstance(curr_context, LoggingContext) + parent_context = curr_context self._logging_context = LoggingContext( "Measure[%s]" % (self.name,), parent_context ) From d65119d5098c3409d0520861d9de9c7afdb89ebc Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Wed, 16 Dec 2020 15:05:06 -0500 Subject: [PATCH 3/4] Add additional warnings / be a bit safer with assertions. --- synapse/logging/context.py | 14 ++++++++++---- synapse/util/metrics.py | 3 +++ 2 files changed, 13 insertions(+), 4 deletions(-) diff --git a/synapse/logging/context.py b/synapse/logging/context.py index c7a6582a396c..b594a6b0bb3b 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -822,12 +822,18 @@ def defer_to_threadpool(reactor, threadpool, f, *args, **kwargs): Deferred: A Deferred which fires a callback with the result of `f`, or an errback if `f` throws an exception. """ - logcontext = current_context() + curr_context = current_context() + if not curr_context: + logger.warning( + "Calling defer_to_threadpool from sentinel context: metrics will be lost" + ) + parent_context = None + else: + assert isinstance(curr_context, LoggingContext) + parent_context = curr_context def g(): - # It is not expected that this gets called from the sentinel context. - assert isinstance(logcontext, LoggingContext) - with LoggingContext(parent_context=logcontext): + with LoggingContext(parent_context=parent_context): return f(*args, **kwargs) return make_deferred_yieldable(threads.deferToThreadPool(reactor, threadpool, g)) diff --git a/synapse/util/metrics.py b/synapse/util/metrics.py index e06bf9fae924..24123d5cc4d2 100644 --- a/synapse/util/metrics.py +++ b/synapse/util/metrics.py @@ -110,6 +110,9 @@ def __init__(self, clock, name): self.name = name curr_context = current_context() if not curr_context: + logger.warning( + "Starting metrics collection from sentinel context: metrics will be lost" + ) parent_context = None else: assert isinstance(curr_context, LoggingContext) From c7eaba23c48fbc40974b84e799cc8a8582eb3e76 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Wed, 16 Dec 2020 15:09:02 -0500 Subject: [PATCH 4/4] Remove an additional assertion. --- synapse/logging/context.py | 18 ++++++++++++------ 1 file changed, 12 insertions(+), 6 deletions(-) diff --git a/synapse/logging/context.py b/synapse/logging/context.py index b594a6b0bb3b..c2db8b45f3f7 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -640,12 +640,18 @@ def nested_logging_context(suffix: str) -> LoggingContext: Returns: LoggingContext: new logging context. """ - context = current_context() - # It is not expected that a nested context would be created in the sentinel context. - assert isinstance(context, LoggingContext) - return LoggingContext( - parent_context=context, request=str(context.request) + "-" + suffix - ) + curr_context = current_context() + if not curr_context: + logger.warning( + "Starting nested logging context from sentinel context: metrics will be lost" + ) + parent_context = None + prefix = "" + else: + assert isinstance(curr_context, LoggingContext) + parent_context = curr_context + prefix = str(parent_context.request) + return LoggingContext(parent_context=parent_context, request=prefix + "-" + suffix) def preserve_fn(f):