classification
Title: logging must check exc_info correctly
Type: Stage: resolved
Components: Library (Lib) Versions: Python 3.7
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: Nosy List: krivushinme, mp5023, rhettinger, serhiy.storchaka, vinay.sajip
Priority: normal Keywords: patch

Created on 2017-06-26 13:23 by krivushinme, last changed 2017-10-13 14:20 by vinay.sajip. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 3792 closed mp5023, 2017-10-04 22:37
PR 3972 closed mp5023, 2017-10-12 19:13
Messages (11)
msg296892 - (view) Author: Mihail Krivushin (krivushinme) Date: 2017-06-26 13:23
Logging checking `if exc_info:` and this maybe incorrect, due exception instance can have __bool__ method and thus can be false. If this is a case, then error that is return false from __bool__ will cause logging to swallow traceback. We need to check exc_info correctly. Will do PR myself.
msg304208 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2017-10-12 06:58
PR 3792 breaks existing tests, and it seems to me, that it solves different issue, than reported here.
msg304209 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2017-10-12 07:18
This is not an issue that needs fixing; the current behaviour is by design. The documentation states about exc_info:

"There are two keyword arguments in kwargs which are inspected: exc_info which, if it does not evaluate as false, causes exception information to be added to the logging message. If an exception tuple (in the format returned by sys.exc_info()) is provided, it is used; otherwise, sys.exc_info() is called to get the exception information."

So, an individual exception instance returning false will not affect the truthiness of an exc_info tuple (if provided). I propose to close this issue as "not a bug" and reject the PR because (a) there's no issue to fix and (b) what Serhiy said.

If you still think there's an issue here, please post an example script which uses logging as documented and demonstrates a problem.
msg304217 - (view) Author: Raymond Hettinger (rhettinger) * (Python committer) Date: 2017-10-12 07:57
I agree that this should be closed.
msg304233 - (view) Author: Matthew Patton (mp5023) * Date: 2017-10-12 13:26
"exc_info which, if it does not evaluate as false", so we provide '1' or 'True'. The IF passes and immediately the formatter tries to dereference it blindly assuming it's Tuple and throws an Exception.

Either the Formatter needs to guard itself (best) or the caller needs to check the Type before allowing a call to the Formatter to go thru.

Should sys.exc_info() have already been called then the Tuple can have a valid frame reference or it's 3 None's. In this last case the Formatter is emitting a naked, zero context "NoneType None" line into the middle of the stack trace which is just annoying and pointless.

Again, I probably should have written the guard at the formatter to emit nothing when the field is None. It actually checks for the 2nd and 3rd fields, not the first.
msg304235 - (view) Author: Matthew Patton (mp5023) * Date: 2017-10-12 13:39
Additionally (probably should have separate PR) the _checkLevel was full of holes.
First, it's allowing any Integer which if you're claiming to "check" things is rather silly. At least bounds-check it to GE to NOTSET and LE to CRITICAL (or MAX or something handy in that regard).

Second, why is a string representation of an Integer a problem that needs to force the caller to fix his code? Same with lowercase of a recognized value. "Be liberal in what you accept" would seem to apply here. If it can be trivially reduced to an integer or upcased() to get a match then just do it, and send the corrected value back to the caller.
msg304238 - (view) Author: Matthew Patton (mp5023) * Date: 2017-10-12 13:48
And the reason to stomp on the "Level " is because by not doing so the message that is a single field (regex/awk) has been converted non-deterministically into two. This is very bad behavior. If emitting the string/int as-is looks wrong then "Level(value)" or some other notation that keeps it a single field is how it should print.
msg304265 - (view) Author: Matthew Patton (mp5023) * Date: 2017-10-12 16:17
I believe this diff addresses the failure of formatException() to check it's parameter's datatype. I still maintain this should be re-opened since it's guaranteed to raise an exception when someone sets 'exc_info=TruthyValue' in kwargs. albeit with a more focused PR.


diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py
index 00a022039d..5c61cd56a1 100644
--- a/Lib/logging/__init__.py
+++ b/Lib/logging/__init__.py
@@ -533,6 +533,8 @@ class Formatter(object):
         This default implementation just uses
         traceback.print_exception()
         """
+        if not isinstance(ei, tuple) or ei[0] is None:
+            return ""
         sio = io.StringIO()
         tb = ei[2]
         # See issues #9427, #1553375. Commented out for now.
@@ -584,9 +586,7 @@ class Formatter(object):
         if self.usesTime():
             record.asctime = self.formatTime(record, self.datefmt)
         s = self.formatMessage(record)
-        if (isinstance(record.exc_info, tuple) and record.exc_info[0]):
-            # Intercept 'Boolean' - causes subscript error if passed to formatException,
-            # and empty Tuples which emit 'NoneType None' into message.
+        if record.exc_info:
             # Cache the traceback text to avoid converting it multiple times
             # (it's constant anyway)
             if not record.exc_text:
msg304321 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2017-10-13 07:53
Matthew Patton: you don't appear to have read the documentation correctly. The formatException() method's exc_info positional parameter is expected to be a normal exception tuple, not just any truthy value. This is clearly stated in the documentation for the method.

That is different to the logger.debug() etc. methods, where a truthy value can be provided for the exc_info keyword parameter.
msg304340 - (view) Author: Matthew Patton (mp5023) * Date: 2017-10-13 14:05
I've triggered it which is why I looked for the problem and offered the defensive patch. As API writers you can NEVER assume your parameters are what you think they should be and just blindly proceed.
msg304341 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2017-10-13 14:20
> I've triggered it which is why I looked for the problem and offered the defensive patch.

That's why I asked for a small example which used logging as documented and demonstrated a problem. You haven't done that.

> As API writers you can NEVER assume your parameters are what you think they should be and just blindly proceed.

I think you'll find that in Python usage in general and the Python stdlib in particular, exhaustive checking of input parameters is not the norm. I'm not saying that no error checking is ever done nor that it should never be done, but your "NEVER" doesn't seem to hold up, as the stdlib contains many counterexamples.
History
Date User Action Args
2017-10-13 14:20:06vinay.sajipsetmessages: + msg304341
2017-10-13 14:05:52mp5023setmessages: + msg304340
2017-10-13 07:53:46vinay.sajipsetmessages: + msg304321
2017-10-12 19:13:50mp5023setpull_requests: + pull_request3950
2017-10-12 16:17:07mp5023setmessages: + msg304265
2017-10-12 13:48:08mp5023setmessages: + msg304238
2017-10-12 13:39:18mp5023setmessages: + msg304235
2017-10-12 13:26:44mp5023setmessages: + msg304233
2017-10-12 07:57:15rhettingersetstatus: pending -> closed

nosy: + rhettinger
messages: + msg304217

stage: patch review -> resolved
2017-10-12 07:18:46vinay.sajipsetstatus: open -> pending
resolution: not a bug
messages: + msg304209
2017-10-12 06:58:18serhiy.storchakasetnosy: + serhiy.storchaka
messages: + msg304208
2017-10-12 05:35:06berker.peksagsetnosy: + vinay.sajip
2017-10-11 19:03:04mp5023setnosy: + mp5023
2017-10-11 19:01:34mp5023setversions: + Python 3.7
2017-10-04 22:37:31mp5023setkeywords: + patch
stage: patch review
pull_requests: + pull_request3863
2017-06-26 13:23:05krivushinmecreate