Руководство по Python модулю logging

Логирование

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

Цель логирования

Логирование ведется в следующих целях:

Сбор информации
Исправление проблем
Генерация статистики
Аудит
Профилирование

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

Какие события регистрировать

События, которые должны регистрироваться, включают в себя ошибки проверки входа, ошибки проверки подлинности и авторизации, ошибки приложения, изменения конфигурации, а также запуск и завершение работы приложения.

Какие события не регистрировать

События, которые не должны регистрироваться, включают в себя исходный код приложения, значения идентификации сеанса, токены доступа, конфиденциальные личные данные, пароли, строки подключения к базе данных, ключи шифрования, данные банковского счета и данные владельца карты.

Лучшие практики логирования

Ниже приведены некоторые рекомендации по ведению журнала.

Ведение журнала должно быть значимым.
Ведение журнала должно содержать контекст.
Ведение журнала должно быть структурировано и выполнено на разных уровнях.
Ведение журнала должно быть сбалансированным; он не должен содержать слишком мало или слишком много информации.
Регистрация сообщений должна быть понятна людям и разбираться машинами.
Логирование в более сложных приложениях должно осуществляться в несколько файлов журнала.
Логирование должно быть адаптировано к разработке и продакшену.

Модуль logging

Модуль регистрации Python определяет функции и классы, которые реализуют гибкую систему регистрации событий для приложений и библиотек.

Компоненты модуля logging

Модуль ведения журнала имеет четыре основных компонента: средства ведения журнала (регистраторы), обработчики, фильтры и средства форматирования. Регистраторы предоставляют интерфейс, который непосредственно использует код приложения. Обработчики отправляют записи журнала (созданные регистраторами) в соответствующий пункт назначения. Фильтры предоставляют более точную возможность определить, какие записи журнала выводить. Форматировщики определяют формат записей журнала в конечном выводе.

Иерархия logging в Python

Регистраторы Python образуют иерархию. Регистратор с именем main является родителем main.new.

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

Уровни логирования Python

Уровни используются для определения серьезности события. Существует шесть уровней ведения журнала:

CRITICAL
ERROR
WARNING
INFO
DEBUG
NOTSET

Если уровень ведения журнала установлен на WARNING, все сообщения WARNING, ERROR и CRITICAL записываются в файл журнала или консоль. Если установлено значение ERROR, регистрируются только сообщения ERROR и CRITICAL.

У логгеров есть концепция эффективного уровня. Если уровень явно не задан в логгере, вместо него используется уровень его родителя. Если родитель не имеет явного установленного уровня, его родитель проверяется, и так далее - все предки ищутся, пока не будет найден явно установленный уровень.

Когда регистратор создается с помощью getLogger(), уровень устанавливается равным NOTSET. Если уровень ведения журнала не установлен явно с помощью setLevel(), сообщения передаются родителям регистратора. Цепочка регистраторов предков регистрируется, пока либо не будет найден предок с уровнем, отличным от NOTSET, либо пока не будет достигнут корень. В корневом логгере установлен уровень WARNING по умолчанию.

Корневой логгер

Все регистраторы являются потомками корневого регистратора. Каждый регистратор передает сообщения журнала своему родителю. Новые регистраторы создаются с помощью метода getLogger(name). Вызов функции без имени (getLogger()) возвращает корневой логгер.

Корневой регистратор всегда имеет явный набор уровней, который по умолчанию WARNING.

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

Простой пример логирования Python

Модуль logging имеет простые методы, которые можно использовать сразу, без какой-либо настройки. Это может быть использовано для простой регистрации.

simple.py

#!/usr/bin/env python

import logging

logging.debug('Это отладочное сообщение')
logging.info('Это информационное сообщение')
logging.warning('Это предупреждающее сообщение')
logging.error('Это сообщение об ошибке')
logging.critical('Это критическое сообщение')

В примере вызываются пять методов модуля logging. Сообщения пишутся в консоль.

$ simple.py
WARNING:root:Это предупреждающее сообщение
ERROR:root:Это сообщение об ошибке
CRITICAL:root:Это критическое сообщение

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

Установка уровня логирования

Уровень ведения журнала устанавливается с помощью setLevel(). Он устанавливает порог для этого логгера на lvl. Сообщения, которые менее серьезны, чем lvl, будут игнорироваться.

set_level.py

#!/usr/bin/env python

import logging

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

logging.debug('Это отладочное сообщение')
logging.info('Это информационное сообщение')
logging.warning('Это предупреждающее сообщение')
logging.error('Это сообщение об ошибке')
logging.critical('Это критическое сообщение')

В этом примере мы изменили уровень ведения журнала на DEBUG.

logger = logging.getLogger('dev')

getLogger() возвращает регистратор с указанным именем. Если имя None, он возвращает корневой логгер. Имя может быть разделенной точкой точкой, определяющей иерархию журналирования; например, 'a', 'a.b' или 'a.b.c'. Обратите внимание, что существует неявное корневое имя, которое не отображается.

$ set_level.py
Это предупреждающее сообщение
Это сообщение об ошибке
Это критическое сообщение

Теперь все сообщения были записаны.

Эффективный уровень ведения журнала в Python

Эффективный уровень ведения журнала - это уровень, установленный в явном виде или определяемый родителями журнала.

effective_level.py

#!/usr/bin/env python

import logging

main_logger = logging.getLogger('main')
main_logger.setLevel(5)

dev_logger = logging.getLogger('main.dev')

print(main_logger.getEffectiveLevel())
print(dev_logger.getEffectiveLevel())

В этом примере мы рассмотрим эффективный уровень логирования двух логгеров.

dev_logger = logging.getLogger('main.dev')

Уровень dev_logger не установлен; затем используется уровень его родителя.

$ effective_level.py
5
5

Это вывод.

Обработчики журналов Python

Обработчик - это объект, отвечающий за отправку соответствующих сообщений журнала (в зависимости от серьезности сообщений журнала) в указанное обработчиком место назначения.

Обработчики распространяются как уровни. Если регистратор не имеет установленного обработчика, его цепочка предков используется для поиска обработчика.

handlers.py

#!/usr/bin/env python

import logging

logger = logging.getLogger('dev')
logger.setLevel(logging.INFO)

fileHandler = logging.FileHandler('test.log')
fileHandler.setLevel(logging.INFO)

consoleHandler = logging.StreamHandler()
consoleHandler.setLevel(logging.INFO)

logger.addHandler(fileHandler)
logger.addHandler(consoleHandler)

logger.info('информационное сообщение')

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

fileHandler = logging.FileHandler('test.log')

FileHandler отправляет записи журнала в файл test.log.

consoleHandler = logging.StreamHandler()

StreamHandler отправляет записи журнала в поток. Если поток не указан, используется sys.stderr.

logger.addHandler(fileHandler)

Обработчик добавляется в логгер с помощью addHandler().

Средства форматирования журнала Python

Форматтер - это объект, который настраивает окончательный порядок, структуру и содержимое записи журнала. Помимо строки сообщения, записи журнала также включают дату и время, имена журналов и уровень серьезности журнала.

formatter.py

#!/usr/bin/env python

import logging

logger = logging.getLogger('dev')
logger.setLevel(logging.INFO)

consoleHandler = logging.StreamHandler()
consoleHandler.setLevel(logging.INFO)

logger.addHandler(consoleHandler)

formatter = logging.Formatter('%(asctime)s  %(name)s  %(levelname)s: %(message)s')
consoleHandler.setFormatter(formatter)

logger.info('информационное сообщение')

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

formatter = logging.Formatter('%(asctime)s  %(name)s  %(levelname)s: %(message)s')

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

consoleHandler.setFormatter(formatter)

Форматтер устанавливается на обработчик с помощью setFormatter().

$ formatter.py
2019-03-28 14:53:27,446  dev  INFO: информационное сообщение

Сообщение с определенным форматом отображается в консоли.

Python logging basicConfig

basicConfig() настраивает корневой логгер. Он выполняет базовую настройку системы ведения журнала, создавая обработчик потока с форматером по умолчанию. debug(), info(), warning(), error() и critical() автоматически вызывают basicConfig(), если для корневого регистратора не определены обработчики.

basic_config.py

#!/usr/bin/env python

import logging

logging.basicConfig(filename='test.log', format='%(filename)s: %(message)s',
                    level=logging.DEBUG)

logging.debug('Это отладочное сообщение')
logging.info('Это информационное сообщение')
logging.warning('Это предупреждающее сообщение')
logging.error('Это сообщение об ошибке')
logging.critical('Это критическое сообщение')

В этом примере корневая программа регистрации настраивается с помощью basicConfig.

logging.basicConfig(filename='test.log', format='%(filename)s: %(message)s',
    level=logging.DEBUG)

С помощью имени файла filename мы устанавливаем файл, в который мы записываем сообщения журнала. Формат format определяет, что записывается в файл; у нас есть имя файла и сообщение. С уровнем level мы устанавливаем порог регистрации.

$ basic_config.py
$ cat test.log
basic_config.py: Это отладочное сообщение
basic_config.py: Это информационное сообщение
basic_config.py: Это предупреждающее сообщение
basic_config.py: Это сообщение об ошибке
basic_config.py: Это критическое сообщение

После запуска программы у нас есть пять сообщений, записанных в файл test.log.

Python logging fileConfig

fileConfig() считывает конфигурацию ведения журнала из файла формата configparser.

log.conf

[loggers]
keys=root,dev

[handlers]
keys=consoleHandler

[formatters]
keys=extend,simple

[logger_root]
level=INFO
handlers=consoleHandler

[logger_dev]
level=INFO
handlers=consoleHandler
qualname=dev
propagate=0

[handler_consoleHandler]
class=StreamHandler
level=INFO
formatter=extend
args=(sys.stdout,)

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

[formatter_simple]
format=%(asctime)s - %(message)s

log.conf определяет регистратор, обработчик и форматер.

file_config.py

#!/usr/bin/env python

import logging
import logging.config

logging.config.fileConfig(fname='log.conf')

logger = logging.getLogger('dev')
logger.info('Это информационное сообщение')

В этом примере файл конфигурации журнала считывается из файла log.conf.

$ file_config.py
2019-03-28 15:26:31,137 - dev - INFO - Это информационное сообщение

Переменные в Python logging

Динамические данные записываются с использованием форматирования строки.

log_variable.py

#!/usr/bin/env python

import logging

root = logging.getLogger()
root.setLevel(logging.INFO)

log_format = '%(asctime)s %(filename)s: %(message)s'
logging.basicConfig(filename="test.log", format=log_format)

# случился инцидент

error_message = 'аутентификация не удалась'

root.error(f'error: {error_message}')

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

2019-03-21 14:17:23,196 log_variable.py: error: аутентификация не удалась

Форматирование даты/времени в Python logging

Дата и время включаются в сообщение журнала вместе с записью журнала. С помощью опции конфигурации datefmt мы можем отформатировать строку datetime.

date_time.py

#!/usr/bin/env python

import logging

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

log_format = '%(asctime)s %(filename)s: %(message)s'
logging.basicConfig(filename="test.log", format=log_format,
                    datefmt='%Y-%m-%d %H:%M:%S')

logger.info("информационное сообщение")

В примере форматируется дата и время сообщения журнала.

log_format = '%(asctime)s %(filename)s: %(message)s'

Мы включаем строку datetime в журнал вместе с asctime.

logging.basicConfig(filename="test.log", format=log_format,
                    datefmt='%Y-%m-%d %H:%M:%S')

Опция datefmt форматирует строку даты и времени.

2019-03-21 14:17:23,196 log_variable.py: error: аутентификация не удалась
2019-03-21 14:23:33 date_time.py: информационное сообщение

Обратите внимание на разницу в формате строки даты и времени.

Трассировка стека логирования Python

Трассировка стека - это стек вызовов функций, которые выполнялись до точки возникновения исключений. Трассировка стека включается опцией exc_info.

stack_trace.py

#!/usr/bin/env python

import logging

log_format = '%(asctime)s %(filename)s: %(message)s'
logging.basicConfig(filename="test.log", format=log_format)

vals = [1, 2]

try:
    print(vals[4])

except Exception as e:
    logging.error("произошло исключение", exc_info=True)

В этом примере мы регистрируем исключение, которое выдается при попытке доступа к несуществующему списковому индексу.

logging.error("произошло исключение", exc_info=True)

Трассировка стека включается в журнал, устанавливая для exc_info значение True.

2019-03-21 14:56:21,313 stack_trace.py: произошло исключение
Traceback (most recent call last):
  File "C:\Users\Jano\Documents\pyprogs\pylog\stack_trace.py", line 11, in <module>
    print(vals[4])
IndexError: list index out of range

Трассировка стека включена в журнал.

Python logging getLogger

getLogger() возвращает регистратор с указанным именем. Если имя не указано, возвращается корневой регистратор. Обычная практика - помещать туда имя модуля с помощью __name__.

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

get_logger.py

#!/usr/bin/env python

import logging
import sys

main = logging.getLogger('main')
main.setLevel(logging.DEBUG)

handler = logging.FileHandler('my.log')

format = logging.Formatter('%(asctime)s  %(name)s
    %(levelname)s: %(message)s')
handler.setFormatter(format)

main.addHandler(handler)

main.info('информационное сообщение')
main.critical('критическое сообщение')
main.debug('отладочное сообщение')
main.warning('предупреждение')
main.error('сообщение об ошибке')

В примере создается новый регистратор с помощью getLogger(). Дается обработчик файла и форматер.

main = logging.getLogger('main')
main.setLevel(logging.DEBUG)

Создан регистратор с именем main; мы устанавливаем уровень ведения журнала на DEBUG.

handler = logging.FileHandler('my.log')

Обработчик файла создан. Сообщения будут записаны в файл my.log.

format = logging.Formatter('%(asctime)s  %(name)s
    %(levelname)s: %(message)s')
handler.setFormatter(format)

Форматер создан. Он включает в себя время, имя регистратора, уровень регистрации и сообщение для входа. Форматтер устанавливается на обработчик с помощью setFormatter().

main.addHandler(handler)

Обработчик добавляется в логгер с помощью addHandler().

$ cat my.log
2019-03-21 14:15:45,439  main  INFO: информационное сообщение
2019-03-21 14:15:45,439  main  CRITICAL: критическое сообщение
2019-03-21 14:15:45,439  main  DEBUG: отладочное сообщение
2019-03-21 14:15:45,439  main  WARNING: предупреждение
2019-03-21 14:15:45,439  main  ERROR: сообщение об ошибке

Конфигурация YAML для логирования в Python

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

$ pip install pyyaml

Нам нужно установить модуль pyyaml.

config.yaml

version: 1

formatters:
  simple:
    format: "%(asctime)s %(name)s: %(message)s"
  extended:
    format: "%(asctime)s %(name)s %(levelname)s: %(message)s"

handlers:
  console:
    class: logging.StreamHandler
    level: INFO
    formatter: simple

  file_handler:
    class: logging.FileHandler
    level: INFO
    filename: test.log
    formatter: extended
    propagate: false

loggers:
  dev:
    handlers: [console, file_handler]
  test:
    handlers: [file_handler]
root:
  handlers: [file_handler]

В файле конфигурации мы определили различные форматеры, обработчики и регистраторы. Опция распространения предотвращает распространение сообщений журнала на родительские регистраторы; в нашем случае, к корневому логгеру. В противном случае сообщения будут продублированы.

log_yaml.py

#!/usr/bin/env python

import logging
import logging.config
import yaml

with open('config.yaml', 'r') as f:

    log_cfg = yaml.safe_load(f.read())

logging.config.dictConfig(log_cfg)

logger = logging.getLogger('dev')
logger.setLevel(logging.INFO)

logger.info('Это информационное сообщение')
logger.error('Это сообщение об ошибке')

В этом примере мы читаем файл конфигурации и используем dev logger.

$ log_yaml.py
2019-03-28 11:36:54,854 dev: Это информационное сообщение
2019-03-28 11:36:54,855 dev: Это сообщение об ошибке

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

...
2019-03-28 11:36:54,854 dev INFO: Это информационное сообщение
2019-03-28 11:36:54,855 dev ERROR: Это сообщение об ошибке

Внутри файла test.log находятся сообщения журнала. Они производятся расширенным форматером с дополнительной информацией.

http://zetcode.com/python/logging/

Вернуться на верх