Weird: logger only uses the formatter of the first handler for exceptions

I'm witnessing the logging module behaving in a funny way. Am I missing something ?

I'm doing the usual thing of having two handlers: a Stream开发者_如何学CHandler for logging only INFO and higher to the console, and a FileHandler that will also handle all the DEBUG information.

It worked fine until I decided to have a different format for the exeptions. I wanted a full stacktrace in the file, but just the exception type and value on the console. Since handlers have a setFormatter function, and since it seems easy to write a subclass of logging.Formatter, I thought it would work.

The console handler and the file handler both have their own formatter. The print statements in the code proves it. However, the call to logger.exception will use only the formatException of the first handler added => the exception is logged in the file with the format it should have in the console. Change the order of the logger.addHandler lines and then it's the formatException of the file handler that's used everywhere.

import logging
import sys

class ConsoleFormatter(logging.Formatter):
    def formatException(self, exc_info):
        # Ugly but obvious way to see who's talking.
        return "CONSOLE EXCEPTION %s: %s" % exc_info[:2]

def setup(path):
    logger = logging.getLogger()
    #
    file_handler = logging.FileHandler(path, mode='w')
    if __debug__:
        file_handler.setLevel(logging.DEBUG)
    else:
        file_handler.setLevel(logging.INFO)
    formatter = logging.Formatter("%(asctime)s %(levelname)-8s "
                                  "%(name)-16s %(message)s "
                                  "[%(filename)s@%(lineno)d in %(funcName)s]")
    file_handler.setFormatter(formatter)

    #
    console_handler = logging.StreamHandler(sys.stderr)
    console_handler.setLevel(logging.INFO)
    console_formatter = ConsoleFormatter("%(levelname)-8s - %(message)s")
    console_handler.setFormatter(console_formatter)

    # >>> FUN HAPPENS HERE <<<
    # Only the formatter of the first handler is used !  Both on the console
    # and in the file.  Change the order of these two lines to see.
    logger.addHandler(console_handler)
    logger.addHandler(file_handler)
    #
    # Proof that the two handlers have different formatters:
    print logger.handlers
    print file_handler.formatter.formatException
    print console_formatter.formatException
    #
    logger.setLevel(logging.DEBUG)
    logger.info("Logger ready.")

setup('test.log')
logger = logging.getLogger()
logger.debug("Only visible in the file.")
try:
    1/0
except ZeroDivisionError:
    logger.exception("boom")

What's going on ?

EDIT: I'm using python 2.6 by the way. EDIT: Typo in code about "console_formatter" variable name corrected.

---

This is the code I came up with. It does the job :).

class CachelessFormatter(logging.Formatter):
    # I came up with that after reading the answers to
    #     http://stackoverflow.com/questions/5875225/
    # which pointed me to
    #     http://bugs.python.org/issue6435
    # I still think Vinay Sajip has a bit of an attitude :p.
    def format(self, record):
        # Disable the caching of the exception text.
        backup = record.exc_text
        record.exc_text = None
        s = logging.Formatter.format(self, record)
        record.exc_text = backup
        return s

class ConsoleFormatter(CachelessFormatter):
    def formatException(self, exc_info):
        return "           %s: %s" % exc_info[:2]

def setup(path):
    file_handler = logging.FileHandler(path, mode='w')
    file_handler.setLevel(logging.DEBUG)
    formatter = CachelessFormatter("%(asctime)s %(levelname)-8s "
                                   "%(name)-16s %(message)s "
                                   "[%(filename)s@%(lineno)d in %(funcName)s]")
    file_handler.setFormatter(formatter)

    console_handler = logging.StreamHandler(sys.stderr)
    console_handler.setLevel(logging.INFO)
    formatter = ConsoleFormatter("%(levelname)-8s - %(message)s")
    console_handler.setFormatter(formatter)

    logger = logging.getLogger()
    logger.addHandler(file_handler)
    logger.addHandler(console_handler)
    if __debug__:
        logger.setLevel(logging.DEBUG)
    else:
        logger.setLevel(logging.INFO)
    logger.info("Logger ready.")

if __name__ == '__main__':
    setup('test.log')
    logger = logging.getLogger()
    logger.debug("Only shows in the file")
    try:
        1 / 0
    except ZeroDivisionError:
        pass
    logger.exception("boom")

---

I found your problem! If you look in logger/__init__.py at the source code for Formatter.format, on line 440 (for py2.6) you will see the following:

        if record.exc_info:
            # Cache the traceback text to avoid converting it multiple times
            # (it's constant anyway)
            if not record.exc_text:
                record.exc_text = self.formatException(record.exc_info)

This is not true in your case since you're overriding formatException. If you comment out the if not record.exc_text (and fix indentation accordingly), it seems to work as expected.

The bug seems to already be reported here: http://bugs.python.org/issue6435

---

The first time I ran your code, I got a traceback:

Traceback (most recent call last):
  File "logger.py", line 42, in <module>
    setup('test.log')
  File "logger.py", line 37, in setup
    print console_formatter.formatException
NameError: global name 'console_formatter' is not defined

That's probably the source of the issue. The formats were correct when I changed the console_handler code:

console_handler = logging.StreamHandler(sys.stderr)
console_handler.setLevel(logging.INFO)
console_formatter = ConsoleFormatter("%(levelname)-8s - %(message)s")
console_handler.setFormatter(console_formatter)