info@severcart.org
Русский English

Логирование в Django. Правильный путь

20 декабря 2017 г.    Django

Правильное ведение логирования играет решающее значение для процесса отладки и устранения неполадок. Оно не только полезно для локального девелопменга, но и для продашен. При просмотре журналов в поиске проблемы, редко кто-то говорит: "Наше приложение слишком много логирует." Но чаще можно услышать иное. Итак, принимая это во внимание, давайте начнем.

Введение в логирование на Python

В верхней части каждого файла должно быть что-то подобное:

import logging
logger = logging.getLogger(__name__)

Переменная __name__ будет заменена точечным путём до Python модуля, например, скрипт myproject/myapp/views.py, то будет использоваться myproject.myapp.views. Теперь можно применять logger по всему файлу:

# Простая строка, зарегистрированная на уровне «warning»
logger.warning("Your log message is here")

# Строка с переменной на уровне «info»
logger.info("The value of var is %s", var)

# Ведение журнала трассировки для пойманного исключения
try:
    function_that_might_raise_index_error()
except IndexError:
    # эквивалентно logger.error(msg, exc_info=True)
    logger.exception("Something bad happened")

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

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

  • debug. Информация не нужна для повседневной работы, но полезна в разработке.
  • info: Информация, которая полезна во время обычной работы.
  • warning: Информация, которая может быть проблематичной, но не является срочной.
  • error: Информация, которая важна и, вероятно, требует срочного внимания.
  • critical: на практике используется редко, но если вам нужно больше, чем ошибка, то это то что нужно.

Куда логировать

Ваше приложение не должно беспокоиться о том, куда идут log сообщения. Вместо этого оно должно записывать все в консоль (stdout / stderr), и пусть сервер сам решает, что дальше делать с этой информацией. Обычно они помещаются в выделенный файл, захваченный журналом Systemd или Docker, с последующей отправкой на отдельный сервис, такой как ElasticSearch, или некоторое их сочетание. Хранение файлов журналов – это задача развертывания, а не приложения.

Единственное, что нужно вашему приложению – это формат журналов. Обычно это всего лишь строка с соответствующими данными, но если ваш сервер уже добавляет отметку времени в журнал, то вероятно, нужно будет исключить ее из своего собственного форматирования. Аналогично, если ваш агрегатор журналов может принимать JSON, возможно, более подходящим является форматирование, такое как python-json-logger.

Конфигурирование логирования. Настройка Sentry

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

Настроим Sentry, отправив любые сообщения службы в журнал, уровня warning или выше. В противном случае они были бы потеряны в море журнальных файлов, которые на практике редко проверяются. Для этого добавим «корневой» журнал, который будет использоваться для всех log сообщений, которые отправляются из любого модуля Python. Пример настройки Django:

import logging.config
LOGGING_CONFIG = None
logging.config.dictConfig({
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'console': {
            # точный формат не важен, это минимальная информация
            'format': '%(asctime)s %(name)-12s %(levelname)-8s %(message)s',
        },
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'formatter': 'console',
        },
        # Добавить обработчик для Sentry для `warning` и выше
        'sentry': {
            'level': 'WARNING',
            'class': 'raven.contrib.django.raven_compat.handlers.SentryHandler',
        },
    },
    'loggers': {
    # корневой логгер
        '': {
            'level': 'WARNING',
            'handlers': ['console', 'sentry'],
        },
    },
})

Логирование из приложения

Как правило требуется сведения о предупреждениях и ошибках о сторонних зависимостей, но, как правило, требуется гораздо глубокое понимание кода приложения. В идеале, код целиком живет в одном пространстве имён, чтобы его можно было охватить одним логером. Предположим, что проект использует пространство имен myproject, основываясь на коде выше.

logging.config.dictConfig({
    # ...
    'loggers': {
        '': {
            'level': 'WARNING',
            'handlers': ['console', 'sentry'],
        },
        'myproject': {
            'level': 'INFO',
            'handlers': ['console', 'sentry'],
            # требуется, чтобы избежать двойного ведения журнала с помощью корневого логгера
            'propagate': False,
        },
    },
})

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

import os
LOGLEVEL = os.environ.get('LOGLEVEL', 'info').upper()
logging.config.dictConfig({
    # ...
    'loggers': {
        '': {
            'level': 'WARNING',
            'handlers': ['console', 'sentry'],
        },
        'myproject': {
            'level': LOGLEVEL,
            'handlers': ['console', 'sentry'],
            # требуется, чтобы избежать двойного ведения журнала с помощью корневого регистратора
            'propagate': False,
        },
    },
})

Теперь ведение журнала по умолчанию будет info, но может быть легко временно изменено, установив переменную среды LOGLEVEL = debug. В качестве альтернативы, если хранилище журналов не является проблемой, учитывайте возможность ведения журнала на уровне debug. Их достаточно легко отфильтровать с помощью простого grep или с помощью инструмента визуализации журнала, например, Kibana.

Отфильтровывание шума

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

logging.config.dictConfig({
    # ...
    'loggers': {
        '': {
            'level': 'WARNING',
            'handlers': ['console', 'sentry'],
        },
        'myproject': {
            'level': LOGLEVEL,
            'handlers': ['console', 'sentry'],
            # требуется, чтобы избежать двойного ведения журнала с помощью корневого регистратора
            'propagate': False,
        },
        # Не отправляйте журналы этого модуля в Sentry
        'noisy_module': {
            'level':'ERROR',
            'handlers': ['console'],
            'propagate': False,
        },
    },
})

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

logging.config.dictConfig({
    # ...
    'loggers': {
        # ...
        # Не логгировать этот модуль
        'noisy_module': {
            'level': 'NOTSET',
            'propagate': False,
        },
    },
})

Логирование локальный запросов

По умолчанию в Django будет выполняться журналирование запросов с runserver. Переопределяя конфигурацию Django происходит потеря этой возможности. Но её достаточно легко добавить:

from django.utils.log import DEFAULT_LOGGING
logging.config.dictConfig({
    # ...
    'formatters': {
        # ...
        'django.server': DEFAULT_LOGGING['formatters']['django.server'],
    },
    'handlers' {
        # ...
        'django.server': DEFAULT_LOGGING['handlers']['django.server'],
    },
    'loggers': {
        # ...
        'django.server': DEFAULT_LOGGING['loggers']['django.server'],
    },
})

Этот метод немного хрупкий, поскольку зависит от некоторых внутренних компонентов, которые могут меняться между версиями, но поломки легко исправить используя прямое копирование/вставку из исходников Django.