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

Backend пишет все сообщения в единый поток stdout/stderr. Локально используется сгруппированный однострочный формат без цветов и ANSI-кодов, в production — одна JSON-запись на строку. Имена полей сохраняются в обоих представлениях. Файловых handlers и ротации внутри Django нет: сбор, хранение и ротация являются задачей контейнера или платформы запуска.

Настройки

Переменная	Значение по умолчанию	Назначение
`LOG_FORMAT`	`console` при `DEBUG=true`, иначе `json`	`console` или `json`
`LOG_LEVEL`	`DEBUG` при `DEBUG=true`, иначе `INFO`	Уровень кода проекта
`DJANGO_LOG_LEVEL`	`INFO`	Django framework
`DJANGO_SERVER_LOG_LEVEL`	`ERROR`	Встроенный access log Django; HTTP middleware уже пишет ответы
`DJANGO_REQUEST_LOG_LEVEL`	`ERROR`	Traceback необработанных ошибок Django без дублирования 4xx
`DB_LOG_LEVEL`	`WARNING`	SQL backend Django
`LDAP_LOG_LEVEL`	`WARNING`	Внутренние сообщения `ldap3`
`CELERY_LOG_LEVEL`	`INFO`	Celery framework
`CHANNELS_LOG_LEVEL`	`INFO`	Django Channels
`CHANNELS_SERVER_LOG_LEVEL`	`WARNING`	Access log Channels; штатные ответы уже пишет HTTP middleware
`DAPHNE_LOG_LEVEL`	`WARNING`	Низкоуровневый HTTP/WS transport Daphne
`ASYNCIO_LOG_LEVEL`	`WARNING`	asyncio internals
`PIL_LOG_LEVEL`	`WARNING`	Pillow internals
`RULES_LOG_LEVEL`	`WARNING`	Детальная трассировка django-rules

LOG_TRUST_X_FORWARDED_FOR=true разрешает брать первый валидный IP из X-Forwarded-For, затем из X-Real-IP. Настройка применяется к HTTP и WebSocket. Включайте её только когда Django недоступен в обход доверенного reverse proxy, а proxy заменяет входящие заголовки клиента. Иначе используется валидный REMOTE_ADDR/ASGI scope.client.

Общие поля

Каждая запись содержит:

timestamp, level, logger, event, message;
в JSON также source (файл:строка);
HTTP: request_id, user_id, http_method, path, client_ip;
WebSocket: request_id, connection_id, user_id, path;
Celery: task_id, task_name; для задач, созданных внутри HTTP/WS-операции, через безопасные message headers наследуются request_id, user_id и client_ip; путь, payload, args и kwargs не переносятся;
поля события: идентификатор бизнес-объекта, status_code, duration_ms, счётчики, состояние или тип ошибки.

Входящий X-Request-ID принимается только если состоит из безопасных ASCII символов и не длиннее 128 символов. Иначе генерируется новый ID. Этот же ID возвращается клиенту в заголовке ответа. Query string не записывается.

Пример локальной записи:

2026-08-14T14:30:00.123+00:00 INFO [HTTP] http.request.completed @eusrr.http [GET "/api/v1/documents/" → 200 24.18ms] [req="b764..." user=42 ip="127.0.0.1"] "HTTP request completed"

Уровень, событие и logger занимают фиксированные позиции без повторяющихся level=, event= и logger=. HTTP method/path/status/duration выводятся позиционно; корреляция использует короткие обозначения req, conn, task, user, ip. Остальные поля события сохраняют полные имена внутри отдельного блока. Скобки и короткие обозначения являются только локальным визуальным представлением и не добавляются в production JSON.

Пример production-записи:

{"timestamp":"2026-08-14T14:30:00.123+00:00","level":"INFO","logger":"eusrr.http","event":"http.request.completed","message":"HTTP request completed","request_id":"b764...","user_id":42,"http_method":"GET","path":"/api/v1/documents/","status_code":200,"duration_ms":24.18}

Системные события

HTTP middleware формирует одну итоговую запись:

http.request.completed — ответ сформирован; 2xx/3xx пишутся как INFO, 4xx как WARNING, 5xx как ERROR;
http.request.failed — исключение вышло за границу middleware.

WebSocket lifecycle:

websocket.connection.accepted;
websocket.connection.closed с close_code и duration_ms;
websocket.connection.failed с traceback;
websocket.authentication.rejected без JWT и query string.

Celery lifecycle:

celery.task.started;
celery.task.completed с task_state и duration_ms;
celery.task.failed с типом исключения и traceback.

Аргументы и результат задачи намеренно не логируются: они могут содержать персональные данные или секреты. Если задача создана не из HTTP/WS-контекста, но имеет именованный аргумент user_id, lifecycle logger извлекает только этот аргумент. Для periodic/system задач отсутствие user_id и client_ip является корректным: пользователя и клиентского соединения у них нет. Celery worker не перехватывает root logger (CELERY_WORKER_HIJACK_ROOT_LOGGER=False), поэтому формат worker и web-процесса совпадает.

Как писать прикладные логи

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

import logging

logger = logging.getLogger(__name__)

logger.info(
    "Document indexed",
    extra={
        "event": "document.indexed",
        "document_id": document.id,
        "duration_ms": duration_ms,
    },
)

Для ошибки используйте logger.exception() внутри except. Добавляйте тип операции, ID объекта и класс ожидаемой ошибки:

try:
    index_document(document)
except Exception as error:
    logger.exception(
        "Document indexing failed",
        extra={
            "event": "document.indexing_failed",
            "document_id": document.id,
            "error_type": type(error).__name__,
        },
    )
    raise

Правила именования:

event: <domain>.<entity>.<outcome>, например request.notification.sent;
request_id — только correlation ID HTTP/WS, для заявления используется business_request_id;
ID именуются явно: document_id, employee_id, notification_id;
количество — *_count, длительность — duration_ms;
INFO — завершённое бизнес-событие, WARNING — отказ/пропуск или 4xx, ERROR — сбой, требующий внимания, DEBUG — диагностические этапы.

Каждый production-вызов logger.* обязан передавать extra со стабильным event. Это проверяется AST-тестом по всему backend. Для записей сторонних библиотек context filter создаёт событие вида framework.<logger_name>.<level>. Штатные access/protocol-сообщения Daphne и Channels ниже WARNING отключены, поскольку дублируют eusrr.http и eusrr.websocket; предупреждения и ошибки сохраняются в едином формате.

Запрещённые данные

Не логируются:

пароли и их хеши;
JWT, Web Push ключи, LDAP bind credentials, API keys;
Authorization, cookies и session tokens;
полные request.data, body, headers, query string и Celery args/kwargs;
email, телефон, ФИО, username, LDAP DN и текст пользовательского контента, если для расследования достаточно внутреннего ID.

Форматтер маскирует распространённые ключи и конструкции (password=, token=, Bearer ..., cookies), email, телефон и LDAP DN. Строковые значения длиннее 2048 символов обрезаются с маркером [TRUNCATED], чтобы случайный payload или ответ внешнего сервиса не создавал log storm. Это страховка, а не замена правилу не передавать чувствительное значение в logger.

Границы покрытия

Единый формат и обязательный event покрывают production Python-код Django, Channels и Celery. В этот контур не входят логи Next.js/browser, nginx, PostgreSQL, Redis, Docker/runtime и сообщения сторонних процессов до загрузки Django settings. Их форматирование настраивается в соответствующем сервисе, а correlation выполняется по переданному X-Request-ID, когда сервис это поддерживает.

Поиск проблем

Сначала найдите неуспешное событие, затем соберите всю цепочку по correlation ID:

# Все ошибки production JSON-лога
jq 'select(.level == "ERROR")' backend.log

# Полная история HTTP/WebSocket операции
jq 'select(.request_id == "b764...")' backend.log

# Медленные HTTP запросы
jq 'select(.event == "http.request.completed" and .duration_ms > 500)' backend.log

# Сбои конкретного типа Celery-задач
jq 'select(.event == "celery.task.failed" and .task_name == "documents.tasks.index")' backend.log

После изменения logging infrastructure запускайте:

PYTHONPATH=.venv/lib/python3.13/site-packages /usr/bin/python3.13 \
  -m pytest tests/test_logging.py -q
PYTHONPATH=.venv/lib/python3.13/site-packages /usr/bin/python3.13 \
  manage.py check

tests/test_logging.py дополнительно гарантирует отсутствие runtime print(), наличие корректного event у каждого project logger-вызова, отсутствие конфликтов с зарезервированными полями LogRecord и маскирование секретов/PII.

12 KiB Raw Permalink Blame History Unescape Escape