From b971cd6b7e2c2c9f8ec4f5eb41d8f1a0e7fcffad Mon Sep 17 00:00:00 2001 From: sanderegg <35365065+sanderegg@users.noreply.github.com> Date: Fri, 16 Aug 2024 09:16:23 +0200 Subject: [PATCH] fixed test --- .../src/servicelib/logging_utils.py | 122 +++++++-------- .../tests/test_logging_utils.py | 144 +++++++++++++++--- 2 files changed, 181 insertions(+), 85 deletions(-) diff --git a/packages/service-library/src/servicelib/logging_utils.py b/packages/service-library/src/servicelib/logging_utils.py index 487688c849ee..5199edf1558b 100644 --- a/packages/service-library/src/servicelib/logging_utils.py +++ b/packages/service-library/src/servicelib/logging_utils.py @@ -12,9 +12,9 @@ from collections.abc import Callable from contextlib import contextmanager from datetime import datetime -from inspect import getframeinfo, isawaitable, stack +from inspect import getframeinfo, stack from pathlib import Path -from typing import Any, Coroutine, ParamSpec, TypeAlias, TypedDict, TypeVar, overload +from typing import Any, TypeAlias, TypedDict, TypeVar from .utils_secrets import mask_sensitive_data @@ -56,11 +56,11 @@ class CustomFormatter(logging.Formatter): 2. Overrides 'filename' with the value of 'file_name_override', if it exists. """ - def __init__(self, fmt: str, log_format_local_dev_enabled: bool): + def __init__(self, fmt: str, *, log_format_local_dev_enabled: bool) -> None: super().__init__(fmt) self.log_format_local_dev_enabled = log_format_local_dev_enabled - def format(self, record): + def format(self, record) -> str: if hasattr(record, "func_name_override"): record.funcName = record.func_name_override if hasattr(record, "file_name_override"): @@ -86,7 +86,7 @@ def format(self, record): # log_level=%{WORD:log_level} \| log_timestamp=%{TIMESTAMP_ISO8601:log_timestamp} \| log_source=%{DATA:log_source} \| log_msg=%{GREEDYDATA:log_msg} -def config_all_loggers(log_format_local_dev_enabled: bool): +def config_all_loggers(*, log_format_local_dev_enabled: bool) -> None: """ Applies common configuration to ALL registered loggers """ @@ -102,19 +102,26 @@ def config_all_loggers(log_format_local_dev_enabled: bool): fmt = LOCAL_FORMATTING for logger in loggers: - set_logging_handler(logger, fmt, log_format_local_dev_enabled) + set_logging_handler( + logger, fmt=fmt, log_format_local_dev_enabled=log_format_local_dev_enabled + ) def set_logging_handler( logger: logging.Logger, + *, fmt: str, log_format_local_dev_enabled: bool, ) -> None: for handler in logger.handlers: - handler.setFormatter(CustomFormatter(fmt, log_format_local_dev_enabled)) + handler.setFormatter( + CustomFormatter( + fmt, log_format_local_dev_enabled=log_format_local_dev_enabled + ) + ) -def test_logger_propagation(logger: logging.Logger): +def test_logger_propagation(logger: logging.Logger) -> None: """log propagation and levels can sometimes be daunting to get it right. This function uses the `logger`` passed as argument to log the same message at different levels @@ -161,7 +168,9 @@ def _log_arguments( # Before to the function execution, log function details. logger_obj.log( level, - "Arguments: %s - Begin function", + "%s:%s(%s) - Begin function", + func.__module__.split(".")[-1], + func.__name__, formatted_arguments, extra=extra_args, ) @@ -169,67 +178,53 @@ def _log_arguments( return extra_args -P = ParamSpec("P") -R = TypeVar("R") +def _log_return_value( + logger_obj: logging.Logger, + level: int, + func: Callable, + result: Any, + extra_args: dict[str, str], +): + logger_obj.log( + level, + "%s:%s returned %r - End function", + func.__module__.split(".")[-1], + func.__name__, + result, + extra=extra_args, + ) -@overload -def log_decorator( - logger: logging.Logger | None = None, level: int = logging.DEBUG -) -> Callable[[Callable[P, R]], Callable[P, R]]: - ... +F = TypeVar("F", bound=Callable[..., Any]) -@overload def log_decorator( - logger: logging.Logger | None = None, level: int = logging.DEBUG -) -> Callable[ - [Callable[P, Coroutine[Any, Any, R]]], Callable[P, Coroutine[Any, Any, R]] -]: - ... + logger: logging.Logger | None, level: int = logging.DEBUG +) -> Callable[[F], F]: + the_logger = logger or _logger + def decorator(func: F) -> F: + if iscoroutinefunction(func): -def log_decorator( - logger: logging.Logger | None = None, level: int = logging.DEBUG -) -> ( - Callable[[Callable[P, R]], Callable[P, R]] - | Callable[ - [Callable[P, Coroutine[Any, Any, R]]], Callable[P, Coroutine[Any, Any, R]] - ] -): - # Build logger object - logger_obj = logger or _logger + @functools.wraps(func) + async def async_wrapper(*args: Any, **kwargs: Any) -> Any: + extra_args = _log_arguments(the_logger, level, func, *args, **kwargs) + with log_catch(the_logger, reraise=True): + result = await func(*args, **kwargs) + _log_return_value(the_logger, level, func, result, extra_args) + return result - def decorator( - func: Callable[P, R] | Callable[P, Coroutine[Any, Any, R]] - ) -> Callable[P, R] | Callable[P, Coroutine[Any, Any, R]]: - @functools.wraps(func) - async def _async_log_decorator_wrapper(*args: P.args, **kwargs: P.kwargs) -> R: - extra_args = _log_arguments(logger_obj, level, func, *args, **kwargs) - with log_catch(logger_obj, reraise=True): - assert iscoroutinefunction(func) # nosec - value = await func(*args, **kwargs) - # log return value from the function - logger_obj.log( - level, "Returned: - End function %r", value, extra=extra_args - ) - return value + return async_wrapper # type: ignore[return-value] # decorators typing is hard @functools.wraps(func) - def _sync_log_decorator_wrapper(*args: P.args, **kwargs: P.kwargs) -> R: - extra_args = _log_arguments(logger_obj, level, func, *args, **kwargs) - with log_catch(logger_obj, reraise=True): - value = func(*args, **kwargs) - # log return value from the function - logger_obj.log( - level, "Returned: - End function %r", value, extra=extra_args - ) - assert not isawaitable(value) # nosec - return value + def sync_wrapper(*args: Any, **kwargs: Any) -> Any: + extra_args = _log_arguments(the_logger, level, func, *args, **kwargs) + with log_catch(the_logger, reraise=True): + result = func(*args, **kwargs) + _log_return_value(the_logger, level, func, result, extra_args) + return result - if iscoroutinefunction(func): - return _async_log_decorator_wrapper - return _sync_log_decorator_wrapper + return sync_wrapper # type: ignore[return-value] # decorators typing is hard return decorator @@ -263,7 +258,7 @@ def get_log_record_extra(*, user_id: int | str | None = None) -> LogExtra | None return extra or None -def _un_capitalize(s): +def _un_capitalize(s: str) -> str: return s[:1].lower() + s[1:] if s else "" @@ -283,15 +278,16 @@ def log_context( kwargs: dict[str, Any] = {} if extra: kwargs["extra"] = extra - - logger.log(level, "Starting " + msg + " ...", *args, **kwargs) + log_msg = f"Starting {msg} ..." + logger.log(level, log_msg, *args, **kwargs) yield duration = ( f" in {(datetime.now() - start ).total_seconds()}s" # noqa: DTZ005 if log_duration else "" ) - logger.log(level, "Finished " + msg + duration, *args, **kwargs) + log_msg = f"Finished {msg}{duration}" + logger.log(level, log_msg, *args, **kwargs) def guess_message_log_level(message: str) -> LogLevelInt: diff --git a/packages/service-library/tests/test_logging_utils.py b/packages/service-library/tests/test_logging_utils.py index 94d91c483a66..454be9185539 100644 --- a/packages/service-library/tests/test_logging_utils.py +++ b/packages/service-library/tests/test_logging_utils.py @@ -1,58 +1,158 @@ # pylint:disable=redefined-outer-name import logging -from threading import Thread from typing import Any import pytest +from faker import Faker from servicelib.logging_utils import ( + LogExtra, LogLevelInt, LogMessageStr, guess_message_log_level, log_context, log_decorator, ) -from servicelib.utils import logged_gather _logger = logging.getLogger(__name__) @pytest.mark.parametrize("logger", [None, _logger]) async def test_error_regression_async_def( - caplog: pytest.LogCaptureFixture, logger: logging.Logger | None + caplog: pytest.LogCaptureFixture, logger: logging.Logger | None, faker: Faker ): - @log_decorator(logger, logging.ERROR) - async def _raising_error() -> None: + @log_decorator(logger, logging.INFO) + async def _not_raising_fct( + argument1: int, argument2: str, *, keyword_arg1: bool, keyword_arg2: str + ) -> int: + assert argument1 is not None + assert argument2 is not None + assert keyword_arg1 is not None + assert keyword_arg2 is not None + return 0 + + @log_decorator(logger, logging.INFO) + async def _raising_error( + argument1: int, argument2: str, *, keyword_arg1: bool, keyword_arg2: str + ) -> None: + assert argument1 is not None + assert argument2 is not None + assert keyword_arg1 is not None + assert keyword_arg2 is not None msg = "Raising as expected" raise RuntimeError(msg) caplog.clear() + argument1 = faker.pyint() + argument2 = faker.pystr() + key_argument1 = faker.pybool() + key_argument2 = faker.pystr() + + result = await _not_raising_fct( + argument1, argument2, keyword_arg1=key_argument1, keyword_arg2=key_argument2 + ) + assert result == 0 + assert len(caplog.records) == 2 + info_record = caplog.records[0] + assert info_record.levelno == logging.INFO + assert ( + f"{_not_raising_fct.__module__.split('.')[-1]}:{_not_raising_fct.__name__}({argument1!r}, {argument2!r}, keyword_arg1={key_argument1!r}, keyword_arg2={key_argument2!r})" + in info_record.message + ) + return_record = caplog.records[1] + assert return_record.levelno == logging.INFO + assert not return_record.exc_text + assert ( + f"{_not_raising_fct.__module__.split('.')[-1]}:{_not_raising_fct.__name__} returned {result!r}" + in return_record.message + ) - await logged_gather(_raising_error(), reraise=False) - - assert "Traceback" in caplog.text + caplog.clear() + with pytest.raises(RuntimeError): + await _raising_error( + argument1, argument2, keyword_arg1=key_argument1, keyword_arg2=key_argument2 + ) + + assert len(caplog.records) == 2 + info_record = caplog.records[0] + assert info_record.levelno == logging.INFO + assert ( + f"{_raising_error.__module__.split('.')[-1]}:{_raising_error.__name__}({argument1!r}, {argument2!r}, keyword_arg1={key_argument1!r}, keyword_arg2={key_argument2!r})" + in info_record.message + ) + error_record = caplog.records[1] + assert error_record.levelno == logging.ERROR + assert error_record.exc_text + assert "Traceback" in error_record.exc_text @pytest.mark.parametrize("logger", [None, _logger]) -@pytest.mark.parametrize("log_traceback", [True, False]) -async def test_error_regression_def( - caplog: pytest.LogCaptureFixture, logger: logging.Logger | None, log_traceback: bool +def test_error_regression_sync_def( + caplog: pytest.LogCaptureFixture, logger: logging.Logger | None, faker: Faker ): - @log_decorator(logger, logging.ERROR, log_traceback=log_traceback) - def _raising_error() -> None: + @log_decorator(logger, logging.INFO) + def _not_raising_fct( + argument1: int, argument2: str, *, keyword_arg1: bool, keyword_arg2: str + ) -> int: + assert argument1 is not None + assert argument2 is not None + assert keyword_arg1 is not None + assert keyword_arg2 is not None + return 0 + + @log_decorator(logger, logging.INFO) + def _raising_error( + argument1: int, argument2: str, *, keyword_arg1: bool, keyword_arg2: str + ) -> None: + assert argument1 is not None + assert argument2 is not None + assert keyword_arg1 is not None + assert keyword_arg2 is not None msg = "Raising as expected" raise RuntimeError(msg) caplog.clear() + argument1 = faker.pyint() + argument2 = faker.pystr() + key_argument1 = faker.pybool() + key_argument2 = faker.pystr() + + result = _not_raising_fct( + argument1, argument2, keyword_arg1=key_argument1, keyword_arg2=key_argument2 + ) + assert result == 0 + assert len(caplog.records) == 2 + info_record = caplog.records[0] + assert info_record.levelno == logging.INFO + assert ( + f"{_not_raising_fct.__module__.split('.')[-1]}:{_not_raising_fct.__name__}({argument1!r}, {argument2!r}, keyword_arg1={key_argument1!r}, keyword_arg2={key_argument2!r})" + in info_record.message + ) + return_record = caplog.records[1] + assert return_record.levelno == logging.INFO + assert not return_record.exc_text + assert ( + f"{_not_raising_fct.__module__.split('.')[-1]}:{_not_raising_fct.__name__} returned {result!r}" + in return_record.message + ) - thread = Thread(target=_raising_error) - thread.start() - thread.join() - - if log_traceback: - assert "Traceback" in caplog.text - else: - assert "Traceback" not in caplog.text + caplog.clear() + with pytest.raises(RuntimeError): + _raising_error( + argument1, argument2, keyword_arg1=key_argument1, keyword_arg2=key_argument2 + ) + + assert len(caplog.records) == 2 + info_record = caplog.records[0] + assert info_record.levelno == logging.INFO + assert ( + f"{_raising_error.__module__.split('.')[-1]}:{_raising_error.__name__}({argument1!r}, {argument2!r}, keyword_arg1={key_argument1!r}, keyword_arg2={key_argument2!r})" + in info_record.message + ) + error_record = caplog.records[1] + assert error_record.levelno == logging.ERROR + assert error_record.exc_text + assert "Traceback" in error_record.exc_text @pytest.mark.parametrize( @@ -109,7 +209,7 @@ def test_log_context( caplog: pytest.LogCaptureFixture, msg: str, args: tuple[Any, ...], - extra: dict[str, Any] | None, + extra: LogExtra | None, ): caplog.clear()