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

Question

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 StreamHandler 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.

Answer 1

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")