Skip to content

exc_info is not resolved properly when calling BoundLogger.exception #571

@bcdickinson

Description

@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.

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! ❤️

Metadata

Metadata

Assignees

No one assigned

    Labels

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions