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

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

Ведение журнала предоставляет набор удобных функций для простого использования ведения журнала. Это 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', encoding='utf-8', level=logging.DEBUG)
logging.debug('This message should go to the log file')
logging.info('So should this')
logging.warning('And this, too')
logging.error('And non-ASCII stuff, too, like Øresund and Malmö')

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

DEBUG:root:This message should go to the log file
INFO:root:So should this
WARNING:root:And this, too
ERROR:root:And non-ASCII stuff, too, like Øresund and Malmö

Этот пример также демонстрирует, как можно установить уровень ведения журнала, который действует как порог для отслеживания. В данном случае, поскольку мы установили порог на 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() и т.д. В противном случае эти функции вызовут basicConfig() для вас с параметрами по умолчанию. Поскольку это предназначено как одноразовое средство простой настройки, только первый вызов фактически сделает что-то: последующие вызовы фактически не выполняют никаких действий.

Если вы запустите вышеуказанный скрипт несколько раз, сообщения из последующих запусков будут добавлены в файл 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().

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

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

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

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

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

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

Логгеры

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

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

Это наиболее распространённые методы настройки:

• Logger.setLevel() указывает минимальный уровень серьёзности сообщения лога, который будет обрабатывать логгер, где debug — самый низкий встроенный уровень серьёзности, а critical — самый высокий встроенный уровень серьёзности. Например, если уровень серьёзности — INFO, логгер будет обрабатывать только сообщения INFO, WARNING, ERROR и CRITICAL и игнорировать сообщения DEBUG.
• 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(). Для изменения этого для всех форматировщиков, например, для отображения всех времён регистрации в формате GMT, установите атрибут converter в классе Formatter (в time.gmtime для отображения в формате GMT).

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

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

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

Результат практически идентичен результату примера без файла конфигурации:

$ 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'.

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

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