# Логирование 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 не записывается.

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

```text
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-записи:

```json
{"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-процесса
совпадает.

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

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

```python
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 объекта и класс ожидаемой ошибки:

```python
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:

```bash
# Все ошибки 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 запускайте:

```bash
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.