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

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


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

xfcxbk6d4xsoxdb3l7clfzw5yza.jpeg

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

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

b3nzp2buowpixe2wnv1-r-ymj7m.jpeg

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

pvwu-wguspmalhce4hxtbvhqznu.jpeg

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

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

qunfhq8cdqgbtqtmikv0maf1tpc.jpeg

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

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


1zlccllwyct_nesu28sa4kh0za0.jpeg

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

ohqoskth2c-8o9h2btju58-tg04.jpeg

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

pqcf1m-t3srhcoorgfwnnpohbqg.jpeg

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

cURL


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

75mruhc0hnm0q7qtllafjtnz8ak.jpeg

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

jlmnfxdobmhcqctl-uviygpzij8.jpeg

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

j588xz0r-jh48xp1rphfqoljlvk.jpeg

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

gv6v_dz188tviqfjs5siyf9lt8e.jpeg

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

1ja_sdx_in4dcwudr64xjdezf98.jpeg

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

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

lhgdsguqkolxs1vrjusxnshjnmg.jpeg

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

yjinfkjpv0bgzbhfmi8shr7qyno.jpeg

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

xx4lh8tvvwmvzw1-aflbg7ophvq.jpeg

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

vje-gyp_i8kozos10ew_7vyk-68.jpeg

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

0ol3ay03w7toau9tyabduyiu1-m.jpeg

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

ClickHouse


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

rxyqhxvdpvjetfh9jmkw4hfkwvu.jpeg

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

oi5vje-sgh204x5-w1fjywdjyk8.jpeg

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

edr6gpqetfffuhjo6uc2hwznb4s.jpeg

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

y3vrvqez5ghx9umed2htpzgeurm.jpeg

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

hf0ivf6posnoebmrwayqz4wni5c.jpeg

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

5c0iyhrkfdxbgd0psywb7jvv8si.jpeg

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

7b7mhxhtlyos6qbomnnm2p6xcko.jpeg

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

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

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


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

aumccfspkkp7eieqgesgk8awnn4.jpeg

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

w0nopvgiuihtlc2x8b7fdist7lm.jpeg

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

9gn9axljm2rabdxvowa3p8gsjec.jpeg

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

fhrhrr6j0ujdnvdivmn0dwobnlc.jpeg

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

m8sl4atplnknyq_5wefl8b2wgw0.jpeg

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

ruahbzfg8qzvgzi1s2gbexvm0og.jpeg

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

wqnm0gw9rgznoe7rswqshty_u1a.jpeg

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

uclbck5ju2ri2l2qyhjxkwnvxpk.jpeg

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

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

Графики


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

motc5p8irltrzn7aqlsffemkdza.jpeg

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

lovnkuij1s2d39nszmdwvwsde78.jpeg

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

Мониторинги


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

wn1fr9r0fnzl-r4kbkgbj3pwz6w.jpeg

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

qxpna94qppcm5kpnv51d9yyt1ds.jpeg

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

Итоги


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

Рекомендую почитать книгу Site Reliability Engineering от Google, если вам интересны инфраструктурные вещи.

© Habrahabr.ru