--- 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-логгер) | `_id` и доменные атрибуты | | запись об ошибке | `error` | | вызов внешнего сервиса | `ext.service`, `ext.operation`, `ext.status_code`, `duration_ms`, `retry` | `service.*` и `host.*` не заводим — для одного бинаря на одном хосте это шум. Если появятся несколько инстансов, добавим `service.version` одной строкой при старте. ## Корреляция по id сущности Отдельный случайный `trace_id` не заводим, **если у сущностей есть стабильные уникальные идентификаторы** — они и служат ключом корреляции. (Как их выбирают — `arch/db-identifiers.md`, если конвенция взята.) - Каждая запись, относящаяся к сущности, несёт её id в поле `_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`), не логируя: контекст накапливается в цепочке. - Логируем ошибку **один раз — на границе доменного слоя**, которая определяет исход операции. Логирует этот единый чокпоинт, а не каждый транспорт: так транспорты остаются тонкими, и один сбой не даёт дублей. - Транспорты переводят возвращённую ошибку в свой ответ (статус, сообщение пользователю) и **не логируют** её повторно. - **Уровень доменного отказа — по адресату, а не по месту.** У каждой доменной ошибки ровно один логирующий; уровень выбирает он: | Класс отказа | Кому | Уровень | |---|---|---| | штатный конфликт состояния или некорректный ввод | пользователю, он уже получил ответ | `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 есть заголовок** — тогда его нет и в ошибке транспорта. ## Куда пишем - JSON в `stdout` одним потоком; сбор и ротацию делает окружение (docker, journald). По файлам не маршрутизируем. - Базовый уровень в проде — `INFO`, `DEBUG` включается конфигом. dev — `DEBUG`. ## Анализ - Повседневно — `jq`: `jq 'select(.download_id=="a1b2")' app.jsonl`. - Тяжёлое (агрегации, JOIN) — DuckDB поверх JSONL прямо из файла.