Странно: регистратор использует только форматер первого обработчика для исключений

Question

Я наблюдаю, как модуль логирования ведет себя странно. Я что-то упустил?

Обычно я использую два обработчика: StreamHandler для регистрации только INFO и выше на консоли и FileHandler, который также будет обрабатывать всю информацию DEBUG.

Это работало нормально, пока я не решил использовать другой формат для исключений. Мне нужна была полная трассировка стека в файле, но только тип исключения и значение на консоли. Поскольку в обработчиках есть функция setFormatter, и, поскольку кажется, что написать подкласс ведения журналов просто. Я думаю, что это сработает.

Обработчик консоли и обработчик файлов имеют свои собственные средства форматирования. Операторы печати в коде подтверждают это. Однако при вызове logger.exception будет использоваться только formatException первого добавленного обработчика => исключение регистрируется в файле в том формате, который он должен иметь в консоли. Измените порядок строк logger.addHandler, а затем это formatException обработчика файла, который используется везде.

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

Что происходит?

РЕДАКТИРОВАТЬ: Кстати, я использую Python 2.6. РЕДАКТИРОВАТЬ: Исправлена ​​опечатка в коде с именем переменной "console_formatter".

Answer 1

Это код, который я придумал.Это делает работу:).

class CachelessFormatter(logging.Formatter):
    # I came up with that after reading the answers to
    #     /7335610/stranno-registrator-ispolzuet-tolko-formater-pervogo-obrabotchika-dlya-isklychenii
    # 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")

Answer 2

Я нашел твою проблему!Если вы посмотрите в logger/__init__.py исходный код для Formatter.format, в строке 440 (для py2.6) вы увидите следующее:

        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)

В вашем случае это не так, поскольку вы 'переопределение formatException.Если вы закомментируете if not record.exc_text (и исправляете отступ соответственно), похоже, он работает должным образом.

Похоже, ошибка уже сообщена здесь: http://bugs.python.org/issue6435

Answer 3

При первом запуске вашего кода я получил трассировку:

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

Это, вероятно, источник проблемы. Форматы были правильными, когда я изменил код console_handler:

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