Практики 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..Правильный ответ

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

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

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

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

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

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

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

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

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

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

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

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

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

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

Что сделали:

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

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

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

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

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

При очередном перечитывании документов 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<string,string>)

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

• 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

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

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

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

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

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

Например, у нас он достает 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, о чем расскажем позже.