Настройка журналирования (логирования) в Python с примерами

Для начала подключим модуль для работы с логами, создадим в глобальной переменной объект логгера log и напишем пару сообщений:

import logging

log = logging.getLogger(__name__)


def main():
    log.debug('Отладочное сообщение')
    log.info('Информационное сообщение')
    log.warning('Сообщение с предостережением')
    log.error('Сообщение об ошибке')
    log.fatal('Фатальная ошибка, срочно остановить работу')


if __name__ == '__main__':
    main()

Замечу, что модуль logging написан потоко-безопасно, поэтому логгер вполне можно хранить как глобальную переменную. Также при создании логгера logging.getLogger в качестве параметра используется название логгера, чтобы позже можно было различать, откуда пришло сообщение. Использую специальную переменную __name__, чтобы названием логгера было название модуля, где инициализирован логгер. Лучше иметь отдельный логгер хотя бы на каждый модуль.

Также вы могли заметить, что сообщения мы отправляем 5-ю разными способами. Так мы отправляем 5 сообщений, имеющих разный уровень важности:

• debug - отладочная информация, которая используется во время разработки / поиска ошибок.
• info - информационная информация о статусе исполнения программы.
• warning - информация о потенциально опасных или нежелательных операциях (попытка получения несанкционированного доступа, невозможность отправки почты пользователю и т.д.).
• error - об ошибках, произошедших во время работы программы (некритичная ошибка базы данных, падение соединения до используемого сервиса).
• fatal - критичные ошибки, которые не позволяют приложению более нормально работать.

В случае кода выше на выход получаем:

Сообщение с предостережением
Сообщение об ошибке
Фатальная ошибка, срочно остановить работу

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

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

import logging

logging.basicConfig(level=logging.DEBUG)  # <- Добавляем вывод info и debug
log = logging.getLogger(__name__)

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

import logging

logging.basicConfig(
    level=logging.DEBUG,
    format="%(asctime)s - [%(levelname)s] - %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s",
)
log = logging.getLogger(__name__)

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

2021-06-21 16:10:55,866 - [DEBUG] - __main__ - (main.py).main(11) - Отладочное сообщение
2021-06-21 16:10:55,867 - [INFO] - __main__ - (main.py).main(12) - Информационное сообщение
2021-06-21 16:10:55,867 - [WARNING] - __main__ - (main.py).main(13) - Сообщение с предостережением
2021-06-21 16:10:55,867 - [ERROR] - __main__ - (main.py).main(14) - Сообщение об ошибке
2021-06-21 16:10:55,867 - [CRITICAL] - __main__ - (main.py).main(15) - Фатальная ошибка, срочно остановить работу

Сообщения логов могут содержать переменные. Для этого сначала задаём формат в виде printf-строки, после чего аргументами передаём данные для printf-форматирования:

def main():
    log.warning(
        'Пользователь #%d не имеет прав доступа на "%s"',
        1234,
        'Чтение файлов пользователей',
    )

В нашем случае будут подставлены идентификатор пользователя и название права доступа:

2021-06-21 16:20:35,872 - [WARNING] - __main__ - (main.py).main(14) - Пользователь #1234 не имеет прав доступа на "Чтение файлов пользователей"

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

• threading.local - глобальные переменные, однако для каждого потока (thread) они локальны.
• contextvars.ContextVar - глобальные переменные, локальные для каждого асинхронного контекста при программировании с asyncio.

К примеру, у нас используется aiohttp приложение, в middleware мы получаем ip и идентификатор пользователя. Чтобы не протаскивать эти данные всюду, не забывать с ними вызывать логгер, мы сложим их в глобальную переменную ContextVar, а в нашем специальном логгере будем использовать эту глобальную переменную:

from contextvars import ContextVar
import logging

SOME_LOG_EXTRA = ContextVar('SOME_LOG_EXTRA', default={})
SOME_LOG_EXTRA.set({'ip': '127.0.0.1', 'user_id': '1234'})

logging.basicConfig(
    level=logging.DEBUG,
    format="%(asctime)s - [%(levelname)s] - %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s",
)

class CustomAdapter(logging.LoggerAdapter):
    def process(self, msg, kwargs):
        return '%s %s' % (self.extra.get(), msg), kwargs


log = CustomAdapter(logging.getLogger(__name__), SOME_LOG_EXTRA)


def main():
    log.warning(
        'Пользователь не имеет прав доступа на "%s"',
        'Чтение файлов пользователей',
    )

if __name__ == '__main__':
    main()

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

2021-06-21 16:35:30,030 - [WARNING] - __main__ - (main.py).main(22) - {'ip': '127.0.0.1', 'user_id': '1234'} Пользователь не имеет прав доступа на "Чтение файлов пользователей"

До этого все сообщения выводились на стандартный поток вывода (stdout). Однако, часто нужно настроить вывод в какой-то файл или вообще отправлять в сеть. Тогда нам нужно настроить обработчик вывода нашего логгера. В модуле logging есть множество обработчиков - найти их можно по слову Handler. В случае, если нам нужен вывод в файл - используем файловый обработчик - FileHandler:

import logging

logging.basicConfig(
    level=logging.DEBUG,
    format="%(asctime)s - [%(levelname)s] - %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s",
    handlers=[logging.FileHandler('./file.log', encoding='utf-8')]
)

Также часто нам нужно настраивать не один логгер, а сразу несколько - помните, что лучше иметь как минимум по одному логгеру на Python модуль. Для этого подойдёт настройка в виде dictConfig, ведь basicConfig для этих целей уже не хватает.

В общем виде dictConfig выглядит так:

import logging.config

logging.config.dictConfig({
    'version': 1,
    'disable_existing_loggers': True,
    'formatters': {
        'standard': {
            'format': '%(asctime)s [%(levelname)s] %(name)s: %(message)s'
        },
    },
    'handlers': {
        'default': {
            'level': 'INFO',
            'formatter': 'standard',
            'class': 'logging.FileHandler',
            'filename': './file.log',
            'mode': 'a',
            'encoding': 'utf-8',
        },
    },
    'loggers': {
        '': {  # root logger
            'handlers': ['default'],
            'level': 'DEBUG',
            'propagate': True,
        },
        'some.group.*': {
            'level': 'WARNING',
        },
        'some.module': {
            'level': 'ERROR',
        }
    },
})

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

Далее описываются логгеры по названиям (либо же, если вы использовали __name__ - по модулям). Также можно указывать сразу группу логгеров, указывая их по маске some.group.*.

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

Аналогично с форматированием - описываем в formatters.

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