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, «Механизировано».

Принципы

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

{"time":"2026-08-10T11:23:45.123456Z","level":"INFO","msg":"record accepted","capability":"intake","record_id":"…","source":"api","duration_seconds":137}

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

Сообщение

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

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

Уровни

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

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

Правила:

• Уровень не зависит от 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), http.method, http.route, http.status_code, duration_ms
на задачу	capability (значения — по именам заведённых capability в openspec/specs/), record_id, file_id, source
на запись об ошибке	error
на вызов внешнего сервиса	ext.service, ext.operation, ext.status_code, duration_ms, retry

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

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

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

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

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

log := log.With("record_id", record.Id, "capability", "conversion")

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

Ошибки

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

• Идиома Go — либо лог, либо возврат, не оба. Промежуточные слои только оборачивают и возвращают (fmt.Errorf("…: %w", err)), не логируя — контекст накапливается в цепочке %w.

• Логируем ошибку один раз — на границе доменного слоя, которая определяет исход операции. Логирует эта единая точка, а не каждый транспорт — так транспорты остаются тонкими. Границы в transcriber:

  • приём записи (CreateJobFromApi);
  • шаг конвейера (FindAndRunConversionJob, FindAndRunTranscribeJob, FindAndRunTranscribeCheckJob) — исход шага, вызванного циклом воркера;
  • завершение и отказ задачи (completeJob, failJob).

• Транспорты переводят возвращённую ошибку в свой ответ и не логируют её повторно — иначе один сбой даёт дубли.

• Уровень доменного отказа — по адресату, а не по месту. У каждой доменной ошибки ровно один логирующий; уровень выбирает он.

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

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

• Телеметрия внешнего вызова (ext.*, см. ниже) — отдельная запись о поведении зависимости, а не дубль доменной ошибки.

• Глушить ошибку без лога — только с однострочным комментарием «почему».

Расхождение, и оно системное: сегодня шаг конвейера логирует ошибку Error и тут же возвращает её воркеру, который логирует её второй раз. Один сбой даёт две записи.

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

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

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

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

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

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

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

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 не пишутся вовсе.

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

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

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

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

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

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

Живого случая у этого правила сейчас нет: единственный секрет, стоявший в пути обращения, — токен бота, и он ушёл вместе с входом Telegram 2026-08-14. Разбор случая и цена промаха записаны в ../review.md, 2026-08-13: конвенция числила утечку расхождением с оценкой «не логируется», и оценка была неверной.

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

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

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

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

Анализ

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