Unexpected handling of exc_info in structlog v24 when using .exception

[jf2]

Hi.

The new handling of the exception level has introduced a somewhat surprising behaviour.

To reproduce

import sys
import structlog


def custom_exception_processor(logger, name, event_dict):
    if "exc_info" in event_dict:
        exc_type, exc_value, exc_tb = sys.exc_info()
        if exc_value is not None:
            event_dict["event"] = str(exc_value)
        del event_dict["exc_info"]
    return event_dict


structlog.configure(processors=[custom_exception_processor,
                                structlog.stdlib.add_log_level,
                                structlog.stdlib.add_logger_name,
                                structlog.dev.ConsoleRenderer(),
                                structlog.stdlib.ProcessorFormatter.wrap_for_formatter],
                    wrapper_class=structlog.stdlib.BoundLogger,
                    logger_factory=structlog.stdlib.LoggerFactory())
logger = structlog.getLogger("test_logger")
try:
    raise ValueError("test")
except ValueError:
    logger.exception("test", exc_info=True)

I would expect the output to simply read:

[error    ] test                           [test_logger]

Instead, it reads:

[error    ] test                           [test_logger]
Traceback (most recent call last):
  File "inconsistent_exc_info.py", line 23, in <module>
    raise ValueError("test")
ValueError: test

The problem is that the wrapped python logger has a default value of exc_info=True for .exception, which does not get overridden.
Not entirely sure whose responsibility it is (processor or bound logger) to handle this case.

It happens here:

# structlog/_base.py:116 (BoundLoggerBase._process_event)

...
        for proc in self._processors:
            event_dict = proc(self._logger, method_name, event_dict)

        if isinstance(event_dict, (str, bytes, bytearray)):
            return (event_dict,), {}

The returned empty dictionary allows the exc_info to be set to True within the Python logger.

Note that in my reproduction example above, it also does not help if I force the event_dict['exc_info'] = False

Happy to hear your thoughts.

[hynek]

Hm, yeah this is a weird interplay that's as you write is not quite clear how it should be resolved.

A short-term fix for you is using error() instead of exception(), I guess.

Looks like we've got a similar problem solve on ProcessorFormatter in the form of keep_exc_info.

My best guess is that it should be an option on stdlib.BoundLogger to treat exc_info differently?

[hynek]

OK for posterity I took another look and this problem is two-fold but only affects ConsoleRenderer:

• we forward our event_dict to standard library logging at kwargs. Logger.exception has exc_info=True as kwarg.
• that means that we'd have to force an exc_info=False into it, however, exc_info gets popped out of the event_dict by ConsoleRenderer. It figures out that it should do nothing, but hides the fact from Logger.exception.

I think the best way forward would be to make exception handling optional in ConsoleRenderer? And if it's deactivated, exc_info is passed unchanged.