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

structlog not sending exc_info=True to logging wrapper #204

Closed
odannyc opened this issue Mar 29, 2019 · 5 comments

Comments

@odannyc
Copy link

@odannyc odannyc commented Mar 29, 2019

I'm having an issue when I use structlog to emit errors:

try:
    raise ValueError
except Exception:
    structlog.get_logger().exception("something happened")

That will remove the exc_info=True flag from the log so the base logging package can't pick that up and get the exception stack. I know this is true because I stepped through the code until I got to the stdlib logging package, and exc_info was None

This is my configuration:

json_handler = logging.StreamHandler(sys.stdout)
json_handler.setFormatter(jsonlogger.JsonFormatter())
logging.basicConfig(
    format="%(message)s",
    handlers=[json_handler],
    level=logging.INFO,
)

structlog.configure(
    processors=[
        structlog.stdlib.filter_by_level,
        structlog.stdlib.add_logger_name,
        structlog.stdlib.add_log_level,
        structlog.stdlib.PositionalArgumentsFormatter(),
        structlog.processors.StackInfoRenderer(),
        structlog.processors.format_exc_info,
        structlog.processors.UnicodeDecoder(),
        structlog.stdlib.render_to_log_kwargs,
    ],
    context_class=structlog.threadlocal.wrap_dict(dict),
    logger_factory=structlog.stdlib.LoggerFactory(),
    wrapper_class=structlog.stdlib.BoundLogger,
    cache_logger_on_first_use=True,
)
@hynek

This comment has been minimized.

Copy link
Owner

@hynek hynek commented Mar 29, 2019

Is this a dupe of #200?

@hynek

This comment has been minimized.

Copy link
Owner

@hynek hynek commented Mar 29, 2019

No wait, this is the opposite.

Just remove structlog.processors.format_exc_info from your processors and you should be fine. It takes exc_info and renders it into an exception key.

@vxgmichel

This comment has been minimized.

Copy link

@vxgmichel vxgmichel commented Jul 1, 2019

I ran into the same issue and it can be reproduced with the default logger:

import structlog

logger = structlog.get_logger()

try:
    1/0
except:
    logger.exception("Does not print the exception")
    logger.exception("Prints the exception", exc_info=True)

The corresponding output with structlog 19.1.0:

2019-07-01 11:56.36 Does not print the exception
2019-07-01 11:56.36 Prints the exception           
Traceback (most recent call last):
  File "test.py", line 6, in <module>
    1/0
ZeroDivisionError: division by zero
@wimglenn

This comment has been minimized.

Copy link

@wimglenn wimglenn commented Jul 25, 2019

I think the issue is here:

https://github.com/hynek/structlog/blob/19.1.0/src/structlog/_loggers.py#L80

Pure structlog / print logger just assumes logger.exception is a method same as the others. But stdlib does more than that: it's not only a message at level ERROR, it's also forcing the exc_info flag on.

So structlog is not exactly a drop-in replacement for stdlib when used within an except block.

Perhaps we could find a way that usage of the exception method will also inject exc_info=True to event dict, in order that users with a structlog.processors.format_exc_info processor or similar will see the context without having to explicitly opt-in.

btw, I think this is again #130 (which was closed).

@hynek

This comment has been minimized.

Copy link
Owner

@hynek hynek commented Sep 21, 2019

@vxgmichel Your problem is a #200 dupe. Danny was complaining that after configuring structlog to handle exceptions, the exceptions don't reach standard library.

@wimglenn You too are in the wrong ticket and the class you're referring to is the wrong end: it's the one that only writes out the result. The interesting one is the generic BoundLogger which is the interface to the user.

I'm closing this because the original problem is solved by my first response to Danny.


This problem keeps coming up but as I've explained in #130, I cannot change the behavior of the default BoundLogger lest I want to break thousands of systems. But I do agree that it is unfortunate, that get_logger().exception("foo") doesn't do what you'd expect. It's not something that should come up in production however it's a bad first impression. I think I'll solve it by adding a new processor to the development configuration that will set exc_info when the method's name is exception.

@hynek hynek closed this Sep 21, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
4 participants
You can’t perform that action at this time.