Практики SRE: стандартизация логов

Поиск логов в куче сервисов

Поиск логов в куче сервисов

Меня зовут Дима Синявский, я SRE-инженер в Ви.Tech — это IT-дочка ВсеИнструменты.ру. Наш сайт создает более 100 тысяч заказов каждый день. У нас много сервисов и много разработчиков, которые пишут много логов. Пишут их с целью разобраться в ситуации при сбое. В них нужно уметь ориентироваться и найти, то что тебе нужно, даже если ты видишь их впервые.

В предыдущих статьях я рассказывал как мы перешли на vector.dev с Elastic для обработки логов и как мы теперь считаем метрики по логам с его помощью.

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

Предыстория

В 2022 году я пришел на работу в Ви.Tech и погрузился в vector.dev для обработки логов. Это очень гибкое решение, позволяет собирать логи практически любой структуры с любых приложений. Собственно мы так и делали. Благо часть логов мы уже перевели на структурированные JSON логи и их было проще обрабатывать. 

У нас была куча разных трансформов в vector и таблиц в ClickHouse под каждый источник, под каждый сервис логов, часто код копировался из раза в раз с незначительными изменениями. Когда у тебя 5–10 приложений — это еще терпимо, но когда их становится все больше и больше…ты уже начинаешь уставать от повторения одинаковой работы. И хорошо бы это автоматизировать, но ведь все разное! Даже у соседних приложений в одном случае может быть поле cluster, в другом cluster_name, а значит и в базу данных их нельзя положить в один столбец без дополнительных преобразований и приведений к общему виду. И так каждое приложение может писать на свой лад, а нам все это надо поддерживать.

Попробовал работать с логами

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

Конечно классно чувствовать себя всезнайкой логов, но не в 2 часа ночи, когда сбойнул сервис, который ты видишь в первый раз, а логи в нем еще экзотичнее, чем когда-либо. Если нашел документацию на логи (кхм…вы ее видели когда-нибудь?), то тебе повезло. Не нашел — ищешь исходный код приложения и разработчика. Дозвонились до разработчика и он помог разобраться — опять тебе повезло! А я не дозвонился — сижу и читаю исходники. Сколько времени потрачено…уйма!

…то чувство когда, приложения разные, имена полей логов разные, а содержимое одинаковое

…то чувство когда, приложения разные, имена полей логов разные, а содержимое одинаковое

Поиграем в угадайку

Угадайте что вернет запрос к базе данных логов (у нас Clickhouse):

SELECT path, request_query FROM accesslogs

3…2…1…Правильный ответ

Правильный ответ - пусто и url

Правильный ответ — пусто и url

Угадали? Я нет.

В чем проблема?

Посмотрите на картинку ниже, это то что видят люди

Проекции истины

Проекции истины

А истина такова…

Это все лишь URL

Это все лишь URL

Но у каждого человека в голове своя ассоциация благодаря индивидуальному опыту

Проблема — называем одно и тоже по разному

Чем это плохо:

  1. Это вызывает непонимание у людей, неверное толкование данных.
    Бывало до смешного, говорим про http request query, смотрим в логи в Clickhouse, а там в поле request_query сервис пишет полный URL.

  2. Невозможно шаблонизировать запросы к логам.
    Если имена полей лога везде разные, то я не могу составить один запрос и потом в нем лишь менять имя сервиса, чтобы получить например логи доступа http. Если выбирать все поля с SELECT * еще куда ни шло, но если надо несколько полей только, то уже не сработает. 

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

  4. Разрастание схемы данных в БД.
    Так как у нас логи в ClickHouse мы храним их в таблицах, под каждый сервис своя таблица с набором колонок по именам полей. Вариантов наборов полей получается много, даже те же http логи доступа для разных приложений могут иметь разные наборы столбцов. 

Все это делает работу с логами разнообразной, но затратной и неприятной.

Приятная предсказуемая работа с логами. Как?

Мне захотелось переделать это все, чтобы стало проще и приятнее работать с логами, как нам, так и разработчикам. 

Что сделали:

  1. Донесли до разработчиков проблему, те ее приняли и пожелали участвовать в решении

  2. Решили для начала договориться о словаре — что мы и как называем

  3. Задокументировать договоренности и начать применять

Шел второй месяц обсуждений…

И тут случилось это

OpenTelemetry Logs Data Model – вот оно, чего нам не хватало.

OpenTelemetry Logs Data Model — вот оно, чего нам не хватало.

При очередном перечитывании документов OpenTelemetry по трейсингу, я вспомнил, что спецификация говорила и про логи, но так как для GoLang эта часть не реализована еще полностью, то мы не обращали на нее внимание. Начал я искать и нашел OpenTelemetry Logs Data Model — это оказалось ровно, то что мы начали создавать сами.  

Чем хороша OpenTelemetry Logs Data Model

  1. Опирается на семантические конвенции OpenTelemetry SemConv — это тот самый словарь, который мы начали составлять сами в команде. Тут же есть уже обширный реестр атрибутов с описаниями, он покрывает 80% наших нужд, а для остальных мы создаем дополнительный небольшой словарь локальных названий по правилам OpenTelemetry.

  2. Дает гибкую модель для представления и хранения логов — позволяет хранить любые логи не меняя структуру хранения.

Нам она оказалась близка еще потому, что наши разработчики уже используют библиотеки трассировки от OpenTelemetry, т.е. они уже видели имена из SemConv и неявно их соблюдают в части кода.

Стандарт для логов

Объединив наши договоренности с командами и изучив OpenTelemetry Logs Data Model мы за месяц создали и согласовали наш стандарт для логов. 

Фиксируем договоренности команды в стандарте для логов

Фиксируем договоренности команды в стандарте для логов

Что дал нам стандарт:

  1. Зафиксировал соглашения с командами:

    1. по именам — используем реестр атрибутов OpenTelemetry, где не хватает дополняем свой словарь по правилам именования OpenTelemetry

    2. по форматам — приложения пишут структурированные JSON-логи

    3. по структуре хранения логов — определили структуру хранения логов в БД Clickhouse

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

  2. Послужил отправной точкой для упрощения работы с логами в vector.dev

Реализация стандарта логов на практике

Что мы сделали:

  1. Шаблонный сервис и библиотеки кода (модули, пакеты)  адаптировали для логирования по стандарту логов.
    Теперь разработчики не должны заботится о формате логов и названии обязательных полей в них, часто используемые имена полей вынесены в пакет констант. Это упрощает разработку и позволяет делать меньше опечаток

  2. Переделали код трансформов в vector.dev
    Теперь у нас для всех логов единый набор обработчиков для логов — Unified Log Pipeline

  3. Договорились новые сервисы принимать только с логами по нашему стандарту.
    Нет разночтений, не нужно писать новые трансформы в vector.dev

Реализация стандарта заняла у нас 4 месяца, но у вас может получиться быстрее, вы теперь знаете куда и как идти.

Как теперь собираются логи

Модель хранения логов в БД

  • ServiceName — имя источника логов, тип string

  • Timestamp — время события лога, тип DateTime64

  • ObservedTimestamp — время приема лога в vector, тип DateTime64

  • SeverityText — серьезность события (log level), тип string

  • Body — текстовое сообщение или оригинальная запись, тип string

  • Resource — информация о среде, где создан лог (тип map)

  • Attributes — атрибуты структурированного лога, что передало приложение  (тип map)

  • TraceId, SpanId, TraceFlags — данные контекста трассировки, тип string

Пример работы с логами

1. Отправляем лог из приложения

import "vitech/pkg/http_accesslog_needdleware”

zlog.Str(semconv.ServerAddressKey, r.Host).
	 Str(semconv.HTTPMethodKey, r.Method).
 	 Str(semconv.HTTPSchemeKey, httpScheme(r)).
	 Str(semconv.URLPathKey, r.URL.Path).
	 Str(semconv.URLQueryKey, r.URL.RawQuery).
 	 Int(semconv.HTTPStatusCodeKey, r.Status()).
	 Info(‘http request received’).Send()

2. vector.dev агрегатор получает лог виде JSON

{ 
	'Timestamp': '2023-01-04 17:27:29.880230118',
	'SeverityText': 'INFO', 
	'Body': 'http request received', 
	'TraceId': 'b2fa3d72711c1adad9ec88348c46f449', 
	'SpanId': '85733005b2678b28', 
	'TraceFlags': 0,
	'server.address': 'promo',
	'http.method': 'GET',
	'url.scheme: 'https',
	'url.path': '/adv/1232',
	'url.query': 'short=1',
	'http.status_code': 200
}

3. Лог проходит обработку и сохраняется в Clickhouse

Путь лога от приложения через агент vector к хранилищу логов

Путь лога от приложения через агент vector к хранилищу логов

4. Смотрим логи в Clickhouse

SELECT * FROM unified_logs.logs 
WHERE ServiceName = 'promo' FORMAT vertical;

Рассмотрим полученную запись по частям. Ниже выделены те данные, которые мы получили от приложения

Данные лога, которые мы получили от приложения

Данные лога, которые мы получили от приложения

Далее vector.dev агент добавил информацию о среде в которой был создан лог, в данном случае это Kubernetes.

Vector.dev агент добавил информацию о среде в которой был создан лог

Vector.dev агент добавил информацию о среде в которой был создан лог

Затем vector.dev агрегатор получил сообщение, обогатил данными и записал в Clickhouse. 

Vector.dev агрегатор обогатил сообщение данными

Vector.dev агрегатор обогатил сообщение данными

Например, у нас он достает service_name из аннотации pod и кладет в поле ServiceName модели хранения, проставляет время приема лога агрегатором.

Теперь любой лог может быть сохранен в ClickHouse.

Теперь обработка логов ОДИНАКОВА для всех наших приложений!

Одинаково! Одинаково! Одинаково!

Одинаково! Одинаково! Одинаково!

Прием логов от сторонних приложений

Не все приложения в ИТ-ландшафте могут давать вам возможность изменить формат логов и названия их полей под стандарт. Но собирать их все таки хочется и иногда надо. Как же их встроить в Unified Log Pipeline?

Вариант 1. Сохраняем как есть

Если сообщение будет не в JSON — мы сохраним первые 65535 символов текста в поле Body, а в дополнительное служебное поле PipelineErrors запишем признак, что сообщение было слишком большим. Да мы не разберем лог и работать надо будет со строкой, но он у нас будет в едином хранилище доступен для просмотра и поиска!

Вариант 2. Расширение через адаптеры 

Vector.dev строит иерархию компонентов обработки в виде графа и позволяет использовать подстановочные символы при указании источника, чтобы подключить компоненты-источники динамически. Это дает нам возможность сделать «порт для адаптеров» в нашем пайплайне в виде input=["ulp-adapter-*"], он подхватит все компоненты ulp-adapter. 

Так что такое адаптер?  

Адаптер это компонент vector, который принимает сообщение лога, средствами vector парсит его в объект-событие vector — это то, что мы обычно делаем с JSON-логами. Просто тут в адаптере придётся описать структуру строки, чтобы vector понял откуда взять и в какое поле события себе положить. Например, в vector встроен мощный парсер parse_grok. Список доступных парсеров смотрите в документации к vector.

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

Вариант 3. Подготовка на агентах

Можно написать трансформ прямо в vector-агент на машине, где работает нужное вам стороннее приложение. С его помощью считанные логи будут преобразованы перед отправкой в подходящий нам JSON. Следует учитывать, что это создает дополнительную нагрузку на машину. Чем сложнее преобразования (например, очень много сложных регулярных выражений), тем больше нагрузка от vector-agent при обработке логов.

Как удалось сделать обработку логов унифицированной

  1. Стандарт логов закрепил договоренности.

  2. Vector.dev + ClickHouse дали возможность сделать обработку и хранение универсальными

В итоге эта реализация у нас получила название »Unified Log Pipeline (ULP)».

Что дал Unified Log Pipeline

  1. Единый код и тесты обработчиков vector.dev для всех сервисов:

    • раньше на каждый новый сервис нужно было писать и отлаживать код для vector.dev агрегатора

    • теперь, чтобы подключить новый сервис, достаточно подправь конфиг сервиса в Kubernetes и применить его

  2. Наш механизм генерации метрик по логам стал более универсальным, если ранее мы могли делать метрики из http-логов доступа, то теперь можем из любых логов

  3. Единая структура хранения в ClickHouse для всех приложений — теперь структура не меняется, это легче поддерживать, можно шаблонизировать и переиспользовать запросы

  4. Сократилось время подключения логов для сервиса

    • раньше уходило от 3 до 5 часов на написание и тестирование кода для vector.dev

    • теперь 10–20 минут — добавить аннотацию в pod сервиса и применить, это от 18 до 30 раз меньше затрат времени.

Остались некоторые нераскрытые вопросы

Например:

  • Как управлять сроком хранения логов в ULP?

  • Как собирать логи в ULP не с Kubernetes?

  • Как в ULP реализовано включение логов через аннотации pod?

  • Как в ULP исключать логи из части контейнеров kubernetes?

  • Как удалось в ULP сделать более универсальным механизм подсчета метрик по логам?

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

Как это может быть полезно вам

Полезности тут

Полезности тут

  1. Договоритесь и используйте семантические конвенции OpenTelemetry — теперь у вас есть базовая документация на логи и описание, что где лежит. Это снижает когнитивную нагрузку на инженеров, и затраты времени на «рассказать как это устроено»

  2. Попробуйте OpenTelemetry Logs Data Model, как основу для своего стандарта для логов. Он дает гибкость в работе с логами и обеспечивает наличие необходимых базовых данных для логов. Можете применить наши наработки и дополнить их своими. Пробуйте менять модель под себя.

Заключение

Стандартизация логов позволила нам договорится об именах, форматах логов, стандартизировать библиотеки и облегчить работу разработчикам, в том числе и за счет шаблонизации запросов для выборки логов. Да и SRE стало легче поддерживать систему сбора, обработки и хранения логов — отпала необходимость часто менять и расширять код обработчиков vector.dev. Теперь у нас есть волшебный тумблер включения/отключения сбора логов, вместо часов разработки и отладки кода для vector.

Это была отличная и интересная задача. Выражаю благодарность нашей команде SRE!

Мы не остановились и продолжаем совершенствовать наше решение Unified Log Pipeline, о чем расскажем позже.

© Habrahabr.ru