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

• Создание простого логгера;
• Использование нескольких модулей для логирования;
• Форматирование лога;
• Настройки лога

К концу данного раздела вы сможете уверенно создавать логи для своих приложений. Приступим!

Создаем простой логгер

Создание лога при помощи модуля logging это очень просто. Для начала, будет проще взглянуть на часть кода и объяснить его:

Как и ожидалось, чтобы получит доступ к модулю logging, для начала нужно импортировать модуль. Простейший способ создания лога – это использовать функцию basicConfig модуля logging и передать ей несколько ключевых аргументов. Функция принимает следующее: filename, filemode, format, datefmt, level и stream. В нашем примере, мы передадим её названию файла и уровню логирования, что мы и настроим в INFO.

Существует пять уровней логирования (в порядке возрастания): DEBUG, INFO, WARNING, ERROR и CRITICAL. По умолчанию, если вы запустите этот код несколько раз, он добавится в лог, если он существует. Если вы хотите, чтобы ваш логгер перезаписывал лог, передайте его filemode=”w”, как было указано в комментарии к коду. Говоря о запуске кода, вы должны получить следующий результат, после запуска:

Обратите внимание на то, что сообщение о дебаггинге находится не на выходе. Это связанно с тем, что мы установили уровень в INFO, так что наш логгер будет записывать только сообщения INFO, WARNING, ERROR или CRITICAL. Часть root означает, что данное сообщение пришло либо от корневого логгера, либо от основного. Мы взглянем на то, как это можно изменить, что бы следующая часть была более понятной. Если вы не используете basicConfig, тогда модуль протоколирования выведет на консоль / stdout. Модуль logging также может учитывать некоторые исключения в файле, или там, где вы указали. Взглянем на пример:

Давайте немного притормозим. Здесь мы использовали метод getLogger модуля logging, чтобы вернуть объект логгера под названием ex. Это удобно, если у вас есть несколько логгеров в одном приложении, так как это позволяет вам узнать, какие сообщения приходят с каждого логгера. Этот пример провоцирует возникновение ошибки RuntimeError, затем это регистрируется в файле, что может быть очень удобно при лечении багов.

Логирование из нескольких модулей (а также форматирование)

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

Здесь мы импортируем logging и модуль нашего творения (“otherMod”). После чего мы создаем лог-файл, как мы делали это раньше. Другой модуль выглядит следующим образом:

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

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

Здесь мы создали экземпляр логгера под названием “exampleApp”. Мы установили его уровень ведения журнала, создали объект обработчика лог-файла, и объект форматирование. Обработчик файла должен установить объект форматирование в качестве своего форматтера, после чего обработчик файла должен быть добавлен в регистратор логгера. Остальная часть кода по большому счету остается неизменной. Только обратите внимание на то, что вместо logging.info мы используем logger.info, или любое другое название переменной вашего логгера. Давайте рассмотрим обновленный код otherMod2:

Обратите внимание на то, что здесь у нас два определенных логгера. Мы ничего не делаем с module_logger в данном случае, но мы используем другой модуль. Если вы запустите основной скрипт, вы увидите следующий результат в своем файле:

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

Конфигурация логов для работы

Модуль logging может быть сконфигурирован тремя различными способами. Вы можете настроить данный модуль при помощи методов (логгеров, форматтеров, обработчиков, как мы делали это ранее в данном разделе. Вы можете использовать файл конфигурации и передать его fileConfig(). Или же вы можете создать словарь информацией о конфигурации и передать его функции fileConfig(). Давайте создадим файл конфигурации для начала, а затем взглянем на то, как выполнить его в Python. Вот пример файла config:

Обратите внимание на то, что у нас есть два определенных логгера: root и exampleApp. По какой-то причине, необходим именно root. Так что если вы его не включите в код, возникнет ошибка ValueError функции config.py _install_loggers, которая является частью модуля logging. Если вы установите обработчик root на fileHandler, то это приведет к дублированию выхода журнала, так что во избежание этого, мы отправляем его на консоль. Внимательно изучите данный пример. Вам нужна секция для каждого ключа в первых трех секциях. Давайте взглянем на то, как загрузить это в код:

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

Как вы могли догадаться, это очень похоже на другой пример. Теперь мы готовы перейти к следующему методу config. Метода словаря конфигураций dictConfig не существовало в Python до версии 2.7. Так что убедитесь в том, что вы работаете в последней версии, иначе вы не сможете приступить к следующей части. В документации не сказано прямо, как это работает. В действительности, примеры в документации, по какой-то причине показывают YAML. В любом случае, давайте рассмотрим один рабочий код:

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

Подведем итоги

С этого момента вы должны уметь пользовать логгерами и выполнять их конфигурацию несколькими различными методами. Вы также получили все необходимые знания для модификации выдачу при помощи объекта Formatter. Модуль logging очень полезен в решении возникших проблем в работе вашего приложения. Постарайтесь провести больше времени за практической работой с данным модулем перед написанием большого приложения.

Если Вы хотя бы немного знакомы с программированием и пробовали запускать что-то «в продакшен», то вам наверняка станет больно от такого диалога:

— Вась, у нас там приложение слегло. Посмотри, что случилось?

— Эмм… А как я это сделаю?..

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

1. Он никогда не узнает, из-за чего его приложение упало.
2. Он не сможет отследить, что привело к ошибке (даже если приложение не упало).
3. Он не сможет посмотреть состояние своей системы в момент времени N.
4. Он не сможет профилактически поглядывать в логи, чтобы следить за работоспособностью приложения.
5. Он не сможет хвастаться своим… (кхе-кхе).

Впрочем, последний пункт, наверно, лишний. Однако, одну вещь мы поняли наверняка:

Логирование — крайне важная штука в программировании.

В языке Python основным инструментом для логирования является библиотека logging. Так давайте вместе с IT Resume рассмотрим её подробней.

Что такое logging?

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

import logging

Основная функция, которая пригодится Вам для работы с этим модулем — basicConfig(). В ней Вы будете указывать все основные настройки (по крайней мере, на базовом уровне).

У функции basicConfig() 3 основных параметра:

1. level — уровень логирования на Python;
2. filename — место, куда мы направляем логи;
3. format — вид, в котором мы сохраняем результат.

Давайте рассмотрим каждый из параметров более подробно.

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

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

По умолчанию фиксируются только предупреждения (WARNINGS) и события с более высоким приоритетом: ошибки (ERRORS) и критические ошибки (CRITICALS).

logging.basicConfig(level=logging.DEBUG)

А далее, чтобы записать информационное сообщение (или вывести его в консоль, об этом поговорим чуть позже), достаточно написать такой код:

logging.debug('debug message')
logging.info('info message')

И так далее. Теперь давайте обсудим, куда наши сообщения попадают.

Отображение лога и запись в файл

За место, в которое попадают логи, отвечает параметр filename в basicConfig. По умолчанию все Ваши логи будут улетать в консоль.

Другими словами, если Вы просто выполните такой код:

import logging
logging.error('WOW')

То сообщение WOW придёт Вам в консоль. Понятно, что в консоли никому эти сообщения не нужны. Как же тогда направить запись лога в файл? Очень просто:

logging.basicConfig(filename = "mylog.log")

Ок, с записью в файл и выбором уровня логирования все более-менее понятно. А как настроить свой шаблон? Разберёмся.

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

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

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

Сделать это можно, как все уже догадались, с помощью параметра format.

Например, если внутри basicConfig указать:

format = "%(asctime)s - %(levelname)s - %(funcName)s: %(lineno)d - %(message)s"

То вывод ошибки будет выглядеть так:

2019-01-16 10:35:12,468 - ERROR - <module>:1 - Hello, world!

Вы можете сами выбирать, какую информацию включить в лог, а какую оставить. По умолчанию формат такой:

<УРОВЕНЬ>: <ИМЯ_ЛОГГЕРА>: <СООБЩЕНИЕ>.

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

Эпилог

Что же, мы разобрали все основные параметры модуля logging и функции basicConfig, которые позволят Вам настроить базовое логирование в Вашем проекте. Дальше — только практика и набивание шишек 🙂

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

import logging

logging.basicConfig(
    level=logging.DEBUG, 
    filename = "mylog.log", 
    format = "%(asctime)s - %(module)s - %(levelname)s - %(funcName)s: %(lineno)d - %(message)s", 
    datefmt='%H:%M:%S',
    )

logging.info('Hello')

Если хотите разобраться с параметрами более подробно, Вам поможет официальная документация (очень неплохая, кстати).

В этой статье мы познакомимся с возможностями, которые язык 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 в своих скриптах для задач логирования работы ваших программ. Напишите в комментариях под статьей, знали ли вы о данном модуле? Используете ли этот модуль в своих скриптах? Насколько он, на ваш взгляд, полезен и с какими параметрами предпочитаете его использовать вы?

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

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

Когда использовать logging

Для самого простого использования, модуль предоставляет функции debug(), info(), warning(), error() и critical(). Название функций соответствует названию уровней или серьезности логируемых событий. Рекомендации по использованию стандартных уровней сведены в таблицу (в порядке возрастания серьезности).

Уровень сообщений	Когда использовать
CRITICAL	Критическая ошибка, выполнение программы невозможно
ERROR	Из-за серьезной ошибки программа не смогла выполнить какую-либо функцию
WARNING	Индикация того что произошло что-то неожиданное или указывающее на проблемы в ближайшем будущем, программа все еще работает так как ожидается
INFO	Подтверждения, когда программа работает так ожидается
DEBUG	Вывод детальной информации при поиске проблем в программе

Уровень логирования по умолчанию — WARNING, это означает что сообщения этого уровня или выше будут обработаны, ниже — отброшены.

Simple example. (или В Бой!)

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

import logging

logging.warning("Warning message")
logging.info("Info message")

если запустить скрипт с этим кодом, то в консоли будет выведено:

WARNING:root:Warning message

что мы видим: WARNING это индикация уровня события, root — имя логгера, Warning message сообщение. Пока не обращайте внимание на имя логгера, это будет объяснено позже. Строка logging.info("Info message") была проигнорирована т.к. уровень INFO ниже уровня WARNING (который был установлен по умолчанию).

Немного теории.

Модуль logging имеет модульный подход и предлагает несколько категорий компонентов: логгеры (loggers), обработчики (handlers), фильтры (filters) и объекты форматирования (formatters).

• logger содержит интерфейс для логирования. Это основной объект, именно он создает записи в лог.
• handler обработчик, который направляет созданные логгером записи в пункт назначения. Например вывод в консоль, запись в файл, отправка письма и т.д.
• filter позволяет получить больший контроль над фильтрацией записей чем стандартные уровни логирования.

Базовый класс реализует только одно поведение: выстраивание иерархии логгеров при помощи имени логгера и точки. Например инициализирован логгер с именем A.B, тогда записи логгеров с именами A.B.C, A.B.C.D, A.B.D будут обработаны, а логгеров с именами A.BB или B.B.C отброшены.

• formatter является шаблоном для форматирования записи. Возможные атрибуты для заполнения шаблона здесь

Способы конфигурации модуля.

basicConfig

Это базовый, простой способ. Рассмотрим его, на примере чтобы погрузится удивительнйый мир логирования (смайлик):

import logging

logging.basicConfig(
    format='%(asctime)s - %(name)s - %(levelname)s - %(message)s',
    filename='example.log',
    filemode='w',
    level=logging.DEBUG,
    )
logging.debug('This message should go to the log file')
logging.info('So should this')
logging.warning('And this, too')

Рассмотрим параметры переданные в baseConfig: format — преобразует вывод логера по переданному шаблону, filename — сообщает логгеру что необходимо логи заносить в файл с переданным названием example.log, filemod: w — перезаписывать файл при каждом запуске файла, a — дописывать в конец файла и наконец level устанавливает уровень логирования DEBUG. В результате выполнения будет создан файл filemod.log в котором окажутся записи:

2018-05-13 23:41:47,769 - root - DEBUG - This message should go to the log file
2018-05-13 23:41:47,769 - root - INFO - So should this
2018-05-13 23:41:47,769 - root - WARNING - And this, too

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

getLogger

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

import logging

# создание логгера с именем "main" (может быть любым)
logger = logging.getLogger('main')
# установка уровня логирования
logger.setLevel(logging.DEBUG)

# создание обработчика с логированием в консоль
cons_handler = logging.StreamHandler()
# установка уровня логирования конкретно этого обработчика
cons_handler.setLevel(logging.DEBUG)

# создание обработчика с логированием в файл "2_example.log"
file_handler = logging.FileHandler("3_example.log", mode="a")
file_handler.setLevel(logging.WARNING)

# создание шаблона отображения
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# связвание обработчиков с шаблоном форматирования
cons_handler.setFormatter(formatter)
file_handler.setFormatter(formatter)

# добавление обработчиков логгеру
logger.addHandler(cons_handler)
logger.addHandler(file_handler)

# использование логгера
logger.debug('debug message')
logger.info('info message')
logger.warn('warn message')
logger.error('error message')
logger.critical('critical message')

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

2018-05-15 22:40:07,974 - main - DEBUG - debug message
2018-05-15 22:40:07,974 - main - INFO - info message
2018-05-15 22:40:07,974 - main - WARNING - warn message
2018-05-15 22:40:07,975 - main - ERROR - error message
2018-05-15 22:40:07,975 - main - CRITICAL - critical message

и файл с именем 3_example.log с содержимым:

2018-05-15 22:40:07,974 - main - WARNING - warn message
2018-05-15 22:40:07,975 - main - ERROR - error message
2018-05-15 22:40:07,975 - main - CRITICAL - critical message

Хочу пояснить следующие моменты:

• Первым делом получаем логгер — экземпляр класса Logger с именем main. Причем действует правило: одно имя — один экземпляр. Это означает что при первом вызове метода логгер создается, а при последующих передается уже созданный экземпляр логгера. На практике это означает что достаточно вызвать и настроить логгер в одном месте (модуле), выполнить этот код (импортировать модуль), во всех последующих местах вызывать настроеный логгер и… просто логировать.
• Далее получаем обработчики. Полный список с описанием здесь их много и они разные: вывод в консоль, запись в файл (возможно с ротацией логов), отправка через сокет, http, UDP, отправка письмом, чтение/запись в очередь и т.д. Далее в приимерах будут те что пользовался я сам.
• Нужно четко понимать что у логгера может быть множество обработчиков, каждый обработчик может иметь свой шаблон сообщения, уровень логирования и фильтрацию. Поэтому в консоль попали все сообщения логгера, а в файл с уровнем WARNING и выше.
• И наконец получаем шаблоны сообщений. Параметры для шаблонов здесь, основные параметры далее в примерах примерах.

Оптимизация. Процесс подстановки аргументов в шаблон ленивый, и произойдет только если запись действительно будет обрабатываться, поэтому в функцию логирования нужно передавать шаблон строки с аргументами, например logger.debug("received params %s", a). Если же передавать заранее сформированную строку, то ресурсы системы будут потрачены независимо от того будет запись занесена в лог или нет.

Оптимизация. Вычисление аргуменов для логирования может быть долгим. Для того чтобы не терять время можно воспользоваться методом isEnabledFor логгера, который принимает уровень логирования, проверяет будет ли производится запись и возвращает ответ в True или False. Например:

if logger.isEnabledFor(logging.DEBUG):
    logger.debug('Message with %s', expensive_func())

dictConfig

Мой любимый способ. Сразу к примеру:

import logging
import logging.config

DEBUG = True

LOGGING_CONF = {
    "disable_existing_loggers": True,
    "version": 1,
    "formatters": {
        "verbose": {
            "format": "%(levelname)-8s %(asctime)s [%(filename)s:%(lineno)d] %(message)s",
            "datefmt": "%Y-%m-%d %H:%M:%S",
        },
        "brief": {
            "format": "%(levelname)-8s %(asctime)s %(name)-16s %(message)s",
        }
    },
    "handlers": {
        "console": {
            "level": "DEBUG",
            "class": "logging.StreamHandler",
            "formatter": "verbose",
        },
        "other_cons": {
            "level": "DEBUG",
            "class": "logging.StreamHandler",
            "formatter": "brief",
        },
    },
    "loggers": {
        "main": {
            "level": "INFO",
            "handlers": ["console"],
        },
        "slave": {
            "level": "DEBUG" if DEBUG else "INFO",
            "handlers": ["other_cons"],
        },
    },
}

logging.config.dictConfig(LOGGING_CONF)

logger = logging.getLogger("main")
logger.info("loggers %s configured", ", ".join(LOGGING_CONF["loggers"]))

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

В примере, переменная DEBUG как раз для такого контроля, эта переменная может импортироваться из настроек проекта и определять поведение целевых логгеров. Это может помочь выводить проект в production — не придется ходить по модулям и править все DEBUG = True на False.

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

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

INFO     2018-05-20 22:43:12 [4_dictConfig.py:45] loggers main, slave configured

fileConfig

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

По умолчанию disable_existing_loggers = True
Вместо непосредственно файла может принимать экземпляр класса RawConfigParser, что позволяет хранить конфигурацию проекта в одном файле.

import logging
import logging.config

logging.config.fileConfig("5_logging.conf")

logger = logging.getLogger("simpleExample")

logger.debug("debug message")
logger.info("info message")
logger.warn("warn message")
logger.error("error message")
logger.critical("critical message")

[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
datefmt=

и вывод будет:

2018-05-20 23:31:29,215 - simpleExample - DEBUG - debug message
2018-05-20 23:31:29,216 - simpleExample - INFO - info message
2018-05-20 23:31:29,216 - simpleExample - WARNING - warn message
2018-05-20 23:31:29,216 - simpleExample - ERROR - error message
2018-05-20 23:31:29,217 - simpleExample - CRITICAL - critical message

Код думаю понятен, переходим к седующему способу конфигурации.

listen

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

Некоторые варианты использования

Наследование

Как я уже упоминал, в логгерах, через имена, реализовано наследование. Рассмотрим пример:

import sys
import logging

# этот ужас из-за первой цифры в названии файла
log_dict_conf = __import__("4_dictConfig")
slave = __import__("6_inh_slave")

logger = logging.getLogger("slave." + __name__)
logger.debug("logger with name: %s created", logger.name)


def simple_func(a, b, c):
    s = slave.sum(a, b)
    m = slave.mult(s, c)
    logger.debug("received params %s, %s, %s; return %s", a, b, c, m)
    return m


if __name__ == "__main__":
    args = sys.argv[1:4]
    if len(args) == 3:
        logger.debug("received params from sys.argv")
        args = list(map(int, args))
    else:
        args = [4, 5, 6]
        logger.debug("load default params")
    logger.info("received params %s, %s, %s", *args)
    logger.info(simple_func(*args))

import logging
logger = logging.getLogger("slave." + __name__)
logger.debug("logger with name: %s created", logger.name)


def sum(a, b):
    s = a + b
    logger.debug("received params %s, %s; sum %s", a, b, s)
    return s


def mult(a, b):
    m = a * b
    logger.debug("received params %s, %s; multiply %s", a, b, m)
    return m

выполнив python 6_inh_main.py 1 2 3 в консоли получим:

INFO     2018-05-24 00:54:14 [4_dictConfig.py:45] loggers main, slave configured
DEBUG    2018-05-24 00:54:14,411 slave.6_inh_slave logger with name: slave.6_inh_slave created
DEBUG    2018-05-24 00:54:14,412 slave.__main__   logger with name: slave.__main__ created
DEBUG    2018-05-24 00:54:14,412 slave.__main__   received params from sys.argv
INFO     2018-05-24 00:54:14,412 slave.__main__   received params 1, 2, 3
DEBUG    2018-05-24 00:54:14,412 slave.6_inh_slave received params 1, 2; sum 3
DEBUG    2018-05-24 00:54:14,412 slave.6_inh_slave received params 3, 3; multiply 9
DEBUG    2018-05-24 00:54:14,412 slave.__main__   received params 1, 2, 3; return 9
INFO     2018-05-24 00:54:14,412 slave.__main__   9

Пройдем по порядку. Для начала имортируем модуль 4_dictConfig в котором инициализируем логгеры, это он в первой строке сообщает какие логгеры были настроены. Мне нравится подход, при котром логгеры инициализируюися в одном модуле, и затем получаются getLogger -ом по необходимости.

Затем имортируется модуль 6_inh_slave, и в нем, при вызове getLogger -а к имени инициализированного логгера slave через точку добавлен __name__ (вернет имя модуля если модуль импортируется), что определяет логгер-потомок slave -а с именем slave.6_inh_slave. Логгер-потомок наследует поведение логгера-родителя, однако теперь понятно из логгера какого модуля была сделана запись. Можно в наследовании подставлять имя пакета, название функционального блока или класса, здесь как душе угодно.