Логгирование в Django (начальный обзор)

Django — один из самых популярных веб фреймворков Python, используемый многими организациями. Поскольку он использует встроенное средство ведения логов Python logging, использование логов в Django совсем несложная задача.

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

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

Создание виртуальной среды

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

Поскольку в этой статье мы будем использовать Python 3, перед созданием виртуальной среды Python проверьте, что вы используете версию Python не ниже 3.6.1:

$ python3 --version
Python 3.7.0

Затем создайте каталог, чтобы сохранить наш проект:

$ mkdir test && cd $_

Отлично. Прежде чем перейти к следующему разделу, давайте создадим и активируем нашу новую виртуальную среду:

test$ mkvirtualenv loggers --python=python3 
Using base prefix '/usr/local/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7' 
New python executable in /Users/casey/projects/django-logging/env/bin/python3.7 
Also creating executable in /Users/casey/projects/django-logging/env/bin/python 
Installing setuptools, pip, wheel... done.
loggers$ source env/bin/activate
(env) test$

Теперь все хорошо, перейдем к установке Django.

Установка Django

В виртуальной среде установим Django:

(env) test$ pip install Django
Collecting Django
  Using cached https://files.pythonhosted.org/packages/d1/e5/2676be45ea49cfd09a663f289376b3888accd57ff06c953297bfdee1fb08/Django-2.1.3-py3-none-any.whl
Collecting pytz (from Django)
  Using cached https://files.pythonhosted.org/packages/f8/0e/2365ddc010afb3d79147f1dd544e5ee24bf4ece58ab99b16fbb465ce6dc0/pytz-2018.7-py2.py3-none-any.whl
Installing collected packages: pytz, Django
Successfully installed Django-2.1.3 pytz-2018.7

Проверим как установилась Django выводом версии:

(env) test$ python -m django --version
3.0.8

Теперь перейдем к созданию простого приложения loggers.

Создание простого приложение

Для этой статьи наш проект не будет чем-то необычным — простой обработчик одной веб-страницы, которая будет испытательным стендом для логгирования сообщений.

Команда django-admin создаст для нас начальный скелет приложения:

(env) test$ django-admin startproject loggers

в вашем каталоге test вы увидите новую папку приложения:

(env) test$ ls
loggers

В качестве последнего шага, чтобы убедиться, что все работает, перейдем в каталог test и запустим встроенный веб-сервер Django:

(env) test$ cd loggers
(env) test$ python manage.py runserver
Performing system checks...

System check identified no issues (0 silenced).

You have 17 unapplied migration(s). Your project may not work properly until you apply the migrations for app(s): admin, auth, contenttypes, sessions.
Run 'python manage.py migrate' to apply them.

July 30, 2020 - 10:00:12
Django version 3.0.8, using settings 'loggers.settings'
Starting development server at http://127.0.0.1:8000/
Quit the server with CONTROL-C.

Видите это страшное сообщение о 17 непримененных миграциях? Просто игнорируй это. Откройте браузер и перейдите на http://localhost:8000, и вы должны увидеть веб-страницу Django по умолчанию

Добавление нового модуля Django

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

(env) test$ python manage.py startapp hello

Эта команда создаст новую папку с именем hello вместе с несколькими дополнительными файлами Python. Замените содержимое hello/views.py следующим:

from django.http import HttpResponse

def index(request):
    return HttpResponse("Hello logging world.")

Это создает наше первоначальное представление (view), но нам все еще нужно сообщить об этом Django. Создайте новый файл в hello/urls.py и добавьте в него следующее:

from django.urls import path

from . import views

urlpatterns = [
    path('', views.index, name='index'),
]

Это связывает наше представление с базовым URL. Теперь все, что нам нужно сделать, это подключить его к файлу loggers/urls.py, чтобы Django знал, как все маршрутизировать. Откройте loggers/urls.py и замените его содержимое следующим:

from django.contrib import admin
from django.urls import include, path

urlpatterns = [
    path('admin/', admin.site.urls),
    path('', include('hello.urls'))
]

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

(env) test$ python manage.py runserver

Вместо стандартного экрана приветствия Django, мы увидим наш вывод строки «Hello logging world.»

Теперь, когда у нас есть простое приложение, давайте посмотрим, как включить логгирование в Django.

Первые шаги с логгированием

Самое простое для включения логирования, которое мы можем сделать, это просто импортировать модуль Python logging и начать регистрацию. Начните с обновления файла app/views.py следующим кодом:

import logging

from django.http import HttpResponse

logger = logging.getLogger(__name__)

def index(request):

    logger.error("Test!!")

    return HttpResponse("Hello logging world.")

Здесь мы импортируем модуль logging и затем используем метод getLogger, чтобы получить экземпляр logging, который мы можем использовать. В методе index мы отправляем наше сообщение в журнал, используя метод logger.error. Всего существует 5 методов записи логов соответствующих уровню сообщений: logger.debug, logger.error, logger.warning, logger.info, logger.critical. И два базовых метода: logger.log и logger.exception

Перезапустите веб-сервер и обновите страницу, чтобы увидеть наше сообщение в окне консоли:

(env) test$ python manage.py runserver
Performing system checks...

System check identified no issues (0 silenced).

You have 15 unapplied migration(s). Your project may not work properly until you apply the migrations for app(s): admin, auth, contenttypes, sessions.
Run 'python manage.py migrate' to apply them.


July 30, 2020 - 10:00:12
Django version 3.0.8, using settings 'loggers.settings'
Starting development server at http://127.0.0.1:8000/
Quit the server with CONTROL-C.
Test!!
[30/Jul/2020 02:11:35] "GET / HTTP/1.1" 200 20
Not Found: /favicon.ico
[30/Jul/2020 02:11:35] "GET /favicon.ico HTTP/1.1" 404 2024

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

Мы можем изменить настройки логирование непосредственно в представление (view), сразу после импоритирования. По умолчанию Django использует формат dictConfig  для настройки handlers, loggers, filters и formatters. Эти настройки задаются с помощью словаря LOGGING, который объединяется с конфигурацией ведения журнала Django по умолчанию. Выглядеть это будет следующим образом:

import logging

logging.config.dictConfig({
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'console': {
            'format': '%(name)-12s %(levelname)-8s %(message)s'
        },
        'file': {
            'format': '%(asctime)s %(name)-12s %(levelname)-8s %(message)s'
        }
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'formatter': 'console'
        },
        'file': {
            'level': 'DEBUG',
            'class': 'logging.FileHandler',
            'formatter': 'file',
            'filename': 'debug.log'
        }
    },
    'loggers': {
        '': {
            'level': 'DEBUG',
            'handlers': ['console', 'file']
        }
    }
})

Или что бы настройки логгирования применились для всего проекта лучше всего это сделать в файле настроек loggers/settings.py. Просто добавив в конец файла следующие строки:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'console': {
            'format': '%(name)-12s %(levelname)-8s %(message)s'
        },
        'file': {
            'format': '%(asctime)s %(name)-12s %(levelname)-8s %(message)s'
        }
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'formatter': 'console'
        },
        'file': {
            'level': 'DEBUG',
            'class': 'logging.FileHandler',
            'formatter': 'file',
            'filename': 'debug.log'
        }
    },
    'loggers': {
        '': {
            'level': 'DEBUG',
            'handlers': ['console', 'file']
        }
    }
}

Рассмотрим это настройки более подробно.

version

Схема dictConfig не требует версии, но ее установка обеспечивает обратную совместимость. В настоящее время единственным допустимым значением здесь является 1.

disable_existing_loggers

Этот параметр отключает существующие логгеры. По умолчанию Django использует некоторые из своих собственных логеров. Эти логгеры связаны с Django ORM и другими внутренними частями Django. Значением по умолчанию является False, но не помешает указывать это явно. При установке этого значения в True нужно указать дополнительные логгеры . В противном случае сообщения могут быть потеряны.

formatters (форматы)

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

%(name)-12s %(levelname)-8s %(message)s

Вот что здесь используется:

• %(name) – это имя пакета, которое выдает сообщение журнала
• %(levelname) – степень важности сообщения (ERROR, WARNING, INFO, и т.д.)
• %(message) – само сообщение

-12s и -8s управляют интервалом между различными спецификациями формата. Сообщения в этом формате будет выглядеть следующим образом:

hello.views  ERROR    Test!!

Вы можете заметить, что formatter в file содержит дополнительный спецификатор %(asctime). Это добавляет временную метку к каждому сообщению, отправляемому через обработчик file. В качестве примера, сообщение из нашего определенного debug.log будет выглядеть так:

2020-11-29 14:36:58,739 hello.views  ERROR    Test!!

handlers (обработчики)

Этот раздел определяет, как обрабатывать сообщения журнала. Мы можем отправлять сообщения на консоль, файлы или даже в сокеты! Все обработчики по умолчанию описаны в документации по Python здесь. Эта конфигурация определяет отдельные обработчики: один для сообщений консоли и другой для сообщений, отправляемых в файл. Кроме того, для обработчика file мы указываем класс обработчика, имя файла и log level. В этом обработчике также указано, какой formatter нужно использовать.

loggers (логгеры)

В этом разделе мы связываем все это вместе и определяем наши логгеры, включая способы обработки сообщений корневого логгера — root logger (представленного пустой строкой). Мы также устанавливаем уровень ведения журнала logging level — DEBUG и определяем два обработчика, один для консоли и один для файла.

В нашем примере мы не использовали один параметр который необходимо упомянуть здесь это filters

filters (фильтры)

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

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

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

Мы рассмотрим использование фильтров в разделе настройки почтовых сообщений

Давайте сейчас обновим конфигурацию и посмотрим что получилось.

Тестирование новой конфигурации

Обновите страницу в браузере, теперь сообщение журнала консоли содержит дополнительную информацию из строки формата:

$ python manage.py runserver
...

July 30, 2020 - 10:00:12
Django version 3.0.8, using settings 'loggers.settings'
Starting development server at http://127.0.0.1:8000/
Quit the server with CONTROL-C.
hello.views  ERROR    Test!!

Файл журнала будет содержать то же сообщение и формат, но с добавлением отметки времени:

(env) test$ cat debug.log 
2020-07-30 14:36:58,739 hello.views  ERROR    Test!!

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

Далее, рассмотрим более подробно стандартные логгеры (logging) для ведения логов, которые предоставляет Django.

Стандартные логгеры

В среде веб-сервера у нас часто есть рутинная информация, которую мы должны регистрировать. Django предоставляет несколько стандартных логгеров (loggers) для ведения логов.

django

Это универсальный логгер принимающий все сообщения. Сообщения не записываются непосредственно в этот логгер поэтому нужно использовать один из следующих логгеров.

django.request

Этот логгер обрабатывает все сообщения вызванные HTTP-запросами и вызывает исключения для определенных кодов состояния. Все коды ошибок HTTP 5xx будут вызывать сообщения об ERROR. Аналогичным образом, коды HTTP 4xx будут отображаться в виде WARNING.

django.server

Когда сервер запускается с помощью команды runserver (что мы и делали), он будет регистрировать сообщения, связанные с обработкой этих запросов, точно так же, как логгер django.request, за исключением того, что все другие сообщения регистрируются на уровне INFO.

django.template

Независимо от того, как часто я работал с шаблонами Django, я никогда не собирал их без ошибок с первого раза. Логгер django.template обрабатывает ошибки, связанные с отображением шаблонов.

django.db.backends

Этот логгер обрабатывает любые сообщения связанные с взаимодействием кода с базой данных. Все операторы SQL уровня приложения будут отображаться на уровне DEBUG. Поскольку это может быть довольно шумно, необходимо включить ведение журнала отладки, изменив settings.DEBUG на True.

django.security.*

Django предоставляет обработчики ошибок, связанных с безопасностью. В частности, этот логгер будет получать любые сообщения, возникающие в результате ошибки SuspiciousOperation. Django определяет подклассы для каждого типа ошибок безопасности, таких как DisallowedHost или InvalidSessionKey. Остальные подклассы SuspiciousOperation можно найти здесь.

Примечание. Если сообщение будет обрабатываться django.security то оно не будет отправлено через логгер django.request. Так что не игнорируйте сообщения от логгера django.security. *!

django.security.csrf

Этот логгер не наследуется от SuspiciousOperation. Он обрабатывает любые исключения, которые происходят из-за атак Cross-Site Request Forgery (CSRF).

И так в качестве следующего примера давайте запишем сообщения с помощью логгера django.request. Это делается путем добавления логгера в раздел регистрации конфигурации следующим образом:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'console': {
            'format': '%(name)-12s %(levelname)-8s %(message)s'
        },
        'file': {
            'format': '%(asctime)s %(name)-12s %(levelname)-8s %(message)s'
        }
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'formatter': 'console'
        },
        'file': {
            'level': 'DEBUG',
            'class': 'logging.FileHandler',
            'formatter': 'file',
            'filename': 'debug.log'
        }
    },
    'loggers': {
        '': {
            'level': 'DEBUG',
            'handlers': ['console', 'file'],
            'propagate': True
        },
        'django.request': {
            'level': 'DEBUG',
            'handlers': ['console', 'file']
        }
    }
})

Это будет регистрировать сообщения-запросы, подобные следующим:

2020-07-29 13:58:55,044 django.request WARNING Not Found: /

Обратите внимание на использование параметра propagate. Этим параметром регулируется возможность передачи сообщения другим логгерам. Если оно установлено в False то дальше сообщение не пойдет.

Так же для каждого модуля в вашем приложение вы можете описать свой логгер (например для ведение отдельных файлов). Это делается следующим образом:

...
    'loggers': {
    ...
        'loggers.hello': {
            'level': 'DEBUG',
            'handlers': ['console',],
            'propagate': True
        },
    },

Настройка отправки сообщений об ошибках по email

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

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

что бы он работал нужно добавить настройки отправки почты также в файл settings.py (в нашем примере мы будет использовать сервер yandex, но можно использовать любой другой, с соотвествующими настройками)

ADMINS = (
    ('admin', 'admin@example.com'),
)
...
EMAIL_SUBJECT_PREFIX = '[SuperService] '
EMAIL_HOST = 'smtp.yandex.ru'
EMAIL_HOST_USER = 'user@example.ru'
EMAIL_HOST_PASSWORD = 'XXXXXX'
EMAIL_PORT = 465
EMAIL_USE_TLS = False
EMAIL_USE_SSL = True

SERVER_EMAIL = 'user@example.ru'
DEFAULT_FROM_EMAIL = 'user@example.ru'
...

Имена используемых параметров сами говорят за себя их предназначение. Очень важно понимать что бы все заработало сервер на котором запускается Django должен уметь отправлять почту (на нем должна быть настроена отправка почты по SMTP). Настройка отправки почты на сервере выходит за рамки данной статьи. Что бы немного облегчить поиск проблем связанных с настройкой отправки почты на сервере можно имитировать отправку почты Django. То есть вместо реальной отправки писем записывать их в локальный файл. Для этого нужно указать соотвествующий почтовой бекенд email_backend и файл для записи в настройках.

...
EMAIL_FILE_PATH = 'email-messages'
...
LOGGING = {
...
   'mail_admins': {
            'level': 'DEBUG',
            'class': 'django.utils.log.AdminEmailHandler',
            'include_html': True,
            'email_backend': 'django.core.mail.backends.filebased.EmailBackend',
        },
...

Так же можно добавить фильтр django.utils.log.RequireDebugFalse, который сделает так что бы письма отправлялись только когда отключен режим DEBUG то есть установлен DEBUG=False

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

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

from django.core.mail import send_mail
...
send_mail(
        subject = "Test Email",
        message = "This is a test email",
        from_email = None,   # This will have no effect is you have set DEFAULT_FROM_EMAIL in settings.py
        recipient_list = ['user@example.com'], 
        fail_silently = False   
    )

Еще один пример конфигурации логгирования

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

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',
        }
    },
    'handlers': {
        'null': {
            'level': 'DEBUG',
            'class': 'logging.NullHandler',
        },
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'simple'
        },
        'mail_admins': {
            'level': 'ERROR',
            'class': 'django.utils.log.AdminEmailHandler',
            'filters': ['special']
        }
    },
    'loggers': {
        'django': {
            'handlers': ['null'],
            'propagate': True,
            'level': 'INFO',
        },
        'django.request': {
            'handlers': ['mail_admins'],
            'level': 'ERROR',
            'propagate': False,
        },
        'myproject.custom': {
            'handlers': ['console', 'mail_admins'],
            'level': 'INFO',
            'filters': ['special']
        }
    }
}

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

Определяет два formatters (форматера):

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

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

Определяет три handlers (обработчика):

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

Настраивает три loggers (логгера):

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

Раскрашивание сообщений в консоли

В завершение я бы хотел рассмотреть еще один момент, включение цветной консоли. И хотя эта тема напрямую не связана с логгированием. Удобство чтения сообщений в консоли значительно улучшает и упрощает процесс поиска багов. Для того бы включить раскрашивание сообщений в консоли нужно в начале установить пакет rich (минимальная версия python 3.6.1) командой

pip install rich

а затем настройте handlers консоли на использование rich.logging.RichHandler вместо logging.StreamHandler

...
 "formatters": {"rich": {"datefmt": "[%X]"}},
...
 'handlers': {
        'console': {
            'class': 'rich.logging.RichHandler',
            'formatter': 'console'
        },
 ....

Ваша жизнь после этого станет намного ярче 🙂

Заключение

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

При написание статьи использовались следующие источники:

• Getting started quickly with django logging
• https://docs.djangoproject.com/en/3.0/topics/logging/
• https://docs.djangoproject.com/en/3.0/topics/email/
• https://www.willmcgugan.com/blog/tech/post/richer-django-logging/