diff --git a/CHANGELOG.md b/CHANGELOG.md index cc53c62f..f8cf7148 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -30,9 +30,14 @@ You can find our backwards-compatibility policy [here](https://github.com/hynek/ ## Fixed -- `structlog.traceback.ExceptionDictTransformer` now correctly handles missing exceptions. - - [#657](https://github.com/hynek/structlog/pull/657) +- Fix handling calls to `{logger}.exception()` outside of exception blocks. + Depending on the structlog configuration, + this either resulted in an event dict key `exception: "MISSING"` or lead to an error. + Now, an invalid or missing `exc_info` will just be ignored. + This means, that calling `{logger}.exception()` outside of an exception block is basically the same as calling `{logger}.error()`. + + [#634](https://github.com/hynek/structlog/issues/634) + [#680](https://github.com/hynek/structlog/pull/680) - Instantiating `structlog.dev.ConsoleRenderer` does not mutate the passed *styles* dict anymore. diff --git a/src/structlog/_frames.py b/src/structlog/_frames.py index 1eb8e7c9..6acd7549 100644 --- a/src/structlog/_frames.py +++ b/src/structlog/_frames.py @@ -16,22 +16,12 @@ from .typing import ExcInfo -def is_missing_exc_info(exc_info: ExcInfo) -> bool: - """ - Return True if exc_info is the missing value. - """ - return exc_info == (None, None, None) # type: ignore[comparison-overlap] - - def _format_exception(exc_info: ExcInfo) -> str: """ Prettyprint an `exc_info` tuple. Shamelessly stolen from stdlib's logging module. """ - if is_missing_exc_info(exc_info): - return "MISSING" - sio = StringIO() traceback.print_exception(exc_info[0], exc_info[1], exc_info[2], None, sio) diff --git a/src/structlog/dev.py b/src/structlog/dev.py index 40dc636a..38b02df0 100644 --- a/src/structlog/dev.py +++ b/src/structlog/dev.py @@ -733,11 +733,9 @@ def __call__( if exc_info or exc is not None: sio.write("\n\n" + "=" * 79 + "\n") + exc_info = _figure_out_exc_info(exc_info) if exc_info: - exc_info = _figure_out_exc_info(exc_info) - - if exc_info != (None, None, None): - self._exception_formatter(sio, exc_info) + self._exception_formatter(sio, exc_info) elif exc is not None: if self._exception_formatter is not plain_traceback: warnings.warn( diff --git a/src/structlog/processors.py b/src/structlog/processors.py index c4803a30..ac1bd98c 100644 --- a/src/structlog/processors.py +++ b/src/structlog/processors.py @@ -19,7 +19,7 @@ import threading import time -from types import FrameType +from types import FrameType, TracebackType from typing import ( Any, Callable, @@ -28,6 +28,7 @@ NamedTuple, Sequence, TextIO, + cast, ) from ._frames import ( @@ -38,7 +39,12 @@ from ._log_levels import NAME_TO_LEVEL, add_log_level from ._utils import get_processname from .tracebacks import ExceptionDictTransformer -from .typing import EventDict, ExceptionTransformer, ExcInfo, WrappedLogger +from .typing import ( + EventDict, + ExceptionTransformer, + ExcInfo, + WrappedLogger, +) __all__ = [ @@ -407,11 +413,9 @@ def __init__( def __call__( self, logger: WrappedLogger, name: str, event_dict: EventDict ) -> EventDict: - exc_info = event_dict.pop("exc_info", None) + exc_info = _figure_out_exc_info(event_dict.pop("exc_info", None)) if exc_info: - event_dict["exception"] = self.format_exception( - _figure_out_exc_info(exc_info) - ) + event_dict["exception"] = self.format_exception(exc_info) return event_dict @@ -586,21 +590,30 @@ def __call__( return event_dict -def _figure_out_exc_info(v: Any) -> ExcInfo: +def _figure_out_exc_info(v: Any) -> ExcInfo | None: """ - Depending on the Python version will try to do the smartest thing possible - to transform *v* into an ``exc_info`` tuple. + Try to convert *v* into an ``exc_info`` tuple. + + Return ``None`` if *v* does not represent an exception or if there is no + current exception. """ if isinstance(v, BaseException): return (v.__class__, v, v.__traceback__) - if isinstance(v, tuple): - return v + if isinstance(v, tuple) and len(v) == 3: + has_type = isinstance(v[0], type) and issubclass(v[0], BaseException) + has_exc = isinstance(v[1], BaseException) + has_tb = v[2] is None or isinstance(v[2], TracebackType) + if has_type and has_exc and has_tb: + return v if v: - return sys.exc_info() # type: ignore[return-value] + result = sys.exc_info() + if result == (None, None, None): + return None + return cast(ExcInfo, result) - return v + return None class ExceptionPrettyPrinter: diff --git a/src/structlog/tracebacks.py b/src/structlog/tracebacks.py index b5c4b433..96ab71e6 100644 --- a/src/structlog/tracebacks.py +++ b/src/structlog/tracebacks.py @@ -22,8 +22,6 @@ from types import ModuleType, TracebackType from typing import Any, Iterable, Sequence, Tuple, Union -from ._frames import is_missing_exc_info - try: import rich @@ -418,8 +416,6 @@ def __init__( self.use_rich = use_rich def __call__(self, exc_info: ExcInfo) -> list[dict[str, Any]]: - if is_missing_exc_info(exc_info): - return [] trace = extract( *exc_info, show_locals=self.show_locals, diff --git a/tests/processors/test_renderers.py b/tests/processors/test_renderers.py index 8f225c80..9fa24e5c 100644 --- a/tests/processors/test_renderers.py +++ b/tests/processors/test_renderers.py @@ -514,12 +514,12 @@ def test_nop_missing(self): def test_formats_tuple(self): """ - If exc_info is a tuple, it is used. + If exc_info is an arbitrary 3-tuple, it is not used. """ formatter = ExceptionRenderer(lambda exc_info: exc_info) d = formatter(None, None, {"exc_info": (None, None, 42)}) - assert {"exception": (None, None, 42)} == d + assert {} == d def test_gets_exc_info_on_bool(self): """ @@ -580,6 +580,4 @@ def test_no_exception(self, ei): """ A missing exception does not blow up. """ - assert {"exception": "MISSING"} == format_exc_info( - None, None, {"exc_info": ei} - ) + assert {} == format_exc_info(None, None, {"exc_info": ei}) diff --git a/tests/test_dev.py b/tests/test_dev.py index 1193c040..89871300 100644 --- a/tests/test_dev.py +++ b/tests/test_dev.py @@ -545,10 +545,7 @@ def test_no_exception(self): r = dev.ConsoleRenderer(colors=False) assert ( - "hi" - == r( - None, None, {"event": "hi", "exc_info": (None, None, None)} - ).rstrip() + "hi" == r(None, None, {"event": "hi", "exc_info": None}).rstrip() ) def test_columns_warns_about_meaningless_arguments(self, recwarn): diff --git a/tests/test_tracebacks.py b/tests/test_tracebacks.py index f8d0f1e5..42a5b75c 100644 --- a/tests/test_tracebacks.py +++ b/tests/test_tracebacks.py @@ -15,6 +15,8 @@ import pytest +import structlog + from structlog import tracebacks @@ -772,12 +774,75 @@ def test_json_traceback_value_error( tracebacks.ExceptionDictTransformer(**kwargs) -def test_exception_dict_transformer_missing_exc_info(): +class TestLogException: """ - ExceptionDictTransformer returns an empty list if exc_info is missing. + Higher level integration tests for `Logger.exception()`. """ - transformer = tracebacks.ExceptionDictTransformer() - result = transformer(exc_info=(None, None, None)) + @pytest.fixture + def cap_logs(self) -> structlog.testing.LogCapture: + """ + Create a LogCapture to be used as processor and fixture for retrieving + logs in tests. + """ + return structlog.testing.LogCapture() + + @pytest.fixture + def logger( + self, cap_logs: structlog.testing.LogCapture + ) -> structlog.Logger: + """ + Create a logger with the dict_tracebacks and a LogCapture processor. + """ + old_processors = structlog.get_config()["processors"] + structlog.configure([structlog.processors.dict_tracebacks, cap_logs]) + logger = structlog.get_logger("dict_tracebacks") + try: + yield logger + finally: + structlog.configure(processors=old_processors) + + def test_log_explicit_exception( + self, logger: structlog.Logger, cap_logs: structlog.testing.LogCapture + ) -> None: + """ + The log row contains a traceback when `Logger.exception()` is + explicitly called with an exception instance. + """ + try: + 1 / 0 + except ZeroDivisionError as e: + logger.exception("onoes", exception=e) + + log_row = cap_logs.entries[0] + + assert log_row["exception"][0]["exc_type"] == "ZeroDivisionError" + + def test_log_implicit_exception( + self, logger: structlog.Logger, cap_logs: structlog.testing.LogCapture + ) -> None: + """ + The log row contains a traceback when `Logger.exception()` is called + in an `except` block but without explicitly passing the exception. + """ + try: + 1 / 0 + except ZeroDivisionError: + logger.exception("onoes") + + log_row = cap_logs.entries[0] + + assert log_row["exception"][0]["exc_type"] == "ZeroDivisionError" + + def test_no_exception( + self, logger: structlog.Logger, cap_logs: structlog.testing.LogCapture + ) -> None: + """ + `Logger.exception()` should not be called outside an `except` block + but this cases is gracefully handled and does not lead to an exception. + + See: https://github.com/hynek/structlog/issues/634 + """ + logger.exception("onoes") - assert [] == result + assert [{"event": "onoes", "log_level": "error"}] == cap_logs.entries