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

Fix exc_info and race condition in ProcessorFormatter #109

Closed
wants to merge 3 commits into from
Closed

Fix exc_info and race condition in ProcessorFormatter #109

wants to merge 3 commits into from

Conversation

@andreiko
Copy link

@andreiko andreiko commented May 3, 2017

I'm totally new to structlog so it's possible that I just missed something, but I think there's an issue with exception formatting and some sort of race condition in ProcessorFormatter. Let me illustrate that with a code example:

#!/usr/bin/env python3
import logging
import structlog
import sys

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

handler_structlog = logging.StreamHandler(stream=sys.stdout)
handler_structlog.setFormatter(structlog.stdlib.ProcessorFormatter(
    processor=structlog.processors.JSONRenderer(),
    # processor=structlog.dev.ConsoleRenderer(colors=False),
    foreign_pre_chain=[
        structlog.processors.format_exc_info,
    ],
))

handler_classic = logging.StreamHandler(stream=sys.stdout)
handler_classic.setFormatter(logging.Formatter(
    fmt="%(asctime)s - %(levelname)s - %(message)s",
))

logger1 = logging.getLogger('L1')
logger1.addHandler(handler_classic)
logger1.addHandler(handler_structlog)

logger2 = logging.getLogger('L2')
logger2.addHandler(handler_structlog)
logger2.addHandler(handler_classic)

for logger in (logger1, logger2):
    try:
        raise RuntimeError("ohnoes")
    except Exception:
        logger.exception("the worst has happened")

    print("--")
    print()

Here I'm creating two stdlib handlers: one that's using ProcessorFormatter and one with the standard logging.Formatter.
Then I create two loggers, each having those two handlers but in different order.

If I run it with the latest release of structlog, I'll get the following output:

2017-05-02 22:30:47,560 - ERROR - the worst has happened
Traceback (most recent call last):
  File "/Users/andrey/dev/src/github.com/andreiko/sandbox/sandbox.py", line 30, in <module>
    raise RuntimeError("ohnoes")
RuntimeError: ohnoes
{"event": "the worst has happened"}
Traceback (most recent call last):
  File "/Users/andrey/dev/src/github.com/andreiko/sandbox/sandbox.py", line 30, in <module>
    raise RuntimeError("ohnoes")
RuntimeError: ohnoes
--

{"event": "the worst has happened"}
Traceback (most recent call last):
  File "/Users/andrey/dev/src/github.com/andreiko/sandbox/sandbox.py", line 30, in <module>
    raise RuntimeError("ohnoes")
RuntimeError: ohnoes
2017-05-02 22:30:47,560 - ERROR - {"event": "the worst has happened"}
Traceback (most recent call last):
  File "/Users/andrey/dev/src/github.com/andreiko/sandbox/sandbox.py", line 30, in <module>
    raise RuntimeError("ohnoes")
RuntimeError: ohnoes
--

I see a couple of issues here:

  1. Traceback from the exception got printed outside of the json document because processor functions hadn't had access to exc_info field.
  2. The logger in which structlog formatter had been used first, printed out the json document twice because the record had been mutated in ProcessorFormatter.

I tried to pull together a patch and after the fix the output looks like I would expect it to:

2017-05-02 22:31:58,257 - ERROR - the worst has happened
Traceback (most recent call last):
  File "/Users/andrey/dev/src/github.com/andreiko/sandbox/sandbox.py", line 30, in <module>
    raise RuntimeError("ohnoes")
RuntimeError: ohnoes
{"event": "the worst has happened", "exception": "Traceback (most recent call last):\n  File \"/Users/andrey/dev/src/github.com/andreiko/sandbox/sandbox.py\", line 30, in <module>\n    raise RuntimeError(\"ohnoes\")\nRuntimeError: ohnoes"}
--

{"event": "the worst has happened", "exception": "Traceback (most recent call last):\n  File \"/Users/andrey/dev/src/github.com/andreiko/sandbox/sandbox.py\", line 30, in <module>\n    raise RuntimeError(\"ohnoes\")\nRuntimeError: ohnoes"}
2017-05-02 22:31:58,257 - ERROR - the worst has happened
Traceback (most recent call last):
  File "/Users/andrey/dev/src/github.com/andreiko/sandbox/sandbox.py", line 30, in <module>
    raise RuntimeError("ohnoes")
RuntimeError: ohnoes
--
  1. Exception is inside the json document
  2. Handler that came after ProcessorFormatter printed the original record message
@codecov
Copy link

@codecov codecov bot commented May 4, 2017

Codecov Report

Merging #109 into master will decrease coverage by 0.38%.
The diff coverage is 62.5%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master     #109      +/-   ##
==========================================
- Coverage     100%   99.61%   -0.39%     
==========================================
  Files          13       13              
  Lines         774      782       +8     
  Branches       96       98       +2     
==========================================
+ Hits          774      779       +5     
- Misses          0        2       +2     
- Partials        0        1       +1
Impacted Files Coverage Δ
src/structlog/stdlib.py 97.74% <62.5%> (-2.26%) ⬇️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 5636314...38dafc2. Read the comment docs.

@hynek
Copy link
Owner

@hynek hynek commented May 7, 2017

Thank you very much for that detailed report/patch! The only big picture thing that comes to my mind is that we probably will have to make the unsetting of stack information on the log record an option since it’s possible, someone (there is always someone) may rely on it being there?

I could get talked into making the new behavior the default because it’s just very unlikely.

@@ -393,16 +393,22 @@ class ProcessorFormatter(logging.Formatter):
.. versionadded:: 17.1.0
"""
def __init__(self, processor, foreign_pre_chain=None, *args, **kwargs):
def __init__(self, processor, foreign_pre_chain=None,
unset_record_stack=False, *args, **kwargs):

This comment has been minimized.

@andreiko

andreiko May 9, 2017
Author

How does this look now?

This modified version of record doesn't really go anywhere except the base implementation of format(), so maybe append_stack=True parameter that would do the opposite thing would be better.

What do you think?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Linked issues

Successfully merging this pull request may close these issues.

None yet

2 participants