dev-conventions/conventions/lang/go/logging.md

extends

extends
arch/time.md

Логирование

Как и когда писать логи. Это правила оформления кода (How), а не спецификация поведения: наблюдаемые требования к логам, входящие в контракт функциональности, живут в спеках. Форма записи — LANGUAGE.md.

Лог читают инструментами, а не глазами: повседневно — jq (jq 'select(.download_id=="a1b2")' app.jsonl), тяжёлое (агрегации, JOIN) — DuckDB поверх JSONL прямо из файла. Отсюда почти все правила ниже: запись существует для запроса к ней.

{"time":"2026-06-28T11:23:45.123Z","level":"INFO","msg":"download accepted","download_id":"01jz2k7f8q9r3s4t5v6w7x8y9z","media_type":"movie"}

Формат записи

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 так и должно быть: ширина фиксируется на носитель.

Сообщение

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. Уровень выбирается по адресату

ДОЛЖЕН. Уровень отвечает на вопрос «кому сообщение», а не «насколько громко сломалось».

№	Уровень	Кому и когда
R8.1	DEBUG	разработчику при отладке; в проде выключен
R8.2	INFO	владельцу, аудит постфактум
R8.3	WARN	владельцу, «может стать проблемой»
R8.4	ERROR	владельцу, в разбор

Почему. Адресат — единственный признак, по которому разные авторы в разных местах кода выберут уровень одинаково. «Насколько серьёзно» каждый оценивает по-своему, шкала расползается — и вместе с ней теряет смысл базовый порог в проде (R40), потому что он отсекает уже не то, что задумано.

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 не нужно — сам факт завершения информативнее.

Поля: единый словарь

R13. Одно поле — одно имя по всему коду

ДОЛЖЕН. Не mediaType/media/media_type вперемешку.

Почему. Имя поля — и есть интерфейс запроса к логам. Второе имя для той же величины делает любую выборку по ней молча неполной: фильтр отработает, часть записей в него не попадёт, и заметить это можно, только заранее зная, что они должны были быть.

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) добавляется одной строкой при старте.

Корреляция

R18. Ключ корреляции — идентификатор сущности, а не trace_id

НЕ СЛЕДУЕТ. Отдельный случайный 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

СЛЕДУЕТ. Логгер с дописанным ключом протаскивается сквозь асинхронные стадии:

log := log.With("download_id", id)
ctx = logctx.With(ctx, log) // достаём логгер из ctx в каждой стадии

Почему. Ручное дописывание ключа пропускают не в основном сценарии, а в редких ветках — обработке ошибок и ранних выходах, где корреляция нужнее всего. Логгер из контекста дописывает ключ сам, и запись без идентификатора становится невозможной, а не маловероятной.

Ошибки

R21. Ошибка логируется атрибутом error

ДОЛЖЕН. log.Error("layout failed", "error", err, "download_id", id).

Почему. Ошибка, вклеенная в текст сообщения, дробит категорию (R4) и уносит текст туда, где по нему нельзя отфильтровать. Ключ единый — так же, как по умолчанию в zap/zerolog: выборка «все записи с ошибкой» не должна зависеть от того, кто писал конкретный вызов, и ради этого единообразия краткостью жертвуют.

R22. Промежуточный слой либо логирует, либо возвращает

НЕ ДОЛЖЕН. Слой, возвращающий ошибку выше, её не логирует — только оборачивает (%w).

Почему. Иначе один сбой даёт столько записей, сколько слоёв он прошёл, и количество ERROR перестаёт соответствовать количеству отказов — а считают именно его. Контекст при этом не теряется: он накапливается в цепочке обёрток и попадает в единственную запись на границе (R23).

R23. Ошибка логируется один раз — на границе доменного слоя

ДОЛЖЕН. Логирует единый чокпоинт, определяющий исход операции.

Почему. У ошибки нужен ровно один логирующий, иначе неизбежны дубли; и этим местом выбрана доменная граница, а не транспорт, потому что там известен исход операции целиком и, значит, класс отказа (R25) — транспорт знает лишь то, что ему вернули ошибку. Побочный эффект того же выбора: транспорты остаются тонкими.

R24. Транспорт не логирует ошибку повторно

НЕ ДОЛЖЕН. Транспорт переводит возвращённую ошибку в свой ответ (статус, сообщение пользователю) и на этом останавливается.

Почему. Запись уже сделана на границе (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-записи, повтор тика внешним циклом (поллинг, сверка) — уровень доменной записи об исходе тика.

WHEN зависимость недоступна и ретраи вызова исчерпаны → ext-запись `ERROR`   (R29.4)
AND  тик фонового цикла упал по той же причине        → доменная запись `WARN` (R27)

Из этого следует, что у лежащей зависимости ext-запись пишет ERROR каждый тик. Это и есть механизм эскалации: доменный слой не паникует, а телеметрия зависимости честно показывает, что она недоступна. Если поток ERROR от поллинга мешает — это лечится понижением частоты тика или подавлением повторов в самом клиенте, а не переклассификацией уровня.

R30. Ответ 4xx — успех на транспортном уровне

ДОЛЖЕН. Завершённый HTTP-ответ с 4xx логируется как успешный вызов (ext.status_code записан); решение «это ошибка» принимает доменный вызывающий.

Почему. Транспорт своё дело сделал: запрос доставлен, ответ получен и разобран. Классифицировать 4xx как сбой транспорта значит смешать «сервис недоступен» с «сервис ответил нам нет» — это разные инциденты с разной реакцией, и различает их как раз ext-уровень. Что 404 значит для операции, знает только вызывающий: для одной это отказ, для другой — штатный ответ.

HTTP и healthcheck

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 она не пишется вовсе и при этом остаётся доступной при отладке.

Безопасность: что не логируем

R34. Секреты не логируются

НЕ ДОЛЖЕН. Ни в полях, ни в сообщениях: пароли и 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, того нет и в ошибке.

Куда пишем

R39. Логи идут в stdout одним потоком

ДОЛЖЕН. Сбор и ротацию делает окружение (docker, journald); по файлам не маршрутизируем.

Почему. Приложение, которое само решает, что куда писать, дублирует работу супервизора и расходится с ней при первой же смене окружения: срок хранения, сжатие и ротация оказываются настроены в двух местах и по-разному. Один поток вдобавок сохраняет порядок записей — маршрутизация по файлам теряет его ровно там, где важен ход событий.

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).