Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

Add type hints to the logging context code. #8939

Merged
merged 4 commits into from
Jan 5, 2021
Merged
Show file tree
Hide file tree
Changes from 2 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions changelog.d/8939.misc
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
Various clean-ups to the structured logging and logging context code.
30 changes: 16 additions & 14 deletions synapse/logging/context.py
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down Expand Up @@ -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
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LogRecord instances can have properties dynamically added, but mypy doesn't seem to like that.


# 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

Expand Down Expand Up @@ -616,9 +621,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
Expand All @@ -632,17 +635,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
)
Expand Down Expand Up @@ -825,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)
clokep marked this conversation as resolved.
Show resolved Hide resolved
with LoggingContext(parent_context=logcontext):
return f(*args, **kwargs)

Expand Down
8 changes: 5 additions & 3 deletions synapse/storage/database.py
Original file line number Diff line number Diff line change
Expand Up @@ -42,7 +42,6 @@
from synapse.config.database import DatabaseConnectionConfig
from synapse.logging.context import (
LoggingContext,
LoggingContextOrSentinel,
current_context,
make_deferred_yieldable,
)
Expand Down Expand Up @@ -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()

Expand Down
7 changes: 6 additions & 1 deletion synapse/util/metrics.py
Original file line number Diff line number Diff line change
Expand Up @@ -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
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is an actual behavior change -- are we expecting to measure things started by the sentinel context? Should we add a warning here about this?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think we're expecting it, but I certainly can't guarantee that we're not doing it. A warning might be a better first step.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Well this assertion should never fire since curr_context will be the sentinel (in which case it is false-y) or a LoggingContext, the assertion is just there for mypy. I can add a warning though.

self._logging_context = LoggingContext(
"Measure[%s]" % (self.name,), parent_context
)
Expand Down