Примеры логгирования с Python Logging

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

Простейший (обратите внимание: не лучший) способ сделать это — использовать много операторов вывода (print) своем коде. Это плохая идея, так как вы получите много вывода в консоли, и, скорее всего, удалите инструкции для вывода, как только исправите ошибку.

Как отслеживать ошибки правильно? Логгирование!

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

Пример #1 – Приложение для одного файла

Первый пример — простая программа, которая поможет проиллюстрировать основные возможности модуля logging. Эта программа состоит из одного файла под именем app.py, который содержит один класс:

class FirstClass:
    def __init__(self):
        self.current_number = 0
        
    def increment_number(self):
        self.current_number += 1
        
    def decrement_number(self):
        self.current_number -= 1
        
    def clear_number(self):
        self.current_number = 0


number = FirstClass()
number.increment_number()
number.increment_number()
print("Текущее значение: %s" % str(number.current_number))
number.clear_number()
print("Текущее значение: %s" % str(number.current_number))

Вы можете запустить эту программу, выполнив:

$ python app.py
Текущее значение: 2
Текущее значение: 0

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

Настройка модуля логгирования

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

  • установки уровня строгости ведения лога
  • указания файла для записи сообщений
  • установки формата сообщений

Измените конструктор класса FirstClass, чтобы настроить модуль logging:

def __init__(self):
    self.current_number = 0
 
    # Создайте Logger
    self.logger = logging.getLogger(__name__)
    self.logger.setLevel(logging.WARNING)
 
    # Создайте обработчик для записи данных в файл
    logger_handler = logging.FileHandler('python_logging.log')
    logger_handler.setLevel(logging.WARNING)
 
    # Создайте Formatter для форматирования сообщений в логе
    logger_formatter = logging.Formatter('%(name)s - %(levelname)s - %(message)s')
 
    # Добавьте Formatter в обработчик
    logger_handler.setFormatter(logger_formatter)
 
    # Добавьте обработчик в Logger
    self.logger.addHandler(logger_handler)
    self.logger.info('Настройка логгирования окончена!')

Не забудьте добавить import logging

Конструктор настраивает использование модуля logging и заканчивается записью о том, что настройка завершена.

Добавление лог-сообщений

Чтобы добавить сообщения лога, вы можете использовать один из методов модуля логгирования python для вывода в логе:

def increment_number(self):
    self.current_number += 1
    self.logger.warning('Число увеличивается!')
    self.logger.info('Число еще увеличивается!!')

def decrement_number(self):
    self.current_number -= 1

def clear_number(self):
    self.current_number = 0
    self.logger.warning('Очистка значения!')
    self.logger.info('Значение еще не очищено!!')

Если вы снова запустите программу, вы все равно увидите тот же вывод консоли.

$ python app.py
Текущее значение: 2
Текущее значение: 0

Уровень серьёзности логгирования

Чтобы узнать, что делает модуль logging, проверьте файл лога, который был создан:

$ cat python_logging.log
__main__ - WARNING - Число увеличивается!  
__main__ - WARNING - Число увеличивается!  
__main__ - WARNING - Очистка значения!

Интересно, это то, чего вы ждали? Должно было быть еще две записи «Число еще увеличивается!!», но они не отобразились. Почему? Ну, дело в том, что у модуля logging 5 уровней серьезности:

  • DEBUG (низший)
  • INFO
  • WARNING
  • ERROR
  • CRITICAL (высший)

Наша программа использует настройку по умолчанию (WARNING) для серьезности ведения лога, это означает, что любое сообщение журнала с меньшей степенью серьезности, чем WARNING, не будет отображаться. Следовательно, сообщения INFO так же не отображаются.
Поменяйте следующие строки в __init__():

# Создайте Logger
self.logger = logging.getLogger(__name__)
self.logger.setLevel(logging.INFO)
# Создайте обработчик для записи данных в файл
logger_handler = logging.FileHandler('python_logging.log')
logger_handler.setLevel(logging.INFO)

Теперь проверьте файл лога, сообщения уровня INFO отображаются:

$ cat python_logging.log
__main__ - WARNING - Число увеличивается!  
__main__ - WARNING - Число увеличивается!  
__main__ - WARNING - Очистка значения!  
__main__ - INFO - Настройка логгирования окончена!  
__main__ - WARNING - Число увеличивается!  
__main__ - INFO - Число еще увеличивается!!  
__main__ - WARNING - Число увеличивается!  
__main__ - INFO - Число еще увеличивается!!  
__main__ - WARNING - Очистка значения!  
__main__ - INFO - Значение еще не очищено!!

Пример #2 – Logging в модуле

Второй пример немного сложнее, так как он обновляет структуру программы для включения пакета с одним модулем:

python_logging
    python_logging
        __init__.py
        first_class.py
    app.py

Файл first_class.py содержит класс FirstClass, который был создан в первом примере:

import logging


class FirstClass:  
    def __init__(self):  
        self.current_number = 0  
  
  # Создайте Logger  
  self.logger = logging.getLogger(__name__)  
        self.logger.setLevel(logging.INFO)  
  
        # Создайте обработчик для записи данных в файл  
  logger_handler = logging.FileHandler('python_logging.log')  
        logger_handler.setLevel(logging.INFO)  
  
        # Создайте Formatter для форматирования сообщений в логе  
  logger_formatter = logging.Formatter('%(name)s - %(levelname)s - %(message)s')  
  
        # Добавьте Formatter в обработчик  
  logger_handler.setFormatter(logger_formatter)  
  
        # Добавте обработчик в Logger  
  self.logger.addHandler(logger_handler)  
        self.logger.info('Настройка логгирования окончена!')  
  
    def increment_number(self):  
        self.current_number += 1  
  self.logger.warning('Число увеличивается!')  
        self.logger.info('Число еще увеличивается!!')  
  
    def decrement_number(self):  
        self.current_number -= 1  
  
  def clear_number(self):  
        self.current_number = 0  
  self.logger.warning('Очистка значения!')  
        self.logger.info('Значение еще не очищено!!')

Чтобы использовать этот модуль, обновите файл app.py в каталоге верхнего уровня и импортируйте класс FirstClass для его использования:

from python_logging.first_class import FirstClass


number = FirstClass()
number.increment_number()
number.increment_number()
print("Текущее значение: %s" % str(number.current_number))  
number.clear_number()  
print("Текущее значение: %s" % str(number.current_number))

Запустим app.py и проверим файл лога:

$ python app.py
Текущее значение: 2
Текущее значение: 0
$ cat python_logging.log
...
__main__ - WARNING - Очистка значения!  
__main__ - INFO - Значение еще не очищено!!
python_logging - INFO - Настройка логгирования окончена!  
python_logging.first_class - WARNING - Число увеличивается!  
python_logging.first_class - INFO - Число еще увеличивается!!  
python_logging.first_class - WARNING - Число увеличивается!  
python_logging.first_class - INFO - Число еще увеличивается!!  
python_logging.first_class - WARNING - Очистка значения!  
python_logging.first_class - INFO - Значение еще не очищено!!

Пример #3: Logging в пакетах

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

python_logging
    python_logging
        __init__.py
        first_class.py
        second_class.py
    app.py

Вот базовая версия файла second_class.py:

class SecondClass:
    def __init__(self):
        self.enabled = False
 
    def enable_system(self):
        self.enabled = True
 
    def disable_system(self):
        self.enabled = False

Можно дублировать настройки logger в конструктор этого класса (копия из first_class.py). Это приведет к большому количеству ненужного повторяющегося кода.
Лучше всего переместить настройку logger в файл __init__.py:

from os import path, remove  
import logging  
import logging.config  
  
from .first_class import FirstClass  
from .second_class import SecondClass  
  
  
# Удалите существующий файл лога, если он есть, чтобы создавать новый файл во время каждого выполнения  
if path.isfile("python_logging.log"):  
    remove("python_logging.log")  
  
# Создайте Logger  
logger = logging.getLogger(__name__)  
logger.setLevel(logging.INFO)  
  
# Создайте обработчик для записи данных в файл  
logger_handler = logging.FileHandler('python_logging.log')  
logger_handler.setLevel(logging.INFO)  
  
# Создайте Formatter для форматирования сообщений в логе  
logger_formatter = logging.Formatter('%(name)s - %(levelname)s - %(message)s')  
  
# Добавьте Formatter в обработчик  
logger_handler.setFormatter(logger_formatter)  
  
# Добавте обработчик в Logger  
logger.addHandler(logger_handler)  
logger.info('Настройка логгирования окончена!')

В зависимости от типа создаваемой программы вам может быть полезно удалить любые существующие файлы лога до записи любых новых сообщений во время выполнения этой программы. Один из вариантов, если вы хотите сохранить текущий лог приложения, воспользоваться RotatingFileHandler из модуля Logging.
Теперь, когда настройка модуля логгирования выполняется в __init__.py, файл second_class.py можно значительно упростить и не беспокоиться о его настройке:

import logging


class SecondClass(object):  
    def __init__(self):  
        self.enabled = False  
        self.logger = logging.getLogger(__name__)  
  
    def enable_system(self):  
        self.enabled = True  
        self.logger.warning('Включение системы!')  
        self.logger.info('Система все еще включается!!')  
  
    def disable_system(self):  
        self.enabled = False  
        self.logger.warning('Выключение системы!')  
        self.logger.info('Система все еще выключается!!')

Так же нужно упростить def __init__() в first_class.py:

def __init__(self):  
    self.current_number = 0  
    self.logger = logging.getLogger(__name__)

Наконец, обновления в __init__.py приводят к необходимости следующих обновлений в app.py:

from python_logging import FirstClass, SecondClass  
  
  
number = FirstClass()  
number.increment_number()  
number.increment_number()  
print("Текущее значение: %s" % str(number.current_number))  
number.clear_number()  
print("Текущее значение: %s" % str(number.current_number))  
  
system = SecondClass()  
system.enable_system()  
system.disable_system()  
print("Текущее состояние системы: %s" % str(system.enabled))

Попробуйте снова запустить программу и посмотрите файл лога:

$ cat python_logging.log
python_logging - INFO - Настройка логгирования окончена!  
python_logging.first_class - WARNING - Число увеличивается!  
python_logging.first_class - INFO - Число еще увеличивается!!  
python_logging.first_class - WARNING - Число увеличивается!  
python_logging.first_class - INFO - Число еще увеличивается!!  
python_logging.first_class - WARNING - Очистка значения!  
python_logging.first_class - INFO - Значение еще не очищено!!  
python_logging.second_class - WARNING - Включение системы!  
python_logging.second_class - INFO - Система все еще включается!!  
python_logging.second_class - WARNING - Выключение системы!  
python_logging.second_class - INFO - Система все еще выключается!!

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

Пример #4: Logging в пакетах с JSON

Четвертый (и последний) пример расширяет возможности логгирования, добавив входной файл (JSON) для настройки логгера.
Первое изменение для этого примера в __init__.py, чтобы изменить настройки логгера для использования входного файла JSON:

from os import path, remove  
import logging  
import logging.config  
import json  
  
from .first_class import FirstClass  
from .second_class import SecondClass  
  
  
# Удалите существующий файл лога, если он есть, чтобы создавать новый файл во время каждого выполнения  
if path.isfile("python_logging.log"):  
    remove("python_logging.log")  
  
with open("python_logging_configuration.json", 'r') as logging_configuration_file:  
    config_dict = json.load(logging_configuration_file)  
  
logging.config.dictConfig(config_dict)  
  
# Запись о том, что logger настроен  
logger = logging.getLogger(__name__)  
logger.info('Настройка логгирования окончена!')

Теперь, когда у нас есть код для обработки входного файла, давайте определим входной файл (python_logging_configuration.json). Обязательно добавьте этот файл в папку верхнего уровня, чтобы он мог быть легко идентифицирован интерпретатором python. Вы должны запустить эту программу из папки верхнего уровня, чтобы сделать входной файл JSON доступным интерпретатору python, поскольку он находится в текущем / рабочем каталоге.
Вот файл конфигурации:


{  
  "version": 1,  
  "disable_existing_loggers": false,  
  "formatters": {  
    "simple": {  
      "format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s"  
  }  
  },  
  "handlers": {  
    "file_handler": {  
      "class": "logging.FileHandler",  
  "level": "DEBUG",  
  "formatter": "simple",  
  "filename": "python_logging.log",  
  "encoding": "utf8"  
  }  
  },  
  "root": {  
    "level": "DEBUG",  
  "handlers": ["file_handler"]  
  }  
}

Запустите программу еще раз и посмотрите файл лога:

$ cat python_logging.log
2019-01-05 20:13:40,636 - python_logging - INFO - Настройка логгирования окончена!  
2019-01-05 20:13:40,636 - python_logging.first_class - WARNING - Число увеличивается!  
2019-01-05 20:13:40,636 - python_logging.first_class - INFO - Число еще увеличивается!!  
2019-01-05 20:13:40,636 - python_logging.first_class - WARNING - Число увеличивается!  
2019-01-05 20:13:40,636 - python_logging.first_class - INFO - Число еще увеличивается!!  
2019-01-05 20:13:40,636 - python_logging.first_class - WARNING - Очистка значения!  
2019-01-05 20:13:40,636 - python_logging.first_class - INFO - Значение еще не очищено!!  
2019-01-05 20:13:40,636 - python_logging.second_class - WARNING - Включение системы!  
2019-01-05 20:13:40,636 - python_logging.second_class - INFO - Система все еще включается!!  
2019-01-05 20:13:40,636 - python_logging.second_class - WARNING - Выключение системы!  
2019-01-05 20:13:40,636 - python_logging.second_class - INFO - Система все еще выключается!!

Файл лога почти такой же, но строка даты и времени добавлена ​​в каждое сообщение. Этот формат сообщений логгирования очень удобный: дата / время — package.module — сообщение журнала

Если Вам не нравится работать с JSON, входной файл также может быть определен как файл YAML. Вот пример: Good Logging Practice in Python

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

Максим
Я создал этот блог в 2018 году, чтобы распространять полезные учебные материалы, документации и уроки на русском. На сайте опубликовано множество статей по основам python и библиотекам, уроков для начинающих и примеров написания программ.
Мои контакты: Почта
admin@pythonru.comAlex Zabrodin2018-10-26OnlinePython, Programming, HTML, CSS, JavaScript

Статьи по теме