Хабрахабр

Логи не нужны?

Разработка сильно изменилась за последние годы. Вместо монолитных приложений пришли микросервисы и функции. Базы данных из универсальных промышленных монстров переродились в узконаправленные. Docker изменил взгляд на деплой. Но изменилось ли наше представление о логах?

Логи разнородные, потому что много языков: Scala, Java, Python, Go. Одна из больших проблем в Яндекс.Вертикалях были логи — 18 ТБ в день и 250 000 логов в секунду, все пишется в файлы. При этом это уже третья версия логов. Потом их собирает Fluent Bit, пишет в Kafka, на одной железной машине работают обработчики, собирают из Kafka и пишут всё на диск.

По этим логам поиск идет с помощью grep. Как следствие, возникает проблема долгого поиска. Если у вас есть проблемы в продакшн, вы не будете часами искать свои логи. На некоторых сервисах grep может достигать часов. Что из этого получилось, расскажет Алексей Данилов (danevge) — разработчик команды инфраструктуры в Яндекс.Вертикалях. Чтобы решить проблему, в Яндекс решили написать свой велосипед доставки логов для поиска. Разрабатывает, пишет и поддерживает проекты auto.ru и Яндекс.Недвижимость.

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

Статья — расширенная версия доклада Алексея Данилова «Логи не нужны» на РИТ++ 2019 DevOps Conf, которая стилистически изменена и дополнена новым материалом. Примечание. Видеозапись выступления Алексея вы можете найти по ссылке на нашем YouTube-канале.

В команде Яндекс.Вертикалки 300 человек, примерно 100 из них — разработчики. В разработке мы ничем не отличаемся от большинства компаний, которые создают собственные продуктовые решения. Микросервисы, все живет в Docker, в темном углу пылится монолит на PHP, деплоим посредством Hashicorp Nomad и держим зоопарк языков: Scala, Java, Go, Node.js, Python.

Когда мы серьезно подошли к этой проблеме, то использовали уже третью версию их сбора и обработки. Одна из больших проблем инфраструктуры в Яндекс.Вертикалях — логи приложений. Упрощенно это работало так:

  • приложения писали в файлы;
  • Fluent Bit читал файлы и построчно отправлял в Kafka;
  • на выделенной железной машине стояло приложение, которое читало топик Kafka и писало в файлы на диск.

В горячее время у нас было 18 ТБ логов в день или 250 000 строк в секунду. Это очень большой объем, который усложняет работу с этими данными. Единственный способ анализа — это grep, так как все хранится в файлах. Для больших приложений анализ мог длиться часами. При проблемах в продакшн у вас нет этого времени.

Они не могли приемлемо обработать наш поток. Готовые решения не подходили по цене, ресурсам или скорости. Предполагаю, что мы не умеем его готовить. Сложно даже подсчитать количество попыток приготовить Elasticsearch. Но это и не то, что нам нужно, если для его использования, как хранилища логов, требуются особые способности (скилы).

В такой ситуации мы решили реализовать собственную систему сбора и анализа логов.

Велосипед

Примечание: Если очередной велосипед не интересен, то переходите сразу к разделу «Типизация».

Формат

Мы используем несколько ЯП и любим микросервисы. Чтобы работать с логами однообразно сформировали собственный JSON-формат. Он закрывает большинство потребностей в дальнейшей работе с логами.


Пример логов со всеми возможными полями.

Docker log driver

Для сбора логов мы написали собственный docker log driver — приложение на Go. Оно собирается специальным образом, доставляется командами docker plugin, хранится в registry и работает в единственном экземпляре под управлением Docker.

Наш драйвер слушает stdout контейнера и сразу же передает логи в приложение, которое стоит рядом. Так как любые проблемы с log driver могут негативно повлиять на всю работу, мы старались написать минимальную реализацию. Уже оно занимается более сложной частью доставки.

Проблемы

Отдельно упомяну проблемы обновления версии docker log driver.


Скриншот с внутренней Grafana.

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

Для этого пришлось бы перезапустить все контейнеры и все сервисы, что могло вылиться в проблемы. Docker-драйвер нельзя пойти и сразу обновить. Поэтому, чтобы установить новую версию, мы просто ждем, когда все контейнеры обновятся сами.

Общая схема

Рассмотрим общую схему новой системы сбора и доставки логов. Остальные подробности не так интересны.

Docker слушает pipe из контейнера и перенаправляет его Docker-драйверу. Приложения пишут логи в JSON-формате в stdout. Docker-драйвер читает и аcинхронно переплавляет все в Pusher.

Он готовит, насыщает, батчует и пушит логи в яндексовую Message Queue. Pusher стоит на каждой железной машине. Поток логов из MQ разбирается тремя типами воркеров и пишется в хранилища.

Хранилищ для записи логов три.

  • Яндексовый mapReduce для хранения и анализа логов за длительный период времени. Это аналог Hadoop.
  • ClickHouse для хранения логов в течении последних суток.
  • Humio (как эксперимент) для хранения логов за последние сутки.

Профит

Общий формат позволяет одинаково писать логи и обрабатывать. Сбор логов автоматический, без использования диска, а доставка — в районе пары секунд. Ключевые поисковые запросы от 2 секунд до 5 секунд. Хранение и поиск за большой период времени.

У двух последних есть официальные Docker-драйвера. Для объемов поменьше рассмотрите альтернативные варианты: Humio, Splunk и Elastic. Если вы вы живете в AWS, то есть Amazon CloudWatch.

Amazon CloudWatch

Amazon CloudWatch обрабатывает метрики, события и логи. Последние он не ищет, не дает суперпоисковых штуко и обрабатывает не в привычном виде. Amazon CloudWatch обрабатывает логи, анализирует, фильтрует и показывает на графиках.


Amazon CloudWatch преобразует логи в метрики и графики.

Что делать с логами?

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

Это путь в ад. Как только вы соберете логи, то следующее предложение будет: «Давайте что-нибудь распарсим, как-нибудь обработаем, где-нибудь запишем и начнем выводить на графиках, на дашбордах». Особенно, если мы говорим об общих инструментах.

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

Это будет большое месиво информации, которое не получится обработать. Начнется игра в формализование логов: «Давайте мы вот эти строчки будем писать в особом формате, чтобы потом их было удобно парсить!». Так тоже не работает. Поверьте, мы пробовали.

Типизация

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

Just in case

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

// validate customer
func Validate(customer Customer) { // ??? log.debug(“Validate customer %v”, customer) … log.Error(“Customer not valid %v. Reason: %s”, ...) ….
}

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

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

Но тогда мы сталкиваемся с новой проблемой. Правильный путь — выбросить их и забыть. Как разобрать ситуацию при ошибке?

Fatal/Critical error

Для начала рассмотрим только критические ошибки. Это ошибки из-за которых страдают пользователи и разработчики. Первые — когда не могут совершить операцию. Вторые — когда нужно вносить исправления руками.

Почему не подходят логи?

Если об ошибке команда разработки узнает от пользователей через поддержку или из Twitter, то пора что-то менять. Нет быстрой реакции.

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

Нет ответа на вопросы: Нет общей картины.

  • как часто возникает такая ошибка;
  • она произошла на остальных репликах сервиса;
  • была ли раньше?

Чтобы исправить эти проблемы, используйте подходящий инструмент, например, sentry.io. Он позволяет работать с репрезентативной, полной (содержащей контекст) информацией об ошибке с настраиваемыми alerting rule. На сайте sentry описаны различия логов от использования sentry.io.

Not critical error

Мы выбросили фатальные и критические ошибки и теперь они пишутся в Sentry. Но остались внутренние ошибки — различные библиотеки или ответы от сторонних сервисов.

Допустим, сервис А обратился к сервису В, но, из-за проблем с сетью, не смог получить ответ. Хороший пример — успешный retry. Ошибка при первом обращении критическая? После ошибки сервис А повторно обратился к сервису В и получил валидный ответ. В данном случае процесс завершился успешно, а пользователь смог воспользоваться сервисом. Нет.

Это деградация сервиса, хоть ответ пользователю и пришел на 50 мс позднее. Если для работы сервиса подобные ошибки не критические и они не влияют на пользователя при редком повторении, то это вовсе не ошибки. Такой тип логов относится к предупреждениям — Warning.

Warning

Предупреждения — это информация о деградации сервиса.

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

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

Чтобы проследить за изменениями за длительный интервал времени было бы неплохо иметь также ретроспективный анализ. Но одновременно с этим нужно иметь инструмент для просмотра общей картины, нужен анализ в реальном времени. Деградации выше определенного уровня (thresholds) могут негативно сказаться на пользователях — нужна реакция при сильной деградации.

Нужны не логи с пометкой Warning, а метрики деградации.

Популярнейший инструмента для сбора метрик — Prometheus, а для визуализации можно использовать Grafana. Если требуется большой контекст (такой же, как у ошибки), то подойдет тот же Sentry, но с выключенными оповещениями. Однако, в большинстве случаев будет достаточно контекста. Он будет использоваться для графиков — Prometheus labels.

Примеры.

В условном user_service произошли три события. Они влияют на работу сервиса: долгий запрос к БД, повторное обращение к API сервиса service_b и не были найдены права пользователя в кэше. Графики и алерты будут настроены так, как это важно разработчикам сервиса, благодаря контексту.

Tracing

Это первое с чего бы пришлось начать, если бы мы выбрали путь, где нужно парсить логи. Сама по себе эта информация в логах бесполезна, потому что нужно строить цепочки вызовов, видеть данные внутри запросов, ошибки в цепочках вызовов, времена ответов, количество RPS.

Советую использовать OpenTracing, который они оба поддерживают. Для трассировки есть отличные инструменты — Jaeger или Zipkin.

Собирать трейсинг можно из трех источников.

  • Если используете общие балансеры — парсите логи с них и отправляйте в Jaeger.
  • Сами сервисы, если они получают адреса через Service Discovery и ходят напрямую. В данном случае трассировка из сервисов отправляется напрямую в Jaeger.
  • Умный service mesh. Он умеет сам собирать и отправлять трассировку, например, Istio.

Initial information

Это информация о вызовах API сервиса, запуске Cron, запросах в БД или вызовах других сервисов.

{ "_message": "Request: ...; request_id: ...,... ", "_level": "INFO", "_time": "2019-03-08T12:04:05.000+07:00", "_context": "r.y.a.w.v.c.Handler", "_tread": "785534"
}

Эта информация относится к блоку «Just in case», но стоит отдельно, потому что встречается чаще. Эта информация нужна для разбора ошибки и ее можно выбросить.

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

Execution time

Это информация о времени выполнении методов, API, запросах БД или других сервисов.

{ "_message": "Get customer 12ms", "_level": "INFO", "_time": "2019-03-08T12:04:05.000+07:00", "_context": "r.y.a.w.v.c.CustomerRepository", "_tread": "785534"
}

В логах от нее нет ценности, потому что нужно эту информацию анализировать, отображать на графиках, настраивать thresholds. Этот тип логов нужно заменить на метрики, например, в Prometheus.

Business info

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

Приложения писали бизнес-логи в выделенный файл. Для логов с бизнес-данными были сформированы соглашения с фиксированными полями в формате TSKV, которые необходимы для аналитики. Это пример того во что превращается любой парсинг. Дальше логи читались и построчно отправлялись в MQ, а отдельное приложение их обрабатывало и записывало в БД.

Не получится парсить весь поток логов в надежде, что данные сойдутся.

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

Уже там они будут обработаны, сохранены в соответствующее хранилище и использованы командой аналитики. Хорошее решение — прямая отправка этих данных в MQ. Например, для отображения мы используем Tableau.

Performance

Это тип логов редко встречается в логах приложений и чаще собирается как метрика. Отдельно добавлю, что для сбора базовых метрик, которые специфичны для языка, достаточно использовать библиотеку Prometheus. Она по умолчанию соберет все до чего дотянется. Цена добавления этих метрик небольшая.

Итог типизации

Разобрав логи по типам мы можем подобрать более мощные инструменты для работы с ними. Здесь нет сложных систем или космических технологий как у Amazon, нет того, что нельзя поднять уже завтра. Вероятно, часть из этих систем или аналоги у вас уже есть: где-то пылится Sentry, где-то работает Prometheus.

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

Есть исключение — Debug-логи, которые можно применять в редких случаях.

Debug log

Debug-логи должны представлять из себя развернутую информацию. Они не должны дублировать то, что уже отправляется в системы, которые мы описали выше. Этот тип существует для разбора особых случаев. Например, на продакшн происходит непонятный баг, а в моменте по метриками непонятно, что происходит.

Так как мы говорим о нескольких сервисах, то их не будет много. Debug-логи включайте на горячую, без перезапуска сервиса. Достаточно ELK стека без сложного «приготовления». Сложная инфраструктура не нужна. Также имеет смысл добавить алерт в Sentry со всем необходимым контекстом.

Но их отлично заменяет debugging. Debug-логи можно использовать для разработки.

Подведем итоги

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

Логи в сыром виде бесполезны, но их можно превратить в полезные метрики.

Достаточно создать инфраструктуру доставки полезных метрик и данных вокруг сервисов. В результате появятся полезные метрики, которые говорят о сервисах, и прозрачно показывают все, что с ними происходит.

Ошибки должны содержать контекст самой ошибки.

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

Debug имеет место быть, но с ним надо быть строгим. Правильные инструменты сделают работу с вашими сервисами приятнее и прозрачнее.

Полный список тем и тезисов смотрите на отдельной странице «Доклады». На HighLoad++ 2019 в ноябре будет секция DevOps — 13 докладов о нагрузках в AWS, системе мониторинга в Lamoda, конвейерах для поставки моделей, жизни без Kubernetes и многом другом. А на DevOpsConf встретимся весной — подписывайтесь на рассылку, сообщим, когда определим даты и локацию.

Показать больше

Похожие публикации

Добавить комментарий

Ваш адрес email не будет опубликован. Обязательные поля помечены *

Кнопка «Наверх»