jellybit/docs/conventions/logging.md

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

Конвенция: *как* и *когда* писать логи в 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":"01jz2k7f8q9r3s4t5v6w7x8y9z","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`), не в текст.
- **Смена состояния загрузки — единая категория `state transition`** с полями
  `from`/`to`/`code` (какое именно состояние и по какой причине — это данные,
  не текст). Любой переход (в т.ч. `cancel`/`retry`/`relink`) пишет этот
  `msg`, чтобы весь жизненный цикл собирался одним фильтром: `jq
  'select(.msg=="state transition" and .download_id=="…")'`. Физический эффект
  сверх перехода — отдельная запись своей категории (`layout linked`,
  `layout reverted`, `review hint added`), не подменяет запись перехода.

## Уровни

Принцип: уровень — это **адресат** («кому сообщение»), а не «насколько
громко сломалось». `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`
одной строкой при старте.

## Корреляция по id сущности

Отдельный случайный `trace_id` не заводим — у сущностей уже есть стабильные
осмысленные ключи: ULID-идентификаторы (`download_id`, `recognition_id`,
`batch_id`, см. [database.md](database.md)), они лежат в SQLite.

- Каждая запись, относящаяся к сущности, несёт её id в поле `<entity>_id`.
  Для загрузки — scoped-логгер, протаскиваемый через `context.Context`
  сквозь асинхронные стадии (приём → скачивание → распознавание →
  раскладка), чтобы ключ дописывался на каждую запись сам:

```go
log := log.With("download_id", id, "infohash", ih)
ctx = logctx.With(ctx, log) // достаём логгер из ctx в каждой стадии
```

- Все записи одной загрузки собираются одним фильтром:
  `jq 'select(.download_id=="01jz2k7f8q9r3s4t5v6w7x8y9z")' app.jsonl`.
- ULID глобально уникален across сущностей, поэтому штатно работает и
  простой grep по голому id — он находит все упоминания сущности независимо
  от имени поля: `grep 01jz2k7f8q9r3s4t5v6w7x8y9z 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`.
- Логируем ошибку **один раз — на границе доменного слоя**, которая
  определяет исход операции: полем `error`. В Go логирует этот единый
  чокпоинт, а не каждый транспорт — так транспорты остаются тонкими. Границы
  в jellybit:
  - use-case `Ingest` (приём);
  - **асинхронные стадии воркера** (поллинг, распознавание, авто-раскладка) —
    исход стадии, вызванной таймером/циклом;
  - **публичные команды воркера** (`Apply`/`Refine`/`Cancel`/`Retry`/`Undo`/
    `Delete`/…), вызываемые транспортами. Исход команды логирует ровно один
    чокпоинт (`worker.logCmd`, в `defer` при именованном возврате), а не
    HTTP/web/Telegram — они одну и ту же команду зовут из трёх мест.
- Транспорты (HTTP/web/Telegram) переводят возвращённую ошибку в свой ответ
  (статус, сообщение пользователю) и **не логируют** её повторно — иначе
  один сбой даёт дубли.
- **Уровень доменного отказа — по адресату, а не по месту.** У каждой
  доменной ошибки ровно один логирующий; уровень выбирает он. На **границе
  команды** (пользователь инициировал действие и ждёт ответа — `worker.logCmd`):

  | Класс отказа | Кому | Уровень |
  |---|---|---|
  | штатный конфликт состояния / некорректный ввод (`ErrConflict`, `ErrNotReady`, `ErrInvalidInput`, `ErrNotFound`, `layout.ErrCollision`) | пользователю (уже получил ответ на поверхности) | `DEBUG` |
  | нарушенный инвариант хранилища/учёта (не безопасность данных: файлы уже разложены) | команде, «может стать проблемой» | `WARN` |
  | сбой БД / ФС / недоступность зависимости | команде, в разбор | `ERROR` |

  Тот же класс отказа в **асинхронной стадии** (пользователь не ждёт: авто-
  раскладка, поллинг) адресован уже команде как деградация автоматики — уровень
  поднимается. Пример: `layout.ErrCollision` в ручном `Apply` — `DEBUG` (человек
  видит причину в карточке), а в авто-раскладке — `WARN` («auto-apply failed,
  left for review»): автоматика не довела задачу, это «может стать проблемой».

- **Повторяющийся сбой фонового цикла (поллинг/сверка) — `WARN`, не `ERROR`.**
  Одиночный промах тика (`poll`/`sweep`/`list failed`, недоступный
  qBittorrent) транзиентен: следующий тик повторит. Тот же класс сбоя внутри
  синхронной операции (`ingest.Ingest`) — `ERROR`, потому что операция
  провалилась целиком и повтора нет. То есть уровень задаёт не текст ошибки, а
  наличие штатного ретрая: тик повторится → `WARN`, разовая операция упала →
  `ERROR`. (Устойчивый сбой N тиков подряд эскалировать в `ERROR` — на будущее,
  сейчас не реализовано.)
- Телеметрия внешнего вызова (`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`).
- **Ошибка HTTP-транспорта несёт URL — потенциальный носитель секрета.**
  `*url.Error` (стандартный `net/http`) встраивает полный URL запроса, а
  секрет может жить прямо в нём: токен Telegram в пути (`…/bot<TOKEN>/…`),
  `api_key` метабазы в query. Санитизируем на границе клиента **до** лога и
  обёртки — `logging.SanitizeErr(err)` разворачивает `*url.Error` в
  первопричину (URL отбрасывается, `errors.Is` на причину сохраняется).
  Применяется в `ext.*`-обёртке (`ExtCall`), клиентах metadata и tgbot. Общее
  правило: **секрет не кладём в URL, если у API есть заголовок** — тогда его
  нет и в ошибке транспорта.

## Куда пишем и уровень

- Пишем JSON в `stdout` одним потоком; сбор и ротацию делает окружение
  (docker/journald). Не маршрутизируем по файлам.
- Базовый уровень в проде — `INFO`; `DEBUG` включается через конфиг/env при
  необходимости. dev — `DEBUG`.

## Анализ

- Повседневно — `jq` (`jq 'select(.download_id=="a1b2")' app.jsonl`).
- Тяжёлое (агрегации, JOIN) — DuckDB поверх JSONL прямо из файла.