Python лог ошибок в файл

Сталкивались ли вы с трудностями при отладке Python-кода? Если это так — то изучение того, как наладить логирование (журналирование, logging) в Python, способно помочь вам упростить задачи, решаемые при отладке.

Вы, кроме того, узнаете о том, как Sentry Python SDK способен помочь вам в мониторинге приложений и в упрощении рабочих процессов, связанных с отладкой кода. Платформа Sentry обладает нативной интеграцией со встроенным Python-модулем logging, и, кроме того, предоставляет подробную информацию об ошибках приложения и о проблемах с производительностью, которые в нём возникают.

Начало работы с Python-модулем logging

В Python имеется встроенный модуль logging, применяемый для решения задач логирования. Им мы будем пользоваться в этом руководстве. Первый шаг к профессиональному логированию вы можете выполнить прямо сейчас, импортировав этот модуль в своё рабочее окружение.

import logging

Встроенный модуль логирования Python даёт нам простой в использовании функционал и предусматривает пять уровней логирования. Чем выше уровень — тем серьёзнее неприятность, о которой сообщает соответствующая запись. Самый низкий уровень логирования — это debug (10), а самый высокий — это critical (50).

Дадим краткие характеристики уровней логирования:

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

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

• Warning (30): этот уровень логирования предусматривает вывод предупреждений, он применяется для записи сведений о событиях, на которые программист обычно обращает внимание. Такие события вполне могут привести к проблемам при работе приложения. Если явно не задать уровень логирования — по умолчанию используется именно warning.

• Error (40): этот уровень логирования предусматривает вывод сведений об ошибках — о том, что часть приложения работает не так как ожидается, о том, что программа не смогла правильно выполниться.

• Critical (50): этот уровень используется для вывода сведений об очень серьёзных ошибках, наличие которых угрожает нормальному функционированию всего приложения. Если не исправить такую ошибку — это может привести к тому, что приложение прекратит работу.

В следующем фрагменте кода показано использование вышеперечисленных уровней логирования при выводе нескольких сообщений. Здесь используется синтаксическая конструкция logging.<level>(<message>).

logging.debug("A DEBUG Message")
logging.info("An INFO")
logging.warning("A WARNING")
logging.error("An ERROR")
logging.critical("A message of CRITICAL severity")

Ниже приведён результат выполнения этого кода. Как видите, сообщения, выведенные с уровнями логирования warning, error и critical, попадают в консоль. А сообщения с уровнями debug и info — не попадают.

WARNING:root:A WARNING
ERROR:root:An ERROR
CRITICAL:root:A message of CRITICAL severity

Это так из-за того, что в консоль выводятся лишь сообщения с уровнями от warning и выше. Но это можно изменить, настроив логгер и указав ему, что в консоль надо выводить сообщения, начиная с некоего, заданного вами, уровня логирования.

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

Обратите внимание на то, что в примере, который мы будем тут разбирать, весь код находится в файле main.py. Когда мы производим рефакторинг существующего кода или добавляем новые модули — мы сообщаем о том, в какой файл (имя которого построено по схеме <module-name>.py) попадает новый код. Это поможет вам воспроизвести у себя то, о чём тут идёт речь.

Логирование в файл

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

logging.basicConfig(level=logging.INFO, filename="py_log.log",filemode="w")
logging.debug("A DEBUG Message")
logging.info("An INFO")
logging.warning("A WARNING")
logging.error("An ERROR")
logging.critical("A message of CRITICAL severity")

Поговорим о логгере root, рассмотрим параметры basicConfig():

• level: это — уровень, на котором нужно начинать логирование. Если он установлен в info — это значит, что все сообщения с уровнем debug игнорируются.

• filename: этот параметр указывает на объект обработчика файла. Тут можно указать имя файла, в который нужно осуществлять логирование.

• filemode: это — необязательный параметр, указывающий режим, в котором предполагается работать с файлом журнала, заданным параметром filename. Установка filemode в значение w (write, запись) приводит к тому, что логи перезаписываются при каждом запуске модуля. По умолчанию параметр filemode установлен в значение a (append, присоединение), то есть — в файл будут попадать записи из всех сеансов работы программы.

После выполнения модуля main можно будет увидеть, что в текущей рабочей директории был создан файл журнала, py_log.log.

Так как мы установили уровень логирования в значение info — в файл попадут записи с уровнем info и с более высокими уровнями.

Записи в лог-файле имеют формат <logging-level>:<name-of-the-logger>:<message>. По умолчанию <name-of-the-logger>, имя логгера, установлено в root, так как мы пока не настраивали пользовательские логгеры.

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

logging.basicConfig(level=logging.INFO, filename="py_log.log",filemode="w",
                    format="%(asctime)s %(levelname)s %(message)s")
logging.debug("A DEBUG Message")
logging.info("An INFO")
logging.warning("A WARNING")
logging.error("An ERROR")
logging.critical("A message of CRITICAL severity")

Существуют и многие другие атрибуты записи лога, которыми можно воспользоваться для того чтобы настроить внешний вид сообщений в лог-файле. Настраивая поведение логгера root — так, как это показано выше, проследите за тем, чтобы конструктор logging.basicConfig()вызывался бы лишь один раз. Обычно это делается в начале программы, до использования команд логирования. Последующие вызовы конструктора ничего не изменят — если только не установить параметр force в значение True.

Логирование значений переменных и исключений

Модифицируем файл main.py. Скажем — тут будут две переменных — x и y, и нам нужно вычислить значение выражения x/y. Мы знаем о том, что при y=0 мы столкнёмся с ошибкой ZeroDivisionError. Обработать эту ошибку можно в виде исключения с использованием блока try/except.

Далее — нужно залогировать исключение вместе с данными трассировки стека. Чтобы это сделать — можно воспользоваться logging.error(message, exc_info=True). Запустите следующий код и посмотрите на то, как в файл попадают записи с уровнем логирования info, указывающие на то, что код работает так, как ожидается.

x = 3
y = 4

logging.info(f"The values of x and y are {x} and {y}.")
try:
    x/y
    logging.info(f"x/y successful with result: {x/y}.")
except ZeroDivisionError as err:
    logging.error("ZeroDivisionError",exc_info=True)

Теперь установите значение y в 0 и снова запустите модуль.

Исследуя лог-файл py_log.log, вы увидите, что сведения об исключении были записаны в него вместе со стек-трейсом.

x = 4
y = 0

logging.info(f"The values of x and y are {x} and {y}.")
try:
    x/y
    logging.info(f"x/y successful with result: {x/y}.")
except ZeroDivisionError as err:
    logging.error("ZeroDivisionError",exc_info=True)

Теперь модифицируем код так, чтобы в нём имелись бы списки значений x и y, для которых нужно вычислить коэффициенты x/y. Для логирования исключений ещё можно воспользоваться конструкцией logging.exception(<message>).

x_vals = [2,3,6,4,10]
y_vals = [5,7,12,0,1]

for x_val,y_val in zip(x_vals,y_vals):
    x,y = x_val,y_val
    logging.info(f"The values of x and y are {x} and {y}.")
    try:
        x/y
        logging.info(f"x/y successful with result: {x/y}.")
    except ZeroDivisionError as err:
        logging.exception("ZeroDivisionError")

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

Настройка логирования с помощью пользовательских логгеров, обработчиков и форматировщиков

Отрефакторим код, который у нас уже есть. Объявим функцию test_division.

def test_division(x,y):
    try:
        x/y
        logger2.info(f"x/y successful with result: {x/y}.")
    except ZeroDivisionError as err:
        logger2.exception("ZeroDivisionError")

Объявление этой функции находится в модуле test_div. В модуле main будут лишь вызовы функций. Настроим пользовательские логгеры в модулях main и test_div, проиллюстрировав это примерами кода.

Настройка пользовательского логгера для модуля test_div

import logging

logger2 = logging.getLogger(__name__)
logger2.setLevel(logging.INFO)

# настройка обработчика и форматировщика для logger2
handler2 = logging.FileHandler(f"{__name__}.log", mode='w')
formatter2 = logging.Formatter("%(name)s %(asctime)s %(levelname)s %(message)s")

# добавление форматировщика к обработчику
handler2.setFormatter(formatter2)
# добавление обработчика к логгеру
logger2.addHandler(handler2)

logger2.info(f"Testing the custom logger for module {__name__}...")

def test_division(x,y):
    try:
        x/y
        logger2.info(f"x/y successful with result: {x/y}.")
    except ZeroDivisionError as err:
        logger2.exception("ZeroDivisionError")

Настройка пользовательского логгера для модуля main

import logging
from test_div import test_division 

# получение пользовательского логгера и установка уровня логирования
py_logger = logging.getLogger(__name__)
py_logger.setLevel(logging.INFO)

# настройка обработчика и форматировщика в соответствии с нашими нуждами
py_handler = logging.FileHandler(f"{__name__}.log", mode='w')
py_formatter = logging.Formatter("%(name)s %(asctime)s %(levelname)s %(message)s")

# добавление форматировщика к обработчику 
py_handler.setFormatter(py_formatter)
# добавление обработчика к логгеру
py_logger.addHandler(py_handler)

py_logger.info(f"Testing the custom logger for module {__name__}...")

x_vals = [2,3,6,4,10]
y_vals = [5,7,12,0,1]

for x_val,y_val in zip(x_vals,y_vals):
    x,y = x_val, y_val
    # вызов test_division
    test_division(x,y)
    py_logger.info(f"Call test_division with args {x} and {y}")

Разберёмся с тем, что происходит коде, где настраиваются пользовательские логгеры.

Сначала мы получаем логгер и задаём уровень логирования. Команда logging.getLogger(name) возвращает логгер с заданным именем в том случае, если он существует. В противном случае она создаёт логгер с заданным именем. На практике имя логгера устанавливают с использованием специальной переменной name, которая соответствует имени модуля. Мы назначаем объект логгера переменной. Затем мы, используя команду logging.setLevel(level), устанавливаем нужный нам уровень логирования.

Далее мы настраиваем обработчик. Так как мы хотим записывать сведения о событиях в файл, мы пользуемся FileHandler. Конструкция logging.FileHandler(filename) возвращает объект обработчика файла. Помимо имени лог-файла, можно, что необязательно, задать режим работы с этим файлом. В данном примере режим (mode) установлен в значение write. Есть и другие обработчики, например — StreamHandler, HTTPHandler, SMTPHandler.

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

Потом мы добавляем форматировщик к обработчику, пользуясь конструкцией вида <handler>.setFormatter(<formatter>). А в итоге добавляем обработчик к объекту логгера, пользуясь конструкцией <logger>.addHandler(<handler>).

Теперь можно запустить модуль main и исследовать сгенерированные лог-файлы.

Рекомендации по организации логирования в Python

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

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

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

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

• Применяйте ротацию лог-файлов ради упрощения отладки. При работе над большим приложением, в состав которого входит несколько модулей, вы, вполне вероятно, столкнётесь с тем, что размер ваших лог-файлов окажется очень большим. Очень длинные логи сложно просматривать в поисках ошибок. Поэтому стоит подумать о ротации лог-файлов. Сделать это можно, воспользовавшись обработчиком RotatingFileHandler, применив конструкцию, которая строится по следующей схеме: logging.handlers.RotatingFileHandler(filename, maxBytes, backupCount). Когда размер текущего лог-файла достигнет размера maxBytes, следующие записи будут попадать в другие файлы, количество которых зависит от значения параметра backupCount. Если установить этот параметр в значение K — у вас будет K файлов журнала.

Сильные и слабые стороны логирования

Теперь, когда мы разобрались с основами логирования в Python, поговорим о сильных и слабых сторонах этого механизма.

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

Кроме того, исследование логов ошибок — это сложно, особенно в том случае, если сообщения об ошибках не содержат достаточных сведений о контекстах, в которых происходят ошибки. Когда выполняют команду logging.error(message), не устанавливая при этом exc_info в True, сложно обнаружить и исследовать первопричину ошибки в том случае, если сообщение об ошибке не слишком информативно.

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

В следующем разделе мы поговорим о том, как интегрировать в Python-проект поддержку Sentry, что позволит упростить процесс отладки кода.

Интеграция Sentry в Python-проект

Установить Sentry Python SDK можно, воспользовавшись менеджером пакетов pip.

pip install sentry-sdk

После установки SDK для настройки мониторинга приложения нужно воспользоваться таким кодом:

sentry_sdk.init(
     dsn="<your-dsn-key-here>",
     traces_sample_rate=0.85,
)

Как можно видеть — вам, для настройки мониторинга, понадобится ключ dsn. DSN расшифровывается как Data Source Name (имя источника данных). Найти этот ключ можно, перейдя в Your-Project > Settings > Client Keys (DSN).

После того, как вы запустите Python-приложение, вы можете перейти на Sentry.io и открыть панель управления проекта. Там должны быть сведения о залогированных ошибках и о других проблемах приложения. В нашем примере можно видеть сообщение об исключении, соответствующем ошибке ZeroDivisionError.

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

Продолжая изучение логов, можно увидеть, помимо записей уровня error, записи уровня info. Налаживая мониторинг приложения с использованием Sentry, нужно учитывать, что эта платформа интегрирована с модулем logging. Вспомните — в нашем экспериментальном проекте уровень логирования был установлен в значение info. В результате Sentry записывает все события, уровень которых соответствует info и более высоким уровням, делая это в стиле «навигационной цепочки», что упрощает отслеживание ошибок.

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

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

Код, использованный в данном руководстве, можно найти в этом GitHub-репозитории.

Итоги

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

Когда вы будете работать над своим следующим Python-проектом — не забудьте реализовать в нём механизмы логирования. И можете испытать бесплатную пробную версию Sentry.

О, а приходите к нам работать? 🤗 💰

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

Для начала работы нам потребуется подключить с помощью оператора import модуль логирования. Также в рамках нашего тестового примера мы будем использовать модуль datetime, который поставляет полезные функции для работы с датой и временем. В начале вашего скрипта/модуля (у меня это основной тестовый скрипт с именем main.py) поместите следующие строки:

import logging
import datetime

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

Итак, в основной части скрипта пишем следующий код (я специально снабдил его комментариями, поясняющими подробно происходящее, чтобы сделать логику скрипта максимально доступной читателю с разным уровнем владения Python):

if __name__ == '__main__':
    # получаем логгер для нашего модуля
    logger = logging.getLogger(__name__)

    # создаём хендлер для файла лога, кодировка файла будет UTF-8 для поддержки кириллических сообщений в логе
    fileHandler = logging.FileHandler(filename='application_log.log', encoding='utf-8')

    # задаём базовую конфигурацию логирования
    logging.basicConfig(format='[%(levelname)-10s] %(asctime)-25s - %(message)s', handlers=[fileHandler], level=logging.INFO)

    # кортеж, содержащий дни недели. необходим для отражения дня, в который была запущена и завершилась программа
    days = ('понедельник', 'вторник', 'среда', 'четверг', 'пятница', 'суббота', 'воскресенье')

    # получаем текущие дату и время в переменную now_dt
    now_dt = datetime.datetime.now()

    # получить точное наименование дня недели, в который запустился наш скрипт
    current_weekday = days[now_dt.weekday()]

    # формат для даты запуска/завершения скрипта
    date_format = "%d.%m.%Y %H:%M:%S.%f"

    # =======================================
    # Начало основной логики скрипта
    # =======================================
    logging.info(">>> Программа запущена. День: %s; Точная дата и время запуска: %s", current_weekday, now_dt.strftime(date_format))

    # Запрашиваем ввод числа с клавиатуры
    user_input = input("Введите целое число от 0 до 100: ")
    
    # Проверяем, что было введено число, а не что-то иное
    if user_input.isnumeric():
        logger.info("Пользовательский ввод корректен. Введено число: %s", user_input)
        # преобразуем число, хранящееся в строке к настоящему число с типом int
        input_int_var = int(user_input)
        # проверяем диапазон, в котором находится число
        if input_int_var < 0 or input_int_var > 100:
            logger.error("Ошибка: введено некорректное число, выходящее за допустимый диапазон: %s", input_int_var)
            print(f'Ошибка, введено число, выходящее за допустимый диапазон.')
        elif input_int_var == 0:
            logger.warning("Предупреждение: пользователь ввёл 0")
            print(f'Вы ввели {input_int_var}. Ввод нуля допустим, но нежелателен, '
                  'т.к. операция деления на 0 число не будет выполнена.')
        else:
            print(f'Вы ввели {input_int_var}. Отличное число!')
            result = 100 / input_int_var
            print(f'Результат деления 100 / {input_int_var} = { 100 / input_int_var}')
    else:
        # Если пользователь ввёл не число, то логируем ошибку в файл лога и выводим ошибку на консоль
        logger.error("Ошибка ввода: пользователь ввёл нечисловое значение!")
        print(f'Извините, ввод '{user_input}' не является корректным числом в допустимом диапазоне')

    # повторно получим текущие дату и время, чтобы отразить момент завершения скрипта в логе
    now_dt = datetime.datetime.now()
    # логируем запись о завершении программы
    logging.info("<<< Программа завершена. День %s; Точная дата и время завершения: %s", current_weekday, now_dt.strftime(date_format))

По комментариям должен быть понятен основной ход выполнения скрипта. Из основных особенностей — в самом начале скрипта мы получаем экземпляр логгера для нашего скрипта в переменную logger. Этот экземпляр логгера будет использоваться для вывода сообщений в заданный нами файл лога с именем application_log.log. Файл (а точнее его хендлер) мы специфицируем посредством создания экземпляра класса FileHandler и передачей ему необходимых параметров с именем файла, а также кодировкой файла UTF-8. 

Далее важной строкой является вызов функции basicConfig(), в которую мы передаём параметры, включающие в себя: формат сообщений лога, список хендлеров, которые будут использоваться для записи сообщений лога (в нашем случае у нас только один хендлер для файла лога), а также уровень логирования по умолчанию. Уровень логирования мы установим равным logging.INFO — для того, чтобы информационные сообщения также попадали в лог, а не только предупреждения/ошибки:

logging.basicConfig(format='[%(levelname)-10s] %(asctime)-25s - %(message)s', handlers=[fileHandler], level=logging.INFO)

Отмечу, что по умолчанию basicConfig() будет работать в режиме добавления в файл лога, это значит, что файл лога будет постоянно расти при каждом запуске скрипта. Если вы хотите, чтобы сообщения перезаписывались при каждом новом запуске скрипта, передайте в функцию параметр filemode=’w+’. В нашем же случае filemode не задан явно, поэтому по умолчанию он будет равен значению ‘a’ (от англ. append — добавлять).

В части параметра format ещё отмечу входящие в него опции:

• levelname — собственно, задаёт уровень логирования текущего сообщения, попадающего в лог
• asctime — будет содержать дату и время попадания записи в лог
• message — само сообщение, которое задаётся логикой нашей программы

Также под каждый из этих элементов лога отводится фиксированное количество позиций (для уровня логирования 10 символов, для даты и времени — 25 символов) — чтобы наш лог смотрелся красиво. Значения 10 и 25 подобраны мной экспериментально, при желании вы можете их поменять.

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

Давайте запустим наш скрипт и введём сначала корректное значение 77, входящее в диапазон от 0 до 100:

Мы видим, что в этом случае программа отработала с успехом и выдала результат деления 100 на 77, также обратим внимание, что создался новый файл application_log.log с сообщениями логирования нашего скрипта:

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

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

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

Наконец, производим последний запуск скрипта, и в этот раз мы введём вообще не число, а строку «проверка микрофона»:

Смотрим, что появилось в файле лога:

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

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

Спасибо за внимание, до встречи в следующих статьях!

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

Содержание:

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

Обратите внимание, что параметры logging.basicConfig() должны передаваться до первого вызова функций ведения журнала. Если в консоли интерпретатора уже была вызвана хотя бы одна функция, то необходимо перезагрузить пакет logging или выйти и снова зайти в консоль интерпретатора. С версии Python-3.8 для этой цели можно использовать ключевой аргумент force=True

Логирование событий в файл.

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

# test.py
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')

Теперь, если открыть файл example.log то можно увидеть сообщения журнала:

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

В примере также показано, как можно установить уровень ведения журнала level, который служит порогом для отслеживания событий. Так как установлен уровень отображения событий level=logging.DEBUG, то в файл были записаны все сообщения.

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

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

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

Если необходимо установить уровень ведения журнала из командной строки, а значение параметра для --log=<level> было получено например в переменную loglevel, то можно использовать функцию getattr для получения значения, которое передается logging.basicConfig() в качестве аргумента level:

>>> import logging
>>> loglevel = 'info'
# 'loglevel' преобразовываем в верхний регистр, чтобы
# пользователь мог указать --log=INFO или --log=info
>>> getattr(logging, loglevel.upper())
# 20

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

...
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, ...)
...

Логирование событий из нескольких модулей.

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

# app.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.

# mylib.py
import logging

def do_something():
    # регистрация сообщений в пользовательском модуле
    logging.info('Doing something')

Если запустить файл app.py, то в myapp.log увидим следующее:

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

Код примера можно расширить на несколько модулей, но используя этот простой шаблон, из записей файла журнала будет не понятно из каких модулей поступали сообщения. Если необходимо отслеживать местоположение сообщений, то смотрите раздел «Продвинутое использование модуля logging«.

Регистрация значений переменных.

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

>>> import logging
>>> x = 10
>>> y = 'See'
>>> logging.warning('%s how the variable is passed `x`: %d', y, x)
# WARNING:root:See how the variable is passed `x`: 10

Добавление значений переменных в описание события использует форматирование строк в стиле printf. Такое поведение в модуле logging сохранено для обратной совместимости. С версии Python-3.2 класс logging.Formatter() получил ключевой аргумент style='%', при помощи которого можно установить спецификации форматирования '{' или '$'. Эти спецификации поддерживают подходы, определенные в str.format() и string.Template() соответственно.

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

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

>>> import logging
>>> x = 10
>>> y = 'Look'
# подготовим сообщение, например используя f-строку
>>> msg = f'{y} how the variable is passed `x`: {x}'
>>> logging.warning(msg)
# WARNING:root:See how the variable is passed `x`: 10

Форматирование вида отображаемых сообщений.

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

import logging

logging.basicConfig(filename='example.log', 
                    format='[%(levelname)s] => %(message)s', 
                    level=logging.DEBUG)
logging.debug('This message should appear on the file')
logging.info('So should this')
logging.warning('And this, too')

Этот запишет в файл example.log следующее:

[DEBUG] => This message should appear on the file
[INFO] => So should this
[WARNING] => And this, too

Обратите внимание, что запись root, имевшая место в предыдущих примерах, исчезла. Для полного набора параметров, которые могут появляться в строке сообщения журналируемого события смотрите документацию по атрибутам объекта logging.LogRecord()

Для простого использования модуля достаточно использования таких атрибутов как levelname (серьезность), message (описание события, включая данные переменных) и возможно понадобится отображение времени, когда произошло событие.

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

Чтобы отобразить дату и время события, необходимо поместить атрибут %(asctime)s в строку формата:

import logging

logging.basicConfig(filename='example.log', 
                    format='[%(asctime)s] [%(levelname)s] => %(message)s', 
                    level=logging.DEBUG)
logging.warning('is when this event was logged.')

Код выше выведет в файл example.log следующее:

[2020-06-07 19:05:18,852] [WARNING] => is when this event was logged.

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

import logging

logging.basicConfig(filename='example.log', 
                    format='[%(asctime)s] [%(levelname)s] => %(message)s', 
                    datefmt='%Y-%m-%d %H:%M:%S',
                    level=logging.DEBUG)
logging.warning('is when this event was logged.')

Теперь в файл example.log можно увидеть запись:

[2020-06-07 19:15:40] [WARNING] => is when this event was logged.

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

Логирование исключений с трассировкой стека.

Для того, что бы регистрировать перехваченные исключения с полной трассировкой стека, используйте функцию logging.exception(). Она подходит для кода, который может вызвать ряд исключений, которые например нельзя ожидать. И вместо того, чтобы завершить программу, можно записать информацию об ошибке и продолжить ее работу.

import logging

# базовая настройка logging
...

# определение функции `main_loop()`
def main_loop():
    ...

while True:
    try:
        main_loop()
    except Exception:
        logging.exception('Фатальная ошибка в основном цикле')

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

[2020-06-07 19:15:40] [ERROR] => Фатальная ошибка в основном цикле
Traceback (most recent call last):
  File "test.py", line 14, in
    main_loop()
  File "test.py", line 9, in main_loop
    print(foo(x))
  File "test.py", line 4, in foo
    return 10 // n
    ZeroDivisionError: integer division or modulo by zero

Обратите внимание, что первая строка — это сообщение, которое передается в logging.exception(), а последующие строки — трассировка полного стека, включая тип исключения, в данном случае ZeroDivisionError.

По умолчанию функция logging.exception() использует уровень журнала ERROR. Также для этих целей, можно использовать обычное функции регистрации событий, такие как logging.debug(), logging.info(), logging.warn() и т. д., только устанавливать значение аргумента exc_info=True:

import logging
...
...

while True:
    try:
        main_loop()
    except Exception:
        logging.error('Фатальная ошибка в основном цикле', exc_info=True)

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

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

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

Обратите внимание, что фрагменты кода в статье предполагают, что вы уже импортировали модуль logging:

import logging

Концепции Python Logging

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

Уровни Python Logging

Уровень лога соответствует его важности: лог ERROR важнее, чем WARNING. Тогда как лог DEBUG следует использовать только при отладке приложения.
Python предлагает шесть уровней лога; каждый уровень связан с числом, которое указывает на важность лога: NOTSET=0, DEBUG=10, INFO=20, WARNING=30, ERROR=40 и CRITICAL=50.
Иерархия уровней интуитивно понятна: DEBUG < INFO < WARNING. Кроме NOTSET, со спецификой которого, ознакомимся позднее.

Форматирование лога в Python

Форматирование лога дополняет сообщение, добавляя к нему контекстную информацию. Полезно знать, когда отправляется лог, где (файл Python, номер строки, метод и т. д.), а так же дополнительный контекст, такой как поток и процесс. Чрезвычайно полезные данные при отладке многопоточного приложения.

"%(time)s — %(log_name)s — %(level)s — %(func_name)s:%(line_no)d — %(message)s"

Он превращается в:

2019-01-16 10:35:12,468 - keyboards - ERROR - <module>:1 - привет мир

Обработчик ведения лога в Python

Обработчик лога — компонент, который записывает и отображает данные лога. Он отображает лог в консоли (через StreamHandler), в файле (через FileHandler), с помощью отправки электронного письма (через SMTPHandler) и других методов.
В каждом обработчике лога 2 важных поля:

• Форматировщик, который добавляет контекстную информацию в лог.
• Уровень важности лога, который отфильтровывает логи, уровни которых ниже. Поэтому обработчик лога с уровнем INFO не будет обрабатывать логи DEBUG.

Стандартная библиотека содержит несколько обработчиков, которых достаточно для большинства случаев: https://docs.python.org/3/library/logging.handlers.html#module-logging.handlers. Наиболее распространенные — StreamHandler и FileHandler:

console_handler = logging.StreamHandler()
file_handler = logging.FileHandler("MyLogFile.txt")

Python Logger

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

toto_logger = logging.getLogger("Privacy")

У логгера три основных поля:

• Propagate: определяет, должен ли лог распространяться на родителя журнала. По умолчанию равен True.
• Level: как и уровень обработчика лога, уровень логгера используется для фильтрации “менее важных” логов. Кроме того, в отличие от обработчика лога, уровень проверяется только на “детях” логгера; и после того, как лог распространился среди его родителей, уровень не будет проверятся. Это скорее не интуитивное поведение.
• Handlers: список обработчиков, на которые отправит лог, когда поступит в логгер. Это делает обработку логов гибкой, например, вы создадите обработчик лога для записи в файл, который регистрирует логи DEBUG и обработчик лога для отправки электронной почты, который будет использоваться только для логов CRITICAL. Таким образом, отношение обработчика-логгера становится похожим на издатель-потребитель: где лог будет передаваться всем обработчикам после проверки уровня лога.

Logger определяется по имени, это означает, что если создан лог с именем foo, последующие вызовы logging.getLogger (" foo") будут возвращать один и тот же объект:

assert id(logging.getLogger("foo")) == id(logging.getLogger("foo"))

Как вы могли догадаться, у логгеров есть иерархия. В верхней части иерархии корневой лог, к которому можно получить доступ через logging.root. Этот лог вызывается, когда используются такие методы, как logging.debug(). По умолчанию, уровень корневого лога — WARNING, поэтому каждый лог с уровнем ниже игнорируется (например, через logging.info("info")).
Другая особенность корневого логгера заключается в том, что его обработчик, по умолчанию, создается при первом входе в лог с уровнем, выше WARNING.
Использование корневого логгера с помощью таких методов, как logging.debug(), не рекомендуется

lab = logging.getLogger("f.r")
assert lab.parent == logging.root # lab.parent действительно корневой логгер

Тем не менее логгер использует “точечную запись”, значит логгер с именем f.r будет потомком логгерра f. Однако это справедливо только в том случае, когда создан лог f, иначе родитель fr по прежнему будет корнем.

la = logging.getLogger("f")
assert lab.parent == la # родитель lab теперь la вместо корня

Эффективный уровень логгера

Когда логгер решает, должен ли лог выводится в соответствии с уровнем важности (например, если уровень лога ниже уровня логгера, сообщение будет проигнорировано), он использует свой “эффективный уровень” вместо фактического уровня.
Эффективный уровень совпадает с уровнем логгера, если уровень не равен NOTSET. Однако, если уровень логгера равен NOTSET, эффективным уровнем будет первый уровень родителя, у которого уровень не NOTSET.
По умолчанию, новый логгер имеет уровень NOTSET. Поскольку корневой логгер с уровнем WARNING, эффективный уровень логгера будет WARNING.
Поэтому, даже если новый логгер подключен к некоторым обработчикам, эти обработчики не будут вызываться, если уровень лога не превысит WARNING:

foo_logger = logging.getLogger("foo")
assert foo_logger.level == logging.NOTSET # у нового логгера уровень NOTSET
assert foo_logger.getEffectiveLevel() == logging.WARNING # и его эффективный уровень не является уровнем корневого логгера
# прикрепите консольный обработчик к foo_logger
console_handler = logging.StreamHandler()
foo_logger.addHandler(console_handler)
foo_logger.debug("debug level") # ничего не отображается, так как уровень лога DEBUG меньше чем эффективный уровень foo 
foo_logger.setLevel(logging.DEBUG)
foo_logger.debug("debug message") # теперь вы увидите на экране "debug message" 

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

Рекомендации по работе с Python Logging

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

• Настройте корневой логгер, но никогда не используйте его в своем коде, никогда не вызывайте функцию типа logging.info(), которая оставляет корневой логгер без дела. Если хотите убрать сообщения об ошибках из используемых библиотек, обязательно настройте корневой лог для записи в файл, например, чтобы облегчить отладку. По умолчанию корневой логгер выводит только на stderr, поэтому журнал может легко потеряться.
• Чтобы использовать логгирование, создайте новый логгер с помощью logging.getLogger(имя логгера). Я использую __name__ в качестве имени логгера, но вы можете подобрать и другие варианты. Чтобы добавить больше одного обработчика, есть метод, который возвращает логгер.

import logging
import sys
from logging.handlers import TimedRotatingFileHandler


FORMATTER = logging.Formatter("%(time)s — %(name)s — %(level)s — %(message)s")
LOG_FILE = "my_app.log"


def get_console_handler():
    console_handler = logging.StreamHandler(sys.stdout)
    console_handler.setFormatter(FORMATTER)
    return console_handler


def get_file_handler():
    file_handler = TimedRotatingFileHandler(LOG_FILE, when='midnight')
    file_handler.setFormatter(FORMATTER)
    return file_handler


def get_logger(logger_name):
    logger = logging.getLogger(logger_name)
    logger.setLevel(logging.DEBUG) # лучше иметь больше логов, чем их нехватку
    logger.addHandler(get_console_handler())
    logger.addHandler(get_file_handler())
    logger.propagate = False
    return logger

После этого, вы можете создать новый логгер и пользоваться им:

my_logger = get_logger("Имя модуля например")
my_logger.debug("debug сообщение")

• Используйте классы RotatingFileHandler, такие, как TimedRotatingFileHandler, из примера вместо FileHandler, так как он автоматически меняет файл для, когда тот достигает максимального размера или делает это каждый день.
• Используйте такие инструменты, как Sentry, Airbrake, Raygun и т.д., чтобы автоматически ловить сообщения об ошибке. Это полезно при работе с приложениями. Там лог бывает очень многословным, а логи ошибок могут легко потеряться. Другое преимуществом использования этих инструментов это возможность получить подробную информацию о значениях переменных которые связанны с ошибкой: какой URL-адрес вызывает ошибку, какой пользователь и т. д.