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

Одна из больших проблем в Яндекс.Вертикалях были логи — 18 ТБ в день и 250 000 логов в секунду, все пишется в файлы. Логи разнородные, потому что много языков: Scala, Java, Python, Go. Потом их собирает 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 filebeat;
  
• на выделенной железной машине стояло приложение, которое читало топик Kafka и писало в файлы на диск.
  

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

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

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

Велосипед

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

Формат

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


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

Docker log driver

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

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

Проблемы

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


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

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

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

Общая схема

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



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

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

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

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

Профит

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

Для объемов поменьше рассмотрите альтернативные варианты: Humio, Splunk и Elastic. У двух последних есть официальные Docker-драйвера. Если вы вы живете в 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.

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

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

• Если используете общие балансеры — парсите логи с них и отправляйте в 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 со всем необходимым контекстом.

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

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

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

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

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

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

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

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

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