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 all 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.
50 changes: 32 additions & 18 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,20 +635,23 @@ 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
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:
context = current_context()
return LoggingContext(
parent_context=context, request=str(context.request) + "-" + suffix
)
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):
Expand Down Expand Up @@ -822,10 +828,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():
with LoggingContext(parent_context=logcontext):
with LoggingContext(parent_context=parent_context):
return f(*args, **kwargs)

return make_deferred_yieldable(threads.deferToThreadPool(reactor, threadpool, g))
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
10 changes: 9 additions & 1 deletion synapse/util/metrics.py
Original file line number Diff line number Diff line change
Expand Up @@ -108,7 +108,15 @@ 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:
logger.warning(
"Starting metrics collection from sentinel context: metrics will be lost"
)
parent_context = None
else:
assert isinstance(curr_context, LoggingContext)
parent_context = curr_context
self._logging_context = LoggingContext(
"Measure[%s]" % (self.name,), parent_context
)
Expand Down