← вся теориятеория к собесу · Мониторинг и логи

Логи: структура, объём, идентификатор запроса

Логи: формат, объём, связность

Лог - это поток записей о том, что делал сервис. Сгенерировал 20 тысяч таких строк в двух видах. Обычным текстом - 75 байт на строку. Тем же содержимым в виде структурированных записей - 190 байт. При скромных 500 строках в секунду это 3 гигабайта в сутки против 7,7, то есть 91 гигабайт в месяц против 230. Структурированный лог стоит дороже, и это осознанная плата.

Стержень: логи стоят денег за объём, структура окупается на разборе, а без сквозного идентификатора запроса они бесполезны в сервисной архитектуре.

// Формулировки: «зачем структурированные логи?», «что писать в лог, а что нет?», «как собрать историю одного запроса?»

Структура против текста

Обычный лог - это строка для человека. Структурированный - запись с именованными полями: время, уровень, сервис, сообщение и отдельные поля с числами и идентификаторами. Разница видна на первом же вопросе к данным.

Замерил на тех же 20 тысячах строк. Из текстового лога среднюю длительность я достал регулярным выражением (это шаблон для поиска по тексту) за 18 миллисекунд - быстро. Из структурированного разбор занял 62 миллисекунды - медленнее. Но дальше самое интересное: я дописал ОДНУ строку, где та же длительность записана другими словами, и регулярка её молча не нашла. 20 000 значений из 20 001 строки. На проде это выглядит так: после релиза формат сообщения слегка поменяли, и половина графика тихо исчезла, а никто не заметил.

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

структурированный лог: запись с именованными полями вместо строки для человека
разбор регуляркой: вытаскивание значений шаблоном; ломается от смены формулировки

Объём и уровни

Объём считается арифметикой, а не на глаз. Мой замер: 190 байт на структурированную запись, 500 записей в секунду - это 7,7 гигабайта в сутки и 230 в месяц с ОДНОГО сервиса. Умножьте на десяток сервисов и на срок хранения, и получите строку в бюджете, которая иногда превышает стоимость самих серверов.

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

// И два запрета, которые стоят дорого при нарушении. В логи не пишут секреты - ключи, пароли, содержимое заголовков авторизации. И не пишут персональные данные без необходимости: лог уезжает в общее хранилище, где доступ шире, чем к базе, живёт месяцами и попадает в резервные копии.

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

Сквозной идентификатор запроса

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

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

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

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

Как отвечать: «Зачем структурированные логи, если текстовые читаются глазами?»

Затем, что глазами их читают только в разработке, а на проде по ним отвечают на вопросы. Я мерил разницу на двадцати тысячах строк: из текстового лога значение достаётся регуляркой за восемнадцать миллисекунд, из структурированного разбор занимает шестьдесят две - текст быстрее. Но потом я дописал одну строку, где то же значение записано другими словами, и регулярка её молча не нашла. Именно так после релиза тихо исчезает половина графика. У структурированного лога поля не зависят от формулировки сообщения. Плата за это честная: у меня 75 байт на текстовую строку против 190 на структурированную, при пятистах строках в секунду это 91 гигабайт в месяц против 230 с одного сервиса. Поэтому вместе со структурой сразу решают вопрос уровней и агрегатов, иначе объём становится отдельной статьёй бюджета.

Ответ честно показывает, что у структуры есть цена, и объясняет, за что её платят. Признание минусов делает аргумент сильнее, а не слабее.

На чём валятся

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

Проверьте себя

Пять вопросов из банка по этой подтеме. Всего их 8, остальные разбираются в тренажёре.

#dvo_logging1 / 5
Инцидент в цепочке из шести сервисов: логи есть у всех, а собрать путь запроса не выходит. Чего не хватает?
A)Единого часового пояса в логах всех сервисов
B)Централизованного хранилища вместо логов на нодах
C)Более подробного уровня логирования на входном сервисе
D)Сквозного идентификатора запроса во всех записях
показать ответ и разбор
+D)Сквозного идентификатора запроса во всех записях
// разбор: Без общего идентификатора связать записи можно только по времени и догадкам, а при параллельных запросах это не работает вовсе. Входной прокси генерирует идентификатор, каждый сервис прокидывает его дальше в заголовках и пишет в каждую строку лога. Тогда фильтр по одному значению собирает всю цепочку, а тот же идентификатор связывает логи с трассой и с записью в тикете инцидента.
#dvo_logging2 / 5
Сервис в проде по умолчанию логирует на уровне DEBUG. Чем это плохо и как правильно?
A)DEBUG в проде топит объёмом; держать INFO
B)DEBUG в проде безопасен, если хранилище большое
C)Уровни логов на прод не влияют, это лишь метки
D)Стоит логировать на TRACE ради полноты
показать ответ и разбор
+A)DEBUG в проде топит объёмом; держать INFO
// разбор: DEBUG/TRACE в проде — это огромный объём малополезных записей: дорогое хранилище, нагрузка на пайплайн логов и, главное, важные сообщения тонут в шуме. В проде держат INFO (или WARN) как базовый уровень, а DEBUG включают точечно и временно — для конкретного компонента при разборе инцидента, желательно динамически, без передеплоя. Уровень — это рычаг «сигнал/шум и стоимость», а не просто метка.
#dvo_logging3 / 5
В логи приложения попадают номера карт и токены пользователей. Чем это грозит и что делать?
A)Ничего: доступ к логам и так только у команды
B)Достаточно зашифровать весь стор логов целиком
C)Утечка ПДн — маскировать до записи
D)Удалять такие строки вручную раз в месяц
показать ответ и разбор
+C)Утечка ПДн — маскировать до записи
// разбор: Карты, пароли, токены, персональные данные в логах — это утечка и нарушение требований (ПДн, PCI). Логи копируются в индексы, бэкапы, у них шире доступ, чем кажется. Правильно: редактировать/маскировать чувствительные поля до записи (на уровне логгера/фильтра), не логировать тела с секретами, ограничивать срок хранения и доступ. Шифрование стора и ручная чистка не спасают: внутри доступа данные открыты, а к моменту уборки уже разошлись.
#dvo_logging4 / 5
Команда считает частоту ошибок, гоняя grep/агрегации по централизованным логам на каждом дашборде. Чем это плохо?
A)Grep по логам даёт более точный счёт, чем метрики
B)Считать частоты дорого и медленно по логам — для этого есть метрики
C)Проблема лишь в регулярках, надо писать их аккуратнее
D)Полнотекстовый поиск по логам не поддерживается
показать ответ и разбор
+B)Считать частоты дорого и медленно по логам — для этого есть метрики
// разбор: Логи хороши для разбора конкретного случая (что именно и в каком контексте произошло), но считать по ним частоты/тренды на каждом рендере дашборда дорого и медленно: полнотекстовые агрегации по большому объёму. Частоты, доли ошибок, латентность выносят в метрики (counter/histogram) — они дёшевы, агрегируются и годятся для алертов. Разделение: метрики отвечают «сколько и как часто», логи — «что конкретно случилось».
#dvo_logging5 / 5
Зачем приложению в проде писать логи?
A)Чтобы ускорить работу приложения
B)Восстановить ход событий после сбоя
C)Чтобы хранить данные пользователей вместо базы
D)Чтобы автоматически исправлять возникшие ошибки
показать ответ и разбор
+B)Восстановить ход событий после сбоя
// разбор: Лог это след событий: по нему разбирают, что предшествовало сбою и на каком шаге всё сломалось. Данные в нём не хранят — это временный поток, который вдобавок стоит денег за объём.

дальше

Теорию прочитали. Навык ставится повторением

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

Открыть тренажёр Вся тема: Мониторинг и логи