Logging

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

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

Границы с соседями. Metrics отвечают на вопрос «сколько и как часто», лог — на вопрос «что именно случилось с этим запросом»; идентификаторам, которым не место в метках, место здесь. Объём, сроки хранения и семплирование разобраны в Telemetry Economics. Что из сигналов будит человека, решает Symptom vs Cause Alerting. Путь запроса через несколько сервисов показывает Distributed Tracing, и лог связывается с трейсом одним полем.

Что должен уметь

Главный навык на уровне L4 — писать запись для того, кто будет её искать, а не для того, кто её пишет. Я считаю его главным, потому что всё остальное в логировании решается инструментами, а это нет. Формат можно навязать библиотекой, сбор — платформой. Какие поля понадобятся в три часа ночи, знает только человек, который представил себе этот поиск заранее.

Пишет запись структурой, а не строкой: событие названо, контекст лежит в отдельных полях, а не вклеен в текст сообщения.
Выбирает уровень по принятому в команде определению и не использует ERROR для того, что не требует ничьих действий.
Не пишет в лог пароли, токены, ключи и персональные данные; знает, какие поля его сервиса к ним относятся.

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

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

L6+

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

Материалы

Статьи и доклады

Brandur Leach — Fast and flexible observability with canonical log lines (Stripe, 2019). Лучшее из известных мне практических описаний одной идеи: в конце запроса пишется одна широкая запись со всем важным. Читать обязательно, включая конец, где набор полей становится контрактом.
Adam Wiggins — The Twelve-Factor App, фактор XI «Logs». Полстраницы, которые закрывают спор о файлах: приложение пишет поток событий в стандартный вывод и не знает, куда он уходит.
Charity Majors — Logs vs Structured Events (2019). Резкая позиция: строки и уровни пора заменить широкими структурированными событиями, по одному на запрос в каждом сервисе. С отказом от уровней я не согласен, остальное рекомендую.
OpenTelemetry — Logs Data Model. Готовый список полей записи: время, уровень, тело, атрибуты, ресурс и идентификаторы трейса и спана. Удобно брать как отправную точку для своего контракта.
OWASP — Logging Cheat Sheet. Раздел о том, что из записи исключают: пароли, строки подключения, ключи шифрования, платёжные и персональные данные. Советую держать этот список рядом с ревью.
Grafana Loki — Label best practices. Про метки в хранилище логов: статические хороши, динамические берут скупо. Полезна честностью: авторы признаются, что пересматривают даже собственную привычку делать меткой уровень.
Logging Sucks — манифест о том, что привычное логирование сломано и OpenTelemetry само по себе его не чинит. По моим наблюдениям, вторая половина тезиса важнее первой: стандарт доставки не заменяет решения, что записывать.

Инструменты

Структурный логгер в языке — например, log/slog в стандартной библиотеке Go. По моим наблюдениям, чаще всего хватает того, что уже есть в языке; отдельная библиотека нужна, когда команде требуется общий набор обязательных полей.
Grafana Loki — хранилище, которое индексирует метки, а не текст записи. Имеет смысл там, где уже живут Grafana и Prometheus и по логам чаще фильтруют, чем ищут.
OpenSearch — полнотекстовый индекс. Его берут, когда по логам ищут как по документам; цена в размере индекса и в том, что его надо кому-то сопровождать.

Best practices

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

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

Событие вместо строки. «Не удалось обработать заказ 4512 пользователя 77» — строка, в которой всё важное вклеено в текст. Найти по ней все ошибки одного пользователя можно только регулярным выражением. То же событие структурой называет себя один раз, а номер заказа и пользователя несёт отдельными полями. Разница проявляется при первом же поиске. Мне близка мысль, с которой начинается манифест Logging Sucks: стандарт доставки эту работу не сделает, что записывать, решает человек.

Приложение не занимается судьбой своего лога. Это правило записано в одиннадцатом факторе The Twelve-Factor App: сервис пишет поток событий в стандартный вывод, а собирает, направляет и хранит его среда. Сервис, который сам ведёт файлы, ротирует их и отправляет по сети, получает три новых способа упасть, и ни один из них не связан с его работой.

Уровни работают, пока у них есть определения. Я регулярно вижу сервисы, где ERROR пишут на всё подряд, от отказа базы до неверного пароля пользователя, и через месяц на этот уровень никто не смотрит. Рабочее определение короткое. ERROR требует действия человека. WARN означает, что сервис справился сам, но так быть не должно. INFO описывает ход нормальной работы. Спор о том, нужен ли INFO в проде, кончается в первом же инциденте, где нет ошибок, а сервис ведёт себя странно.

Некоторых данных в логе не бывает. Список у OWASP читается за минуту: пароли, строки подключения, ключи, платёжные данные, персональные данные сверх необходимого. Трудность в том, что попадают они туда не по умыслу. Кто-то логирует тело запроса целиком, а в теле лежит токен. Поэтому маскирование ставят на входе в логгер, списком полей, которые никогда не пишутся. Искать секреты по уже записанному поздно: лог к этому моменту разошёлся по хранилищам с другими правами доступа.

Каждая запись несёт идентификатор запроса. Без него записи одного сервиса ещё можно сложить по времени, а записи пяти сервисов уже нет. В модели данных OpenTelemetry для этого есть готовые поля — идентификаторы трейса и спана прямо в записи лога. Поле одно. Оно превращает три отдельных инструмента в один: от точки на графике к трейсу, от трейса к записям.

Алерты на тексте логов я считаю ошибкой почти всегда. Алерт по регулярному выражению ломается от переформулированного сообщения, а считает он то, что дешевле и надёжнее считать счётчиком. Число событий — дело метрики, объяснение события — дело лога. Исключение одно: чужая система, которая не отдаёт ничего, кроме текста.

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

Связанные листья

Metrics — что считается, а не записывается; идентификаторы оттуда переезжают сюда.
Telemetry Economics — объём, семплирование и сроки хранения логов как статья расходов.
Systematic Troubleshooting — как записи используют при поиске поломки; плохой лог ломает метод на первом же шаге.
Symptom vs Cause Alerting — почему человека будит метрика симптома, а лог остаётся для объяснения.
Secrets Management — секрет, попавший в лог, считается утёкшим и требует ротации.
Blameless Postmortem — хронология разбора собирается в том числе из логов; без идентификаторов её собирают руками.
Distributed Tracing — путь запроса между сервисами и вторая половина связки по идентификатору.

Открытые вопросы

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

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

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