transcriber/docs/conventions/logging.md

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

Конвенция: *как* и *когда* писать логи в transcriber. Это правила оформления
кода (How), а не спецификация поведения — наблюдаемые требования к логам (что
система обязана залогировать как часть контракта capability) живут в спеках
OpenSpec.

**Взято из проекта jellybit.** Расхождения с сегодняшним кодом названы по месту.
Главные: обработчик текстовый, а не JSON; уровень зашит `INFO` и не
настраивается; `msg` — предложение с заглавной буквы, а не константная
категория; шаг конвейера логирует и себя, и свой исход, и при этом возвращает
ошибку выше, где её логируют снова.

**Механизировано:** форма вызова — `sloglint`: только пары
«ключ-значение», `msg` константой, **атрибуты (`slog.String` и прочие) не
употребляются вовсе**. Запрет `fmt.Print*` и встроенных `print`/`println` —
`forbidigo`; вывод в stdout через `fmt.Fprintln(os.Stdout, …)` правилом не
ловится и остаётся прозой этой записи. Прозой остаются также уровень по адресату,
единая логирующая точка и словарь имён полей: оракула у них нет. Адреса —
[go-linters.md](go-linters.md), «Механизировано».

## Принципы

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

```json
{"time":"2026-08-10T11:23:45.123456Z","level":"INFO","msg":"job accepted","capability":"intake","job_id":"…","source":"telegram","duration_seconds":137}
```

*Расхождение:* `main.go` ставит `slog.NewTextHandler(os.Stdout, …)`.

## Сообщение

- `msg` — короткая константа в нижнем регистре: `job accepted`,
  `recognition done`, `conversion failed`. Данные — в атрибутах:
  `log.Info("job accepted", "job_id", id, "source", "telegram")`.
- `msg` — чистая категория без префикса подсистемы: `recognition done`, а не
  `recognize: done`. Подсистему выносим в поле `capability`, не в текст.
- **Смена состояния задачи — единая категория `state transition`** с полями
  `from`, `to` и причиной. Любой переход пишет этот `msg`, чтобы весь
  жизненный цикл собирался одним отбором:
  `jq 'select(.msg=="state transition" and .job_id=="…")'`. Физический эффект
  сверх перехода — отдельная запись своей категории (`file converted`,
  `text delivered`), она запись перехода не подменяет.

*Расхождение:* сегодня `msg` — предложение вида `Starting conversion job`,
поля `capability` нет, отдельной категории перехода нет.

## Уровни

Принцип: уровень — это **адресат** («кому сообщение»), а не «насколько громко
сломалось». `slog` даёт четыре уровня; их и используем.

| Уровень | Кому и когда | Примеры в transcriber |
| --- | --- | --- |
| `DEBUG` | разработчику при отладке; в продакшене выключен | `GET /health`, пустой прогон воркера, проверка готовности операции распознавания, тела запросов и ответов внешних сервисов |
| `INFO` | владельцу, разбор постфактум | приём записи, переход задачи, конвертация выполнена, текст отправлен, старт и остановка процессов, **событийный вызов внешнего сервиса** |
| `WARN` | владельцу, «может стать проблемой» | повтор внешнего вызова, задача досталась повторно по истечении захвата, пустой текст распознавания |
| `ERROR` | владельцу, в разбор | внешний сервис недоступен, задача ушла в `failed`, необработанная ошибка |

Правила:

- Уровень **не зависит от capability**: `ERROR` в приёме и в распознавании
  одинаково серьёзны.
- `WARN` не значит «ничего страшного». `WARN` значит «может стать проблемой».
  Если это не «может» — это `INFO`.
- Меняется адресат — меняется уровень. Негодный ввод от пользователя — это
  `DEBUG` (норма, владельцу разбирать нечего), а не `ERROR`.
- **Событийное — `INFO`, рутинно-частое — `DEBUG`.** Операция по реальному
  действию (приём записи, запуск распознавания, отправка текста) идёт на `INFO`.
  Повторяющаяся служебная операция, которую запускает таймер или опрос и которая
  сама по себе события не несёт (проверка здоровья, пустой прогон воркера,
  опрос готовности операции), — на `DEBUG`: на `INFO` она зашумляет разбор.
- `slog` не разделяет CRITICAL и FATAL — сбой на старте логируем `ERROR` и
  завершаем процесс с ненулевым кодом.

*Расхождение:* уровень зашит константой в `main.go`, `DEBUG` включить нечем.
Пустой прогон воркера не логируется вовсе — и это правилу не противоречит.

## Время

- Поле — `time` (ключ `slog` по умолчанию).
- UTC, RFC 3339 с долями секунды, суффикс `Z`.
- Логи — **в UTC**, как и хранение в БД: это даёт однозначный порядок событий и
  лексикографическую сортировку. Часовой пояс есть только у **отображения**.

## Поля: словарь имён

Главное условие — **единый словарь**: одно поле, одно имя по всему коду.

- Доменные поля — плоский `snake_case`.
- Системные домены — точечная иерархия (по образцу OpenTelemetry): `http.*`,
  `ext.*`.
- JSON плоский: все поля на верхнем уровне, без вложенности.

| Когда добавляем | Поля |
| --- | --- |
| на входящий HTTP-запрос | `transport` (`http`, `telegram`), `http.method`, `http.route`, `http.status_code`, `duration_ms` |
| на задачу | `capability` (значения — по именам заведённых capability в `openspec/specs/`), `job_id`, `file_id`, `source` |
| на запись об ошибке | `error` |
| на вызов внешнего сервиса | `ext.service`, `ext.operation`, `ext.status_code`, `duration_ms`, `retry` |

Не заводим `service.*` и `host.*` — для одного бинарника на одном хосте это шум.

*Расхождение:* в коде встречаются `job_id`, `file_id`, `operation_id`,
`worker`, `path`, `src_path`, `dest_path` — то есть словарь сложился сам и
пересечён с этим лишь частично.

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

Отдельный случайный `trace_id` не заводим — у сущностей уже есть стабильные
осмысленные ключи: идентификаторы задачи и файла, они лежат в базе.

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

```go
log := log.With("job_id", job.Id, "capability", "conversion")
```

- Все записи одной задачи собираются одним отбором:
  `jq 'select(.job_id=="…")' app.jsonl`.

## Ошибки

Ошибки Go логируем как атрибут, а не как текст сообщения:
`log.Error("conversion failed", "error", err, "job_id", id)`. Ключ — `error`.

- Идиома Go — **либо лог, либо возврат, не оба**. Промежуточные слои только
  оборачивают и возвращают (`fmt.Errorf("…: %w", err)`), не логируя — контекст
  накапливается в цепочке `%w`.
- Логируем ошибку **один раз — на границе доменного слоя**, которая определяет
  исход операции. Логирует эта единая точка, а не каждый транспорт — так
  транспорты остаются тонкими. Границы в transcriber:
  - приём записи (`CreateJobFromTelegram`, `CreateJobFromApi`);
  - **шаг конвейера** (`FindAndRunConversionJob`, `FindAndRunTranscribeJob`,
    `FindAndRunTranscribeCheckJob`) — исход шага, вызванного циклом воркера;
  - завершение и отказ задачи (`completeJob`, `failJob`).
- Транспорты переводят возвращённую ошибку в свой ответ и **не логируют** её
  повторно — иначе один сбой даёт дубли.
- **Уровень доменного отказа — по адресату, а не по месту.** У каждой доменной
  ошибки ровно один логирующий; уровень выбирает он.

  | Класс отказа | Кому | Уровень |
  | --- | --- | --- |
  | негодный ввод, задача не найдена, действие сейчас недопустимо | пользователю (он уже получил ответ на поверхности) | `DEBUG` |
  | запись распознана пустой, задача досталась повторно | владельцу, «может стать проблемой» | `WARN` |
  | сбой БД, диска, недоступность внешнего сервиса | владельцу, в разбор | `ERROR` |

- **Повторяющийся сбой фонового цикла — `WARN`, а не `ERROR`.** Одиночный
  промах шага временный: задача останется в своём состоянии, и следующий тик
  повторит. Тот же класс сбоя в синхронной операции приёма — `ERROR`, потому что
  операция провалилась целиком и повтора нет. Уровень задаёт не текст ошибки, а
  наличие штатного повтора.
- Телеметрия внешнего вызова (`ext.*`, см. ниже) — отдельная запись о поведении
  зависимости, а не дубль доменной ошибки.
- Глушить ошибку без лога — только с однострочным комментарием «почему».

*Расхождение, и оно системное:* сегодня шаг конвейера логирует ошибку `Error` и
тут же возвращает её воркеру, который логирует её второй раз. Один сбой даёт две
записи. Плюс `internal/controller/http/transcribe.go` пишет через `log.Printf`
мимо `slog` целиком.

## Внешние сервисы: логируем все вызовы

**Каждый** вызов внешнего сервиса логируется. Поля:

- `ext.service` — `telegram`, `speechkit`, `object-storage`, `ffmpeg`;
- `ext.operation` — логическая операция (`getFile`, `sendMessage`,
  `RecognizeFile`, `GetOperation`, `PutObject`, `convert`);
- `ext.status_code` — код ответа, если применим;
- `duration_ms` — длительность вызова;
- `retry` — номер попытки, если повторы были.

Уровни вызова:

- `INFO` — успешный **событийный** вызов (заливка объекта, запуск распознавания,
  отправка сообщения, конвертация);
- `DEBUG` — успешный **рутинно-частый** вызов (опрос готовности операции,
  длинный опрос обновлений);
- `WARN` — попытка не удалась, делаем повтор;
- `ERROR` — повторы исчерпаны либо сервис недоступен. Завершённый ответ с 4xx —
  это успех на транспортном уровне; решение «это ошибка» принимает доменный
  вызывающий.

Тело запроса и ответа — только на `DEBUG` и **после** вычистки секретов.

*Расхождение:* обёртки `ext.*` нет. Из внешних вызовов логируется только
конвертация (через метрику длительности) и запуск распознавания; заливка в
Object Storage, скачивание файла из Telegram и опрос операции не логируются
никак.

## HTTP и проверка здоровья

- Входящие HTTP-запросы логируем с полями `http.method`, `http.route`,
  `http.status_code`, `duration_ms`, `transport`.
- **Поле, которое уже даёт логгер с подставленным ключом, руками не
  доклеиваем.** Иначе в JSON получается дублирующийся ключ, и строгий
  потребитель молча оставит одно из значений. Правило проверяется чтением,
  линтером не выражается.
- **`GET /health` и `GET /metrics` логируем на `DEBUG`** — их дёргают
  периодически, на `INFO` они забивают разбор шумом. В продакшене при базовом
  `INFO` они не пишутся.

Расхождения здесь больше нет: слой журналирования запросов свой,
`main.go`, хук `OnServe` — вместе с gin ушёл и `sloggin`. `/health` и `/metrics`
идут на `DEBUG`, то есть при боевом `INFO` не пишутся вовсе.

Хранилище ведёт **свой** журнал запросов в собственной таблице, и он виден
владельцу в панели. Заменой потоку процесса он не служит: в журнал контейнера,
по которому разбирают отказы, эта таблица не попадает.

## Безопасность: что не логируем

Никаких секретов в полях и сообщениях. Под запретом:

- токен бота Telegram;
- ключ SpeechKit и заголовок `Authorization`;
- пара ключей Object Storage;
- **сам текст расшифровки и имена файлов пользователя** — это содержимое личной
  переписки. Логируем длину текста, а не текст. Имя файла ничем не заменяем:
  ни укороченным именем, ни отпечатком от него — отпечаток та же приватная
  величина, а корреляцию держат идентификаторы сущностей. Чем при этом
  прослеживается приём, нормирует спека `intake`, а не эта запись.

Дополнительно:

- Тела запросов и ответов внешних сервисов — только на `DEBUG`, с вычисткой
  секретов и обрезкой по длине.
- При сомнении не логируем значение, логируем факт его наличия
  (`"has_api_key", true`).
- **Ошибка HTTP-транспорта несёт URL — возможный носитель секрета.**
  `*url.Error` из `net/http` встраивает полный URL запроса, а токен Telegram
  живёт прямо в пути (`…/bot<TOKEN>/…`). Такую ошибку разворачивают в
  первопричину на границе клиента **до** лога и до обёртки: URL отбрасывается,
  проверка `errors.Is` на причину сохраняется. Общее правило: **секрет не кладём
  в URL, если у сервиса есть заголовок** — тогда его нет и в ошибке транспорта.

Разговор с Telegram этому правилу следует, и точка чистки одна на все вызовы —
`internal/adapter/telegram`, `NewBot`. Токен стоит в пути **каждого** обращения к
Bot API, поэтому чистка на месте употребления закрывала бы один вызов из пяти:

- отказ транспорта разворачивает в первопричину клиент бота (`safeClient`), а
  библиотека отдаёт наш отказ вызывающему нетронутым — этим закрыты `getFile`,
  `sendMessage`, скачивание записи и `getMe` из конструктора;
- длинный опрос печатает свои отказы **пакетным логгером самой библиотеки**,
  минуя наш `slog`; логгер подменён на вычищающий (`tgbotapi.SetLogger`), и
  замена точная — токен известен.

Прежде здесь стоял `http.Get(file.Link(token))`, отказ уезжал в журнал вместе с
токеном, а конвенция числила это расхождением с оценкой «не логируется», которая
была неверной. Запись — [../review.md](../review.md), 2026-08-13; оракулом
служат проверки `internal/adapter/telegram/bot_test.go`, судящие по тексту
отказа и строке журнала.

*Изъятие, а не расхождение:* расширение берётся из имени отправителя дословно
(`filepath.Ext`), поэтому имя `запись.тайное-слово` отдаёт приватный хвост
расширением. В журнал оно идёт **собственным полем** строки приёма — это
объявленное изъятие инварианта приватности ([CLAUDE.md](../../CLAUDE.md),
«Инварианты»); ни имени файла в хранилище, ни пути к нему в журнале нет вовсе
(норма — `openspec/specs/intake`). Наружу — в метку метрики — хвост не выходит:
там расширение приводится к перечню известных форматов. Остаток описан в
[../security.md](../security.md).

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

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

*Расхождение:* поля конфигурации под уровень лога нет.

## Анализ

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