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

More annotations for synapse.logging, part 1 #10980

Closed
wants to merge 3 commits into from
Closed
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
6 changes: 6 additions & 0 deletions mypy.ini
Original file line number Diff line number Diff line change
Expand Up @@ -96,6 +96,12 @@ files =
[mypy-synapse.handlers.*]
disallow_untyped_defs = True

[mypy-synapse.logging.formatter]
disallow_untyped_defs = True

[mypy-synapse.logging.handlers]
disallow_untyped_defs = True

[mypy-synapse.rest.*]
disallow_untyped_defs = True

Expand Down
83 changes: 59 additions & 24 deletions synapse/logging/context.py
Original file line number Diff line number Diff line change
Expand Up @@ -22,21 +22,37 @@

See doc/log_contexts.rst for details on how this works.
"""
import functools
import inspect
import logging
import threading
import typing
import warnings
from typing import TYPE_CHECKING, Optional, Tuple, TypeVar, Union
from types import TracebackType
from typing import (
TYPE_CHECKING,
Any,
Callable,
Optional,
Tuple,
Type,
TypeVar,
Union,
cast,
)

import attr
from typing_extensions import Literal

from twisted.internet import defer, threads
from twisted.internet.interfaces import IReactorThreads, ThreadPool

if TYPE_CHECKING:
from synapse.logging.scopecontextmanager import _LogContextScope

T = TypeVar("T")
F = TypeVar("F", bound=Callable[..., Any])

logger = logging.getLogger(__name__)

try:
Expand Down Expand Up @@ -66,7 +82,7 @@ def get_thread_resource_usage() -> "Optional[resource._RUsage]":


# a hook which can be set during testing to assert that we aren't abusing logcontexts.
def logcontext_error(msg: str):
def logcontext_error(msg: str) -> None:
logger.warning(msg)


Expand Down Expand Up @@ -220,28 +236,28 @@ def __init__(self) -> None:
self.scope = None
self.tag = None

def __str__(self):
def __str__(self) -> str:
return "sentinel"

def copy_to(self, record):
def copy_to(self, record: "LoggingContext") -> None:
pass

def start(self, rusage: "Optional[resource._RUsage]"):
def start(self, rusage: "Optional[resource._RUsage]") -> None:
pass

def stop(self, rusage: "Optional[resource._RUsage]"):
def stop(self, rusage: "Optional[resource._RUsage]") -> None:
pass

def add_database_transaction(self, duration_sec):
def add_database_transaction(self, duration_sec: float) -> None:
pass

def add_database_scheduled(self, sched_sec):
def add_database_scheduled(self, sched_sec: float) -> None:
pass

def record_event_fetch(self, event_count):
def record_event_fetch(self, event_count: int) -> None:
pass

def __bool__(self):
def __bool__(self) -> bool:
return False


Expand Down Expand Up @@ -379,7 +395,12 @@ def __enter__(self) -> "LoggingContext":
)
return self

def __exit__(self, type, value, traceback) -> None:
def __exit__(
self,
type: Optional[Type[BaseException]],
value: Optional[BaseException],
traceback: Optional[TracebackType],
) -> None:
"""Restore the logging context in thread local storage to the state it
was before this context was entered.
Returns:
Expand All @@ -399,10 +420,8 @@ def __exit__(self, type, value, traceback) -> None:
# recorded against the correct metrics.
self.finished = True

def copy_to(self, record) -> None:
"""Copy logging fields from this context to a log record or
another LoggingContext
"""
def copy_to(self, record: "LoggingContext") -> None:
"""Copy logging fields from this context to another LoggingContext"""

# we track the current request
record.request = self.request
Expand Down Expand Up @@ -575,7 +594,7 @@ class LoggingContextFilter(logging.Filter):
record.
"""

def __init__(self, request: str = ""):
def __init__(self, request: str = "") -> None:
self._default_request = request

def filter(self, record: logging.LogRecord) -> Literal[True]:
Expand Down Expand Up @@ -626,7 +645,12 @@ def __init__(
def __enter__(self) -> None:
self._old_context = set_current_context(self._new_context)

def __exit__(self, type, value, traceback) -> None:
def __exit__(
self,
type: Optional[Type[BaseException]],
value: Optional[BaseException],
traceback: Optional[TracebackType],
) -> None:
context = set_current_context(self._old_context)

if context != self._new_context:
Expand Down Expand Up @@ -711,16 +735,19 @@ def nested_logging_context(suffix: str) -> LoggingContext:
)


def preserve_fn(f):
def preserve_fn(f: F) -> F:
Copy link
Contributor

Choose a reason for hiding this comment

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

We might want add a comment noting that the return type of F changes into a Deferred[T] if the original return type was not a Deferred.

I don't think we came to a consensus in #synapse-devs on whether it was okay to use slightly misleading type hints in this kind of situation.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Ahh, I didn't spot that this also happens in run_in_background. Hmm, maybe this needs more thought?

Copy link
Member

Choose a reason for hiding this comment

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

I think it should be tractable to add this to our mypy plugin to make it correctly convert the return value from awaitable to deferred?

"""Function decorator which wraps the function with run_in_background"""

def g(*args, **kwargs):
@functools.wraps(f)
def g(*args: Any, **kwargs: Any) -> Any:
return run_in_background(f, *args, **kwargs)

return g
return cast(F, g)


def run_in_background(f, *args, **kwargs) -> defer.Deferred:
def run_in_background(
f: Callable[..., T], *args: Any, **kwargs: Any
) -> "defer.Deferred[T]":
Copy link
Member

Choose a reason for hiding this comment

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

This doesn't work if T is already an awaitable

"""Calls a function, ensuring that the current context is restored after
return from the function, and that the sentinel context is set once the
deferred returned by the function completes.
Expand Down Expand Up @@ -823,7 +850,9 @@ def _set_context_cb(result: ResultT, context: LoggingContext) -> ResultT:
return result


def defer_to_thread(reactor, f, *args, **kwargs):
def defer_to_thread(
reactor: IReactorThreads, f: Callable[..., T], *args: Any, **kwargs: Any
) -> "defer.Deferred[T]":
"""
Calls the function `f` using a thread from the reactor's default threadpool and
returns the result as a Deferred.
Expand Down Expand Up @@ -855,7 +884,13 @@ def defer_to_thread(reactor, f, *args, **kwargs):
return defer_to_threadpool(reactor, reactor.getThreadPool(), f, *args, **kwargs)


def defer_to_threadpool(reactor, threadpool, f, *args, **kwargs):
def defer_to_threadpool(
reactor: IReactorThreads,
threadpool: ThreadPool,
f: Callable[..., T],
*args: Any,
**kwargs: Any,
) -> "defer.Deferred[T]":
"""
A wrapper for twisted.internet.threads.deferToThreadpool, which handles
logcontexts correctly.
Expand Down Expand Up @@ -897,7 +932,7 @@ def defer_to_threadpool(reactor, threadpool, f, *args, **kwargs):
assert isinstance(curr_context, LoggingContext)
parent_context = curr_context

def g():
def g() -> T:
with LoggingContext(str(curr_context), parent_context=parent_context):
return f(*args, **kwargs)

Expand Down
12 changes: 8 additions & 4 deletions synapse/logging/formatter.py
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,13 @@
import logging
import traceback
from io import StringIO
from types import TracebackType
from typing import Optional, Tuple, Type, Union

ExceptionInfo = Union[
Tuple[Type[BaseException], BaseException, Optional[TracebackType]],
Tuple[None, None, None],
]


class LogFormatter(logging.Formatter):
Expand All @@ -28,10 +35,7 @@ class LogFormatter(logging.Formatter):
where it was caught are logged).
"""

def __init__(self, *args, **kwargs):
super().__init__(*args, **kwargs)

def formatException(self, ei):
def formatException(self, ei: ExceptionInfo) -> str:
sio = StringIO()
(typ, val, tb) = ei

Expand Down
4 changes: 2 additions & 2 deletions synapse/logging/handlers.py
Original file line number Diff line number Diff line change
Expand Up @@ -49,7 +49,7 @@ def __init__(
)
self._flushing_thread.start()

def on_reactor_running():
def on_reactor_running() -> None:
self._reactor_started = True

reactor_to_use: IReactorCore
Expand All @@ -74,7 +74,7 @@ def shouldFlush(self, record: LogRecord) -> bool:
else:
return True

def _flush_periodically(self):
def _flush_periodically(self) -> None:
"""
Whilst this handler is active, flush the handler periodically.
"""
Expand Down