Getting a more useful 'logging' module error output in python

Question

I am using the logger module of python (python version 3.x, but it should not matter) and I noticed that an error in a format string is reported as such:

Traceback (most recent call last):
  File "/usr/lib/python3.1/logging/__init__.py", line 770, in emit
    msg = self.format(record)
  File "/usr/lib/python3.1/logging/__init__.py", line 650, in format
    return fmt.format(record)
  File "/usr/lib/python3.1/logging/__init__.py", line 438, in format
    record.message = record.getMessage()
  File "/usr/lib/python3.1/logging/__init__.py", line 308, in getMessage
    msg = msg % self.args
TypeError: %d format: a number is required, not str

As you can see, there is no mention of where the actual error (in my code) was. By the way, here's what was wrong in my code:

logging.debug('This is a string %d', str(foo))

Changing the %d in %s solved the problem.

My question is: how do I get some slightly more useful information from the logging module output? Do I have to write my own logger? Where do I tweak the logger module?

Answer 1

If I understand you properly, the problem here is that the traceback does not give you any indication from where in your code the error originates. Somehow you had to track down the line

logging.debug('This is a string %d', str(foo))

yourself.

The logging module was designed so that exceptions that occur during an emit() call are handled by the handler's handleError method:

def handleError(self, record):
    """
    Handle errors which occur during an emit() call.

    This method should be called from handlers when an exception is
    encountered during an emit() call. If raiseExceptions is false,
    exceptions get silently ignored. This is what is mostly wanted
    for a logging system - most users will not care about errors in
    the logging system, they are more interested in application errors.
    You could, however, replace this with a custom handler if you wish.
    The record which was being processed is passed in to this method.
    """

You can override this method to see the full traceback:

    import sys
    import logging

    class MyStreamHandler(logging.StreamHandler):
        def handleError(self, record):
            raise

    if __name__ == '__main__':
        console = MyStreamHandler()
        logger=logging.getLogger(__name__)
        logger.setLevel(logging.DEBUG)
        logger.addHandler(console)
        logger.debug('%d','ahh')

yields

Traceback (most recent call last):
  File "/tmp/test.py", line 25, in <module>
    logger.debug('%d','ahh')
  File "/usr/lib/python2.6/logging/__init__.py", line 1036, in debug
    self._log(DEBUG, msg, args, **kwargs)
  File "/usr/lib/python2.6/logging/__init__.py", line 1165, in _log
    self.handle(record)
  File "/usr/lib/python2.6/logging/__init__.py", line 1175, in handle
    self.callHandlers(record)
  File "/usr/lib/python2.6/logging/__init__.py", line 1212, in callHandlers
    hdlr.handle(record)
  File "/usr/lib/python2.6/logging/__init__.py", line 673, in handle
    self.emit(record)
  File "/usr/lib/python2.6/logging/__init__.py", line 796, in emit
    self.handleError(record)
  File "/usr/lib/python2.6/logging/__init__.py", line 768, in emit
    msg = self.format(record)
  File "/usr/lib/python2.6/logging/__init__.py", line 648, in format
    return fmt.format(record)
  File "/usr/lib/python2.6/logging/__init__.py", line 436, in format
    record.message = record.getMessage()
  File "/usr/lib/python2.6/logging/__init__.py", line 306, in getMessage
    msg = msg % self.args
TypeError: %d format: a number is required, not str

whereas using the usual StreamHandler, you get only:

Traceback (most recent call last):
  File "/usr/lib/python2.6/logging/__init__.py", line 768, in emit
    msg = self.format(record)
  File "/usr/lib/python2.6/logging/__init__.py", line 648, in format
    return fmt.format(record)
  File "/usr/lib/python2.6/logging/__init__.py", line 436, in format
    record.message = record.getMessage()
  File "/usr/lib/python2.6/logging/__init__.py", line 306, in getMessage
    msg = msg % self.args
TypeError: %d format: a number is required, not str

Answer 2

Was just about to post this when Unutbu beat me to it. But here it is anyway:

You could try subclassing whichever handler you're using (example below using StreamHandler) and overiding the format method with a function that wraps it in a try: block

import traceback, logging

class MyStreamHandler(logging.StreamHandler):
    def format(self, record):
        try:
            return logging.StreamHandler.format(self, record)
        except TypeError:
            # Print a stack trace that includes the original log call
            traceback.print_stack() 


if __name__ == "__main__":
    log = logging.getLogger("testlogger")
    handler = MyStreamHandler()

    log.addHandler(handler)

    log.error("Try interpolating an int correctly: %i", 1)

    log.error("Now try passing a string to an int: %d", 'abc')

    log.error("And then a string to a string %s", 'abc')

gives me:

Try interpolating an int correctly: 1
  File "logtest2.py", line 19, in ?
    log.error("Now try passing a string to an int: %d", 'abc')
  File "/usr/lib64/python2.4/logging/__init__.py", line 999, in error
    apply(self._log, (ERROR, msg, args), kwargs)
  File "/usr/lib64/python2.4/logging/__init__.py", line 1079, in _log
    self.handle(record)
  File "/usr/lib64/python2.4/logging/__init__.py", line 1089, in handle
    self.callHandlers(record)
  File "/usr/lib64/python2.4/logging/__init__.py", line 1126, in callHandlers
    hdlr.handle(record)
  File "/usr/lib64/python2.4/logging/__init__.py", line 642, in handle
    self.emit(record)
  File "/usr/lib64/python2.4/logging/__init__.py", line 731, in emit
    msg = self.format(record)
  File "logtest2.py", line 8, in format
    traceback.print_stack()
None
And then a string to a string abc

I wouldn't leave this in any production code, but it should help you find things like

log.error("%d", 'a string')