AttributeError raised when calling logger.exception without exception information

[am1ter]

Hello everyone!

Before I describe the issue, let me provide some context.

Main issue:

I encountered an error when attempting to call logger.exception outside an except block without including any information about an exception. For example:

from structlog import getLogger

logger = getLogger()
logger.exception('test')

This code raises the following error:

Traceback (most recent call last):
  File "/home/amiter/coding/structlog/amiter.py", line 3, in <module>
    bl.exception('test_exception')
  File "/home/amiter/coding/structlog/src/structlog/_log_levels.py", line 94, in exception
    return self.error(event, **kw)
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/amiter/coding/structlog/src/structlog/_log_levels.py", line 169, in meth
    return self._proxy_to_logger(name, event, **kw)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/amiter/coding/structlog/src/structlog/_base.py", line 204, in _proxy_to_logger
    args, kw = self._process_event(method_name, event, event_kw)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/amiter/coding/structlog/src/structlog/_base.py", line 159, in _process_event
    event_dict = proc(self._logger, method_name, event_dict)
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/amiter/coding/structlog/src/structlog/dev.py", line 426, in __call__
    self._exception_formatter(sio, exc_info)
  File "/home/amiter/coding/structlog/src/structlog/dev.py", line 191, in rich_traceback
    Traceback.from_exception(*exc_info, show_locals=True)
  File "/home/amiter/coding/structlog/.venv/lib/python3.11/site-packages/rich/traceback.py", line 335, in from_exception
    rich_traceback = cls.extract(
                     ^^^^^^^^^^^^
  File "/home/amiter/coding/structlog/.venv/lib/python3.11/site-packages/rich/traceback.py", line 406, in extract
    exc_type=safe_str(exc_type.__name__),
                      ^^^^^^^^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute '__name__'. Did you mean: '__ne__'?

I find this error message confusing because it seems like an internal bug.

It is clear that moving the logger call inside the try/except block resolves the issue. Additionally, including information about the exception using constructions like logger.exception('test', exc_info=False) or logger.exception('test', exc_info=ZeroDivisionError()) also prevents the error.

The cause of the AttributeError is that the code blocks in stdlib.BoundLogger.exception() and _log_levels.exception() set exc_info to True using kw.setdefault("exc_info", True), even when there is no exc_info in sys.exc_info(). Subsequently, the processors._figure_out_exc_info() function runs the following code:

def _figure_out_exc_info(v: Any) -> ExcInfo:
    """
    Depending on the Python version will try to do the smartest thing possible
    to transform *v* into an ``exc_info`` tuple.
    """
    if isinstance(v, BaseException):
        return (v.__class__, v, v.__traceback__)

    if isinstance(v, tuple):
        return v  # type: ignore[return-value]

    if v:
        return sys.exc_info()  # type: ignore[return-value]

    return v

Because sys.exc_info() is blank we get tuple with value (None, None, None) and then the following code raises AttributeError, that I showed above.

Tests-related issue:

Furthermore, I noticed that some tests in the structlog library ignore this unexpected behavior. For instance, the tests TestBoundLogger.test_exception_exc_info() and TestFilteringLogger.test_exception() use BoundLogger(ReturnLogger(), [], {}) and do not check this case.

Solution

To address this issue, I would like to create a pull request to fix the problem. However, I would appreciate your advice on the following questions:

1. The standard library logging module allows calling logger.exception() without any additional arguments, and it does not raise any exceptions. Should we follow the same behavior in structlog, or maybe should we raise an exception when sys.exc_info() is empty?
2. Should I add new tests to ensure that logger.exception("test") works correctly even when there is no additional information about the exception, or should I modify existing tests to cover this case?

Thank you for your attention, and I look forward to your feedback.

[GabDug]

I indeed faced the same problem, trying to migrate from the standard lib to structlog.

I instead used a custom processor, and changed _figure_out_exc_info's signature to OptExcInfo.

I guess following the same behaviour as the standard library would be more intuitive, ans ease migration.

def _figure_out_exc_info(v: Any) -> Union["sys._OptExcInfo", "ExcInfo"]:
    if isinstance(v, BaseException):
        return (v.__class__, v, v.__traceback__)

    if isinstance(v, tuple):
        return v  # type: ignore[return-value]

    if v:
        return sys.exc_info()  # type: ignore[return-value]

    return (None, None, None)

def error_mapping_processor(_, __, event_dict: EventDict) -> EventDict:
    if "exc_info" in event_dict:
        exc_type, exc_value, exc_traceback = _figure_out_exc_info(event_dict.pop("exc_info"))
        if exc_type is None or exc_value is None or exc_traceback is None:
            return event_dict
        event_dict["error.stack"] = "".join(traceback.format_exception(exc_type, exc_value, exc_traceback))
        event_dict["error.message"] = str(exc_value)
        event_dict["error.kind"] = exc_type.__name__

    return event_dict

[am1ter]

@hynek Hello! What do you think about this issue?

1. I can create a pull request and change the behavior of the exception method if you think it is a good idea.
2. I can also try to fix the issues with the unit tests and suggest an additional PR related to it.

[hynek]

So firstly I don't think structlog should crash here. I'm usually in the crash-early camp, but in this case the semantics are a bit muddy.

That said, correct me if I'm wrong but ISTM that the problem are exception formatters that don't handle (None, None, None) correctly?

Therefore, the fix would be adding guard clauses before

structlog/src/structlog/_frames.py

Line 23 in d87abcb

sio = StringIO()

and

structlog/src/structlog/dev.py

Line 421 in d87abcb

self._exception_formatter(sio, exc_info)

?

---

What exactly would you suggest to test in TestBoundLogger.test_exception_exc_info() and BoundLogger(ReturnLogger(), [], {})?

[am1ter]

@hynek hello!

1. Yes, I believe making a small change to the following code block would be sufficient to prevent the exception from being raised:
   

   structlog/src/structlog/dev.py

   Lines 418 to 429 in d87abcb

   	if exc_info:
   	exc_info = _figure_out_exc_info(exc_info)
   	self._exception_formatter(sio, exc_info)
   	elif exc is not None:
   	if self._exception_formatter is not plain_traceback:
   	warnings.warn(
   	"Remove `format_exc_info` from your processor chain "
   	"if you want pretty exceptions.",
   	stacklevel=2,
   	)
   	sio.write("\n" + exc)

   
   However, in my opinion, it would be clearer and more precise to add a guard clause here:
   

   structlog/src/structlog/stdlib.py

   Lines 208 to 217 in d87abcb

   	def exception(
   	self, event: str | None = None, *args: Any, **kw: Any
   	) -> Any:
   	"""
   	Process event and call `logging.Logger.error` with the result,
   	after setting ``exc_info`` to `True`.
   	"""
   	kw.setdefault("exc_info", True)
   	return self.error(event, *args, **kw)

   
   

   structlog/src/structlog/_log_levels.py

   Lines 83 to 86 in d87abcb

   	def exception(self: FilteringBoundLogger, event: str, **kw: Any) -> Any:
   	kw.setdefault("exc_info", True)
   	return self.error(event, **kw)

   
   Currently, I'm not certain whether this change would affect another part of the library or not, but it seems incorrect to set exc_info to True when there is no actual exception information.

2. Regarding tests: I'm not an expert, but I can suggest capturing the log message that is printed to stdout and verifying its correctness. Here's an example:

   with contextlib.redirect_stdout(io.StringIO()) as log_msg:
       logger.exception(message)
   log_msg.getvalue()

   Alternatively, we could consider adding an additional StreamHandler to the IO object:

   log_text_io = io.StringIO()
   handler = logging.StreamHandler(log_text_io)
   logger.addHandler(handler)
   logger.exception(message)
   log_msg.getvalue()

What are your thoughts on this?

[hynek]

Given that BoundLoggers are pluggable, I don’t think that’s the correct place. For instance that would still crash with the default config.

I think the correct place is indeed the one that gets the traceback (albeit indirect) and acts on it. Which would be the format processor. ConsoleRenderer too, because it does special magic for a better DX.

---

As for the test I misread you. Of course we have to also add tests, once we add special treatment for this case. :)

[hynek]

I believe #533 should fix your issues?

[am1ter]

I believe #533 should fix your issues?

Thank you very much! Now it works as expected. I am looking forward for merging #533 into the main.