Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

WIP: Handle Logger.exception() outside "except" block #635

Closed
wants to merge 3 commits into from
Closed
Show file tree
Hide file tree
Changes from 1 commit
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
17 changes: 9 additions & 8 deletions src/structlog/processors.py
Original file line number Diff line number Diff line change
Expand Up @@ -28,6 +28,8 @@
NamedTuple,
Sequence,
TextIO,
Tuple,
Union,
)

from ._frames import (
Expand Down Expand Up @@ -407,11 +409,9 @@ def __init__(
def __call__(
self, logger: WrappedLogger, name: str, event_dict: EventDict
) -> EventDict:
exc_info = event_dict.pop("exc_info", None)
if exc_info:
event_dict["exception"] = self.format_exception(
_figure_out_exc_info(exc_info)
)
exc_info = _figure_out_exc_info(event_dict.pop("exc_info", None))
if exc_info != (None, None, None):
Copy link

@raqbit raqbit Jul 24, 2024

Choose a reason for hiding this comment

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

It seems like this would pass any None/Falsy exc_info in the event dict into the formatter. Is this expected?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Changed it to if exc_info and exc_info != (None, None, None). This should work.

Not happy though, that exc_info can be literally anything. I will take a look if this can somehow be changed/improved.

event_dict["exception"] = self.format_exception(exc_info)

return event_dict

Expand Down Expand Up @@ -586,7 +586,7 @@ def __call__(
return event_dict


def _figure_out_exc_info(v: Any) -> ExcInfo:
def _figure_out_exc_info(v: Any) -> Union[ExcInfo, Tuple[None, None, None]]:
sscherfke marked this conversation as resolved.
Show resolved Hide resolved
"""
Depending on the Python version will try to do the smartest thing possible
to transform *v* into an ``exc_info`` tuple.
Expand All @@ -598,7 +598,8 @@ def _figure_out_exc_info(v: Any) -> ExcInfo:
return v

if v:
return sys.exc_info() # type: ignore[return-value]
# Can be "(None, None, None)" if not called inside an error context:
return sys.exc_info()

return v

Expand Down Expand Up @@ -642,7 +643,7 @@ def __call__(
exc = event_dict.pop("exception", None)
if exc is None:
exc_info = _figure_out_exc_info(event_dict.pop("exc_info", None))
if exc_info:
if exc_info != (None, None, None):
Copy link
Owner

Choose a reason for hiding this comment

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

looks like this was the actual bug, right? because a negative result from _figure_out_exc_info isn't falsey

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Yes, more or less. The (None, None, None) case was handled elsewhere (surprisingly, from a typing perspective ;-)), but it only worked for the default exception formatter.

exc = _format_exception(exc_info)

if exc:
Expand Down
73 changes: 73 additions & 0 deletions tests/test_tracebacks.py
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,8 @@

import pytest

import structlog

from structlog import tracebacks


Expand Down Expand Up @@ -730,3 +732,74 @@ def test_json_traceback_value_error(
monkeypatch.setattr(kwargs["suppress"][0], "__file__", None)
with pytest.raises(ValueError, match=next(iter(kwargs.keys()))):
tracebacks.ExceptionDictTransformer(**kwargs)


class TestLogException:
"""
Higher level "integration tests" for "Logger.exception()".
"""

@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 [{"event": "onoes", "log_level": "error"}] == cap_logs.entries
Loading