company_banner

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

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


    Анатолий Островский 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, если вам интересны инфраструктурные вещи.
    Яндекс
    Как мы делаем Яндекс

    Комментарии 7

      0
      немедленно откатывать

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

        +1
        проверку ручки health check,

        Всё бы, может, и ничего, только handler — это не ручка. Ну, совсем, ну никак. Откройте словарь уже!


        Зачем пытаться делать свой новояз, основываясь на чьих-то ошибочных знаниях??

          0
          Я, может быть, чего то не понимаю, но к чему это дополнение? Действительно, handler — это не ручка. В статье ничего нет про handler.
            +1

            Это значит, вы статью читали невнимательно ;)


            И не только эту. Вся братия Яндекса называет хэндлеры ручками ("у них так повелось"). Вот, вы попробуйте обратить внимание.

              +1
              Не только они, вошло в привычный оборот в больших компаниях. Хотя, видимо, пошло как раз от них.
                0

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

            +1
            Handler — это скорее обработчик. В данном контексте «ручка» больше смахивает на «endpoint», имхо.

          Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

          Самое читаемое