Тренды

Логи в Python. Настройка и централизация

21.12.2019

Введение

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

В этом посте мы покажем вам, как:

Настроить приоритет и расположение журналов.
Создать пользовательские настройки, включающие несколько логгеров и адресатов.
Добавить трассировку исключений в логи.
Отформатировать логи в JSON и централизовать их.

Основы

Модуль logging включен в стандартную библиотеку Python. Метод basicConfig() — самый быстрый способ настройки. Тем не менее в документации рекомендуется создавать логгер для каждого модуля приложения, а значит, может быть сложно конфигурировать логгер для каждого модуля, используя только basicConfig(). Поэтому большинство приложений (включая веб-фреймворки, например, Django) автоматически ведут журналы на основе файлов или словаря. Если вы хотите начать с одного из этих методов, мы рекомендуем сразу перейти к нужному разделу.

У basicConfig() три основных параметра:

level: минимальный уровень логирования. Доступны уровни: DEBUG, INFO, WARNING, ERROR и CRITICAL. Уровень по умолчанию — WARNING, то есть фильтруются сообщения уровней DEBUG и INFO.
handler: определяет, куда направить логи. Если не указано иное, используется StreamHandler для направления сообщений в sys.stderr.
format: формат, по умолчанию он такой:

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

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

Поскольку по умолчанию пишутся только журналы WARNING и более высокого уровня, вам может не хватать логов с низким приоритетом. Кроме того, вместо StreamHandler или SocketHandler для потоковой передачи непосредственно на консоль или во внешнюю службу по сети, вам лучше использовать FileHandler, чтобы писать в один или несколько файлов на диске.

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

Базовый пример

В следующем примере используется basicConfig(), чтобы сконфигурировать приложение для логирования DEBUG и выше на диск, и указывается на наличие даты, времени и серьёзности в строке лога:

import logging

def word_count(myfile):
    logging.basicConfig(level=logging.DEBUG, filename='myapp.log', format='%(asctime)s %(levelname)s:%(message)s')
    try:
        # считаем слова, логируем результат.
        with open(myfile, 'r') as f:
            file_data = f.read()
            words = file_data.split(" ")
            num_words = len(words)
            logging.debug("this file has %d words", num_words)
            return num_words
    except OSError as e:
        logging.error("error reading the file")

Если на входе будет недоступный файл, в лог запишется это:

2019-03-27 10:49:00,979 DEBUG:this file has 44 words
2019-03-27 10:49:00,979 ERROR:error reading the file

Благодаря новой конфигурации сообщения отладки не фильтруются и, кроме сообщения об ошибке, дают информацию о дате, местном времени и уровне важности:

%(asctime)s: дата и местное время.
%(levelname)s: уровень.
%(message)s: сообщение.

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

Подробности

Что делать, когда приложение разрастается? Вам нужна надёжная, масштабируемая конфигурация и имя логгера как часть каждого лога. В этой части мы:

Настроим множественное логирование с отображением имени лога.
Используем fileConfig, чтобы реализовать пользовательское логирование и роутинг.
Запишем в лог трассировку и необработанные исключения.

Конфигурирование

Следуя лучшим практикам, используем метод получения имени лога модуля:

logger = logging.getLogger(name)

__name__ ссылается на полное имя модуля, из которого вызван метод getLogger. Это вносит ясность. Например, приложение включает lowermodule.py, вызываемый из uppermodule.py. Тогда getLogger(__name__) выведет имя ассоциированного модуля. Пример с форматом лога, включающим его имя:

# lowermodule.py
import logging

logging.basicConfig(level=logging.DEBUG, format='%(asctime)s %(name)s %(levelname)s:%(message)s')
logger = logging.getLogger(__name__)

def word_count(myfile):
    try:
        with open(myfile, 'r') as f:
            file_data = f.read()
            words = file_data.split(" ")
            final_word_count = len(words)
            logger.info("this file has %d words", final_word_count)
            return final_word_count
    except OSError as e:
        logger.error("error reading the file")
[...]

# uppermodule.py

import logging
import lowermodule 

logging.basicConfig(level=logging.DEBUG, format='%(asctime)s %(name)s %(levelname)s:%(message)s')
logger = logging.getLogger(__name__)

def record_word_count(myfile):
    logger.info("starting the function")
    try:
        word_count = lowermodule.word_count(myfile)
        with open('wordcountarchive.csv', 'a') as file:
            row = str(myfile) + ',' + str(word_count)
            file.write(row + '\n')
    except:
        logger.warning("could not write file %s to destination", myfile)
    finally:
        logger.debug("the function is done for the file %s", myfile)

Последовательный запуск uppermodule.py для существующего и не существующего файлов даст такой вывод:

2019-03-27 21:16:41,200 __main__ INFO:starting the function
2019-03-27 21:16:41,200 lowermodule INFO:this file has 44 words
2019-03-27 21:16:41,201 __main__ DEBUG:the function is done for the file myfile.txt
2019-03-27 21:16:41,201 __main__ INFO:starting the function
2019-03-27 21:16:41,202 lowermodule ERROR:[Errno 2] No such file or directory: 'nonexistentfile.txt'
2019-03-27 21:16:41,202 __main__ DEBUG:the function is done for the file nonexistentfile.txt

Имя модуля логгера следует сразу за временной меткой. Если вы не использовали getLogger, имя модуля отображается как root, затрудняя определение источника. uppermodule.py отображается как __main__ (основной) потому, что это модуль верхнего уровня.

Сейчас два лога настраиваются двумя вызовами basicConfig. Далее мы покажем, как настроить множество логов с одним вызовом fileConfig.

fileConfig

fileConfig и dictConfig позволяют реализовать более гибкое логирование на основе файлов или словаря. Оно используется в Django и Flask. В файле конфигурации должны быть три секции:

[loggers] — имена логгеров.
[handlers] — типы обработчиков: fileHandler, consoleHander.
[formatters] — форматы логов.

Каждая секция должна иметь списки. Уточняющие секции ключей (например, для определённого типа обработчика) должны иметь такой формат: [<ИМЯ_СЕКЦИИ>_<ИМЯ_КЛЮЧА>]. Файл logging.ini может выглядеть так:

[loggers]
keys=root

[handlers]
keys=fileHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=fileHandler

[handler_fileHandler]
class=FileHandler
level=DEBUG
formatter=simpleFormatter
args=("/path/to/log/file.log",)

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

Документация рекомендует прикреплять каждый обработчик к одному логу, прописывать основные настройки в корневом (root) логе и уточнять их в дочерних, а не дублировать одно и то же в дочерних логах. Подробнее в документации. В этом примере мы указали в root настройки для обоих логов, что избавило нас от дублирования кода.

Вместо logging.basicConfig(level=logging.DEBUG, format=’%(asctime)s %(name)s %(levelname)s:%(message)s’) в каждом модуле мы можем сделать так:

import logging.configlogging.config.fileConfig('/path/to/logging.ini', disable_existing_loggers=False)logger = logging.getLogger(name)

Этот код отключает существующие не корневые логгеры, включенные по умолчанию. Не забудьте импортировать logging.config. Кроме того, посмотрите в документацию логирования на основе словаря.

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

Чтобы logging.error перехватывала трассировку, установите sys.exc_info в True. Ниже пример с включенным и отключенным параметром:

# lowermodule.py

logging.config.fileConfig('/path/to/logging.ini', disable_existing_loggers=False)
logger = logging.getLogger(__name__)

def word_count(myfile):
    try:
    # считаем слова, логируем результат.
    [...]
    except OSError as e:
        logger.error(e)
        logger.error(e, exc_info=True)
[...]

Вывод для несуществующего файла:

2019-03-27 21:01:58,191 lowermodule - ERROR:[Errno 2] No such file or directory: 'nonexistentfile.txt'
2019-03-27 21:01:58,191 lowermodule - ERROR:[Errno 2] No such file or directory: 'nonexistentfile.txt'
Traceback (most recent call last):
  File "/home/emily/logstest/lowermodule.py", line 14, in word_count
    with open(myfile, 'r') as f:
FileNotFoundError: [Errno 2] No such file or directory: 'nonexistentfile.txt'

Первая строка — вывод без трассировки, вторая и далее — с трассировкой. Кроме того, с помощью logger.exception вы можете логировать определённое исключение без дополнительных вмешательств в код.

Перехват необработанных исключений

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

Необработанное исключение возникает вне try...except или, когда вы не включаете нужный тип исключения в except. Например, если приложение обнаруживает TypeError, а ваш except обрабатывает только NameError, исключение передаётся в другие try, пока не встретит нужный тип.

Если ничего не встретилось, исключение становится необработанным. Интерпретатор вызывает sys.excepthook с тремя аргументами: класс исключения, его экземпляр и трассировка. Эта информация обычно появляется в sys.stderr, но если вы настроили свой лог для вывода в файл, traceback не логируется.

Вы можете использовать стандартную библиотеку traceback для форматирования трассировки и её включения в лог. Перепишем word_count() так, чтобы она пыталась записать количество слов в файл. Неверное число аргументов в write() вызовет исключение:

# lowermodule.py
import logging.config
import traceback

logging.config.fileConfig('logging.ini', 
disable_existing_loggers=False)
logger = logging.getLogger(__name__)

def word_count(myfile):
    try:
        # считаем слова, логируем результат.
        with open(myfile, 'r+') as f:
            file_data = f.read()
            words = file_data.split(" ")
            final_word_count = len(words)
            logger.info("this file has %d words", final_word_count)
            f.write("this file has %d words", final_word_count)
            return final_word_count
    except OSError as e:
        logger.error(e, exc_info=True)
    except:
        logger.error("uncaught exception: %s", traceback.format_exc())
        return False
if __name__ == '__main__':
    word_count('myfile.txt')

При выполнении этого кода возникнет TypeError, не обрабатываемое в try-except. Однако оно логируется благодаря коду, включенному во второе выражение except:

# исключение не обрабатывается, но логируется.
2019-03-28 15:22:31,121 lowermodule - ERROR:uncaught exception: Traceback (most recent call last):
  File "/home/emily/logstest/lowermodule.py", line 23, in word_count
    f.write("this file has %d words", final_word_count)
TypeError: write() takes exactly one argument (2 given)

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

Многострочные исключения легко читаются, но если вы объединяете свои журналы с внешним сервисом, то далее можно преобразовать их в JSON, чтобы гарантировать корректный анализ. Теперь мы покажем, как использовать для этого python-json-logger.

Унификация

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

Логирование в JSON

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

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

Сообщество Python разработало библиотеки, конвертирующие логи в JSON. Используем python-json-logger. Установка:

pip install python-json-logger

Теперь обновите файл конфигурации для настройки существующего модуля форматирования или добавления нового, ( [formatter_json]в примере ниже). Он должен использовать pythonjsonlogger.jsonlogger.JsonFormatter. В разделе format можно указать атрибуты, необходимые каждой записи:

[loggers]
keys=root,lowermodule

[handlers]
keys=consoleHandler,fileHandler

[formatters]
keys=simpleFormatter,json

[logger_root]
level=DEBUG
handlers=consoleHandler

[logger_lowermodule]
level=DEBUG
handlers=fileHandler
qualname=lowermodule

[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=simpleFormatter
args=(sys.stdout,)

[handler_fileHandler]
class=FileHandler
level=DEBUG
formatter=json
args=("/home/emily/myapp.log",)

[formatter_json]
class=pythonjsonlogger.jsonlogger.JsonFormatter
format=%(asctime)s %(name)s %(levelname)s %(message)s

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

Консольные логи по-прежнему соответствуют simpleFormatter для удобства чтения, но логи, созданные логгером lowermodule, теперь пишутся в JSON.

При включении pythonjsonlogger.jsonlogger.JsonFormatter в конфигурацию функция fileConfig() должна иметь возможность создавать JsonFormatter, пока выполняется код из среды, где импортируется pythonjsonlogger.

Если вы не используете файловую конфигурацию, нужно импортировать python-json-logger, а также определить обработчик и модуль форматирования, как описано в документации:

from pythonjsonlogger import jsonlogger

logHandler = logging.StreamHandler()formatter = jsonlogger.JsonFormatter()logHandler.setFormatter(formatter)logger.addHandler(logHandler)

logger = logging.getLogger()

Почему JSON предпочтительнее, особенно когда речь идёт о сложных или подробных записях? Вернёмся к примеру многострочной трассировки:

2019-03-27 21:01:58,191 lowermodule - ERROR:[Errno 2] No such file or directory: 'nonexistentfile.txt'Traceback (most recent call last):  File "/home/emily/logstest/lowermodule.py", line 14, in word_count    with open(myfile, 'r') as f:FileNotFoundError: [Errno 2] No such file or directory: 'nonexistentfile.txt'

Этот лог легко читать в файле или в консоли. Но если он обрабатывается платформой управления и правила многострочного агрегирования не настроены, то каждая строка может отображаться как отдельный лог. Это затруднит точное восстановление событий. Теперь, когда мы логируем трассировку исключений в JSON, приложение создаёт единый журнал:

{"asctime": "2019-03-28 17:44:40,202", "name": "lowermodule", "levelname": "ERROR", "message": "[Errno 2] No such file or directory: 'nonexistentfile.txt'", "exc_info": "Traceback (most recent call last):\n  File \"/home/emily/logstest/lowermodule.py\", line 19, in word_count\n    with open(myfile, 'r') as f:\nFileNotFoundError: [Errno 2] No such file or directory: 'nonexistentfile.txt'"}

Сервис логирования может легко интерпретировать этот JSON и показать всю информацию о трассировке, включая exc_info:

Пользовательские атрибуты

Еще одно преимущество — добавления атрибутов, анализируемых внешним сервисом управления автоматически. Ранее мы настроили formatдля стандартных атрибутов. Можно логировать пользовательские атрибуты, используя поле python-json-logs. Ниже мы создали атрибут, отслеживающий продолжительность операции в секундах:

# lowermodule.py
import logging.config
import traceback
import time

def word_count(myfile):
    logger = logging.getLogger(__name__)
    logging.fileConfig('logging.ini', disable_existing_loggers=False)
    try:
        starttime = time.time()
        with open(myfile, 'r') as f:
            file_data = f.read()
            words = file_data.split(" ")
            final_word_count = len(words)
            endtime = time.time()
            duration = endtime - starttime 
            logger.info("this file has %d words", final_word_count, extra={"run_duration":duration})
            return final_word_count
    except OSError as e:
        [...]

Вывод:

В системе управления атрибуты анализируются так:

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

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

Логи и другие источники данных

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

Если вы обновите формат для включения dd.trace_iddd.span_id, система управления автоматически сопоставит журналы и трассировки каждого запроса. Это означает, что при просмотре трассировки вы можете просто щелкнуть вкладку “логи” в представлении трассировки, чтобы просмотреть все логи, созданные во время конкретного запроса:

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

Заключение

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

Читать дальше:

Перевод статьи Nils Bunge, Emily Chang: How to collect, customize, and centralize Python logs

Логи в Python. Настройка и централизация

Введение

Основы

Базовый пример

Подробности

Конфигурирование

fileConfig

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

Перехват необработанных исключений

Унификация

Логирование в JSON

Пользовательские атрибуты

Логи и другие источники данных

Заключение

Читайте также

Как перевести iPhone в черно-белый режим и почему вам следует это...

5 недооценённых приложений в помощь программисту

Обзор шаблонов SnapML и их возможностей в Lens Studio

Тесты

Насколько хорошо вы умеете пользоваться Linux?

Хорошо ли вы разбираетесь в процессе веб-дизайна?

Насколько хорошо вы разбираетесь в Python?