exc_info is not resolved properly when calling BoundLogger.exception

[bcdickinson]

I have a slightly unusual setup that I should explain first. I'm using the maximalist approach of routing all of my structlog and stdlib logging through ProcessorFormatter as per the docs, but we're also sending logs at ERROR and above to Rollbar using pyrollbar and its RollbarHandler.

Unfortunately, RollbarHandler on its own doesn't play nicely with that approach because it doesn't call self.format() anywhere meaning we don't have anywhere to plug in ProcessorFormatter. So, we have a custom subclass (called StructlogRollbarHandler) that does similar things to ProcessorFormatter.format() in its emit() method before calling the superclass emit() method to send the payload to Rollbar. A notable exception to that is using the raw record.msg rather than record.getMessage() as per #520.

That means that it's really important for us that all our LogRecord objects, whether from structlog or stdlib loggers, look the same when they get to the Handler.emit(record) stage of the pipeline, because we can't rely on ProcessorFormatter or any structlog renderers patching things up for us. This is mostly working fine, apart from calls to BoundLogger.exception.

When we call BoundLogger.exception, the LogRecord that gets to our StructlogRollbarHandler.emit(record) method has an event dict for its record.msg attribute, as you'd expect, and that dict has "exc_info" in it, but the record.exc_info attribute itself is None! Obviously this isn't the case for stdlib-originated records.

Having spent a while debugging, this seems to be because BoundLogger.exception calls self.error rather than doing something like self._proxy_to_logger("exception", event, *args, **{"exc_info": True, **kw}). That means that the wrapped logging.Logger thinks this was a logger.error call and not a logger.exception call, which changes the behaviour in a really subtle way.

All of our LogRecord objects from structlog go through ProcessorFormatter.wrap_for_formatter, which puts exc_info in the record.msg event dict and strips it out of the kwargs. Then, because of the aforementioned change of the effective log method from .exception to .error, the stdlib logger doesn't set this back to True for us and then Logger._log doesn't call sys.exc_info() for us.

• logging.Logger.error
• logging.Logger.exception

I'm honestly not sure whether this is a bug in my code or structlog. I accept that using ProcessorFormatter alongside other formatters isn't really documented/supported, but it's really close to working perfectly apart from this!

Sorry for writing such a long issue, thank you for an amazing library! ❤️

[pahrohfit]

Got a small code snippet to demo this behavior?

[bcdickinson]

Sure, I've put together a gist with a minimal example: https://gist.github.com/bcdickinson/b5ec383a518995addc0df629f6c7a83f

[pahrohfit]

Gotcha, I see now. Will look at the codebase to see if there is a bug/better way, but here is a structlog.processor and some small changes to your structlog.configure call, as well as your logging.Handler to correct it.

Also, as stated on the ProcessFormatter doc:

Its static method `wrap_for_formatter` must be the final processor in *structlog*'s processor chain.

This was missing (part of the update to structlog.configure

import logging.config
import structlog.dev
import structlog.processors
import structlog.stdlib


def fixup_event(
    logger: logging.Logger, method_name: str, event_dict: structlog.typing.EventDict
) -> structlog.typing.EventDict:
    if method_name != "error":
        return event_dict

    if event_dict.get('exc_info') == True:
        event_dict['exc_info'] = structlog.processors._figure_out_exc_info(event_dict['exc_info'])
    return event_dict


structlog.configure(
    processors=[fixup_event, structlog.stdlib.ProcessorFormatter.wrap_for_formatter],
    logger_factory=structlog.stdlib.LoggerFactory(),
    wrapper_class=structlog.stdlib.BoundLogger,
    cache_logger_on_first_use=True,
)


class CustomHandler(logging.Handler):
    """
    The idea here is still that this understands structlog-y records that have
    been through ProcessorFormatter.wrap_for_formatter, but it doesn't then use
    ProcessorFormatter to format them.
    """

    def emit(self, record: logging.LogRecord) -> None:
        message, exc_info = record.getMessage(), record.exc_info
        if isinstance(record.msg, dict):
            message, exc_info = record.msg['event'], record.msg.get('exc_info', None)

        print(
            f"level: {record.levelname}; "
            f"msg: {message}; "
            f"exc_info: {exc_info}"
        )


if __name__ == "__main__":
    logging.config.dictConfig(
        {
            "version": 1,
            "formatters": {
                "console": {
                    "()": structlog.stdlib.ProcessorFormatter,
                    "processors": [
                        structlog.stdlib.ProcessorFormatter.remove_processors_meta,
                        structlog.processors.JSONRenderer(),
                    ],
                }
            },
            "handlers": {
                "normal_handler": {
                    "class": "logging.StreamHandler",
                    "formatter": "console",
                    "stream": "ext://sys.stdout",
                },
                "custom_handler": {
                    "class": "__main__.CustomHandler",
                },
            },
            "loggers": {
                "structlog_logger": {
                    "handlers": [
                        "normal_handler",
                        "custom_handler",
                    ],
                    "level": "DEBUG",
                    "propagate": False,
                },
                "non_structlog_logger": {
                    "handlers": [
                        "normal_handler",
                        "custom_handler",
                    ],
                    "level": "DEBUG",
                    "propagate": False,
                },
            },
        }
    )

    structlog_logger = structlog.get_logger("structlog_logger")
    non_structlog_logger = logging.getLogger("non_structlog_logger")

    structlog_logger.info("structlog info log")
    print()

    non_structlog_logger.info("non-structlog info log")
    print()

    try:
        raise Exception("Bang!")
    except Exception:
        structlog_logger.exception("structlog exception log")
        print()

        non_structlog_logger.exception("non-structlog exception log")

Now produces:

{"event": "structlog info log"}
level: INFO; msg: structlog info log; exc_info: None

{"event": "non-structlog info log"}
level: INFO; msg: non-structlog info log; exc_info: None

{"exc_info": ["<class 'Exception'>", "Exception('Bang!')", "<traceback object at 0x103bfe840>"], "event": "structlog exception log"}
level: ERROR; msg: structlog exception log; exc_info: (<class 'Exception'>, Exception('Bang!'), <traceback object at 0x103bfe840>)

{"event": "non-structlog exception log", "exc_info": ["<class 'Exception'>", "Exception('Bang!')", "<traceback object at 0x103bfe840>"]}
level: ERROR; msg: non-structlog exception log; exc_info: (<class 'Exception'>, Exception('Bang!'), <traceback object at 0x103bfe840>)

[bcdickinson]

Thanks for looking into this! I tried just monkey patching BoundLogger.exception to proxy to the logging.Logger.exception method instead of .error. This fixes the missing exc_info, but ends up printing a stack trace when ProcessorFormatter.format(record) calls super().format(record). I guess that's maybe why it calls .error in the first place?

Monkey patch:

def monkey_patched_boundlogger_exception(
    self: structlog.stdlib.BoundLogger,
    event: str | None = None,
    *args: Any,
    **kw: Any,
) -> Any:
    kw.setdefault("exc_info", True)
    return self._proxy_to_logger("exception", event, *args, **kw)


structlog.stdlib.BoundLogger.exception = monkey_patched_boundlogger_exception

structlog exception log output:

{"exc_info": true, "event": "structlog exception log"}
Traceback (most recent call last):
  File "/home/bdickinson/Git/structlog-520-snippet/structlog_520.py", line 98, in <module>
    raise Exception("Bang!")
Exception: Bang!
level: ERROR; msg: {'exc_info': True, 'event': 'structlog exception log'}; exc_info: (<class 'Exception'>, Exception('Bang!'), <traceback object at 0x7fc5dbc51140>)

I wonder if ProcessorFormatter.format should be calling the superclass method at all. Maybe it would make more sense to inline the code we actually want instead and keep tighter control of the output? I think that would just be something like setting record.asctime = record.formatTime() and setting record.exc_textappropriately, but I'm not super confident.

EDIT - the more I think about it, the more I think we shouldn't be calling return super().format(record) at the end of ProcessorFormatter.format(record) and should instead just return the output of the last processor directly. My thinking goes that we've already normalised both structlog and non-structlog LogRecords and the final processor in the ProcessorFormatter.processors should already have output a formatted string.

All that happens when the superclass method gets called is that it tries to format in values for which there won't be any placeholders any more (we've already done our formatting) and maybe adds some junk we didn't want if exc_info or stack_info are truthy (again, if we want to handle that stuff, we'd already have used ExceptionRender, StackInfoRenderer etc. as part of self.processors).

EDIT 2 - I've realised the above is wrong. The issue seems to be that keep_exc_info and keep_stack_info are only respected when the log record comes from a non-structlog logger.

[bcdickinson]

Hi @pahrohfit, I've put together a PR (#572) that fixes my issue and keeps all the tests green and I'd really appreciate your feedback on whether this needs more documentation or tests or anything.