Добавил конвенции для логирования
This commit is contained in:
@@ -0,0 +1,185 @@
|
||||
# Логирование
|
||||
|
||||
Конвенция: *как* и *когда* писать логи в 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))
|
||||
```
|
||||
|
||||
## Уровни
|
||||
|
||||
Принцип: уровень — это **адресат** («кому сообщение»), а не «насколько
|
||||
громко сломалось». `slog` даёт четыре уровня; их и используем.
|
||||
|
||||
| Уровень | Кому и когда | Примеры в jellybit |
|
||||
|---|---|---|
|
||||
| `DEBUG` | разработчику при отладке; в проде выключен | healthcheck-эндпоинты, тела запросов/ответов внешних API, промежуточные шаги распознавания |
|
||||
| `INFO` | команде, аудит постфактум | приём загрузки, распознан фильм/сериал, раскладка выполнена, старт процессов, **каждый вызов внешнего сервиса** (старт/успех) |
|
||||
| `WARN` | команде, «может стать проблемой» | retry внешнего вызова, низкая уверенность распознавания (ушло в ревью), приближение к лимиту |
|
||||
| `ERROR` | команде, в техдолг / разбор | внешний сервис недоступен после ретраев, операция загрузки не выполнена, необработанная ошибка |
|
||||
|
||||
Правила:
|
||||
|
||||
- Уровень **не зависит от capability** — `ERROR` в `ingest` и в
|
||||
`file-layout` одинаково серьёзны.
|
||||
- `WARN` ≠ «ничего страшного». `WARN` = «может стать проблемой». Если это
|
||||
не «может» — это `INFO`.
|
||||
- Меняется адресат — меняется уровень. Невалидный ввод от пользователя —
|
||||
это `DEBUG` (норма, команде разбирать нечего), а не `ERROR`.
|
||||
- `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`.
|
||||
- В коде оборачиваем с контекстом (`fmt.Errorf("…: %w", err)`); логируем
|
||||
развёрнутую ошибку один раз — в точке, где решено «дальше не пробрасываем».
|
||||
- **Не** логировать одну ошибку дважды по цепочке: либо логируешь и гасишь,
|
||||
либо оборачиваешь и пробрасываешь — не оба сразу.
|
||||
- Глушить ошибку без лога — только с однострочным комментарием «почему».
|
||||
|
||||
## Внешние сервисы (обязательно логируем все вызовы)
|
||||
|
||||
**Каждый** вызов внешнего сервиса (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` — старт и успешный результат (трафик низкий, шум допустим);
|
||||
- `WARN` — попытка не удалась, делаем retry;
|
||||
- `ERROR` — ретраи исчерпаны / сервис недоступен.
|
||||
|
||||
Тело запроса/ответа — только на `DEBUG` и **после** вычистки секретов
|
||||
(см. «Безопасность»).
|
||||
|
||||
## HTTP и healthcheck
|
||||
|
||||
- Входящие HTTP-запросы логируем с полями `http.method`, `http.route`,
|
||||
`http.status_code`, `duration_ms`.
|
||||
- **Эндпоинты 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 прямо из файла.
|
||||
Reference in New Issue
Block a user