jellybit/docs/conventions/logging.md

Логирование

Конвенция: как и когда писать логи в jellybit. Это правила оформления кода (How), а не спецификация поведения — наблюдаемые требования к логам (что система ОБЯЗАНА залогировать как часть контракта capability) живут в OpenSpec-спеках (### Requirement с SHALL).

Краткая выжимка и инварианты — в CLAUDE.md, раздел «Конвенции кода».

Механизировано (.golangci.yml): slog вместо fmt.Print* — forbidigo; константный msg и стиль ключ-значение — sloglint. Ниже — только то, что правилом не выражается.

Принципы

• Структурированный JSON (slog.JSONHandler), один формат для dev и prod.
• Сообщение (msg) — категория события; данные — в полях. Каждое поле — отдельный ключ с типизированным значением: это даёт фильтрацию и агрегацию через jq/DuckDB без регулярок.

{"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. Данные — в атрибутах: log.Info("download accepted", "download_id", id, "media_type", "movie").
• 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), они лежат в SQLite.

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

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-ошибки логируем как атрибут, не как текст сообщения: log.Error("layout failed", "error", err, "download_id", id). Ключ — 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 прямо из файла.