🎨 Improving servicelib.logging_utils

packages/service-library/src/servicelib/logging_utils.py

@@ -9,12 +9,12 @@
 import functools
 import logging
 from asyncio import iscoroutinefunction
-from collections.abc import Callable
+from collections.abc import Callable, Iterator
 from contextlib import contextmanager
 from datetime import datetime
 from inspect import getframeinfo, stack
 from pathlib import Path
-from typing import Any, Iterator, TypeAlias, TypedDict, TypeVar
+from typing import Any, TypeAlias, TypedDict, TypeVar
 
 from .utils_secrets import mask_sensitive_data
 
@@ -141,7 +141,57 @@ def test_logger_propagation(logger: logging.Logger) -> None:
     logger.debug(msg, "debug")
 
 
-def _log_arguments(
+class LogExceptionsKwargsDict(TypedDict, total=True):
+    logger: logging.Logger
+    level: int
+    msg_prefix: str
+    exc_info: bool
+    stack_info: bool
+
+
+@contextmanager
+def log_exceptions(
+    logger: logging.Logger,
+    level: int,
+    msg_prefix: str = "",
+    *,
+    exc_info: bool = False,
+    stack_info: bool = False,
+) -> Iterator[None]:
+    """If an exception is raised, it gets logged with level.
+
+    NOTE that this does NOT suppress exceptions
+
+    Example: logging exceptions raised a "section of code" for debugging purposes
+
+    # raises
+    with log_exceptions(logger, logging.DEBUG):
+        # ...
+        resp.raise_for_status()
+
+    # does NOT raises  (NOTE: use composition of context managers)
+    with suppress(Exception), log_exceptions(logger, logging.DEBUG):
+        # ...
+        resp.raise_for_status()
+    """
+    try:
+        yield
+    except asyncio.CancelledError:
+        msg = f"{msg_prefix} call cancelled ".strip()
+        logger.log(level, msg)
+        raise
+    except Exception as exc:  # pylint: disable=broad-except
+        msg = f"{msg_prefix} raised {type(exc).__name__}: {exc}".strip()
+        logger.log(
+            level,
+            msg,
+            exc_info=exc_info,
+            stack_info=stack_info,
+        )
+        raise
+
+
+def _log_before_call(
     logger_obj: logging.Logger, level: int, func: Callable, *args, **kwargs
 ) -> dict[str, str]:
     # NOTE: We should avoid logging arguments but in the meantime, we are trying to
@@ -178,7 +228,7 @@ def _log_arguments(
     return extra_args
 
 
-def _log_return_value(
+def _log_after_call(
     logger_obj: logging.Logger,
     level: int,
     func: Callable,
@@ -199,34 +249,60 @@ def _log_return_value(
 
 
 def log_decorator(
-    logger: logging.Logger | None, level: int = logging.DEBUG
+    logger: logging.Logger | None,
+    level: int = logging.DEBUG,
+    *,
+    # NOTE: default defined by legacy: ANE defined full stack tracebacks
+    # on exceptions
+    exc_info: bool = True,
+    exc_stack_info: bool = True,
 ) -> Callable[[F], F]:
-    the_logger = logger or _logger
+    """Logs the decorated function:
+    - *before* its called
+        - input parameters
+    - *after* its called
+        - returned values *after* the decorated function is executed *or*
+        - raised exception (w/ or w/o traceback)
+    """
+    logger_obj = logger or _logger
+
+    def _decorator(func_or_coro: F) -> F:
 
-    def decorator(func: F) -> F:
-        if iscoroutinefunction(func):
+        _log_exc_kwargs = LogExceptionsKwargsDict(
+            logger=logger_obj,
+            level=level,
+            msg_prefix=f"{func_or_coro.__name__}",
+            exc_info=exc_info,
+            stack_info=exc_stack_info,
+        )
+
+        if iscoroutinefunction(func_or_coro):
 
-            @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)
+            @functools.wraps(func_or_coro)
+            async def _async_wrapper(*args: Any, **kwargs: Any) -> Any:
+                extra_args = _log_before_call(
+                    logger_obj, level, func_or_coro, *args, **kwargs
+                )
+                with log_exceptions(**_log_exc_kwargs):
+                    result = await func_or_coro(*args, **kwargs)
+                _log_after_call(logger_obj, level, func_or_coro, result, extra_args)
                 return result
 
-            return async_wrapper  # type: ignore[return-value] # decorators typing is hard
+            return _async_wrapper  # type: ignore[return-value] # decorators typing is hard
 
-        @functools.wraps(func)
-        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)
+        @functools.wraps(func_or_coro)
+        def _sync_wrapper(*args: Any, **kwargs: Any) -> Any:
+            extra_args = _log_before_call(
+                logger_obj, level, func_or_coro, *args, **kwargs
+            )
+            with log_exceptions(**_log_exc_kwargs):
+                result = func_or_coro(*args, **kwargs)
+            _log_after_call(logger_obj, level, func_or_coro, result, extra_args)
             return result
 
-        return sync_wrapper  # type: ignore[return-value] # decorators typing is hard
+        return _sync_wrapper  # type: ignore[return-value] # decorators typing is hard
 
-    return decorator
+    return _decorator
 
 
 @contextmanager

packages/service-library/tests/test_logging_utils.py

@@ -1,6 +1,7 @@
 # pylint:disable=redefined-outer-name
 
 import logging
+from contextlib import suppress
 from typing import Any
 
 import pytest
@@ -12,9 +13,22 @@
     guess_message_log_level,
     log_context,
     log_decorator,
+    log_exceptions,
 )
 
 _logger = logging.getLogger(__name__)
+_ALL_LOGGING_LEVELS = [
+    logging.CRITICAL,
+    logging.ERROR,
+    logging.WARNING,
+    logging.INFO,
+    logging.DEBUG,
+    logging.NOTSET,
+]
+
+
+def _to_level_name(lvl: int) -> str:
+    return logging.getLevelName(lvl)
 
 
 @pytest.mark.parametrize("logger", [None, _logger])
@@ -45,12 +59,13 @@ async def _raising_error(
         msg = "Raising as expected"
         raise RuntimeError(msg)
 
-    caplog.clear()
     argument1 = faker.pyint()
     argument2 = faker.pystr()
     key_argument1 = faker.pybool()
     key_argument2 = faker.pystr()
 
+    # run function under test: _not_raising_fct -----------------
+    caplog.clear()
     result = await _not_raising_fct(
         argument1, argument2, keyword_arg1=key_argument1, keyword_arg2=key_argument2
     )
@@ -70,6 +85,7 @@ async def _raising_error(
         in return_record.message
     )
 
+    # run function under test: _raising_error -----------------
     caplog.clear()
     with pytest.raises(RuntimeError):
         await _raising_error(
@@ -84,7 +100,7 @@ async def _raising_error(
         in info_record.message
     )
     error_record = caplog.records[1]
-    assert error_record.levelno == logging.ERROR
+    assert error_record.levelno == logging.INFO
     assert error_record.exc_text
     assert "Traceback" in error_record.exc_text
 
@@ -156,7 +172,7 @@ def _raising_error(
         in info_record.message
     )
     error_record = caplog.records[1]
-    assert error_record.levelno == logging.ERROR
+    assert error_record.levelno == logging.INFO
     assert error_record.exc_text
     assert "Traceback" in error_record.exc_text
 
@@ -195,6 +211,8 @@ def test_log_context_with_log_duration(
     with log_context(_logger, logging.ERROR, "test", log_duration=with_log_duration):
         ...
 
+    all(r.levelno == logging.ERROR for r in caplog.records)
+
     assert "Starting test ..." in caplog.text
     if with_log_duration:
         assert "Finished test in " in caplog.text
@@ -222,3 +240,85 @@ def test_log_context(
     with log_context(_logger, logging.ERROR, msg, *args, extra=extra):
         ...
     assert len(caplog.messages) == 2
+
+
+@pytest.mark.parametrize("level", _ALL_LOGGING_LEVELS, ids=_to_level_name)
+def test_logs_no_exceptions(caplog: pytest.LogCaptureFixture, level: int):
+    caplog.set_level(level)
+
+    with log_exceptions(_logger, level):
+        ...
+
+    assert not caplog.records
+
+
+@pytest.mark.parametrize("level", _ALL_LOGGING_LEVELS, ids=_to_level_name)
+def test_log_exceptions_and_suppress(caplog: pytest.LogCaptureFixture, level: int):
+    caplog.set_level(level)
+
+    exc_msg = "logs exceptions and suppresses"
+    with suppress(ValueError), log_exceptions(_logger, level, "CONTEXT", exc_info=True):
+        raise ValueError(exc_msg)
+
+    assert len(caplog.records) == (1 if level != logging.NOTSET else 0)
+
+    if caplog.records:
+        assert caplog.records[0].levelno == level
+        record = caplog.records[0]
+        # this is how it looks with exc_info=True
+        #
+        # CRITICAL tests.test_logging_utils:logging_utils.py:170 CONTEXT raised ValueError: logs exceptions and suppresses
+        # Traceback (most recent call last):
+        # File "path/to/file.py", line 163, in log_exceptions
+        #     yield
+        # File "path/to/file2.py", line 262, in test_log_exceptions_and_suppress
+        #     raise ValueError(msg)
+        # ValueError: logs exceptions and suppresses
+        #
+
+        assert record.message == f"CONTEXT raised ValueError: {exc_msg}"
+        # since exc_info=True
+        assert record.exc_text
+        assert exc_msg in record.exc_text
+        assert "ValueError" in record.exc_text
+        assert "Traceback" in record.exc_text
+
+
+@pytest.mark.parametrize("level", _ALL_LOGGING_LEVELS, ids=_to_level_name)
+def test_log_exceptions_and_suppress_without_exc_info(
+    caplog: pytest.LogCaptureFixture, level: int
+):
+    caplog.set_level(level)
+
+    exc_msg = "logs exceptions and suppresses"
+    with suppress(ValueError), log_exceptions(
+        _logger, level, "CONTEXT", exc_info=False
+    ):
+        raise ValueError(exc_msg)
+
+    assert len(caplog.records) == (1 if level != logging.NOTSET else 0)
+
+    if caplog.records:
+        assert caplog.records[0].levelno == level
+        record = caplog.records[0]
+        # this is how it looks with exc_info=False
+        #
+        # CRITICAL tests.test_logging_utils:logging_utils.py:170 CONTEXT raised ValueError: logs exceptions and suppresses
+        #
+
+        assert record.message == f"CONTEXT raised ValueError: {exc_msg}"
+
+        # since exc_info=False
+        assert not record.exc_text
+
+
+@pytest.mark.parametrize("level", _ALL_LOGGING_LEVELS, ids=_to_level_name)
+def test_log_exceptions_and_reraise(caplog: pytest.LogCaptureFixture, level: int):
+    caplog.set_level(level)
+
+    msg = "logs exceptions and reraises"
+    with pytest.raises(ValueError, match=msg), log_exceptions(_logger, level):
+        raise ValueError(msg)
+
+    assert len(caplog.records) == (1 if level != logging.NOTSET else 0)
+    assert all(r.levelno == level for r in caplog.records)