av
903941f587
- CLAUDE.md, «Язык»: ссылаться можно на конкретную запись или на весь корпус разом, но не на их количество — число протухает молча, машина его не считает. Изъятие названо: неизменное число и историческое в записи о прошлом остаются. - Сняты счёты capability, прогонов ревью, типизированных ошибок, воркеров, сверок документов и правил линтера в docs/, спеке pipeline и CLAUDE.md. - Заодно исправлено то, что этот же счёт и скрывал: типизированных ошибок три, а не две — LostAcquisitionError был потерян из перечня.
282 lines
21 KiB
Markdown
282 lines
21 KiB
Markdown
# Логирование
|
||
|
||
Конвенция: *как* и *когда* писать логи в 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` и
|
||
тут же возвращает её воркеру, который логирует её второй раз. Один сбой даёт две
|
||
записи.
|
||
|
||
## Внешние сервисы: логируем все вызовы
|
||
|
||
**Каждый** вызов внешнего сервиса логируется. Поля:
|
||
|
||
- `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 прямо из файла.
|