остальные конвенции переведены на формальный язык

- 11 файлов разобраны на нумерованные правила: 220 правил в каноне, у
  каждого модальность и обязательный блок «Почему»
- классифицирующие места оформлены таблицами, файловый статус снят
  отовсюду, локальные регионы сохранены под прежними именами
This commit is contained in:
av
2026-07-25 19:17:32 +03:00
parent 7701a28df1
commit 31d0620f55
11 changed files with 2404 additions and 811 deletions
+465 -157
View File
@@ -1,5 +1,4 @@
---
status: рекомендуемая
extends: arch/time.md
---
@@ -7,164 +6,404 @@ extends: arch/time.md
Как и когда писать логи. Это правила оформления кода (How), а не
спецификация поведения: наблюдаемые требования к логам, входящие в контракт
функциональности, живут в спеках.
функциональности, живут в спеках. Форма записи — `common/language.md`.
## Принципы
- Структурированный JSON (`slog.JSONHandler`), **один формат для dev и
prod**. Не потому, что текстовый вывод «расходит поля» — смена хендлера
структуру атрибутов не меняет; а потому, что с текстовым dev-выводом
перестаёшь ежедневно гонять собственные `jq`-пайплайны, и поломки
словаря замечаются только в проде.
- Сообщение (`msg`) — категория события; данные — в полях. Каждое поле —
отдельный ключ с типизированным значением: это даёт фильтрацию и
агрегацию через `jq`/DuckDB без регулярок.
Лог читают инструментами, а не глазами: повседневно — `jq`
(`jq 'select(.download_id=="a1b2")' app.jsonl`), тяжёлое (агрегации, JOIN) —
DuckDB поверх JSONL прямо из файла. Отсюда почти все правила ниже: запись
существует для запроса к ней.
```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` так и должно
быть: ширина фиксируется на носитель.
### R1. Структурированный JSON, один формат для dev и prod
**ДОЛЖЕН.** Хендлер — `slog.JSONHandler`, одинаково в разработке и в
проде.
**Почему.** Довод не в том, что текстовый вывод «расходит поля»: смена
хендлера структуру атрибутов не меняет. Довод в читателе — с текстовым
dev-выводом перестаёшь ежедневно гонять собственные `jq`-пайплайны, и
поломки словаря (опечатка в имени поля, потерянный атрибут, склеенное
значение) обнаруживаются только в проде, где заметить их заранее уже
некому.
### R2. Данные — в типизированных полях, а не в тексте сообщения
**ДОЛЖЕН.** Каждая величина — отдельный ключ со значением своего типа.
**Почему.** Фильтрация и агрегация работают по ключам; величина, вклеенная
в текст, достаётся только регуляркой, а регулярка ломается при первой же
правке формулировки. Тип важен отдельно от ключа: число внутри строки не
сравнивается и не суммируется, то есть попадает в лог, но не в отчёт.
### R3. Время записи — UTC
**ДОЛЖЕН.** `time` приводится к UTC через `ReplaceAttr` по `slog.TimeKey`
(см. `lang/go/time.md`).
**Почему.** По умолчанию UTC не получится: встроенные хендлеры пишут время
в зоне самого `time.Time`, то есть в локальной зоне процесса. Записи одного
процесса до и после смены TZ (или записи рядом с данными из БД) перестают
складываться в одну хронологию, причём сдвиг на целые часы глазом не виден
— в отличие от явно неверной даты, он выглядит как правдоподобный порядок
событий.
Точность `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`. Какое именно состояние и по какой причине —
это данные, а не текст. Тогда весь жизненный цикл собирается одним
фильтром. Физический эффект сверх перехода — отдельная запись своей
категории, она не подменяет запись перехода.
### R4. `msg` — константа в нижнем регистре
**ДОЛЖЕН.** Текст сообщения не собирается из переменных:
`log.Info("download accepted", "download_id", id)`.
**Почему.** `msg` — то, по чему записи группируют и считают. Интерполяция
превращает одну категорию в множество уникальных строк, и вопрос «сколько
раз это случилось» перестаёт решаться группировкой. Нижний регистр — чтобы
одна категория не двоилась на варианты, различающиеся только заглавной
буквой.
### R5. `msg` не несёт префикса подсистемы
**НЕ ДОЛЖЕН.** `recognition done`, а не `recognize: done`; подсистема —
отдельное поле.
**Почему.** Префикс кладёт в текст ровно то, по чему потом фильтруют, и
фильтр по подсистеме становится сопоставлением с началом строки вместо
сравнения значения поля. Заодно это второй способ записать одно и то же:
категория дробится на варианты с префиксом и без, а совпадать они обязаны
посимвольно.
### R6. Смена состояния сущности — единая категория
**ДОЛЖЕН.** `state transition` с полями `from`/`to`/`code`; какое именно
состояние и по какой причине — данные, а не текст.
**Почему.** С отдельной категорией на каждый переход жизненный цикл
сущности собирается перечислением всех известных `msg` — и переход,
добавленный в код позже, в это перечисление не попадёт: выборка тихо
останется неполной. Единая категория даёт весь цикл одним фильтром и не
требует обновлять запрос вслед за кодом.
### R7. Физический эффект — отдельная запись, а не вместо перехода
**НЕ ДОЛЖЕН.** Запись о действии, сопровождающем переход, не подменяет
запись самого перехода.
**Почему.** Иначе из выборки по R6 выпадают именно те переходы, у которых
был заметный эффект, — то есть самые интересные. Вторая запись стоит одной
строки в логе; восстановление пропущенного перехода не стоит ничего, потому
что невозможно.
## Уровни
Принцип: уровень — это **адресат** («кому сообщение»), а не «насколько
### R8. Уровень выбирается по адресату
**ДОЛЖЕН.** Уровень отвечает на вопрос «кому сообщение», а не «насколько
громко сломалось».
| Уровень | Кому и когда |
|---|---|
| `DEBUG` | разработчику при отладке; в проде выключен |
| `INFO` | владельцу, аудит постфактум |
| `WARN` | владельцу, «может стать проблемой» |
| `ERROR` | владельцу, в разбор |
| № | Уровень | Кому и когда |
|---|---|---|
| R8.1 | `DEBUG` | разработчику при отладке; в проде выключен |
| R8.2 | `INFO` | владельцу, аудит постфактум |
| R8.3 | `WARN` | владельцу, «может стать проблемой» |
| R8.4 | `ERROR` | владельцу, в разбор |
Правила:
**Почему.** Адресат — единственный признак, по которому разные авторы в
разных местах кода выберут уровень одинаково. «Насколько серьёзно» каждый
оценивает по-своему, шкала расползается — и вместе с ней теряет смысл
базовый порог в проде (R40), потому что он отсекает уже не то, что
задумано.
- Уровень **не зависит от подсистемы**: `ERROR` везде одинаково серьёзен.
- `WARN` ≠ «ничего страшного». `WARN` = «может стать проблемой». Если это
не «может» — это `INFO`.
- Меняется адресат — меняется уровень. Невалидный ввод от пользователя —
`DEBUG` (норма, разбирать нечего), а не `ERROR`.
- **Событийное → `INFO`, рутинно-частое → `DEBUG`.** Операция по реальному
действию или изменению — `INFO`. Повторяющаяся служебная операция,
запускаемая таймером или поллингом и сама по себе не несущая события
(healthcheck, опрос статуса, авто-рефреш UI), — `DEBUG`: на `INFO` она
зашумляет аудит.
- `slog` не разделяет CRITICAL/FATAL — фатальный сбой на старте логируем
`ERROR` и завершаем процесс с ненулевым кодом.
### R9. Уровень не зависит от подсистемы
**НЕ ДОЛЖЕН.** Происхождение записи на выбор уровня не влияет: `ERROR`
везде одинаково серьёзен.
**Почему.** Фильтр по уровню собирает записи из всех подсистем сразу. Если
в шумной подсистеме `ERROR` «дешевле», читателю приходится помнить
происхождение каждой записи, чтобы понять, надо ли реагировать, — то есть
уровень перестаёт быть фильтром и становится подсказкой, требующей знания
кода.
### R10. `WARN` — только когда «может стать проблемой»
**ДОЛЖЕН.** Если «может» не про эту запись, уровень — `INFO`.
**Почему.** `WARN` разбирают вручную и целиком. Как только в нём заводится
«ничего страшного», его перестают читать — и вместе с шумом теряется то
единственное, ради чего уровень существует: предупреждение, на которое ещё
есть время отреагировать.
### R11. Событийное — `INFO`, рутинно-частое — `DEBUG`
**ДОЛЖЕН.** Уровень зависит от того, стоит ли за операцией событие.
| № | Операция | Уровень |
|---|---|---|
| R11.1 | по реальному действию или изменению | `INFO` |
| R11.2 | повторяющаяся служебная, по таймеру или поллингу, сама по себе события не несущая (healthcheck, опрос статуса, авто-рефреш UI) | `DEBUG` |
**Почему.** `INFO` — аудит постфактум (R8.2), и его пригодность
определяется долей записей, за которыми что-то стоит. Периодическая
операция даёт ровный поток при нулевой информации, в котором настоящие
события тонут количественно: их не отфильтровать, потому что фильтровать
приходится по содержанию, а не по уровню.
### R12. Фатальный сбой на старте — `ERROR` и ненулевой код возврата
**ДОЛЖЕН.** `slog` не разделяет CRITICAL/FATAL, поэтому недостающую
степень даёт завершение процесса.
**Почему.** Супервизор (docker, journald, systemd) отличает падение от
штатной остановки по коду возврата, а не по уровню последней записи.
Процесс, который написал `ERROR` и продолжил жить с неработающей
конфигурацией, выглядит здоровым и будет получать трафик; изобретать же
уровень выше `ERROR` не нужно — сам факт завершения информативнее.
## Поля: единый словарь
Главное условие — **одно поле, одно имя по всему коду** (не
`mediaType`/`media`/`media_type` вперемешку).
### R13. Одно поле одно имя по всему коду
- Бизнес-поля — плоский `snake_case`.
- Системные домены — точечная иерархия (адаптация OpenTelemetry): `http.*`,
`ext.*`.
- JSON плоский: все поля на верхнем уровне, без вложенности.
**ДОЛЖЕН.** Не `mediaType`/`media`/`media_type` вперемешку.
| Когда добавляем | Поля |
|---|---|
| входящий 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` одной
строкой при старте.
### R14. Форма имени зависит от вида поля
**ДОЛЖЕН.** Две формы, третьей нет.
| № | Вид поля | Форма имени |
|---|---|---|
| R14.1 | бизнес-поле | плоский `snake_case`: `download_id`, `media_type` |
| R14.2 | системный домен | точечная иерархия (адаптация OpenTelemetry): `http.*`, `ext.*` |
**Почему.** Точка отделяет поля, приходящие от инфраструктуры и одинаковые
в любом проекте, от доменных, которые в каждом свои: по общему префиксу
запрос «все внешние вызовы» пишется без перечисления имён. Заимствование
словаря OpenTelemetry снимает необходимость изобретать имена тому, что уже
названо, и спорить о них на каждом ревью.
### R15. Запись плоская
**НЕ ДОЛЖЕН.** Вложенных объектов в записи нет; точка в имени — часть
имени, а не уровень вложенности.
**Почему.** Плоский ключ адресуется одинаково в `jq`, в DuckDB и в любой
записи независимо от её категории. Вложенность требует знать глубину
заранее, а она у разных категорий разная — и один запрос перестаёт покрывать
весь лог, распадаясь на запрос под каждую форму записи.
### R16. Набор полей определяется ситуацией
**ДОЛЖЕН.** Записи каждой ситуации несут её набор целиком.
| № | Когда добавляем | Поля |
|---|---|---|
| R16.1 | входящий HTTP-запрос (middleware) | `http.method`, `http.route`, `http.status_code`, `duration_ms`, `transport` — если транспортов больше одного |
| R16.2 | работа с сущностью (scoped-логгер) | `<entity>_id` и доменные атрибуты |
| R16.3 | запись об ошибке | `error` |
| R16.4 | вызов внешнего сервиса | `ext.service`, `ext.operation` (логическая операция, не URL), `ext.status_code`, `duration_ms`, `retry` |
**Почему.** Набор задан не «на всякий случай»: без него запись не отвечает
на свой вопрос. HTTP-запись без `duration_ms` не показывает деградацию,
`ext`-запись без `ext.service` не отделяет «легла зависимость» от «у нас
баг», запись о сущности без идентификатора не корреллируется (R19). Полный
набор делает записи однородными — один запрос работает по всем вызовам, а
не по тем, где автор вспомнил про поле.
### R17. `service.*` и `host.*` не заводим
**НЕ СЛЕДУЕТ.** Пока это один бинарь на одном хосте.
**Почему.** Поле с одним и тем же значением во всех записях не несёт
информации, но стоит места в каждой строке и внимания при чтении. Условие
названо явно, поэтому правило отпадёт вместе со своей причиной: с
появлением нескольких инстансов различающее поле (`service.version`)
добавляется одной строкой при старте.
<!-- local:словарь -->
<!-- /local -->
## Корреляция по id сущности
## Корреляция
Отдельный случайный `trace_id` не заводим, **если у сущностей есть
стабильные уникальные идентификаторы** — они и служат ключом корреляции.
(Как их выбирают — `arch/db-identifiers.md`, если конвенция взята.)
### R18. Ключ корреляции — идентификатор сущности, а не `trace_id`
- Каждая запись, относящаяся к сущности, несёт её id в поле `<entity>_id`.
Для долгой операции — scoped-логгер, протаскиваемый через
`context.Context` сквозь асинхронные стадии, чтобы ключ дописывался сам:
**НЕ СЛЕДУЕТ.** Отдельный случайный `trace_id` не заводится, если у
сущностей есть стабильные уникальные идентификаторы. (Как их выбирают —
`arch/db-identifiers.md`, если конвенция взята.)
**Почему.** Идентификатор сущности уже существует, стабилен между
процессами и во времени — по нему собираются записи не одного прохода, а
всей истории сущности, включая вчерашнюю. `trace_id` даёт то же самое
только внутри одной операции, то есть дублирует ключ и добавляет второй
способ спросить об одном. Условие применимости названо: там, где сущности
со стабильным идентификатором нет, связывать записи больше нечем.
### R19. Запись о сущности несёт её идентификатор
**ДОЛЖЕН.** Поле `<entity>_id` в каждой записи, относящейся к сущности.
**Почему.** Принадлежность записи восстанавливается только в момент
записи; постфактум её не вывести — остаётся воспроизводить инцидент заново.
Это же условие, при котором работает R18: отказ от `trace_id` оплачен тем,
что идентификатор стоит везде, а не в удобных местах.
Все записи одной операции собираются одним фильтром:
`jq 'select(.download_id=="01jz…")' app.jsonl`. Если идентификатор
глобально уникален across сущностей, штатно работает и простой `grep` по
голому значению — он находит все упоминания независимо от имени поля.
### R20. Долгая операция ведётся 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: единый ключ важнее краткости).
### R21. Ошибка логируется атрибутом `error`
- Идиома Go — **либо лог, либо возврат, не оба**. Промежуточные слои только
оборачивают и возвращают (`%w`), не логируя: контекст накапливается в
цепочке.
- Логируем ошибку **один раз — на границе доменного слоя**, которая
определяет исход операции. Логирует этот единый чокпоинт, а не каждый
транспорт: так транспорты остаются тонкими, и один сбой не даёт дублей.
**ДОЛЖЕН.** `log.Error("layout failed", "error", err, "download_id", id)`.
**Почему.** Ошибка, вклеенная в текст сообщения, дробит категорию (R4) и
уносит текст туда, где по нему нельзя отфильтровать. Ключ единый — так же,
как по умолчанию в zap/zerolog: выборка «все записи с ошибкой» не должна
зависеть от того, кто писал конкретный вызов, и ради этого единообразия
краткостью жертвуют.
### R22. Промежуточный слой либо логирует, либо возвращает
**НЕ ДОЛЖЕН.** Слой, возвращающий ошибку выше, её не логирует — только
оборачивает (`%w`).
**Почему.** Иначе один сбой даёт столько записей, сколько слоёв он прошёл,
и количество `ERROR` перестаёт соответствовать количеству отказов — а
считают именно его. Контекст при этом не теряется: он накапливается в
цепочке обёрток и попадает в единственную запись на границе (R23).
### R23. Ошибка логируется один раз — на границе доменного слоя
**ДОЛЖЕН.** Логирует единый чокпоинт, определяющий исход операции.
**Почему.** У ошибки нужен ровно один логирующий, иначе неизбежны дубли; и
этим местом выбрана доменная граница, а не транспорт, потому что там
известен исход операции целиком и, значит, класс отказа (R25) — транспорт
знает лишь то, что ему вернули ошибку. Побочный эффект того же выбора:
транспорты остаются тонкими.
<!-- local:границы -->
<!-- /local -->
- Транспорты переводят возвращённую ошибку в свой ответ (статус, сообщение
пользователю) и **не логируют** её повторно.
- **Уровень доменного отказа — по адресату, а не по месту.** У каждой
доменной ошибки ровно один логирующий; уровень выбирает он:
### R24. Транспорт не логирует ошибку повторно
| Класс отказа | Кому | Уровень |
|---|---|---|
| штатный конфликт состояния или некорректный ввод | пользователю, он уже получил ответ | `DEBUG` |
| расхождение производного или учётного состояния, первичные данные целы | владельцу, «может стать проблемой» | `WARN` |
| сбой БД, ФС, недоступность зависимости | владельцу, в разбор | `ERROR` |
**НЕ ДОЛЖЕН.** Транспорт переводит возвращённую ошибку в свой ответ
(статус, сообщение пользователю) и на этом останавливается.
- Тот же класс отказа в **асинхронной стадии** (пользователь не ждёт)
адресован уже владельцу как деградация автоматики — уровень поднимается.
Коллизия в ручном действии — `DEBUG` (человек видит причину на экране), в
авто-обработке — `WARN` (автоматика не довела задачу).
- **Повторяющийся сбой фонового цикла — `WARN`, не `ERROR`.** Одиночный
промах тика транзиентен: следующий тик повторит. Тот же класс сбоя внутри
синхронной операции — `ERROR`, потому что операция провалилась целиком и
повтора нет. Уровень задаёт не текст ошибки, а **наличие штатного
повтора**.
**Почему.** Запись уже сделана на границе (R23); вторая отличается от неё
только формулировкой и читается как второй сбой. Когда транспортов над
одним доменом несколько, дублирование ещё и множится, а расследование
начинается с вопроса, один это инцидент или два.
### R25. Уровень доменного отказа — по классу отказа
**ДОЛЖЕН.** Уровень выбирает единственный логирующий (R23), и выбирает по
классу, а не по месту в коде.
| № | Класс отказа | Кому | Уровень |
|---|---|---|---|
| R25.1 | штатный конфликт состояния или некорректный ввод | пользователю, он уже получил ответ | `DEBUG` |
| R25.2 | расхождение производного или учётного состояния, первичные данные целы | владельцу, «может стать проблемой» | `WARN` |
| R25.3 | сбой БД, ФС, недоступность зависимости | владельцу, в разбор | `ERROR` |
**Почему.** Это применение R8 к отказам: пользователь уже увидел причину на
экране — владельцу разбирать нечего; целостность первичных данных отделяет
«надо посмотреть» от «надо чинить сейчас». Привязка к месту дала бы разный
уровень для одного и того же отказа в зависимости от того, какой транспорт
его вызвал, — и невалидный ввод из формы копился бы в `ERROR` наравне с
упавшей базой.
### R26. Тот же отказ в асинхронной стадии — уровнем выше
**ДОЛЖЕН.** Когда пользователь не ждёт результата, отказ адресован
владельцу как деградация автоматики: коллизия в ручном действии — `DEBUG`,
она же в авто-обработке — `WARN`.
**Почему.** В ручном действии человек видит причину на экране и сам решает,
что делать дальше; запись нужна только для отладки. В автоматике не увидел
никто, задача осталась недоведённой, и лог — единственное место, где это
вообще проявится.
### R27. Повторяющийся сбой фонового цикла — `WARN`
**ДОЛЖЕН.** Тот же класс сбоя внутри синхронной операции — `ERROR`:
уровень задаёт наличие штатного повтора, а не текст ошибки.
**Почему.** Одиночный промах тика транзиентен — следующий тик повторит, и
вмешательство не требуется; `ERROR` на каждый такой промах обесценивает
уровень, на который смотрят в первую очередь. Синхронная операция повтора
не имеет: она провалилась целиком, результат никто не восстановит, и это
ровно тот случай, ради которого `ERROR` держат чистым.
## Внешние сервисы
### R28. Каждый вызов внешнего сервиса логируется
**ДОЛЖЕН.** Все вызовы, включая успешные; поля — по R16.4.
**Почему.** Это единственный способ отличить «у нас баг» от «зависимость
легла»: на своей стороне видно лишь то, что операция не удалась.
Выборочное логирование ломает и второе применение — доля неуспехов и
распределение `duration_ms` считаются, только если знаменатель полный.
### R29. Уровень `ext`-записи — по исходу вызова
**ДОЛЖЕН.** Исход считается по одному вызову с его ретраями.
| № | Исход | Уровень |
|---|---|---|
| R29.1 | успешный событийный вызов | `INFO` |
| R29.2 | успешный рутинно-частый вызов (поллинг, авто-рефреш) | `DEBUG` |
| R29.3 | попытка не удалась, делается retry | `WARN` |
| R29.4 | ретраи исчерпаны, сервис недоступен | `ERROR` |
**Почему.** Неудачная попытка, за которой следует повтор, — ещё не отказ:
операция может завершиться успешно, и `ERROR` на каждую попытку сделал бы
уровень непригодным для главного вопроса «зависимость доступна?».
Исчерпание ретраев и есть момент, когда транспорт сдался и дальше
разбираться владельцу. Различение R29.1 и R29.2 — то же самое разделение
событийного и рутинного, что в R11: поллинг внешнего сервиса зашумляет
аудит так же, как любой другой.
## Два цикла повтора — не путать
Слово «ретрай» означает два разных механизма, и уровень считается по
каждому отдельно:
каждому отдельно: повтор вызова внутри одной операции (ретраи HTTP-клиента)
задаёт уровень `ext`-записи, повтор тика внешним циклом (поллинг, сверка) —
уровень доменной записи об исходе тика.
- **Повтор вызова внутри одной операции** (ретраи HTTP-клиента) — по нему
выбирается уровень **`ext`-записи**: `WARN` на попытку, `ERROR` когда
попытки исчерпаны.
- **Повтор тика внешним циклом** (поллинг, сверка) — по нему выбирается
уровень **доменной записи** об исходе тика: `WARN`, потому что следующий
тик повторит.
```
WHEN зависимость недоступна и ретраи вызова исчерпаны → ext-запись `ERROR` (R29.4)
AND тик фонового цикла упал по той же причине → доменная запись `WARN` (R27)
```
Из этого следует, что у лежащей зависимости `ext`-запись пишет `ERROR`
каждый тик. Это и есть механизм эскалации: доменный слой не паникует, а
@@ -172,71 +411,140 @@ Go-ошибки логируем **атрибутом**, не текстом с
`ERROR` от поллинга мешает — это лечится понижением частоты тика или
подавлением повторов в самом клиенте, а не переклассификацией уровня.
## Внешние сервисы: логируем все вызовы
### R30. Ответ 4xx — успех на транспортном уровне
**Каждый** вызов внешнего сервиса логируется — это единственный способ
отличить «у нас баг» от «зависимость легла». Поля: `ext.service`,
`ext.operation` (логическая операция, не URL), `ext.status_code`,
`duration_ms`, `retry`.
Уровни:
- `INFO` — успешный **событийный** вызов;
- `DEBUG` — успешный **рутинно-частый** вызов (поллинг, авто-рефреш);
- `WARN` — попытка не удалась, делаем retry;
- `ERROR` — ретраи исчерпаны, сервис недоступен.
Завершённый HTTP-ответ с 4xx — это **успех на транспортном уровне**
**ДОЛЖЕН.** Завершённый HTTP-ответ с 4xx логируется как успешный вызов
(`ext.status_code` записан); решение «это ошибка» принимает доменный
вызывающий. Тело запроса и ответа — только на `DEBUG` и после вычистки
секретов.
вызывающий.
**Почему.** Транспорт своё дело сделал: запрос доставлен, ответ получен и
разобран. Классифицировать 4xx как сбой транспорта значит смешать «сервис
недоступен» с «сервис ответил нам нет» — это разные инциденты с разной
реакцией, и различает их как раз `ext`-уровень. Что 404 значит для
операции, знает только вызывающий: для одной это отказ, для другой —
штатный ответ.
## HTTP и healthcheck
- Входящие запросы логируем с `http.*` и `duration_ms` на **`INFO`**: это
аудит обращений, а не отладка. Уровень не понижается из-за кода ответа —
4xx остаётся `INFO`-записью доступа; решение «это ошибка» принимает
доменный слой и пишет свою запись.
- Для корреляции запроса допустим `request_id` — это отдельный слой от
корреляции по сущности и не противоречит отказу от `trace_id`.
- **Healthcheck, liveness, readiness — `DEBUG`.** Их дёргают периодически,
на `INFO` они забивают аудит; в проде с базовым `INFO` они не пишутся.
### R31. Входящий запрос — `INFO` независимо от кода ответа
**ДОЛЖЕН.** Поля по R16.1; 4xx остаётся `INFO`-записью доступа.
**Почему.** Это аудит обращений, а не отладка: запись отвечает на «кто и
когда приходил», и ценность у неё одинаковая при любом коде ответа.
Уровень, зависящий от кода, делает аудит неполным именно на тех запросах,
которые чаще всего разбирают. Доменную оценку исхода даёт отдельная запись
(R25) — она и адресована по-другому.
### R32. Для корреляции запроса допустим `request_id`
**ДОПУСКАЕТСЯ.** Это отдельный слой от корреляции по сущности.
**Почему.** Явное разрешение снимает вопрос, не запрещает ли `request_id`
правило R18. Не запрещает: R18 отказывается от случайного ключа там, где
уже есть стабильный идентификатор сущности, а у HTTP-запроса собственной
сущности нет — связать его записи между собой больше нечем.
### R33. Healthcheck, liveness, readiness — `DEBUG`
**ДОЛЖЕН.** Периодические проверки живости пишутся на отладочном уровне.
**Почему.** Частный случай R11.2, названный отдельно, потому что нарушают
его чаще всего: проверку дёргают по таймеру, и на `INFO` она вытесняет из
аудита всё остальное — в проде с базовым `INFO` (R40) лог превратился бы в
опрос самого себя. На `DEBUG` она не пишется вовсе и при этом остаётся
доступной при отладке.
## Безопасность: что не логируем
Никаких секретов в полях и сообщениях: пароли и cookie сессий, API-ключи и
токены, `Authorization`-заголовки, аутентификационные параметры в ссылках.
### R34. Секреты не логируются
- Тела ответов внешних 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 есть заголовок**
тогда его нет и в ошибке транспорта.
**НЕ ДОЛЖЕН.** Ни в полях, ни в сообщениях: пароли и cookie сессий,
API-ключи и токены, `Authorization`-заголовки, аутентификационные параметры
в ссылках.
**Почему.** Лог уезжает целиком в чужое хранилище, читается шире, чем код,
и переживает ротацию самого секрета. Попавший в него секрет скомпрометирован
с момента записи, а не с момента, когда это заметили, и вычистить его задним
числом из уже собранных копий нельзя.
### R35. Недоверенные и большие тела — только на `DEBUG`, после вычистки и обрезки
**ДОЛЖЕН.** Тела запросов и ответов внешних API, сырой вывод LLM —
`DEBUG`, с вычисткой секретов и обрезкой по длине.
**Почему.** Содержимое пришло снаружи: размер не ограничен, состав
неизвестен, а секрет в нём возможен по недосмотру той стороны. `DEBUG`
выключен в проде (R40), поэтому цена ошибки ограничена отладочной сессией;
обрезка не даёт одной записи вытеснить весь остальной лог за период.
### R36. При сомнении логируется факт, а не значение
**СЛЕДУЕТ.** `"has_api_key", true` вместо самого значения.
**Почему.** Для отладки почти всегда достаточно ответа «значение было или
не было» — потеря полезности близка к нулю, а риск снимается целиком.
Правило нужно потому, что решение принимается в момент написания строки,
когда чувствительность значения ещё неочевидна, а перечитывать этот выбор
никто не придёт.
### R37. `*url.Error` санитизируется на границе клиента
**ДОЛЖЕН.** Ошибка разворачивается в первопричину **до** лога и до
обёртки — раньше трансляции в доменную (`lang/go/errors.md`).
**Почему.** `*url.Error` встраивает полный URL запроса, а секрет живёт
прямо в нём: токен в пути, `api_key` в query. Go редактирует только пароль
из userinfo, остального не трогает, поэтому ошибка уносит секрет и в
обёртку, и в лог целиком. Порядок — часть нормы: санитизация после
трансляции уже опоздала, секрет к этому моменту скопирован в текст обёртки.
Цена — теряется `Op` и сам факт «это был HTTP-транспорт» (`errors.Is` на
причину сохраняется); альтернатива с редактированием URL сохранила бы
структуру, но сложнее.
### R38. Секрет не кладётся в URL, если у API есть заголовок
**НЕ ДОЛЖЕН.** Аутентификация параметром ссылки — только когда другого
способа нет.
**Почему.** Секрет в URL попадает не только в ошибку транспорта (R37), но и
в любую запись, куда URL попал целиком, — то есть обязывает помнить про
санитизацию в каждой такой точке, и одна забытая сводит остальные на нет.
Заголовок снимает задачу в источнике: чего нет в URL, того нет и в ошибке.
<!-- local:секреты -->
<!-- /local -->
## Куда пишем
- JSON в `stdout` одним потоком; сбор и ротацию делает окружение (docker,
journald). По файлам не маршрутизируем.
- Базовый уровень в проде — `INFO`, `DEBUG` включается конфигом. dev —
`DEBUG`.
### R39. Логи идут в `stdout` одним потоком
## Анализ
**ДОЛЖЕН.** Сбор и ротацию делает окружение (docker, journald); по файлам
не маршрутизируем.
- Повседневно — `jq`: `jq 'select(.download_id=="a1b2")' app.jsonl`.
- Тяжёлое (агрегации, JOIN) — DuckDB поверх JSONL прямо из файла.
**Почему.** Приложение, которое само решает, что куда писать, дублирует
работу супервизора и расходится с ней при первой же смене окружения: срок
хранения, сжатие и ротация оказываются настроены в двух местах и по-разному.
Один поток вдобавок сохраняет порядок записей — маршрутизация по файлам
теряет его ровно там, где важен ход событий.
### R40. Базовый уровень — `INFO` в проде и `DEBUG` в dev
**ДОЛЖЕН.** `DEBUG` в проде включается конфигом.
**Почему.** Уровень — единственный регулятор объёма, доступный без
пересборки; если `DEBUG` в проде включается только правкой кода, его не
включают, и разбор инцидента идёт вслепую. `INFO` выбран базовым потому,
что на нём аудит полон (R8.2), а рутинно-частое уже отсечено (R11.2).
## Связано
- `arch/time.md` — точность и зона меток времени фиксируются на носитель.
- `lang/go/time.md` — как ставится UTC в `ReplaceAttr` (R3).
- `lang/go/errors.md` — трансляция ошибки в доменную, порядок относительно
санитизации (R37).
- `arch/db-identifiers.md` — откуда берутся стабильные идентификаторы,
на которых держится корреляция (R18).
<!-- local:механизировано -->
<!-- /local -->