Finding the source of format errors when using python logging

Question

When I have lots of different modules using the standard python logging module, the following stack trace does little to help me find out where, exactly, I had a badly formed log statement:

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: not all arguments converted during string formatting

I'm only starting to use python's logging module, so maybe I am overlooking something obvious. I'm not sure if the stack-trace is useless because I am using greenlets, or if this is normal for the logging module, but any help would be appreciated. I'd be willing to modify the source, anything to make the logging library actually give a clue as to where the problem lies.

Answer 1

Rather than editing installed python code, you can also find the errors like this:

    def handleError(record):
        raise RuntimeError(record)
    handler.handleError = handleError

where handler is one of the handlers that is giving the problem. Now when the format error occurs you'll see the location.

Answer 2

The logging module is designed to stop bad log messages from killing the rest of the code, so the emit method catches errors and passes them to a method handleError. The easiest thing for you to do would be to temporarily edit /usr/lib/python2.6/logging/__init__.py, and find handleError. It looks something like this:

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.
    """
    if raiseExceptions:
        ei = sys.exc_info()
        try:
            traceback.print_exception(ei[0], ei[1], ei[2],
                                      None, sys.stderr)
            sys.stderr.write('Logged from file %s, line %s\n' % (
                             record.filename, record.lineno))
        except IOError:
            pass    # see issue 5971
        finally:
            del ei

Now temporarily edit it. Inserting a simple raise at the start should ensure the error gets propogated up your code instead of being swallowed. Once you've fixed the problem just restore the logging code to what it was.