216 lines
14 KiB
Markdown
216 lines
14 KiB
Markdown
# Логирование
|
||
|
||
Конвенция: *как* и *когда* писать логи в jellybit. Это правила оформления
|
||
кода (How), а не спецификация поведения — наблюдаемые требования к логам
|
||
(что система ОБЯЗАНА залогировать как часть контракта capability) живут в
|
||
OpenSpec-спеках (`### Requirement` с `SHALL`).
|
||
|
||
Краткая выжимка и инварианты — в [CLAUDE.md](../../CLAUDE.md), раздел
|
||
«Конвенции кода».
|
||
|
||
## Принципы
|
||
|
||
- Только `log/slog`, без `fmt.Println` и прямой записи в stdout.
|
||
- Структурированный JSON (`slog.JSONHandler`), один формат для dev и prod.
|
||
- Сообщение (`msg`) — константный шаблон/категория события; данные — в
|
||
полях (атрибутах `slog`), а не в интерполяции текста.
|
||
- Каждое поле — отдельный ключ с типизированным значением. Это даёт
|
||
фильтрацию и агрегацию через `jq`/DuckDB без регулярок.
|
||
|
||
```json
|
||
{"time":"2026-06-28T11:23:45.123456Z","level":"INFO","msg":"download accepted","capability":"ingest","download_id":"a1b2","infohash":"…","media_type":"movie","title":"Дюна: Часть вторая"}
|
||
```
|
||
|
||
## Сообщение
|
||
|
||
- `msg` — короткая константа в нижнем регистре: `download accepted`,
|
||
`recognition done`, `layout failed`. Без переменных в тексте.
|
||
- Данные кладём в атрибуты: `slog.Info("download accepted", "download_id",
|
||
id, "infohash", ih)`.
|
||
|
||
```go
|
||
// Правильно: msg — категория, данные — поля
|
||
log.Info("download accepted", "download_id", id, "media_type", "movie")
|
||
|
||
// Неправильно: данные зашиты в текст, агрегация ломается
|
||
log.Info(fmt.Sprintf("download %s accepted as movie", id))
|
||
```
|
||
|
||
- `msg` — чистая категория без неймспейс-префикса: `recognition done`, а не
|
||
`recognize: done`. Подсистему выносим в поле `capability`
|
||
(`ingest`/`recognition`/`file-layout`/`review`), не в текст.
|
||
|
||
## Уровни
|
||
|
||
Принцип: уровень — это **адресат** («кому сообщение»), а не «насколько
|
||
громко сломалось». `slog` даёт четыре уровня; их и используем.
|
||
|
||
| Уровень | Кому и когда | Примеры в jellybit |
|
||
|---|---|---|
|
||
| `DEBUG` | разработчику при отладке; в проде выключен | healthcheck-эндпоинты, поллинг статуса в qBittorrent, авто-рефреш UI, тела запросов/ответов внешних API, промежуточные шаги распознавания |
|
||
| `INFO` | команде, аудит постфактум | приём загрузки, распознан фильм/сериал, раскладка выполнена, старт процессов, **событийный вызов внешнего сервиса** (по реальному действию) |
|
||
| `WARN` | команде, «может стать проблемой» | retry внешнего вызова, низкая уверенность распознавания (ушло в ревью), приближение к лимиту |
|
||
| `ERROR` | команде, в техдолг / разбор | внешний сервис недоступен после ретраев, операция загрузки не выполнена, необработанная ошибка |
|
||
|
||
Правила:
|
||
|
||
- Уровень **не зависит от capability** — `ERROR` в `ingest` и в
|
||
`file-layout` одинаково серьёзны.
|
||
- `WARN` ≠ «ничего страшного». `WARN` = «может стать проблемой». Если это
|
||
не «может» — это `INFO`.
|
||
- Меняется адресат — меняется уровень. Невалидный ввод от пользователя —
|
||
это `DEBUG` (норма, команде разбирать нечего), а не `ERROR`.
|
||
- **Событийное → INFO, рутинно-частое → DEBUG.** Операция, срабатывающая по
|
||
реальному действию/изменению (приём загрузки, добавление торрента, вызов
|
||
LLM, раскладка), идёт на `INFO`. Повторяющаяся служебная операция,
|
||
которую запускает таймер/поллинг и которая сама по себе не несёт события
|
||
(healthcheck, поллинг статуса в qBittorrent, авто-рефреш UI), — на
|
||
`DEBUG`: на `INFO` она зашумляет аудит. Такие записи смотрят редко, при
|
||
предметной отладке (DEBUG включают точечно).
|
||
- `slog` не разделяет CRITICAL/FATAL — фатальный сбой на старте логируем
|
||
`ERROR` и завершаем процесс (ненулевой код возврата).
|
||
|
||
## Время
|
||
|
||
- Поле — `time` (ключ по умолчанию `slog`).
|
||
- UTC, RFC 3339 с долями секунды, суффикс `Z`:
|
||
`2026-06-28T11:23:45.123456Z`.
|
||
- Логи — **в UTC** (это явный TZ, не нарушает инвариант проекта): даёт
|
||
однозначный порядок событий и лексикографическую сортировку. Бизнес-логика
|
||
по-прежнему работает в `Europe/Moscow` — UTC только в логах.
|
||
|
||
## Поля: словарь имён
|
||
|
||
Главное условие — **единый словарь**: одно поле — одно имя по всему коду
|
||
(не `mediaType`/`media`/`media_type` вперемешку).
|
||
|
||
- Бизнес-/доменные поля — плоский `snake_case`.
|
||
- Системные домены — точечная иерархия (адаптация OpenTelemetry): `http.*`,
|
||
`ext.*`.
|
||
- JSON плоский: все поля на верхнем уровне, без вложенности.
|
||
|
||
| Когда добавляем | Поля |
|
||
|---|---|
|
||
| на входящий HTTP-запрос (middleware) | `transport` (`http`/`web`/`telegram`), `http.method`, `http.route`, `http.status_code`, `duration_ms` |
|
||
| на загрузку (scoped-логгер, см. ниже) | `capability` (`ingest`/`recognition`/`file-layout`/`review`), `download_id`, `infohash`, `media_type`, `title` |
|
||
| на запись об ошибке | `error` |
|
||
| на вызов внешнего сервиса | `ext.service`, `ext.operation`, `ext.status_code`, `duration_ms`, `retry` |
|
||
|
||
Не заводим `service.*`/`host.*` — для одного бинаря на одном хосте это шум.
|
||
Если когда-нибудь поедем в несколько инстансов, добавим `service.version`
|
||
одной строкой при старте.
|
||
|
||
## Корреляция по download_id
|
||
|
||
Отдельный случайный `trace_id` не заводим — у загрузки уже есть стабильный
|
||
осмысленный ключ: `download_id` (и `infohash`), он лежит в SQLite.
|
||
|
||
- Заводим scoped-логгер на загрузку и протаскиваем его через
|
||
`context.Context` сквозь асинхронные стадии (приём → скачивание →
|
||
распознавание → раскладка), чтобы ключ дописывался на каждую запись сам:
|
||
|
||
```go
|
||
log := log.With("download_id", id, "infohash", ih)
|
||
ctx = logctx.With(ctx, log) // достаём логгер из ctx в каждой стадии
|
||
```
|
||
|
||
- Все записи одной загрузки собираются одним фильтром:
|
||
`jq 'select(.download_id=="a1b2")' app.jsonl`.
|
||
|
||
## Ошибки
|
||
|
||
Go-ошибки логируем как атрибут, не как текст сообщения.
|
||
|
||
```go
|
||
// Правильно: msg — категория, ошибка — поле
|
||
log.Error("layout failed", "error", err, "download_id", id)
|
||
|
||
// Неправильно: ошибка зашита в msg, агрегация по событию ломается
|
||
log.Error(err.Error())
|
||
```
|
||
|
||
Правила:
|
||
|
||
- Ошибку передаём полем `"error", err` — не склеиваем в `msg`. Ключ —
|
||
`error` (как по умолчанию в zap/zerolog; единый ключ важнее краткости).
|
||
- Идиома Go — **либо лог, либо возврат, не оба**. Промежуточные слои только
|
||
оборачивают и возвращают (`fmt.Errorf("…: %w", err)`), не логируя —
|
||
контекст накапливается в цепочке `%w`.
|
||
- Логируем ошибку **один раз — на границе доменного слоя** (use-case
|
||
`Ingest`, стадии воркера), которая определяет исход операции: полем
|
||
`error`, уровень `ERROR`. В Go логирует этот единый чокпоинт, а не каждый
|
||
транспорт — так транспорты остаются тонкими.
|
||
- Транспорты (HTTP/web/Telegram) переводят возвращённую ошибку в свой ответ
|
||
(статус, сообщение пользователю) и **не логируют** её повторно — иначе
|
||
один сбой даёт дубли.
|
||
- Телеметрия внешнего вызова (`ext.*`, см. ниже) — отдельная запись о
|
||
поведении зависимости, не дубль доменной ошибки.
|
||
- Глушить ошибку без лога — только с однострочным комментарием «почему».
|
||
|
||
## Внешние сервисы (обязательно логируем все вызовы)
|
||
|
||
**Каждый** вызов внешнего сервиса (qBittorrent, Jellyfin, LLM, TMDB/TVDB)
|
||
логируется. Поля:
|
||
|
||
- `ext.service` — `qbittorrent` / `jellyfin` / `llm` / `tmdb` / `tvdb`;
|
||
- `ext.operation` — логическая операция (`torrents/add`, `chat.completions`,
|
||
`search/movie`);
|
||
- `ext.status_code` — HTTP-код ответа (если применимо);
|
||
- `duration_ms` — длительность вызова;
|
||
- `retry` — номер попытки (если были ретраи).
|
||
|
||
Уровни вызова:
|
||
|
||
- `INFO` — успешный **событийный** вызов (по реальному действию: добавление
|
||
торрента, вызов LLM, рефреш Jellyfin, поиск в метабазе);
|
||
- `DEBUG` — успешный **рутинно-частый** вызов (поллинг статуса
|
||
`torrents/info`/`torrents/files`, авто-рефреш) — см. правило «событийное →
|
||
INFO, рутинно-частое → DEBUG» в разделе «Уровни»;
|
||
- `WARN` — попытка не удалась, делаем retry;
|
||
- `ERROR` — ретраи исчерпаны / сервис недоступен (сетевой сбой/таймаут).
|
||
Завершённый HTTP-ответ с 4xx — это успех на транспортном уровне (`Success`
|
||
с `ext.status_code`); решение «это ошибка» принимает доменный вызывающий.
|
||
|
||
Тело запроса/ответа — только на `DEBUG` и **после** вычистки секретов
|
||
(см. «Безопасность»).
|
||
|
||
## HTTP и healthcheck
|
||
|
||
- Входящие HTTP-запросы логируем с полями `http.method`, `http.route`,
|
||
`http.status_code`, `duration_ms`, `transport` (`http`/`web`/`telegram`).
|
||
- Для корреляции HTTP-запроса допустим `request_id` (напр. chi `RequestID`) —
|
||
это отдельный слой от корреляции загрузки по `download_id` и не противоречит
|
||
отказу от `trace_id`. Если запрос порождает загрузку — связь даёт
|
||
`download_id` в её записях.
|
||
- **Эндпоинты healthcheck/liveness/readiness логируем на `DEBUG`** — их
|
||
дёргают периодически, на `INFO` они забивают аудит шумом. В проде
|
||
(базовый уровень `INFO`) они не пишутся.
|
||
|
||
## Безопасность: что не логируем
|
||
|
||
Никаких секретов в полях и сообщениях. Под запретом:
|
||
|
||
- учётные данные qBittorrent (логин/пароль, cookie сессии);
|
||
- API-ключ и токен LLM-провайдера, `Authorization`-заголовки;
|
||
- ключи TMDB/TVDB и прочих метабаз;
|
||
- содержимое аутентификационных параметров magnet/трекеров.
|
||
|
||
Дополнительно:
|
||
|
||
- Тела запросов/ответов внешних API и сырой вывод LLM (недоверенный, может
|
||
быть большим) — только на `DEBUG`, с вычисткой секретов и обрезкой по длине.
|
||
- При сомнении — не логируем значение, логируем факт его наличия
|
||
(`"has_api_key", true`).
|
||
|
||
## Куда пишем и уровень
|
||
|
||
- Пишем JSON в `stdout` одним потоком; сбор и ротацию делает окружение
|
||
(docker/journald). Не маршрутизируем по файлам.
|
||
- Базовый уровень в проде — `INFO`; `DEBUG` включается через конфиг/env при
|
||
необходимости. dev — `DEBUG`.
|
||
|
||
## Анализ
|
||
|
||
- Повседневно — `jq` (`jq 'select(.download_id=="a1b2")' app.jsonl`).
|
||
- Тяжёлое (агрегации, JOIN) — DuckDB поверх JSONL прямо из файла.
|