This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: Logging of logging exceptions can fail in 3.4 if args are unprintable
Type: behavior Stage: resolved
Components: Library (Lib) Versions: Python 3.4, Python 3.5
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: larry, python-dev, r.david.murray, the.mulhern, vinay.sajip, yselivanov
Priority: normal Keywords: 3.4regression, easy

Created on 2014-03-13 20:43 by the.mulhern, last changed 2022-04-11 14:57 by admin. This issue is now closed.

Messages (11)
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 "<stdin>", line 3, in __repr__
AttributeError: junk
Logged from file <stdin>, 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) * (Python committer) 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) * (Python committer) 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) * (Python committer) 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 <stdin>, 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) * (Python committer) 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) (Python triager) 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) * (Python committer) 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) * (Python committer) 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) * (Python committer) Date: 2014-03-18 14:32
Did you reopen the issue accidentally?  The bug has been fixed.
History
Date User Action Args
2022-04-11 14:57:59adminsetgithub: 65117
2014-03-18 14:32:08r.david.murraysetstatus: open -> closed

messages: + msg213971
2014-03-18 13:53:38the.mulhernsetstatus: closed -> open

messages: + msg213959
2014-03-14 13:58:45r.david.murraysetmessages: + msg213553
2014-03-14 13:48:51vinay.sajipsetnosy: + larry
messages: + msg213552
2014-03-14 13:42:31python-devsetstatus: open -> closed

nosy: + python-dev
messages: + msg213549

resolution: fixed
stage: needs patch -> resolved
2014-03-14 13:16:19the.mulhernsetmessages: + msg213543
2014-03-14 12:46:48r.david.murraysetstatus: closed -> open
versions: - Python 2.7, Python 3.3
title: LogRecord.__init__ should handle exception if % operation fails -> Logging of logging exceptions can fail in 3.4 if args are unprintable
messages: + msg213539

keywords: + 3.4regression
resolution: not a bug -> (no value)
2014-03-14 08:51:38vinay.sajipsetstatus: open -> closed
assignee: vinay.sajip
resolution: not a bug
messages: + msg213524
2014-03-14 08:22:26vinay.sajipsetmessages: + msg213523
versions: + Python 3.3
2014-03-13 21:17:43r.david.murraysetkeywords: + easy
2014-03-13 21:16:26r.david.murraysetversions: + Python 3.4, Python 3.5, - Python 3.1, Python 3.2, Python 3.3
nosy: + r.david.murray

messages: + msg213471

type: enhancement -> behavior
stage: needs patch
2014-03-13 21:00:21yselivanovsetnosy: + vinay.sajip, yselivanov
2014-03-13 20:43:03the.mulherncreate