fixed test

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,75 +168,63 @@ 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,
     )
 
     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:

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()