| msg213465 - (view) |
Author: the mulhern (the.mulhern) |
Date: 2014-03-13 20:43 |
| Here's my illustrating trace: Python 3.3.2 (default, Aug 23 2013, 19:00:04) [GCC 4.8.1 20130603 (Red Hat 4.8.1-1)] on linux Type "help", "copyright", "credits" or "license" for more information. >>> class Junk(): ... def __repr__(self): ... raise AttributeError("junk") ... >>> import logging >>> logging.warning("%r", Junk()) Traceback (most recent call last): File "/usr/lib64/python3.3/logging/__init__.py", line 937, in emit msg = self.format(record) File "/usr/lib64/python3.3/logging/__init__.py", line 808, in format return fmt.format(record) File "/usr/lib64/python3.3/logging/__init__.py", line 546, in format record.message = record.getMessage() File "/usr/lib64/python3.3/logging/__init__.py", line 311, in getMessage msg = msg % self.args File "", line 3, in __repr__ AttributeError: junk Logged from file , line 1 The alternative that would be desirable is that the LogRecord initializer would catch the exception and log that something bad happened while trying to log. I expect that it would be better if it were optional behavior. Note that the use of the % operator happens very early in the logging process, so implementing your own handler or overriding the makeRecord method won't fix this problem. There are plenty of situations where you would like to log a lot of information, but would be embarrassed to crash while logging. I realize that I could implement this by surrounding every log call with some function that caught the exception and then logged that an exception had occurred while trying to log, but I think it might work better within the logging module. |
|
|
| msg213471 - (view) |
Author: R. David Murray (r.david.murray) *  |
Date: 2014-03-13 21:16 |
| Logging tries to catch errors during logging and log them. This is an edge case it doesn't handle, because when it tries to log it...it tries to print the arguments, and of course the repr of the argument fails (again). So I think this is a bug. |
|
|
| msg213523 - (view) |
Author: Vinay Sajip (vinay.sajip) * |
Date: 2014-03-14 08:22 |
| Shouldn't any fix also be applied to 3.3? According to PEP 398, there will be a 3.3.6 release after 3.4 is released (around May 2014). |
|
|
| msg213524 - (view) |
Author: Vinay Sajip (vinay.sajip) * |
Date: 2014-03-14 08:51 |
| I've looked into it further, and IMO this is not a bug. The rationale is this: when an exception is raised during logging, it is passed to a handleError method, see http://hg.python.org/cpython/file/67ada6ab7fe2/Lib/logging/__init__.py#l786 This swallows the exception if logging.raiseExceptions is false or if there is no sys.stderr, otherwise it just writes the original traceback to sys.stderr and ignores any I/O errors which result during that write. ISTM RDM's analysis is not quite right: logging doesn't try to re-print the arguments. The key indicator is the line Logged from file , line 1 which appears in the traceback shown, indicating that there is no exception in the handleError method itself. The suggestion by the.mulhern is also based on an incorrect assumption: logging applies the formatting lazily (i.e. late, rather than early), so it would be premature to do anything in LogRecord.__init__. The exception-causing code is called after determining that the record must be processed, and a formatter is asked to format it. This is by design. Note that logging doesn't crash: if the script class Junk: def __repr__(self): raise AttributeError('junk') import logging; logging.warning('%r', Junk()) print('Done.') is run, it prints Traceback (most recent call last): File "/home/vinay/projects/python/2.7/Lib/logging/__init__.py", line 851, in emit msg = self.format(record) File "/home/vinay/projects/python/2.7/Lib/logging/__init__.py", line 724, in format return fmt.format(record) File "/home/vinay/projects/python/2.7/Lib/logging/__init__.py", line 464, in format record.message = record.getMessage() File "/home/vinay/projects/python/2.7/Lib/logging/__init__.py", line 328, in getMessage msg = msg % self.args File "logtest3.py", line 3, in __repr__ raise AttributeError('junk') AttributeError: junk Logged from file logtest3.py, line 5 Done. That last "Done." shows that logging keeps going: while it prints the exception traceback to sys.stderr (so it looks like it's failing) it is not actually failing, and the code after the logging call continues normally even if there is a formatting failure (or other exception during emission of a logging message). Closing as invalid, unless you come up with something else :-) |
|
|
| msg213539 - (view) |
Author: R. David Murray (r.david.murray) * |
Date: 2014-03-14 12:46 |
| Yes on 3.3 fixes, but you are right that it doesn't need fixed there. This appears to be a 3.4 regression. I used exactly the test you suggest to reproduce it on 3.4...there there is a chained traceback and Done does not get printed. So, the original report is indeed invalid, but we've uncovered a regression. Fortunately it is a low impact regression. I'm guessing this arises from the improvements you made to the "fallback" logging of these errors. |
|
|
| msg213543 - (view) |
Author: the mulhern (the.mulhern) |
Date: 2014-03-14 13:16 |
| Yes, I really misinterpreted what I saw. So glad it's a bug anyway and I'm not just wasting your time ;) |
|
|
| msg213549 - (view) |
Author: Roundup Robot (python-dev)  |
Date: 2014-03-14 13:42 |
| New changeset 73c2a70e4b35 by Vinay Sajip in branch 'default': Closes #20918: Added handling for exceptions during fallback output of logging exceptions. http://hg.python.org/cpython/rev/73c2a70e4b35 |
|
|
| msg213552 - (view) |
Author: Vinay Sajip (vinay.sajip) * |
Date: 2014-03-14 13:48 |
| This fix doesn't seem to meet the criteria for cherry-picking for 3.4 - "Only important interface changes, new features, or bugfixes should be checked in now" - so I haven't created a separate cherry-pick issue for it. But I will add larry to nosy in case he thinks I should do so for 73c2a70e4b35. |
|
|
| msg213553 - (view) |
Author: R. David Murray (r.david.murray) * |
Date: 2014-03-14 13:58 |
| At this point only things that would make it a "brown bag" release (broken out of the box) would get cherry picked. I agree that this doesn't qualify...having repr raise is a pretty unusual occurrence. |
|
|
| msg213959 - (view) |
Author: the mulhern (the.mulhern) |
Date: 2014-03-18 13:53 |
| Thanks for the fix. When you say "having repr raise is a pretty unusual occurrence" you probably mean "having repr raise should be a pretty unusual occurrence". I think its more usual than you realize and the regression in 3.4 will have consequences. |
|
|
| msg213971 - (view) |
Author: R. David Murray (r.david.murray) * |
Date: 2014-03-18 14:32 |
| Did you reopen the issue accidentally? The bug has been fixed. |
|
|