Меня зовут Дима Синявский, я 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 accesslogs3..2..1..Правильный ответ
Угадали? Я нет.
В чем проблема?
Посмотрите на картинку ниже, это то что видят люди
А истина такова...
Но у каждого человека в голове своя ассоциация благодаря индивидуальному опыту
Проблема – называем одно и тоже по разному
Чем это плохо:
Это вызывает непонимание у людей, неверное толкование данных.
Бывало до смешного, говорим про http request query, смотрим в логи в Clickhouse, а там в поле request_query сервис пишет полный URL.Невозможно шаблонизировать запросы к логам.
Если имена полей лога везде разные, то я не могу составить один запрос и потом в нем лишь менять имя сервиса, чтобы получить например логи доступа http. Если выбирать все поля с SELECT * еще куда ни шло, н�� если надо несколько полей только, то уже не сработает.Усложнение поиска логов в инциденте.
Как я писал выше, вам придется потратить время на знакомство с структурой логов и осмысление названий и значений, иногда без посторонней помощи или чтений исходников не обойтись.Разрастание схемы данных в БД.
Так как у нас логи в ClickHouse мы храним их в таблицах, под каждый сервис своя таблица с набором колонок по именам полей. Вариантов наборов полей получается много, даже те же http логи доступа для разных приложений могут иметь разные наборы столбцов.
Все это делает работу с логами разнообразной, но затратной и неприятной.
Приятная предсказуемая работа с логами. Как?
Мне захотелось переделать это все, чтобы стало проще и приятнее работать с логами, как нам, так и разработчикам.
Что сделали:
Донесли до разработчиков проблему, те ее приняли и пожелали участвовать в решении
Решили для начала договориться о словаре – что мы и как называем
Задокументировать договоренности и начать применять
Шел второй месяц обсуждений…
И тут случилось это
При очередном перечитывании документов OpenTelemetry по трейсингу, я вспомнил, что спецификация говорила и про логи, но так как для GoLang эта часть не реализована еще полностью, то мы не обращали на нее внимание. Начал я искать и нашел OpenTelemetry Logs Data Model – это оказалось ровно, то что мы начали создавать сами.
Чем хороша OpenTelemetry Logs Data Model
Опирается на семантические конвенции OpenTelemetry SemConv – это тот самый словарь, который мы начали составлять сами в команде. Тут же есть уже обширный реестр атрибутов с описаниями, он покрывает 80% наших нужд, а для остальных мы создаем дополнительный небольшой словарь локальных названий по правилам OpenTelemetry.
Дает гибкую модель для представления и хранения логов – позволяет хранить любые логи не меняя структуру хранения.
Нам она оказалась близка еще потому, что наши разработчики уже используют библиотеки трассировки от OpenTelemetry, т.е. они уже видели имена из SemConv и неявно их соблюдают в части кода.
Стандарт для логов
Объединив наши договоренности с командами и изучив OpenTelemetry Logs Data Model мы за месяц создали и согласовали наш стандарт для логов.
Что дал нам стандарт:
Зафиксировал соглашения с командами:
по именам – используем реестр атрибутов OpenTelemetry, где не хватает дополняем свой словарь по правилам именования OpenTelemetry
по форматам – приложения пишут структурированные JSON-логи
по структуре хранения логов – определили структуру хранения логов в БД Clickhouse
по ограничениям – договорились о максимальной длине сообщения лога, это важно с точки зрения расчета ресурсов на их хранение
Послужил отправной точкой для упрощения работы с логами в vector.dev
Реализация стандарта логов на практике
Что мы сделали:
Шаблонный сервис и библиотеки кода (модули, пакеты) адаптировали для логирования по стандарту логов.
Теперь разработчики не должны заботится о формате логов и названии обязательных полей в них, часто используемые имена полей вынесены в пакет констант. Это упрощает разработку и позволяет делать меньше опечатокПеределали код трансформов в vector.dev
Теперь у нас для всех логов единый набор обработчиков для логов – Unified Log PipelineДоговорились новые сервисы принимать только с логами по нашему стандарту.
Нет разночтений, не нужно писать новые трансформы в 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 при обработке логов.
Как удалось сделать обработку логов унифицированной
Стандарт логов закрепил договоренности.
Vector.dev + ClickHouse дали возможность сделать обработку и хранение универсальными
В итоге эта реализация у нас получила название “Unified Log Pipeline (ULP)”.
Что дал Unified Log Pipeline
Единый код и тесты обработчиков vector.dev для всех сервисов:
раньше на каждый новый сервис нужно было писать и отлаживать код для vector.dev агрегатора
теперь, чтобы подключить новый сервис, достаточно подправь конфиг сервиса в Kubernetes и применить его
Наш механизм генерации метрик по логам стал более универсальным, если ранее мы могли делать метрики из http-логов доступа, то теперь можем из любых логов
Единая структура хранения в ClickHouse для всех приложений – теперь структура не меняется, это легче поддерживать, можно шаблонизировать и переиспользовать запросы
Сократилось время подключения логов для сервиса
раньше уходило от 3 до 5 часов на написание и тестирование кода для vector.dev
теперь 10-20 минут – добавить аннотацию в pod сервиса и применить, это от 18 до 30 раз меньше затрат времени.
Остались некоторые нераскрытые вопросы
Например:
Как управлять сроком хранения логов в ULP?
Как собирать логи в ULP не с Kubernetes?
Как в ULP реализовано включение логов через аннотации pod?
Как в ULP исключать логи из части контейнеров kubernetes?
Как удалось в ULP сделать более универсальным механизм подсчета метрик по логам?
Эти вопросы требуют развернутого ответа и выходят за рамки данной статьи, к тому же мы продолжаем совершенствовать наше решение.
Как это может быть полезно вам
Договоритесь и используйте семантические конвенции OpenTelemetry – теперь у вас есть базовая документация на логи и описание, что где лежит. Это снижает когнитивную нагрузку на инженеров, и затраты времени на “рассказать как это устроено”
Попробуйте OpenTelemetry Logs Data Model, как основу для своего стандарта для логов. Он дает гибкость в работе с логами и обеспечивает наличие необходимых базовых данных для логов. Можете применить наши наработки и дополнить их своими. Пробуйте менять модель под себя.
Заключение
Стандартизация логов позволила нам договорится об именах, форматах логов, стандартизировать библиотеки и облегчить работу разработчикам, в том числе и за счет шаблонизации запросов для выборки логов. Да и SRE стало легче поддерживать систему сбора, обработки и хранения логов – отпала необходимость часто менять и расширять код обработчиков vector.dev. Теперь у нас есть волшебный тумблер включения/отключения сбора логов, вместо часов разработки и отладки кода для vector.
Это была отличная и интересная задача. Выражаю благодарность нашей команде SRE!
Мы не остановились и продолжаем совершенствовать наше решение Unified Log Pipeline, о чем расскажем позже.
