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

Быстрый пример использования логгирования

Django использует встроенный модуль Python logging для системного логгирования. Подробности об использовании этого модуля описаны в документации модуля. Но для тех, кто никогда не использовал этот модуль (да и для тех кто использовал), мы приводим небольшой пример.

Действующие лица

Конфигурация логгирования в Python состоит из четырех частей:

Loggers(Логгеры)

Логгер – это точка входа в систему логгирования. Каждый логгер как именованный канал для сообщений, в который они отправляются для обработки.

У каждого логгера есть уровень логгирования (log level). Уровень логгирования указывает важность принимаемых сообщений. Python определяет следующие уровни логгирования:

  • DEBUG: Низкий уровень логгирования системной информации для последующего использования в отладке

  • INFO: Общая системная информация

  • WARNING: Информация о мелких проблемах возникших при работе приложения

  • ERROR: Информация об ошибках возникших при работе приложения

  • CRITICAL: Информация о критических ошибках

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

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

После того, как логгер принял сообщение на обработку, оно передается в Handler(Обработчик).

Handlers(Обработчики)

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

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

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

Filters(Фильтры)

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

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

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

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

Formatters(Форматер)

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

Использование логгирования

После настройки логгеров, обработчиков, фильтров и форматеров, добавим логгирование в наш код. Использовать логгирование очень просто. Вот небольшой пример:

# import the logging library
import logging

# Get an instance of a logger
logger = logging.getLogger(__name__)

def my_view(request, arg1, arg):
    ...
    if bad_mojo:
        # Log an error message
        logger.error('Something went wrong!')

Это все! При каждой успешной проверке условия bad_mojo будет записано сообщение ошибки.

Именование логгеров

Вызов logging.getLogger() возвращает (создает при необходимости) экземпляр логгера. Экземпляру логгера может назначить имя. Это имя используется при настройке логгирования.

Для удобства обычно используется __name__ в качестве названия – название модуля, который содержит логгер. Это позволяет вам управлять логгированием на уровне модулей. Однако, если вы используете другую систему организации сообщений, вы может использовать любое составное название, разделенное точками:

# Get an instance of a specific named logger
logger = logging.getLogger('project.interesting.stuff')

Точки в названии логгера позволяют определять иерархию. Логгер project.interesting считается родительским по отношению к логгеру project.interesting.stuff; логгер project родительским по отношению к project.interesting.

Почему иерархия так важна? Потому что логгеры могут быть настроены на передачу сообщений родительским логгерам. Таким образом вы можете определить один обработчик для корневого логгера и обрабатывать сообщения ко всем дочерним логгерам. Обработчик назначенный логгеру project будет обрабатывать сообщения к project.interesting и project.interesting.stuff.

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

Функции логгирования

Логгер предоставляет методы для каждого уровня логгирования:

  • logger.debug()
  • logger.info()
  • logger.warning()
  • logger.error()
  • logger.critical()

Также есть два дополнительных метода:

  • logger.log(): отправить сообщение с указанным уровнем логгирования

  • logger.exception(): Создать ERROR сообщение из последнего исключения(пер. the current exception stack frame).

Настройка логгирования

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

Библиотека логгирования Python предоставляет несколько способов настроить логгирования – от программного интерфейса и до конфигурационных файлов. По умолчанию Django использует dictConfig формат.

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

По умолчанию, параметр конфигурации LOGGING совмещается с стандартной конфигурацией журналирования Django с помощью следующей схемы.

Если ключ disable_existing_loggers в параметре конфигурации LOGGING установлен в True (по умолчанию это так), тогда все логгеры стандартной конфигурации отключаются. Отключенные логгеры отличаются от удалённых; логгер продолжает существовать, но тихо игнорирует всё, что ему передаётся, не пытаясь передавать записи в родительский логгер. Следовательно, вам надо быть аккуратным, используя 'disable_existing_loggers': True; скорее всего вам не нужно такое поведение. Вместо этого, вы можете установить disable_existing_loggers в False и переопределить некоторые или все стандартные логгер; также вы можете установить LOGGING_CONFIG в None и самостоятельно обработать конфигурацию журналирования.

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

Примеры

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

Первый пример – простая настройка записи всех запросов, логгированых логгером django.request, в файл:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'file': {
            'level': 'DEBUG',
            'class': 'logging.FileHandler',
            'filename': '/path/to/django/debug.log',
        },
    },
    'loggers': {
        'django.request': {
            'handlers': ['file'],
            'level': 'DEBUG',
            'propagate': True,
        },
    },
}

При использовании этого примера убедитесь, что пользователь, от которого запускается Django приложение, имеет права на запись файла, указанного в 'filename'.

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

По умолчанию, данная конфигурация только отсылает сообщения уровня INFO или выше на консоль (как и при настройках по умолчанию, за исключением того, что по умолчанию сообщения выводятся только при DEBUG=True). Django не журналирует большое количество таких сообщений. Для того, чтобы увидеть отладочные сообщения Django, которые очень информативны и даже включают в себя все запросы к базе данных, установите переменную окружения DJANGO_LOG_LEVEL=DEBUG:

import os

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
        },
    },
    'loggers': {
        'django': {
            'handlers': ['console'],
            'level': os.getenv('DJANGO_LOG_LEVEL', 'INFO'),
        },
    },
}
Изменено в Django 1.9:

Были изменены настройки журналирования по умолчанию. Смотрите список изменений.

Наконец, здесь показан пример достаточно сложной конфигурации журналирования:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'verbose': {
            'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'
        },
        'simple': {
            'format': '%(levelname)s %(message)s'
        },
    },
    'filters': {
        'special': {
            '()': 'project.logging.SpecialFilter',
            'foo': 'bar',
        },
        'require_debug_true': {
            '()': 'django.utils.log.RequireDebugTrue',
        },
    },
    'handlers': {
        'console': {
            'level': 'INFO',
            'filters': ['require_debug_true'],
            'class': 'logging.StreamHandler',
            'formatter': 'simple'
        },
        'mail_admins': {
            'level': 'ERROR',
            'class': 'django.utils.log.AdminEmailHandler',
            'filters': ['special']
        }
    },
    'loggers': {
        'django': {
            'handlers': ['console'],
            'propagate': True,
        },
        'django.request': {
            'handlers': ['mail_admins'],
            'level': 'ERROR',
            'propagate': False,
        },
        'myproject.custom': {
            'handlers': ['console', 'mail_admins'],
            'level': 'INFO',
            'filters': ['special']
        }
    }
}

Эта конфигурация выполняет следующее:

  • Указывает что конфигурация задана в формате ‘dictConfig версия 1’. На данный момент это единственная версия dictConfig формата.

  • Определяет два форматера:

    • simple, просто возвращает уровень логгирования сообщения (например, DEBUG) и содержимое сообщения.

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

    • verbose, выведет уровень логгирования, сообщение, время, название процесса, потока и модуля, который создал сообщение.

  • Определяет два фильтра:

    • project.logging.SpecialFilter с названием special. Если конструктор фильтра требует наличия дополнительных аргументов, вы можете указать их в словаре настройки фильтра. В этом случае будет передан аргумент foo со значением bar при создании экземпляра SpecialFilter.

    • django.utils.log.RequireDebugTrue – пропускает записи только в случае когда параметр конфигурации DEBUG равен True.

  • Определяет два обработчика:

    • console, StreamHandler, который перенаправляет все сообщения уровня DEBUG (и выше) в stderr. Этот обработчик использует формат simple.

    • mail_admins, AdminEmailHandler, который отправляет e-mail с сообщением уровня ERROR (и выше) администраторам сайта. Этот обработчик использует фильтр special.

  • Настраивает три логгера:

    • django, который перенаправляет все сообщения в обработчик console.

    • django.request, который передает все сообщения уровня ERROR в обработчик mail_admins. Также указывается, что логгер не должен передавать сообщения родительским логгерам. Это означает что сообщения переданные в django.request не будут обрабатываться логгером django.

    • myproject.custom, который передает все сообщения уровня INFO и выше прошедшие фильтр special в два обработчика – console и mail_admins. Это означает что все сообщения уровня INFO (или выше) будут отправлены в консоль, сообщения ERROR и CRITICAL будут отосланы через e-mail.

Собственная конфигурация логгирования

Если вы не хотите использовать формат dictConfig для настройки логгирования, вы можете определить собственный формат.

Параметр конфигурации LOGGING_CONFIG определяет функцию, которая настраивает логгирование в Django. По умолчанию, параметр указывает на logging.dictConfig(). Однако, если вы хотите переопределить настройку логгирования, укажите функцию, которая принимает один аргумент. Содержимое LOGGING будет передано в функцию при настройке логгирования.

Отключение настройки логгирования

Если вы вообще не желаете настраивать журналирование (или требуется самостоятельно настроить журналирование, используя собственный механизм2), вы можете установить LOGGING_CONFIG в None. Это отключит процесс настройки журналирования для случая по умолчанию. Здесь приведён пример отключения конфигурации журналирования Django и затем ручной её настройки:

settings.py
LOGGING_CONFIG = None

import logging.config
logging.config.dictConfig(...)

Установка LOGGING_CONFIG в None только означает, что процесс автоматической настройки отключен, это не влияет на само журналирование. Если вы отключите процесс конфигурации, Django все равно будет вызывать методы журналирования, используя поведение логгеров, настроенное по умолчанию.

Расширения для логгирования в Django

Django предоставляет набор утилит для решения стандартных задач логгирования в Web-приложениях.

Loggers(Логгеры)

Django предоставляет несколько встроенных логгеров.

django

django – логгер принимающий все сообщения. Сообщения не записываются непосредственно в этот логгер.

django.request

Принимает сообщения связанные с процессом обработки запросов. 5XX ответы отправляют ERROR сообщения, 4XX ответы – WARNING сообщения.

Сообщения этого логгера содержат дополнительные данные:

  • status_code: HTTP код ответа.

  • request: объект запроса, который спровоцировал сообщение.

django.template

Добавлено в Django 1.9.

Записывает логи связанные с рендерингом шаблонов.

  • Отсутствие переменной шаблона записывается как DEBUG сообщение.

  • Исключения при выполнении тега {% include %} логгируются как WARNING сообщения при выключенной отладке (удобно т.к. {% include %} перехватывает все исключения и возвращает пустую строку).

django.db.backends

Сообщения связанные с взаимодействием кода с базой данной. Например, каждый SQL запрос создает DEBUG сообщение в этот логер.

Сообщения этого логгера содержат дополнительные данные:

  • duration: Время выполнения SQL запроса.

  • sql: SQL запрос.

  • params: Параметры используемые при выполнении SQL запроса.

Для повышения производительности логгирование SQL запросов включено только при settings.DEBUG равном True, независимо от уровня логгирования и назначенных обработчиков.

Это логгирование не включает запросы, выполняемые при инициализации приложения (например, SET TIMEZONE), или запросы управления транзакциями (такие как BEGIN, COMMIT и ROLLBACK). Используйте логгирование на уровне базы данных, если вы хотите записывать все запросы.

django.security.*

Этот логгер получает сообщения о появлении исключения SuspiciousOperation. Есть подлоггеры для всех типов SuspiciousOperation. Уровень сообщения зависит от того, где обрабатывается исключение. Обычно это сообщения уровня предупреждения. SuspiciousOperation достигшие WSGI обработчика будут логгированы как ошибки. Например, если HTTP Host заголовок указанный клиентом не соответствует ALLOWED_HOSTS, Django вернет 400 ответ и ошибка будет логгирована в django.security.DisallowedHost.

Эти сообщения по умолчанию передаются в логгер ‘django’, что приведет к отправке электронных писем админам при DEBUG=False. Запросы с 400 ответом, вызванным исключением``SuspiciousOperation``, не будут обработаны логгером django.request, а только django.security.

Чтобы игнорировать определенные типы SuspiciousOperation, вы можете переопределить логгер следующим образом:

'handlers': {
    'null': {
        'class': 'logging.NullHandler',
    },
},
'loggers': {
    'django.security.DisallowedHost': {
        'handlers': ['null'],
        'propagate': False,
    },
},

django.db.backends.schema

Логгирует SQL запросы, которые выполняют при миграции базы данных. Запросы, выполняемые в RunPython, не будут записаны.

Handlers(Обработчики)

Django предоставляет один дополнительный обработчик.

class AdminEmailHandler(include_html=False, email_backend=None)

Этот логгер отсылает e-mail администраторам сайта с принятым сообщением.

Если запись в лог содержит атрибут request, письмо будет содержать полную информацию о запросе. Заголовок будет содержать “internal IP”, если IP клиента содержится в настройке INTERNAL_IPS, иначе – “EXTERNAL IP”.

Если сообщение содержит стек трассировки(пер. stack trace information), он будет включен в e-mail.

Параметр include_html в AdminEmailHandler указывает будет ли e-mail содержать HTML содержимое debug-страницы, которая была бы создана при DEBUG равном True. Чтобы установить этот параметр, укажите его в словаре конфигурации django.utils.log.AdminEmailHandler, например так:

'handlers': {
    'mail_admins': {
        'level': 'ERROR',
        'class': 'django.utils.log.AdminEmailHandler',
        'include_html': True,
    }
},

Заметим, что HTML версия письма содержит полный трейсбек с названиями и значениями локальных переменных на каждом уровне стека, а также значения настроек Django. Эта информация потенциально очень важна и возможно вы не захотите отправлять её через электронную почту. Рекомендуется использовать что-то вроде django-sentry, чтобы получить все преимущества – полная информация c трейсбеком и отсутствие отправки важной информации через электронную почту. Вы можете также явно указать фильтрацию важной информации – подробнее в разделе о фильтрации отчетов об ошибках.

Через параметр email_backend класса AdminEmailHandler, можно переопределить бекенд отправки email:

'handlers': {
    'mail_admins': {
        'level': 'ERROR',
        'class': 'django.utils.log.AdminEmailHandler',
        'email_backend': 'django.core.mail.backends.filebased.EmailBackend',
    }
},

По умолчанию используется экземпляр класса, указанного в EMAIL_BACKEND.

send_mail(subject, message, *args, **kwargs)
Добавлено в Django 1.8.

Отправляет сообщения по электронной почте администраторам. Для изменения этого поведения следует унаследовать класс AdminEmailHandler и переопределить данный метод.

Filters(Фильтры)

Django предоставляет два дополнительных фильтра.

class CallbackFilter(callback)

Этот фильтр принимает функцию (которая должна принимать один аргумент - логгированное сообщение), и вызывает ее для каждого переданного сообщения. Сообщение не будет обработано если функция вернет False.

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

from django.http import UnreadablePostError

def skip_unreadable_post(record):
    if record.exc_info:
        exc_type, exc_value = record.exc_info[:2]
        if isinstance(exc_value, UnreadablePostError):
            return False
    return True

и затем добавить её в свою конфигурацию логгирования:

'filters': {
    'skip_unreadable_posts': {
        '()': 'django.utils.log.CallbackFilter',
        'callback': skip_unreadable_post,
    }
},
'handlers': {
    'mail_admins': {
        'level': 'ERROR',
        'filters': ['skip_unreadable_posts'],
        'class': 'django.utils.log.AdminEmailHandler'
    }
},
class RequireDebugFalse

Этот фильтр работает только если настройка DEBUG равна False.

Этот фильтр используется в конфигурации LOGGING по-умолчанию, чтобы предотвратить отсылку писем обработчиком AdminEmailHandler если настройка DEBUG не равна False:

'filters': {
    'require_debug_false': {
        '()': 'django.utils.log.RequireDebugFalse',
    }
},
'handlers': {
    'mail_admins': {
        'level': 'ERROR',
        'filters': ['require_debug_false'],
        'class': 'django.utils.log.AdminEmailHandler'
    }
},
class RequireDebugTrue

Этот фильтр аналогичен RequireDebugFalse за исключением того, что он пропускает записи только в случае когда параметр конфигурации DEBUG равен True.

Стандартная конфигурация логгирования

По умолчанию, Django настраивает следующую конфигурацию журналирования:

Если DEBUG равна True:

  • django, который перенаправляет все сообщения уровня INFO и выше в консоль.

  • Логгер py.warnings, который обрабатывает сообщения от warnings.warn(), отправляет их на консоль.

Если DEBUG установлен в False:

  • По умолчанию логгер django отравляет все сообщения уровня ERROR или CRITICAL в AdminEmailHandler.

Изменено в Django 1.9:

Были изменены настройки журналирования по умолчанию. Смотрите список изменений.

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