Руководство по ведению журналов (Logging HOWTO)

Когда использовать ведение журналов

Ведение журналов предоставляет набор функций для простого использования ведения журналов. Это debug(), info(), warning(), error() и critical(). Чтобы определить, когда использовать ведение журналов, см. таблицу ниже, которая указывает для каждого из набора общих задач лучший инструмент для его решения.

Функции ведения журналов названы по уровню или степени серьезности событий, которые они используются для отслеживания. Стандартные уровни и их применимость описаны ниже (в порядке возрастания степени серьезности):

Уровень по умолчанию — WARNING, что означает, что будут отслеживаться только события этого уровня и выше, если только пакет ведения журнала не настроен иначе.

События, которые отслеживаются, могут обрабатываться различными способами. Самый простой способ обработки отслеживаемых событий — это вывести их на консоль. Ещё один распространённый способ — записать их в файл на диске.

Простой пример

Очень простой пример:

import logging
logging.warning('Watch out!')  # will print a message to the console
logging.info('I told you so')  # will not print anything

Если вы напечатаете эти строки в скрипт и запустите его, вы увидите:

WARNING:root:Watch out!

выведенные на консоль. Сообщение INFO не появляется, потому что уровень по умолчанию — WARNING. Выводимое сообщение включает указание уровня и описание события, предоставленного в вызове ведения журнала, т.е. «Осторожно!». Пока не беспокойтесь о части «root»: это будет объяснено позже. Фактический вывод может быть отформатирован довольно гибко, если вам это нужно; параметры форматирования также будут объяснены позже.

Ведение журналов в файл

Очень распространённая ситуация — запись событий ведения журналов в файл, поэтому давайте посмотрим на это дальше. Убедитесь, что вы попробуете следующее в недавно запущенном интерпретаторе Python и не просто продолжайте от сессии, описанной выше:

import logging
logging.basicConfig(filename='example.log',level=logging.DEBUG)
logging.debug('This message should go to the log file')
logging.info('So should this')
logging.warning('And this, too')

И теперь, если мы откроем файл и посмотрим на то, что у нас есть, мы должны найти сообщения журнала:

DEBUG:root:This message should go to the log file
INFO:root:So should this
WARNING:root:And this, too

Этот пример также показывает, как вы можете установить уровень ведения журнала, который действует как порог для отслеживания. В этом случае, поскольку мы установили порог в DEBUG, все сообщения были напечатаны.

Если вы хотите установить уровень ведения журнала из командной строки, такой как:

--log=INFO

и у вас есть значение параметра, переданного для --log в какой-то переменной loglevel, вы можете использовать:

getattr(logging, loglevel.upper())

чтобы получить значение, которое вы передадите в basicConfig() через аргумент level. Вы можете проверить любые значения пользовательского ввода, возможно, как в следующем примере:

# assuming loglevel is bound to the string value obtained from the
# command line argument. Convert to upper case to allow the user to
# specify --log=DEBUG or --log=debug
numeric_level = getattr(logging, loglevel.upper(), None)
if not isinstance(numeric_level, int):
    raise ValueError('Invalid log level: %s' % loglevel)
logging.basicConfig(level=numeric_level, ...)

Вызов basicConfig() должен быть выполнен до любых вызовов debug(), info() и т.д. Так как это предназначено как удобный инструмент конфигурации, только первый вызов что-то сделает: последующие вызовы являются, по существу, операциями без действия.

Если вы запустите скрипт несколько раз, сообщения от последующих запусков будут добавлены к файлу example.log. Если вы хотите, чтобы каждый запуск начинался заново, не запоминая сообщения от предыдущих запусков, вы можете указать аргумент filemode, изменив вызов в приведённом выше примере на:

logging.basicConfig(filename='example.log', filemode='w', level=logging.DEBUG)

Вывод будет таким же, как и раньше, но к файлу журнала больше не будет добавляться, поэтому сообщения от предыдущих запусков потеряются.

Ведение журналов из нескольких модулей

Если ваша программа состоит из нескольких модулей, вот пример того, как вы могли бы организовать ведение журналов в ней:

# myapp.py
import logging
import mylib

def main():
    logging.basicConfig(filename='myapp.log', level=logging.INFO)
    logging.info('Started')
    mylib.do_something()
    logging.info('Finished')

if __name__ == '__main__':
    main()

# mylib.py
import logging

def do_something():
    logging.info('Doing something')

Если вы запустите myapp.py, вы увидите это в myapp.log:

INFO:root:Started
INFO:root:Doing something
INFO:root:Finished

что, надеюсь, вы и ожидали увидеть. Вы можете обобщить это на несколько модулей, используя шаблон в mylib.py. Обратите внимание, что для этого простого шаблона использования вы не будете знать, откуда в вашем приложении пришли ваши сообщения, кроме как глядя на описание события. Если вы хотите отслеживать местоположение ваших сообщений, вам нужно обратиться к документации за пределами учебного уровня — см. Расширенный учебник по ведению журналов.

Ведение журналов переменных данных

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

import logging
logging.warning('%s before you %s', 'Look', 'leap!')

отобразит:

WARNING:root:Look before you leap!

Как вы можете видеть, слияние переменных данных в сообщение описания события использует старый стиль форматирования строк, %-стиль. Это для обратной совместимости: пакет ведения журнала предшествует новым вариантам форматирования, таким как str.format() и string.Template. Эти новые варианты форматирования поддерживаются, но изучение их выходит за рамки этого учебника: см. Использование конкретных стилей форматирования во всей вашей программе для получения дополнительной информации.

Изменение формата отображаемых сообщений

Чтобы изменить формат отображения сообщений, вам нужно указать используемый вами формат:

import logging
logging.basicConfig(format='%(levelname)s:%(message)s', level=logging.DEBUG)
logging.debug('This message should appear on the console')
logging.info('So should this')
logging.warning('And this, too')

что отобразило бы:

DEBUG:This message should appear on the console
INFO:So should this
WARNING:And this, too

Обратите внимание, что «root», который появлялся в предыдущих примерах, исчез. Для полного набора вещей, которые могут появиться в строках формата, вы можете обратиться к документации по Атрибуты LogRecord, но для простого использования вам нужно только levelname (степень серьезности), message (описание события, включая переменные данные) и, возможно, отобразить время события. Это описано в следующей секции.

Отображение даты/времени в сообщениях

Для отображения даты и времени события, поместите ‘%(asctime)s’ в строку формата:

import logging
logging.basicConfig(format='%(asctime)s %(message)s')
logging.warning('is when this event was logged.')

что должно вывести примерно следующее:

2010-12-12 11:41:42,612 is when this event was logged.

По умолчанию формат отображения даты/времени (показанный выше) похож на ISO8601 или RFC 3339. Если вам нужен больший контроль над форматированием даты/времени, укажите аргумент datefmt в basicConfig, как в этом примере:

import logging
logging.basicConfig(format='%(asctime)s %(message)s', datefmt='%m/%d/%Y %I:%M:%S %p')
logging.warning('is when this event was logged.')

что выведет примерно так:

12/12/2010 11:46:36 AM is when this event was logged.

Формат аргумента datefmt такой же, как поддерживается time.strftime().

Следующие шаги

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

Если ваши потребности в ведении логов простые, используйте приведенные выше примеры, чтобы включить ведение логов в свои скрипты. Если у вас возникнут проблемы или вы что-то не поймёте, задайте вопрос на Usenet-группе comp.lang.python (https://groups.google.com/forum/#!forum/comp.lang.python), и вы, скорее всего, получите помощь в ближайшее время.

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

Поток ведения логов

Поток информации о событиях ведения логов в логгерах и обработчиках показан на следующей диаграмме.

Логгеры

Объекты Logger имеют трехкратную задачу. Во-первых, они предоставляют несколько методов для кода приложения, чтобы приложения могли регистрировать сообщения во время выполнения. Во-вторых, объекты логгеров определяют, какие сообщения логов обрабатывать, исходя из степени важности (стандартная система фильтрации) или объектов фильтров. В-третьих, объекты логгеров передают соответствующие сообщения логов всем заинтересованным обработчикам логов.

Наиболее часто используемые методы объектов логгеров делятся на две категории: конфигурация и отправка сообщений.

Вот наиболее распространенные методы конфигурации:

• Logger.setLevel() указывает минимальную степень важности сообщения лога, которое будет обрабатывать логгер, где «отладка» — самый низкий встроенный уровень серьезности, а «критический» — самый высокий встроенный уровень серьезности. Например, если уровень серьезности — «информация», логгер будет обрабатывать только сообщения «информация», «предупреждение», «ошибка» и «критическая» и проигнорирует сообщения «отладки».
• Logger.addHandler() и Logger.removeHandler() добавляют и удаляют объекты обработчиков из объекта логгера. Обработчики подробно описаны в Обработчики.
• Logger.addFilter() и Logger.removeFilter() добавляют и удаляют объекты фильтров из объекта логгера. Фильтры подробно описаны в Объекты фильтра.

Вам не всегда нужно вызывать эти методы для каждого созданного вами логгера. См. два последних абзаца в этом разделе.

После конфигурации объекта логгера следующие методы создают сообщения логов:

• Logger.debug(), Logger.info(), Logger.warning(), Logger.error() и Logger.critical() все создают записи логов с сообщением и уровнем, соответствующим именам их методов. Сообщение фактически является строкой формата, которая может содержать стандартную синтаксис подстановки строк %s, %d, %f, и так далее. Остальные аргументы — список объектов, соответствующих полям подстановки в сообщении. Что касается **kwargs, методы ведения логов заботятся только о ключе exc_info и используют его для определения, следует ли регистрировать информацию об исключении.
• Logger.exception() создает сообщение лога, аналогичное Logger.error(). Разница заключается в том, что Logger.exception() выводит стек вызовов вместе с ним. Вызывайте этот метод только из обработчика исключений.
• Logger.log() принимает уровень лога в качестве явного аргумента. Это немного более подробный способ регистрации сообщений, чем использование удобных методов уровней логов, перечисленных выше, но именно так регистрируются сообщения на пользовательских уровнях логов.

getLogger() возвращает ссылку на экземпляр логгера с указанным именем, если оно предоставлено, или root в противном случае. Имена представляют собой иерархические структуры, разделенные точками. Несколько вызовов getLogger() с одинаковым именем вернут ссылку на тот же объект логгера. Логгеры, которые расположены ниже в иерархическом списке, являются дочерними элементами логгеров, расположенных выше в списке. Например, учитывая логгер с именем foo, логгеры с именами foo.bar, foo.bar.baz, и foo.bam являются потомками foo.

Логгеры имеют понятие «эффективного уровня». Если уровень не задан явно для логгера, используется уровень его родителя. Если родитель не имеет явно заданного уровня, проверяется его родитель, и так далее — все предки проверяются до тех пор, пока не будет найден явно заданный уровень. У корневого логгера всегда задан явный уровень (по умолчанию WARNING). При принятии решения о обработке события используется эффективный уровень логгера, чтобы определить, передается ли событие обработчикам логгера.

Дочерние логгеры распространяют сообщения до обработчиков, связанных с их родительскими логгерами. Благодаря этому, нет необходимости определять и настраивать обработчики для всех логгеров, используемых приложением. Достаточно настроить обработчики для логгера верхнего уровня и создавать дочерние логгеры по мере необходимости. (Однако можно отключить распространение, установив атрибут propagate логгера в значение False.)

Обработчики

Handler объекты отвечают за рассылку соответствующих сообщений журнала (в зависимости от их уровня серьезности) в указанное место назначения обработчика. Logger объекты могут добавлять к себе ноль или более объектов обработчиков с помощью метода addHandler(). Например, приложение может захотеть отправить все сообщения журнала в файл журнала, все сообщения об ошибках или более высокого уровня в стандартный вывод, а все сообщения критического уровня — на адрес электронной почты. Для этого сценария требуются три отдельных обработчика, каждый из которых отвечает за отправку сообщений определенного уровня серьезности в определенное место.

Стандартная библиотека включает в себя довольно много типов обработчиков (см. Полезные обработчики); в учебниках в основном используются StreamHandler и FileHandler.

Для разработчиков приложений в обработчике имеется очень мало методов, которые их интересуют. Единственные методы обработчиков, которые кажутся релевантными для разработчиков приложений, использующих встроенные объекты обработчиков (то есть не создающих пользовательские обработчики), это следующие методы конфигурации:

• Метод setLevel(), как и в объектах регистрации, задаёт минимальный уровень серьезности, который будет перенаправлен в соответствующее место назначения. Зачем нужны два setLevel() метода? Уровень, установленный в регистраторе, определяет, какой уровень серьезности сообщений он передаст своим обработчикам. Уровень, установленный в каждом обработчике, определяет, какие сообщения этот обработчик отправит.
• setFormatter() выбирает объект Formatter для использования этим обработчиком.
• addFilter() и removeFilter() соответственно настраивают и отключают объекты фильтров в обработчиках.

Код приложения не должен напрямую создавать и использовать экземпляры Handler. Вместо этого, класс Handler — это базовый класс, который определяет интерфейс, который должны иметь все обработчики, и устанавливает некоторое стандартное поведение, которое дочерние классы могут использовать (или переопределять).

Форматировщики

Объекты форматировщика настраивают окончательный порядок, структуру и содержимое сообщения журнала. В отличие от базового класса logging.Handler, код приложения может создавать экземпляры классов форматировщика, хотя вы, вероятно, могли бы унаследовать от форматировщика, если вашему приложению требуется специальное поведение. Конструктор принимает три необязательных аргумента — строку формата сообщения, строку формата даты и индикатор стиля.

logging.Formatter.__init__(fmt=None, datefmt=None, style='%')

Если строка формата сообщения отсутствует, используется исходное сообщение. Если строка формата даты отсутствует, используется стандартный формат даты:

%Y-%m-%d %H:%M:%S

с миллисекундами в конце. style является одним из %, ‘{’ или ‘$’. Если ни один из них не указан, используется ‘%’.

Если style равно ‘%’, строка формата сообщения использует форматирование строк с использованием %(<dictionary key>)s стилей; возможные ключи описаны в Атрибуты записи журнала. Если стиль равен ‘{’, предполагается, что строка формата сообщения совместима с str.format() (используя ключевые аргументы), а если стиль равен ‘$’, строка формата сообщения должна соответствовать тому, что ожидается от string.Template.substitute().

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

'%(asctime)s - %(levelname)s - %(message)s'

Форматировщики используют настраиваемую функцию для преобразования времени создания записи в кортеж. По умолчанию используется time.localtime(); для изменения этого для конкретного экземпляра форматировщика установите атрибут converter экземпляра в функцию с тем же сигнатурным значением, что и time.localtime() или time.gmtime(). Чтобы изменить это для всех форматировщиков, например, если вы хотите, чтобы все отметки времени регистрации отображались по Гринвичу, установите атрибут converter в классе Formatter (в time.gmtime для отображения по Гринвичу).

Настройка регистрации

Программисты могут настроить регистрацию тремя способами:

1. Создание регистраторов, обработчиков и форматировщиков явно с помощью кода Python, вызывающего методы конфигурации, перечисленные выше.
2. Создание файла конфигурации регистрации и чтение его с помощью функции fileConfig().
3. Создание словаря с информацией о конфигурации и передача его функции dictConfig().

Документация по последним двум вариантам см. в Функции конфигурации. Следующий пример настраивает очень простой регистратор, обработчик консоли и простой форматировщик с помощью кода Python:

import logging

# create logger
logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)

# create console handler and set level to debug
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)

# create formatter
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# add formatter to ch
ch.setFormatter(formatter)

# add ch to logger
logger.addHandler(ch)

# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')
logger.error('error message')
logger.critical('critical message')

Запуск этого модуля из командной строки приводит к следующему выводу:

$ python simple_logging_module.py
2005-03-19 15:10:26,618 - simple_example - DEBUG - debug message
2005-03-19 15:10:26,620 - simple_example - INFO - info message
2005-03-19 15:10:26,695 - simple_example - WARNING - warn message
2005-03-19 15:10:26,697 - simple_example - ERROR - error message
2005-03-19 15:10:26,773 - simple_example - CRITICAL - critical message

Следующий модуль Python создаёт регистратор, обработчик и форматировщик, практически идентичные тем, которые приведены в примере выше, с единственным отличием — именами объектов:

import logging
import logging.config

logging.config.fileConfig('logging.conf')

# create logger
logger = logging.getLogger('simpleExample')

# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')
logger.error('error message')
logger.critical('critical message')

Вот файл logging.conf:

[loggers]
keys=root,simpleExample

[handlers]
keys=consoleHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

[logger_simpleExample]
level=DEBUG
handlers=consoleHandler
qualname=simpleExample
propagate=0

[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=simpleFormatter
args=(sys.stdout,)

[formatter_simpleFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s
datefmt=

Вывод почти идентичен выводу примера без файла конфигурации:

$ python simple_logging_config.py
2005-03-19 15:38:55,977 - simpleExample - DEBUG - debug message
2005-03-19 15:38:55,979 - simpleExample - INFO - info message
2005-03-19 15:38:56,054 - simpleExample - WARNING - warn message
2005-03-19 15:38:56,055 - simpleExample - ERROR - error message
2005-03-19 15:38:56,130 - simpleExample - CRITICAL - critical message

Можно заметить, что подход с файлом конфигурации имеет несколько преимуществ по сравнению с подходом с кодом Python, в основном это разделение конфигурации и кода, а также возможность не программистам легко изменять свойства регистрации.

Обратите внимание, что имена классов, указанные в файлах конфигурации, должны быть либо относительными к модулю регистрации, либо абсолютными значениями, которые можно разрешить с помощью обычных механизмов импорта. Таким образом, вы можете использовать либо WatchedFileHandler (относительно модуля регистрации), либо mypackage.mymodule.MyHandler (для класса, определенного в пакете mypackage и модуле mymodule, где mypackage доступен в пути импорта Python).

В Python 3.2 был представлен новый способ настройки регистрации с использованием словарей для хранения информации о конфигурации. Это обеспечивает расширенный функционал по сравнению с подходом на основе файла конфигурации, описанным выше, и является рекомендуемым способом конфигурации для новых приложений и развертываний. Поскольку для хранения информации о конфигурации используется словарь Python, и поскольку вы можете заполнить его различными способами, у вас больше вариантов конфигурации. Например, вы можете использовать файл конфигурации в формате JSON или, если у вас есть возможность работы с YAML, файл в формате YAML для заполнения словаря конфигурации. Или, конечно, вы можете создать словарь в коде Python, получить его в сериализованном виде через сокет или использовать любой подход, который подходит для вашего приложения.

Вот пример той же конфигурации, что и выше, в формате YAML для нового подхода на основе словарей:

version: 1
formatters:
  simple:
    format: '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
handlers:
  console:
    class: logging.StreamHandler
    level: DEBUG
    formatter: simple
    stream: ext://sys.stdout
loggers:
  simpleExample:
    level: DEBUG
    handlers: [console]
    propagate: no
root:
  level: DEBUG
  handlers: [console]

Для получения дополнительной информации о регистрации с использованием словаря см. Функции конфигурации.

Что происходит, если конфигурация не задана

Если конфигурация ведения журнала не задана, может возникнуть ситуация, когда событие ведения журнала необходимо вывести, но обработчики для вывода этого события не найдены. Поведение пакета ведения журнала в таких обстоятельствах зависит от версии Python.

Для версий Python до 3.2 поведение следующее:

• Если logging.raiseExceptions равно False (режим производства), событие отбрасывается без сообщений.
• Если logging.raiseExceptions равно True (режим разработки), сообщение «Не удалось найти обработчики для логгера X.Y.Z» выводится один раз.

В Python 3.2 и более поздних версиях поведение следующее:

• Событие выводится с помощью «обработчика последней инстанции», хранящегося в logging.lastResort. Этот внутренний обработчик не связан ни с одним логгером и действует как StreamHandler, который записывает сообщение об описании события в текущее значение sys.stderr (следовательно, учитываются все перенаправления, которые могут быть в действии). Никакой форматирования сообщения не выполняется — выводится только простое сообщение об описании события. Уровень обработчика установлен на значение WARNING, поэтому все события с таким и более высоким уровнем серьезности будут выведены.

Чтобы получить поведение до версии 3.2, logging.lastResort можно установить в None.

Настройка ведения журнала для библиотеки

При разработке библиотеки, использующей ведение журнала, следует уделить внимание документированию того, как библиотека использует ведение журнала — например, имена используемых логгеров. Также необходимо учесть ее конфигурацию ведения журнала. Если приложение-пользователь не использует ведение журнала, а код библиотеки делает вызовы ведения журнала, то (как описано в предыдущем разделе) события с уровнем серьезности WARNING и выше будут выведены в sys.stderr. Это считается лучшим по умолчанию поведением.

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

Обработчик без действий включен в пакет ведения журнала: NullHandler (с Python 3.1). Экземпляр этого обработчика можно добавить в логгер верхнего уровня пространства имен ведения журнала, используемого библиотекой (если вы хотите предотвратить вывод событий журнала вашей библиотеки в sys.stderr при отсутствии конфигурации ведения журнала). Если все ведение журнала библиотекой foo выполняется с использованием логгеров с именами, соответствующими «foo.x», «foo.x.y» и т. д., то код:

import logging
logging.getLogger('foo').addHandler(logging.NullHandler())

должен иметь желаемый эффект. Если организация создает несколько библиотек, то имя логгера можно задать как «orgname.foo», а не только «foo».

Пользовательские уровни

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