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 stdlib errors being logged as exceptions sometimes. #92

Merged
merged 2 commits into from Feb 8, 2017

Conversation

Projects
None yet
3 participants
@gilbsgilbs
Contributor

gilbsgilbs commented Nov 27, 2016

stdlib error log records were sometimes logged with exception level, sometimes
logged with error level by structlog. This is due to the non 1-1 mapping
between log levels and log names (some levels have the same name). If the
developer adds a new log name that conflicts with an already existing log
level without blacklisting it, it produces the unexpected behavior. It's even
random in Python 3: because of the hash seed, it will always produce the same
result in the same python interpreter instance, but will vary according to the
interpreter instance.

The problem is that once the mistake is done, it's pretty complicated to debug.
And it's even more complicated to write a test (since you will never notice a
behavior change in the same python instance). I think it would be a good idea
to add a disclaimer message at least. Feel free to add a test for this to
prevent future errors and time loss if you have any idea on how to write it.

Fix bug with stdlib.
stdlib error log records were sometimes logged with exception level, sometimes
logged with error level by structlog. This is due to the non 1-1 mapping
between log levels and log names (some levels have the same name). If the
developer adds a new log name that conflicts with an already existing log
level without blacklisting it, it produces the unexpected behavior. It's even
random in Python 3: because of the hash seed, it will always produce the same
result in the same python interpreter instance, but will vary according to the
interpreter instance.

The problem is that once the mistake is done, it's pretty complicated to debug.
And it's even more complicated to write a test (since you will never notice a
behavior change in the same python instance). I think it would be a good idea
to add a disclaimer message at least. Feel free to add a test for this to
prevent future errors and time loss if you have any idea on how to write it.
@codecov-io

This comment has been minimized.

codecov-io commented Nov 27, 2016

Current coverage is 100% (diff: 100%)

Merging #92 into master will not change coverage

@@           master   #92   diff @@
===================================
  Files          13    13          
  Lines         739   753    +14   
  Methods         0     0          
  Messages        0     0          
  Branches       91    94     +3   
===================================
+ Hits          739   753    +14   
  Misses          0     0          
  Partials        0     0          

Powered by Codecov. Last update e9fdd96...5292edf

@gilbsgilbs

This comment has been minimized.

Contributor

gilbsgilbs commented Nov 27, 2016

Just to be 100% clear. With the previous implementation, _LEVEL_TO_NAME could either output to:

{
     ERROR: 'error',
    … other entries …
 }

(expected)
or to:

{
     ERROR: 'exception',
    … other entries …
 }

(unexpected)

This means that the stdlib.BoundLogger class could either log errors to error level (expected) or to exception level (unexpected). Having a quick look at the code, stdlib.BoundLogger.log() seems the only method being impacted by this bug.

You'll probably notice tat this PR does not contain any tt's not about lazyness, but this one is incredibely hard to write. The best test I could write would be a test that:

  • Fails only one time out to two before the fix.
  • Fails only on PY3 (even if the bug might exist on PY2) before the fix.
  • Will not prevent future mistakes with other (new) log levels.

I don't write this kind of Schrödinger test, it's pointless… If you have any better idea on how to implement it, let me know.

@hynek

This comment has been minimized.

Owner

hynek commented Jan 11, 2017

Sorry I didn’t get around to look at this earlier. It looks important and should have a changelog entry I think.

@gilbsgilbs

This comment has been minimized.

Contributor

gilbsgilbs commented Jan 12, 2017

@hynek Done.

@hynek hynek merged commit 69eed86 into hynek:master Feb 8, 2017

3 checks passed

codecov/patch Coverage not affected when comparing e9fdd96...5292edf
Details
codecov/project 100% (+0.00%) compared to e9fdd96
Details
continuous-integration/travis-ci/pr The Travis CI build passed
Details
@hynek

This comment has been minimized.

Owner

hynek commented Feb 8, 2017

thank you and sorry i didn’t get around to this earlier!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment