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

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

Вы можете получить доступ к функциональности ведения журнала, создав журнал с помощью logger = getLogger(__name__), а затем вызвав методы журнала 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. Выведенное сообщение включает указание уровня и описание события, предоставленного в вызове ведения журнала, т.е. «Осторожно!». Фактический вывод может быть отформатирован довольно гибко, если вам это необходимо; варианты форматирования также будут объяснены позже.

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

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

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

import logging
logger = logging.getLogger(__name__)
logging.basicConfig(filename='example.log', encoding='utf-8', level=logging.DEBUG)
logger.debug('This message should go to the log file')
logger.info('So should this')
logger.warning('And this, too')
logger.error('And non-ASCII stuff, too, like Øresund and Malmö')

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

DEBUG:__main__:This message should go to the log file
INFO:__main__:So should this
WARNING:__main__:And this, too
ERROR:__main__: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() и т.д. В противном случае данное событие ведения журнала может не быть обработано желаемым образом.

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

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

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

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

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

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

Обратите внимание, что «корень», который появлялся в предыдущих примерах, исчез. Для полного набора элементов, которые могут появиться в строках формата, вы можете обратиться к документации для Атрибуты 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(). Например, приложение может хотеть отправлять все сообщения журнала в файл журнала, все сообщения уровня error или выше в stdout и все сообщения уровня critical на электронную почту. Для этого нужны три отдельных обработчика, каждый из которых отвечает за отправку сообщений определённого уровня важности в определённое место.

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

Обратите внимание, что имена классов, упомянутые в файлах конфигурации, должны быть либо относительными к модулю logging, либо абсолютными значениями, которые могут быть разрешены с помощью обычных механизмов импорта. Таким образом, вы можете использовать либо WatchedFileHandler (относительно модуля logging), либо 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]

Дополнительную информацию о логировании с помощью словаря см. в Функции конфигурации.

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

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

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

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

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

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

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