classification
Title: enhance formatting in logging package
Type: enhancement Stage: resolved
Components: Library (Lib) Versions: Python 3.4
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: mdt, python-dev, vinay.sajip
Priority: normal Keywords:

Created on 2013-08-06 15:57 by mdt, last changed 2013-08-08 17:29 by python-dev. This issue is now closed.

Messages (9)
msg194559 - (view) Author: M. Dietrich (mdt) Date: 2013-08-06 15:57
in logging/__init__.py line 328 there is a simple line:

     msg = msg % self.args

if that line fails this failure will be logged, not the line itself. i suggest to change the line to something like:

    try: msg = msg % self.args
    except TypeError: msg = 'logging formatting error with "%s" %% %s' % (
        msg, self.args, )

to be able to pinpoint the actual wrong formatting string (the stack trace doesnt help here).
msg194578 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2013-08-06 21:09
In recent versions of Python, information *is* printed which allows pinpointing the source of the formatting error. Consider the following script, logex.py:

import logging

logger = logging.getLogger(__name__)

def test():
    logger.debug('The result is ', 'abc')

def main():
    test()

if __name__ == '__main__':
    logging.basicConfig(level=logging.DEBUG)
    main()

When this is run with Python 2.7:

$ python logex.py
Traceback (most recent call last):
  File "/usr/lib/python2.7/logging/__init__.py", line 842, in emit
    msg = self.format(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 719, in format
    return fmt.format(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 464, in format
    record.message = record.getMessage()
  File "/usr/lib/python2.7/logging/__init__.py", line 328, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Logged from file logex.py, line 6

With Python 3.2:

$ python3.2 logex.py
Traceback (most recent call last):
  File "/usr/lib/python3.2/logging/__init__.py", line 937, in emit
    msg = self.format(record)
  File "/usr/lib/python3.2/logging/__init__.py", line 812, in format
    return fmt.format(record)
  File "/usr/lib/python3.2/logging/__init__.py", line 551, in format
    record.message = record.getMessage()
  File "/usr/lib/python3.2/logging/__init__.py", line 319, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Logged from file logex.py, line 6

As you can see, the filename and line number are identified, so you can see precisely where the formatting error is.
msg194589 - (view) Author: M. Dietrich (mdt) Date: 2013-08-06 23:00
yes, seeing the erranous line where the wrong formatstring comes from is nice but sometimes (for myself: often) i need to know what actually was tried to be logged. this information is lost in both cases.

this is especially sad if you have long-running processes that encounter an error after a long time and that error is logged but the logging itself fails due to formatting issues. i suggest to log whatever is avaiable in the suggested way to at least see this valuable information. the additional information where it comes from for further fixing is apreaciated as well. btw: the stackstrace of the logging internals could be left out in my oppinion, it just pollutes the output with no means to the programer.
msg194594 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2013-08-07 00:01
The location of the error isn't lost - that's the important thing. If it's that important that you never lose the parameters of a logging call, then you could just double check the formatting for errors, or use a specialised message object, as described in the documentation, which allows you control over the formatting:

http://docs.python.org/2/howto/logging.html#using-arbitrary-objects-as-messages
msg194604 - (view) Author: M. Dietrich (mdt) Date: 2013-08-07 11:23
for a logging library the important thing would be to not loose the information that was meant to log. as i said i do alot of long-running huge-data-processing scripts in py using the library. if the logging breaks but doesnt log what was intended to log i judge this a major problem. and furthermore: it is so simple to add both information: the data that was to be logged plus the state that an error occured while formatting and where the log-call was made.
msg194614 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2013-08-07 14:15
From the line number you mentioned, it looks like you're talking about Python 2.7. However, Python 2.7 is closed to new features: generally speaking, only bug fixes are supposed to be committed to this branch.

I can consider expanding the "Logged from ..." error message for 3.4.
msg194633 - (view) Author: M. Dietrich (mdt) Date: 2013-08-07 23:04
thanks, it will be really helpful for me to have this fixed.

as i consider this a "bug" it would be possible to "fix" this for 2.7 and yes you are right, i talked about 2.7 as we are still using this version in production.
msg194634 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2013-08-07 23:18
Sorry, not for 2.7 - it's not a bug.
msg194698 - (view) Author: Roundup Robot (python-dev) Date: 2013-08-08 17:29
New changeset a206f952668e by Vinay Sajip in branch 'default':
Closes #18671: Output more information when logging exceptions occur.
http://hg.python.org/cpython/rev/a206f952668e
History
Date User Action Args
2013-08-08 17:29:05python-devsetstatus: open -> closed

nosy: + python-dev
messages: + msg194698

resolution: fixed
stage: resolved
2013-08-07 23:18:51vinay.sajipsetmessages: + msg194634
2013-08-07 23:04:13mdtsetstatus: pending -> open

messages: + msg194633
2013-08-07 14:15:20vinay.sajipsetstatus: open -> pending
resolution: not a bug -> (no value)
messages: + msg194614

versions: + Python 3.4
2013-08-07 11:23:04mdtsetstatus: pending -> open

messages: + msg194604
2013-08-07 00:01:36vinay.sajipsetstatus: open -> pending

messages: + msg194594
2013-08-06 23:00:48mdtsetstatus: pending -> open

messages: + msg194589
2013-08-06 21:09:51vinay.sajipsetstatus: open -> pending
resolution: not a bug
messages: + msg194578

components: + Library (Lib), - Extension Modules
2013-08-06 16:55:14r.david.murraysetnosy: + vinay.sajip
2013-08-06 15:57:49mdtcreate