- 13 конвенций по осям arch / lang / stack / common; репозитории берут оттуда копии в свой docs/conventions/ и коммитят их у себя - conv — синхронизация копий: add / status / diff / pull / push, локальные регионы исключены из сравнения, поэтому расхождение не даёт шума
243 lines
16 KiB
Markdown
243 lines
16 KiB
Markdown
---
|
||
status: рекомендуемая
|
||
extends: arch/time.md
|
||
---
|
||
|
||
# Логирование
|
||
|
||
Как и когда писать логи. Это правила оформления кода (How), а не
|
||
спецификация поведения: наблюдаемые требования к логам, входящие в контракт
|
||
функциональности, живут в спеках.
|
||
|
||
## Принципы
|
||
|
||
- Структурированный JSON (`slog.JSONHandler`), **один формат для dev и
|
||
prod**. Не потому, что текстовый вывод «расходит поля» — смена хендлера
|
||
структуру атрибутов не меняет; а потому, что с текстовым dev-выводом
|
||
перестаёшь ежедневно гонять собственные `jq`-пайплайны, и поломки
|
||
словаря замечаются только в проде.
|
||
- Сообщение (`msg`) — категория события; данные — в полях. Каждое поле —
|
||
отдельный ключ с типизированным значением: это даёт фильтрацию и
|
||
агрегацию через `jq`/DuckDB без регулярок.
|
||
|
||
```json
|
||
{"time":"2026-06-28T11:23:45.123Z","level":"INFO","msg":"download accepted","download_id":"01jz2k7f8q9r3s4t5v6w7x8y9z","media_type":"movie"}
|
||
```
|
||
|
||
## Время в записи
|
||
|
||
Поле `time` ставит `slog`, но **UTC он по умолчанию не даёт**: встроенные
|
||
хендлеры пишут время в зоне самого `time.Time`, то есть в локальной зоне
|
||
процесса. UTC ставится `ReplaceAttr` по `slog.TimeKey` — см.
|
||
`lang/go/time.md`. Точность `JSONHandler` — миллисекунды, фиксированная
|
||
ширина; это другая точность, чем в БД, и по `arch/time.md` так и должно
|
||
быть: ширина фиксируется на носитель.
|
||
|
||
## Сообщение
|
||
|
||
- `msg` — короткая **константа** в нижнем регистре: `download accepted`,
|
||
`recognition done`, `layout failed`. Данные — в атрибутах:
|
||
`log.Info("download accepted", "download_id", id)`.
|
||
- `msg` — чистая категория **без неймспейс-префикса**: `recognition done`,
|
||
а не `recognize: done`. Подсистема — отдельное поле, не текст.
|
||
- **Смена состояния сущности — единая категория** (`state transition`) с
|
||
полями `from`/`to`/`code`. Какое именно состояние и по какой причине —
|
||
это данные, а не текст. Тогда весь жизненный цикл собирается одним
|
||
фильтром. Физический эффект сверх перехода — отдельная запись своей
|
||
категории, она не подменяет запись перехода.
|
||
|
||
## Уровни
|
||
|
||
Принцип: уровень — это **адресат** («кому сообщение»), а не «насколько
|
||
громко сломалось».
|
||
|
||
| Уровень | Кому и когда |
|
||
|---|---|
|
||
| `DEBUG` | разработчику при отладке; в проде выключен |
|
||
| `INFO` | владельцу, аудит постфактум |
|
||
| `WARN` | владельцу, «может стать проблемой» |
|
||
| `ERROR` | владельцу, в разбор |
|
||
|
||
Правила:
|
||
|
||
- Уровень **не зависит от подсистемы**: `ERROR` везде одинаково серьёзен.
|
||
- `WARN` ≠ «ничего страшного». `WARN` = «может стать проблемой». Если это
|
||
не «может» — это `INFO`.
|
||
- Меняется адресат — меняется уровень. Невалидный ввод от пользователя —
|
||
`DEBUG` (норма, разбирать нечего), а не `ERROR`.
|
||
- **Событийное → `INFO`, рутинно-частое → `DEBUG`.** Операция по реальному
|
||
действию или изменению — `INFO`. Повторяющаяся служебная операция,
|
||
запускаемая таймером или поллингом и сама по себе не несущая события
|
||
(healthcheck, опрос статуса, авто-рефреш UI), — `DEBUG`: на `INFO` она
|
||
зашумляет аудит.
|
||
- `slog` не разделяет CRITICAL/FATAL — фатальный сбой на старте логируем
|
||
`ERROR` и завершаем процесс с ненулевым кодом.
|
||
|
||
## Поля: единый словарь
|
||
|
||
Главное условие — **одно поле, одно имя по всему коду** (не
|
||
`mediaType`/`media`/`media_type` вперемешку).
|
||
|
||
- Бизнес-поля — плоский `snake_case`.
|
||
- Системные домены — точечная иерархия (адаптация OpenTelemetry): `http.*`,
|
||
`ext.*`.
|
||
- JSON плоский: все поля на верхнем уровне, без вложенности.
|
||
|
||
| Когда добавляем | Поля |
|
||
|---|---|
|
||
| входящий HTTP-запрос (middleware) | `http.method`, `http.route`, `http.status_code`, `duration_ms`, `transport` — если транспортов больше одного |
|
||
| работа с сущностью (scoped-логгер) | `<entity>_id` и доменные атрибуты |
|
||
| запись об ошибке | `error` |
|
||
| вызов внешнего сервиса | `ext.service`, `ext.operation`, `ext.status_code`, `duration_ms`, `retry` |
|
||
|
||
`service.*` и `host.*` не заводим — для одного бинаря на одном хосте это
|
||
шум. Если появятся несколько инстансов, добавим `service.version` одной
|
||
строкой при старте.
|
||
|
||
<!-- local:словарь -->
|
||
<!-- /local -->
|
||
|
||
## Корреляция по id сущности
|
||
|
||
Отдельный случайный `trace_id` не заводим, **если у сущностей есть
|
||
стабильные уникальные идентификаторы** — они и служат ключом корреляции.
|
||
(Как их выбирают — `arch/db-identifiers.md`, если конвенция взята.)
|
||
|
||
- Каждая запись, относящаяся к сущности, несёт её id в поле `<entity>_id`.
|
||
Для долгой операции — scoped-логгер, протаскиваемый через
|
||
`context.Context` сквозь асинхронные стадии, чтобы ключ дописывался сам:
|
||
|
||
```go
|
||
log := log.With("download_id", id)
|
||
ctx = logctx.With(ctx, log) // достаём логгер из ctx в каждой стадии
|
||
```
|
||
|
||
- Все записи одной операции собираются одним фильтром:
|
||
`jq 'select(.download_id=="01jz…")' app.jsonl`.
|
||
- Если id глобально уникален across сущностей, штатно работает и простой
|
||
`grep` по голому id — он находит все упоминания независимо от имени поля.
|
||
|
||
## Ошибки
|
||
|
||
Go-ошибки логируем **атрибутом**, не текстом сообщения:
|
||
`log.Error("layout failed", "error", err, "download_id", id)`. Ключ —
|
||
`error` (как по умолчанию в zap/zerolog: единый ключ важнее краткости).
|
||
|
||
- Идиома Go — **либо лог, либо возврат, не оба**. Промежуточные слои только
|
||
оборачивают и возвращают (`%w`), не логируя: контекст накапливается в
|
||
цепочке.
|
||
- Логируем ошибку **один раз — на границе доменного слоя**, которая
|
||
определяет исход операции. Логирует этот единый чокпоинт, а не каждый
|
||
транспорт: так транспорты остаются тонкими, и один сбой не даёт дублей.
|
||
|
||
<!-- local:границы -->
|
||
<!-- /local -->
|
||
|
||
- Транспорты переводят возвращённую ошибку в свой ответ (статус, сообщение
|
||
пользователю) и **не логируют** её повторно.
|
||
- **Уровень доменного отказа — по адресату, а не по месту.** У каждой
|
||
доменной ошибки ровно один логирующий; уровень выбирает он:
|
||
|
||
| Класс отказа | Кому | Уровень |
|
||
|---|---|---|
|
||
| штатный конфликт состояния или некорректный ввод | пользователю, он уже получил ответ | `DEBUG` |
|
||
| расхождение производного или учётного состояния, первичные данные целы | владельцу, «может стать проблемой» | `WARN` |
|
||
| сбой БД, ФС, недоступность зависимости | владельцу, в разбор | `ERROR` |
|
||
|
||
- Тот же класс отказа в **асинхронной стадии** (пользователь не ждёт)
|
||
адресован уже владельцу как деградация автоматики — уровень поднимается.
|
||
Коллизия в ручном действии — `DEBUG` (человек видит причину на экране), в
|
||
авто-обработке — `WARN` (автоматика не довела задачу).
|
||
- **Повторяющийся сбой фонового цикла — `WARN`, не `ERROR`.** Одиночный
|
||
промах тика транзиентен: следующий тик повторит. Тот же класс сбоя внутри
|
||
синхронной операции — `ERROR`, потому что операция провалилась целиком и
|
||
повтора нет. Уровень задаёт не текст ошибки, а **наличие штатного
|
||
повтора**.
|
||
|
||
## Два цикла повтора — не путать
|
||
|
||
Слово «ретрай» означает два разных механизма, и уровень считается по
|
||
каждому отдельно:
|
||
|
||
- **Повтор вызова внутри одной операции** (ретраи HTTP-клиента) — по нему
|
||
выбирается уровень **`ext`-записи**: `WARN` на попытку, `ERROR` когда
|
||
попытки исчерпаны.
|
||
- **Повтор тика внешним циклом** (поллинг, сверка) — по нему выбирается
|
||
уровень **доменной записи** об исходе тика: `WARN`, потому что следующий
|
||
тик повторит.
|
||
|
||
Из этого следует, что у лежащей зависимости `ext`-запись пишет `ERROR`
|
||
каждый тик. Это и есть механизм эскалации: доменный слой не паникует, а
|
||
телеметрия зависимости честно показывает, что она недоступна. Если поток
|
||
`ERROR` от поллинга мешает — это лечится понижением частоты тика или
|
||
подавлением повторов в самом клиенте, а не переклассификацией уровня.
|
||
|
||
## Внешние сервисы: логируем все вызовы
|
||
|
||
**Каждый** вызов внешнего сервиса логируется — это единственный способ
|
||
отличить «у нас баг» от «зависимость легла». Поля: `ext.service`,
|
||
`ext.operation` (логическая операция, не URL), `ext.status_code`,
|
||
`duration_ms`, `retry`.
|
||
|
||
Уровни:
|
||
|
||
- `INFO` — успешный **событийный** вызов;
|
||
- `DEBUG` — успешный **рутинно-частый** вызов (поллинг, авто-рефреш);
|
||
- `WARN` — попытка не удалась, делаем retry;
|
||
- `ERROR` — ретраи исчерпаны, сервис недоступен.
|
||
|
||
Завершённый HTTP-ответ с 4xx — это **успех на транспортном уровне**
|
||
(`ext.status_code` записан); решение «это ошибка» принимает доменный
|
||
вызывающий. Тело запроса и ответа — только на `DEBUG` и после вычистки
|
||
секретов.
|
||
|
||
## HTTP и healthcheck
|
||
|
||
- Входящие запросы логируем с `http.*` и `duration_ms` на **`INFO`**: это
|
||
аудит обращений, а не отладка. Уровень не понижается из-за кода ответа —
|
||
4xx остаётся `INFO`-записью доступа; решение «это ошибка» принимает
|
||
доменный слой и пишет свою запись.
|
||
- Для корреляции запроса допустим `request_id` — это отдельный слой от
|
||
корреляции по сущности и не противоречит отказу от `trace_id`.
|
||
- **Healthcheck, liveness, readiness — `DEBUG`.** Их дёргают периодически,
|
||
на `INFO` они забивают аудит; в проде с базовым `INFO` они не пишутся.
|
||
|
||
## Безопасность: что не логируем
|
||
|
||
Никаких секретов в полях и сообщениях: пароли и cookie сессий, API-ключи и
|
||
токены, `Authorization`-заголовки, аутентификационные параметры в ссылках.
|
||
|
||
- Тела ответов внешних API и сырой вывод LLM (недоверенный, может быть
|
||
большим) — только на `DEBUG`, с вычисткой и обрезкой по длине.
|
||
- При сомнении — не логируем значение, логируем факт его наличия
|
||
(`"has_api_key", true`).
|
||
- **Ошибка HTTP-транспорта несёт URL — потенциальный носитель секрета.**
|
||
`*url.Error` встраивает полный URL запроса, а секрет может жить прямо в
|
||
нём: токен в пути, `api_key` в query. Go редактирует только пароль из
|
||
userinfo, остального не трогает. Санитизируем на границе клиента **до**
|
||
лога и обёртки: разворачиваем `*url.Error` в первопричину. Цена —
|
||
теряется `Op` и сам факт «это был HTTP-транспорт» (`errors.Is` на причину
|
||
сохраняется); альтернатива с редактированием URL сохранила бы структуру,
|
||
но сложнее. Порядок важен: санитизация идёт **раньше** трансляции ошибки
|
||
в доменную (`lang/go/errors.md`), иначе секрет уедет в обёртку.
|
||
- Общее правило: **секрет не кладём в URL, если у API есть заголовок** —
|
||
тогда его нет и в ошибке транспорта.
|
||
|
||
<!-- local:секреты -->
|
||
<!-- /local -->
|
||
|
||
## Куда пишем
|
||
|
||
- JSON в `stdout` одним потоком; сбор и ротацию делает окружение (docker,
|
||
journald). По файлам не маршрутизируем.
|
||
- Базовый уровень в проде — `INFO`, `DEBUG` включается конфигом. dev —
|
||
`DEBUG`.
|
||
|
||
## Анализ
|
||
|
||
- Повседневно — `jq`: `jq 'select(.download_id=="a1b2")' app.jsonl`.
|
||
- Тяжёлое (агрегации, JOIN) — DuckDB поверх JSONL прямо из файла.
|
||
|
||
<!-- local:механизировано -->
|
||
<!-- /local -->
|