Модуль протоколирования Python: дублированный вывод консоли [IPython Notebook/Qtconsole]

Я пытаюсь играть с модулем python logging, но немного запутался здесь. Ниже приведен стандартный script для создания logger, а затем создайте и добавьте file handler и console handler в logger.

import logging

logger = logging.getLogger('logging_test')
logger.setLevel(logging.DEBUG)

print(len(logger.handlers))  # output: 0

# create file handler which logs even debug messages
fh = logging.FileHandler('/home/Jian/Downloads/spam.log', mode='w')
fh.setLevel(logging.DEBUG)

# create console handler with a higher log level
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)

# create formatter and add it to the handlers
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
ch.setFormatter(formatter)
fh.setFormatter(formatter)

# add the handlers to logger
logger.addHandler(ch)
logger.addHandler(fh)

print(len(logger.handlers))  # output: 2

# write some log messages
logger.debug('debug message')
logger.info('info message')
logger.warn('warn message')
logger.error('error message')
logger.critical('critical message')

Я запускаю это в недавно запущенном ядре. file handler работает так, как ожидалось. Но на консольном выходе у меня есть некоторые дублированные сообщения:

2015-07-14 10:59:26,942 - logging_test - DEBUG - debug message
DEBUG:logging_test:debug message
2015-07-14 10:59:26,944 - logging_test - INFO - info message
INFO:logging_test:info message
2015-07-14 10:59:26,944 - logging_test - WARNING - warn message
WARNING:logging_test:warn message
2015-07-14 10:59:26,945 - logging_test - ERROR - error message
ERROR:logging_test:error message
2015-07-14 10:59:26,946 - logging_test - CRITICAL - critical message
CRITICAL:logging_test:critical message

Я полагаю, что эти сообщения журнала с отметками времени взяты из пользовательского console handler, но откуда берутся дублированные сообщения? Могу ли я избавиться от них, скажем, сохранить только каждую другую линию? Любая помощь приветствуется.

Ответы

Ответ 1

Вопрос был поднят здесь.

Наблюдение заключается в следующем: в обычном питоне или в консоли IPython обработчик корневого регистратора не установлен до тех пор, пока сам корневой журнал не будет использоваться для сообщения журнала:

In [1]: import logging

In [2]: logging.getLogger().handlers
Out[2]: []

In [3]: logging.warn('Something happened!')
WARNING:root:Something happened!

In [4]: logging.getLogger().handlers
Out[4]: [<logging.StreamHandler at 0x42acef0>]

Однако в ноутбуке IPython установлен корневой регистратор stderr по умолчанию:

In [1]: import logging

In [2]: logging.getLogger().handlers
Out[2]: [<logging.StreamHandler at 0x35eedd8>]

Может быть, мне что-то не хватает, но я думаю, что в записной книжке не должно быть установлено автоматически, по нескольким причинам:

  • Это сделает конфигурацию протоколирования по умолчанию совместимой между стандартным питоном, консолью IPython и ноутбуком IPython.
  • Как только пользователь записывает сообщение журнала с корневым журналом, обработчик устанавливается автоматически, поэтому сообщения журнала нелегко пропустить.
  • В текущем поведении библиотека, которая настраивает дочерний регистратор, и обработчик для этого регистратора, может легко спамить ноутбук сообщениями отладки, которые должны находиться только в файле журнала (или в другом месте). Например, у астрологии, похоже, есть такая проблема, и я сталкиваюсь с той же проблемой с моей собственной библиотекой. Проблема в том, что для такой библиотеки нет "чистого" способа обойти это. Библиотека может удалить обработчик корневого регистратора при импорте, который является hack-y. Он мог бы установить свой собственный logger propagate атрибут False, чтобы сообщения журнала не распространялись на корневой журнал, но это не только отключает вывод отладки из входа в ноутбук, но и более серьезные сообщения. Кроме того, он запрещает пользователям фактически захватывать все выходные данные журнала, если они хотят.

Альтернативой может быть добавление опции конфигурации, которая определяет уровень журнала для автоматически добавленного обработчика потока, так что становится возможным игнорировать менее серьезные сообщения, появляющиеся в ноутбуке автоматически. Но это все равно по-разному повлияет на поведение между консолью IPython и ноутбуком IPython.

Единственный недостаток, который я вижу в том, что нет набора обработчиков по умолчанию, заключается в том, что некоторые используемые библиотеки/ноутбуки могут полагаться на это поведение и активно работать вокруг него, например, отключив их собственные обработчики, если они обнаружат, что они запущены в ноутбуке ipython. Такие случаи, вероятно, нарушатся с таким изменением.

Таким образом, установка logger.propagate to False или использование reload(logging) предотвратит дублирование вывода, но в зависимости от этого будут иметь побочные эффекты.

Обратите внимание, что reload недоступен в более новой версии python (3.4, возможно, раньше). Начиная с 3.1 и далее см. importlib.reload

Ответ 2

Когда вы выполняете

# create console handler with a higher log level
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)

Создайте еще один StreamHandler. Чтобы решить вашу проблему, вы должны захватить StreamHandler из iPython:

import logging

handlers = logging.getLogger().handlers
for h in handlers:
    if isinstance(h, logging.StreamHandler):
        handler_console = h
        break

Если он не существует, вы создаете свой собственный:

if handler_console is None:
    handler_console = logging.StreamHandler()

Наконец, отформатируйте (установите другие свойства) по желанию:

if handler_console is not None:
    # first we need to remove to avoid duplication
    logging.getLogger().removeHandler(handler_console)
    formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
    handler_console.setFormatter(formatter)
    # then add it back
    logger.addHandler(handler_console)

Ответ 3

Мое решение:

import logging

logger = logging.getLogger()
logger.propagate = False