Канон документов, каталог задач и OpenSpec
docs/ по канону 12: паспорт с целью проекта, архитектура сегодняшнего устройства, схема хранилища, модель угроз, конвенции кода, журнал ревью. Конвенции перенесены из jellybit; места, где код им не следует, помечены строкой «Расхождение» как объявленный долг. tasks/ с роадмапом: две достигнутые цели, две запланированные (веб и многопользовательский режим), два направления (все форматы, долгие записи) и пять задач в беклоге. openspec/config.yaml — маршрутизатор с адресами документов, спек пока нет. CLAUDE.md переписан по форме канона: инварианты с severity, семантика гейта, запреты с путями. Taskfile получил task gate.
This commit is contained in:
@@ -0,0 +1,248 @@
|
||||
# Логирование
|
||||
|
||||
Конвенция: *как* и *когда* писать логи в transcriber. Это правила оформления
|
||||
кода (How), а не спецификация поведения — наблюдаемые требования к логам (что
|
||||
система обязана залогировать как часть контракта capability) живут в спеках
|
||||
OpenSpec.
|
||||
|
||||
**Взято из проекта jellybit.** Расхождения с сегодняшним кодом названы по месту.
|
||||
Главные: обработчик текстовый, а не JSON; уровень зашит `INFO` и не
|
||||
настраивается; `msg` — предложение с заглавной буквы, а не константная
|
||||
категория; шаг конвейера логирует и себя, и свой исход, и при этом возвращает
|
||||
ошибку выше, где её логируют снова.
|
||||
|
||||
**Механизировано:** ничего. Ни `sloglint`, ни `forbidigo` в `.golangci.yml` не
|
||||
включены, поэтому правилами не выражено ни одно из перечисленного ниже.
|
||||
|
||||
## Принципы
|
||||
|
||||
- Структурированный 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` они не пишутся.
|
||||
|
||||
*Расхождение:* `sloggin` пишет все запросы одинаково, `/health` и `/metrics`
|
||||
попадают в лог наравне с остальными.
|
||||
|
||||
## Безопасность: что не логируем
|
||||
|
||||
Никаких секретов в полях и сообщениях. Под запретом:
|
||||
|
||||
- токен бота Telegram;
|
||||
- ключ SpeechKit и заголовок `Authorization`;
|
||||
- пара ключей Object Storage;
|
||||
- **сам текст расшифровки и имена файлов пользователя** — это содержимое личной
|
||||
переписки. Логируем длину текста, а не текст.
|
||||
|
||||
Дополнительно:
|
||||
|
||||
- Тела запросов и ответов внешних сервисов — только на `DEBUG`, с вычисткой
|
||||
секретов и обрезкой по длине.
|
||||
- При сомнении не логируем значение, логируем факт его наличия
|
||||
(`"has_api_key", true`).
|
||||
- **Ошибка HTTP-транспорта несёт URL — возможный носитель секрета.**
|
||||
`*url.Error` из `net/http` встраивает полный URL запроса, а токен Telegram
|
||||
живёт прямо в пути (`…/bot<TOKEN>/…`). Такую ошибку разворачивают в
|
||||
первопричину на границе клиента **до** лога и до обёртки: URL отбрасывается,
|
||||
проверка `errors.Is` на причину сохраняется. Общее правило: **секрет не кладём
|
||||
в URL, если у сервиса есть заголовок** — тогда его нет и в ошибке транспорта.
|
||||
|
||||
*Расхождение:* вычистки нет. Скачивание файла из Telegram идёт обычным
|
||||
`http.Get(file.Link(token))`, и ошибка этого вызова содержит токен бота. Сегодня
|
||||
она не логируется — то есть утечки нет, но защищает от неё только отсутствие
|
||||
строки лога.
|
||||
|
||||
## Куда пишем и уровень
|
||||
|
||||
- Пишем JSON в `stdout` одним потоком; сбор и ротацию делает окружение. Не
|
||||
раскладываем по файлам.
|
||||
- Базовый уровень в продакшене — `INFO`; `DEBUG` включается конфигом при
|
||||
необходимости. При разработке — `DEBUG`.
|
||||
|
||||
*Расхождение:* поля конфигурации под уровень лога нет.
|
||||
|
||||
## Анализ
|
||||
|
||||
- Повседневно — `jq`: `jq 'select(.job_id=="…")' app.jsonl`.
|
||||
- Тяжёлое (сведение, соединение) — DuckDB поверх JSONL прямо из файла.
|
||||
Reference in New Issue
Block a user