Логирование и трассировка запросов — лучшие практики. Доклад Яндекса

Моя цель - предложение широкого ассортимента товаров и услуг на постоянно высоком качестве обслуживания по самым выгодным ценам.
В Яндекс.Маркете большая микросервисная архитектура. Браузерный запрос главной страницы Маркета рождает десятки вложенных запросов в разные сервисы (бэкенды), которые разрабатываются разными людьми. В такой системе бывает сложно понять, по какой именно причине запрос упал или долго обрабатывался.


Анатолий Островский megatolya объясняет, как его команда решила эту проблему, и делится практиками, специфичными для Маркета, но в целом актуальными для любого большого сервиса. Его доклад основан на собственном опыте развёртывания нового маркетплейса в довольно сжатые сроки. Толя несколько лет руководил командой разработки интерфейсов в Маркете, а сейчас перешёл в направление беспилотных автомобилей.

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



При этом наши фронтенды ходят во многие бэкенды. Иногда эти бэкенды похожи между собой (разные инстансы одного и того же приложения). А иногда они уникальны для сервиса (особенный биллинг). Структуру такой системы можно считать классической микросервисной архитектурой.

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



Backend 2 может «гореть» или для конкретного товара, или в конкретное время, или для конкретных пользователей. Нам нужно уметь реагировать на любую ситуацию.



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

Есть много ступеней погружения в эту тему. О каждой из них я коротко расскажу.



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

Единая система идентификации запросов




Это один из самых простых инструментов для понимания того, что сейчас происходит с сервисом. Договоритесь с коллегами, что, например, ваш фронтенд генерирует какой-то id-запрос (переменная requestId на картинке) и далее прокидывает его во все endopoints бэкендов. А бэкенд сам уже ничего не перепридумывает. Он берет пришедший requestId и прокидывает его дальше в запросах к своим бэкендам. При этом он может указать свой префикс, чтобы среди одинаковых requestId можно было найти именно этот бэкенд.



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



Все наши логи промаркированы такими id, чтобы не только понимать, что и в какой момент произошло, но и сохранять контекст этого запроса. Он асинхронный, может сам попозже что-то в лог дописать. А если грепнуть по requestId, ничего хорошего не выйдет.

cURL


Для воспроизведения проблемы мы используем утилиту cURL. Это консольная утилита, которая делает сетевые запросы — http и https. cURL поддерживает еще много разных протоколов, но, занимаясь веб-разработкой, проще считать, что это инструмент для работы с http(s)-запросами.



Чтобы познакомиться с командой cURL, можно зайти на любой сайт, затем зайти в Network и скопировать любой запрос в виде cURL. Получится такая большая строка:



Если постараться разобраться, то здесь нет ничего страшного. Давайте попробуем разобрать его по частям.



Здесь написан запрос к сайту market.yandex.ru.



Здесь добавился User-Agent, который занимает уже много места.



На самом деле все остальное место занимают куки. Их довольно много в коде Яндекса. В сериализованном виде у них весьма грозный вид. По факту кроме них здесь больше ничего и нет.

Так чем же полезен cURL? Если бы вы скопировали его себе и запустили, то увидели ту же самую страницу market.yandex.ru, что и я — отличался бы лишь компьютер, на котором он запускался. Конечно, отличия в IP-адресах могло бы дать некоторые сайд-эффекты, но в целом это были бы одинаковые запросы. Мы бы с вами воспроизвели один и тот же сценарий.



Чтобы каждый раз самим не изобретать такие cURL-запросы, можно воспользоваться npm-пакетом format-curl.



Он принимает в себя все параметры запроса, которые обычно принимает функция — то есть в данном случае только заголовки и url. Но также он умеет query, body и т. д. А на выходе получаем просто строку с cURL-запросом.



Поэтому все наши логи в dev-окружении также содержат сURL-запросы.



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



Учтите, что cURL-запросы подразумевают передачу сессионных куки — это плохо. Если бы вы мне скинули свой cURL-запрос в market.yandex.ru, то я мог бы войти под вашим логином в Маркет и любой другой сервис Яндекса. Поэтому такие запросы мы нигде не храним, а логируем их только в тестовых стендах для себя — таким данным нельзя утекать.

ClickHouse


Далее я расскажу про структурированные логи. Здесь я буду иметь в виду конкретную базу данных ClickHouse, но вы можете выбрать любую. ClickHouse — столбцовая СУБД, в ней удобнее делать select из огромного количества данных и принимать в себя большие чанки данных. Она хороша тем, что в ней можно сохранить большой кусок лога и потом, например, сделать какую-то агрегацию по миллиарду записей.



В данном случае пример select по ClickHouse — обычный SQL. Здесь мы показываем количество запросов по статус-кодам за сегодняшний день.



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



Можно сказать, что отношение двухсоток к отношению общего числа ответов — это Service Level Indicator, который отвечает на вопрос, насколько хорошо работает наше приложение в плане статус-кодов. Он хоть и простой, но уже о чем-то говорит.



На основе нашего индикатора мы можем придумать первый SLI, то есть сказать, например, что 99% наших запросов должны быть ОК. И здесь можем сравнить, что мы выполнили свой SLI. Если бы не выполнили, то могли бы постараться разобрать либо какие-то последние запросы, которые бы пятисотнули, либо просто критичные вещи.



Например, для нас критичны ошибки оплаты, но в данном случае они вернут ноль — повезло :)



Как добиться того, чтобы ваши логи лежали в таком удобном виде, и их можно было забирать через SQL?



Это тема для отдельного большого доклада, и всё сильно зависит от вашей инфраструктуры. Но кажется, здесь есть два пути. Первый: сабмитить метаданные напрямую в runtime, сразу в базу данных. Мы делаем иначе, вторым способом: следим за файлом логов и сабмитим чанками либо тоже в БД, либо в промежуточное место.

У нас это довольно многослойно работает — мы отправляем логи из конкретного инстанса на удаленный сервер-хранилище таких логов.

Трассировка запросов


Нет понятия «трассировка запросов». Этот термин придумали в Google.



Если поискать в интернете «трассировка запросов», то вы встретите команду traceroute. Возможно, это похоже на трассировку запросов.



Есть даже консольная программа, и здесь я ее выполнил для сайта bringly.ru (сервис, который мы разрабатывали прошлой весной). Она помогает понять, через какие машины и сервера проходит запрос перед тем, как попадает на балансер, который ответит либо версткой, либо чем-то другим.



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



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



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



А вот пример трассировки, когда мы не пошли ни в один бэкенд, а сразу дали статус 500. Чем нам полезна такая трассировка? Нам не придется тревожить коллег. У нас есть id этого запроса, поэтому мы можем сами посмотреть в логи и разобраться, что происходит.



Здесь обратная ситуация. Бэкенд сказал, что что-то не так и при этом написал в метаинформации, что именно произошло — появился какой-то стек-трейс.



Как сделать себе такой же инструмент?

Самое важное здесь — база данных. Если у вас есть простейший «INSERT INTO» в базе каких-то действий с сервисом, позже можно будет как минимум с помощью SQL находить нужные события. А при необходимости можно сделать к этому интерфейс.

Графики


Это очень интересная тема, подробно останавливаться на ней сегодня, конечно, не буду :)



Поговорим именно про логирование. Графиков у нас много, мы на них смотрим, когда что-то выкатываем — и в таймингах происходит такой шум.



Графики помогают визуально увидеть, что что-то не так. А дальше нужно все равно смотреть в логи и по ним понимать, что конкретно не так. В данном случае всплеск сразу после релиза как минимум означает, что такой релиз нужно немедленно откатывать.

Мониторинги


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



Мы мониторим соотношение пятисоток к общему числу ответов в минуту. Также мониторим четырехсотки, наличие нагрузки на сервис, проверку ручки health check, который дергает ручку ping каждого из бэкендов и т. д.



Кроме того, у нас есть дашборды мониторингов, которые мы включаем на экранах около рабочих мест. Так мы сразу видим, какие из мониторингов «краснеют». Например, здесь это один из основных, где виден фронтенд и наш основной бэкенд. Здесь видно, что у бэкенда загорелись какие-то мониторинги. Это значит, что в тот момент ответственному за этот сервис придет сообщение в Telegram, либо, возможно, ему даже позвонят — зависит от настройки мониторинга.

Итоги


Единый requestId поможет вам проще находить проблемы в сервисе, который состоит из нескольких приложений. Правильный cURL позволит точнее воспроизводить проблемы и видеть, как вы сами, например, отправляете данные в бэкенд. Структурированные логи позволят придумывать SLI, а ими удобнее пользоваться, чем обычными текстовыми логами. И не забывайте следить за графиками и проводить мониторинги.

Рекомендую почитать книгу Site Reliability Engineering от Google, если вам интересны инфраструктурные вещи.
Источник: https://habr.com/ru/company/yandex/blog/489048/


Интересные статьи

Интересные статьи

Litho — UI-фреймворк от Facebook, который отвечает за быстрый рендеринг тяжелого UI в топовых приложения с миллиардами загрузок. Как его использовать, что происходит под капотом, и...
Первый шаг развертывания в Kubernetes – это размещение вашего приложения в контейнере. В этой серии мы рассмотрим, как можно создать образ небольшого и безопасного контейнера. Бл...
Предлагаю ознакомиться с расшифровкой доклада Романа Хавроненко "ExtendedPromQL" Читать дальше →
Чем Java отличается от других популярных языков? Почему именно Java может быть первым языком для изучения? Давайте составим план, который поможет выучить Java как с нуля, так и с применением навы...
1С Битрикс: Управление сайтом (БУС) - CMS №1 в России по версии портала “Рейтинг Рунета” за 2018 год. На рынке c 2003 года. За это время БУС не стоял на месте, обрастал новой функциональностью...