Что писать в логи, чтобы они пригодились в аварию

Проверка простая. Возьмите жалобу «у меня не прошёл платёж вчера около шести вечера» и попробуйте по логам сказать, что именно произошло. Обычно выясняется, что записей много, а ответа нет: строки есть от каждого сервиса, но сшить их в один путь нечем.

Отсюда и надо отсчитывать, а не от списка уровней.

Единица — не строка, а событие с контекстом

Запись Payment failed бесполезна. Не потому, что коротка, а потому, что не отвечает ни на один вопрос разбора: чей платёж, какой попытки, на каком шаге, что ответил банк.

Полезная запись несёт сам факт и то, что нужно для его понимания: идентификатор операции, идентификатор запроса, шаг, код и текст чужого ответа, длительность. Причём полями, а не внутри фразы.

Разница между

[ERROR] Payment 8831 failed for user 402: gateway timeout after 30s

и

{"level":"error","event":"payment.failed","payment_id":8831,
 "user_id":402,"reason":"gateway_timeout","duration_ms":30012,
 "request_id":"a3f9…"}

не в красоте. По первой нельзя спросить «сколько платежей упало по таймауту за час» иначе как разбором текста регулярным выражением, которое сломается при первой же правке формулировки. По второй это обычная группировка по полю.

Сквозной идентификатор — самое дешёвое, что можно сделать

Один идентификатор, который рождается на входе, кладётся в контекст и проезжает через все вызовы, включая обращения к соседним сервисам. Дальше он пишется в каждую запись.

Это превращает поиск «что было с этим запросом» из расследования в один фильтр. По соотношению пользы к трудозатратам ничего лучше в наблюдаемости я не знаю: день работы, и разбор инцидентов меняется навсегда.

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

Уровни

Их пять или шесть, а решений на практике два: пойдёт ли по этой записи человек.

ERROR — пойдёт. Случилось то, что требует вмешательства. Если по вашим ERROR никто не ходит, это не уровень, а привычка.

WARN — самый испорченный уровень в отрасли. Обычно им помечают «странно, но мы продолжили», и через год их тысячи в час, и не смотрит никто. Заводя WARN, полезно сразу ответить, при каком количестве он станет ERROR. Нет ответа — пишите INFO.

INFO — переходы состояния, по которым восстанавливают ход дела: заказ создан, платёж подтверждён, задание взято в работу. Не «вошли в функцию».

DEBUG — подробности, которые в бою выключены.

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

Чего в логах быть не должно

Секретов. Токены, ключи, заголовки авторизации. Логи уезжают в чужой сервис, лежат там годами и доступны шире, чем база. Это та же причина, по которой переменная окружения секрет не прячет: попав в лог, секрет считается скомпрометированным.

Персональных данных. Телефоны, адреса, содержимое переписки. Идентификатор пользователя — да, его паспорт — нет.

Тел запросов и ответов целиком. Соблазн понятный, а последствия две: в них попадает первое и второе из этого списка, и счёт за хранение растёт быстрее трафика.

Куда писать

В контейнере — в стандартный вывод, и только туда. Не в файл внутри образа: этот файл исчезнет вместе с контейнером, а до тех пор будет тихо съедать диск узла. Сбор, ротация и хранение — задача окружения, и оно с ней справляется, если приложение не пытается делать то же самое само.

Отсюда же вытекает формат времени. Метка ставится в UTC и по ISO 8601, потому что в разборе сшиваются записи с машин, у которых часовые пояса разные. Локальное время в логе — это лишний шаг перевода в тот момент, когда думать некогда.

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

Про объём

Логи не бесплатны. Их хранение, передача и поиск стоят денег, а запись в горячем пути стоит задержки — особенно синхронная запись на диск.

Практический порядок такой. ERROR пишутся всегда. INFO — на переходах состояния, а не на каждом шаге. Подробности по успешным запросам либо не пишутся вовсе, либо пишутся по выборке: одна из ста одинаковых записей рассказывает ровно то же самое, что сто.

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

Условие, при котором это перебор

Одно приложение на одной машине, десяток запросов в минуту — берите print в файл и живите спокойно. Сквозной идентификатор там не нужен, потому что сшивать нечего.

Граница проходит не по нагрузке, а по числу процессов: как только запрос обслуживают двое, восстановить его путь по разрозненным записям становится нельзя, и никакой уровень подробности этого не заменит.