null

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

Введение - микросервисы

Основная часть - боль и страдания

Заключение - М-О-Н-О-Л-И-Т

...

 

Так,  о чем это я? Ах да, логирование. Казалось бы, простая тема, не заслуживающая особого внимания. Что может быть проще, чем вызвать функцию логирования, указать уровень и передать текст лога?

logger.error("Cannot create an element")

Однако давайте представим, что гипотетическая система состоит из хотя бы 5 микросервисов, ей активно пользуются в период с 10 до 19 хотя бы 100 человек. При виде лога об ошибке с подобным текстом резко становится грустно. На самом деле, даже если бы мы рассматривали монолитную архитектуру, грустно было бы все равно. Совершенно непонятно, к какому пользователю или фоновой задаче относится данная запись в логах. Более того, почему не получилось создать "элемент", да и что это за "элемент"?

удивление фото приколы с людьми: 2 тыс изображений найдено в Яндекс  Картинках

Логи должны быть подробными

Логи - это основной наш инструмент, как разработчиков, в ситуации, если что-то пошло не так в продовой эксплуатации. Ведь сама идея логирования в том, чтобы предоставить разработчику информацию о причине проблемы. Для нас бородатые дяди даже придумали уровни логирования, чтобы разделить информацию по уровням важности. Классические 4 уровня логирования рекомендуется использовать примерно следующим образом:

debug - отладочная информация, которая чаще всего используется при тестировании системы

info - средней важности информация, чаще всего регистрирующая факт свершения некоторого события

warn - предупреждения о потенциальных ошибках конфигурации или приближении крупных проблем

error - ошибка свершилась, пора с ней разбираться

Однако лично автор никогда не видел каких-либо четких советов на тему того, что и в каких количествах нужно логировать. И здесь возможны свои крайности. Крайне малое совершенно неинформативных логов, либо чрезвыйная их избыточность, которая затруднит анализ логов даже с использованием таких инструментов как Kibana или Grafana + Loki. Я хочу постараться сформулировать набор рекомендаций, которые могут оказаться полезны для построения информативных логов в том числе в распределенных системах.

Чтобы сформулировать эти "рекомендации", в первую очередь нужно определить сценарии, когда логи могут быть использованы с пользой:

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

2. Наступление событий. Здесь важно сделать акцент на том, что такие события могут быть вызвана как действием пользователя, так и результатом асинхронных задач. Однако важно, чтобы частота отслеживаниемых событий не была большой. Если лоировать каждый запрос на получение информации, мы получим ситуацию, когда большая часть логов совершенно бесполезна. Да, получил пользователь данные для отрисовки странички, ну и что? К тому же очень редко, когда операция получения информации завершается с ошибкой.

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

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

 

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

Случай 1. Ошибки

В случае возникновения нештатных ситуаций нам хочется иметь возможность "легко и быстро" понять причину возникновения проблемы и, следовательно, быстро и без страданий ее устранить. Чаще всего при возникновении ошибки фронт нарисует пользователю печальное сообщение с извинениями. Здесь важно понимать, что ошибка может быть задуманной, а может быть неожиданной. В случае задуманной ошибки разработчику ничего править не нужно - так и планировалось, либо это вообще не проблема рассматриваемой системы. Например, на некий сервис пришел запрос к несуществующему ресурсу - отстрелили 404ую ошибку и дело с концом. Нет смысла что-либо логировать на уровень error в прицнипе, если есть сильная необходимость отслеживать подобные задуманные ошибки, например, при отладке - добро пожаловать на уровень debug. В случае же неожиданной ошибки, нам нужно видеть как можно больше полезной информации. В идеале в случае возникновения такой ситуации, отдать на фронт некий идентификатор, чтобы пользователь в дальнейшем зарегистрировал свое обращение в саппорте, указав выданный ему идентификатор. Тогда по логам, в которых также этот идентификатор есть, мы за пару секунд сможем найти сообщение об ошибке. Однако сам факт "у нас ошибка" мало чем нам поможет. Важно также указать контекст, в рамках которого возникла ошибка. Например, в нашей предметной области есть студенты, у которых обязательно должен быть хотя бы один кот, а мы обнаружили ситуацию, когда кота нет и не можем обработать запрос пользователя. Что нам в таком случае поможет? Правильно, берем объект студента и целиком его логируем вместе со всеми полями, а также логируем данные из запроса пользователя. И все, в таком логе наверняка есть вся доступная нам контекста информация, причем это не стоит с точки зрения производительности ни копейки.

Случай 2. Наступление событий

Переходим к более неочевидным случаям полезности логов. Не редко в информационных системах бывает полезно отслеживать единичные события, наступление которых важно для системы. Подобные логи пригодятся в двух случаях: во-первых, если мы пытаемся понять причину возникнейшей ошибки, нам может быть недостаточно контекста и мы захотим понять историю действий пользователя или даже обработки конкретного запроса. Например, у нас как всегда микросервисы, скажем, 5 штук. На третьем возникла неожиданная ошибка и у нас возник тикет в саппорте, к примеру о том, что пользователю не пришло письмо для восстановления пароля. Мы открываем логи, видим ошибку, но не можем сходу понять, что ее вызвало. Тогда мы переходим к исследованию действий пользователя, которые к этой ошибке привели. Мы открываем логи первых двух сервисов и видим, например, что пользователь запросил восстановление пароля, запрос на генерацию письма со заветной ссылка сброса пароля был принят и взят в работу, но вот как раз на третьем сервисе ссылка не сгенерировалась, так как что-то случилось (например, четвертый сервис в цепочке оказался недоступен). Мы получили не только контекстную локальную информацию об ошибке, но и отследили важные, но редкие события, которые к ней привели.

Случай 3. Отслеживание пользовательской активности

В общем-то, как и упоминалось ранее, лучше отслеживать часто возникающие события другими способами, однако иногда нам может быть полезно заниматься этим не для целей оповещения или сбора статистики, а для фиксации действий пользователя в наиболее сложных сценариях или наиболее критичных для бизнеса. Для того чтобы если ошибка возникнет (случай 1), мы имели больше информации о действиях пользователя с точки зрения истории его активности. То есть принципиальное отличие от случая 2 в том, что отслеживание пользовательской активности позволяет разработчику понять, что делал пользователь до наступления ошибки. Возможно, он совершил что-то злобное и ужасное, о чем разработчик даже не мог предположить, когда писал код.

Случай 4. Отладка

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

 

Распределенное логирование

Комикс мем: "failover отказоустойчивость распределенная архитектура" -  Комиксы - Meme-arsenal.com

Мы дошли, собственно, до основной темы статьи :) Все описанные рекомендации окажутся бесполезными, если мы не сделаем одну простую вещь. Каждая, КАЖДАЯ! Каждая запись лога должна быть снабжена идентификатором запроса и идентификатором пользователя, либо, в случае фоновых задач, идентификатором фоновой задачи. Как бы мы не старались вести подробные и продуманные логи, это окажется малополезным, если мы не сможем идентифицировать к какому запросу относится та или иная запись. В случае микросервисов и высокой нагрузки проблема встает наиболее остро. Автор имел опыт читать логи средствами Grafana + Lokiкогда записей логов было настолько много, что Grafana иногда вешалась 502-ыми ошибками, а также стабильно рисовала логи за временной промежуток, ограниченный 5-10 СЕКУНДАМИ, Карл! 

Идеалогический путь (или по-другому желаемый результат) - мы хотим каждому запросу каждого пользователя присвоить два идентифиатора: первый - запрос, второй - пользователь. Причем идентификатор запроса должно совпадать между несколькими сервисами, если их цепопочка обрабатывает один и тот же логический запрос пользователя.

Для решения подобной задачи, как обычно, есть несколько стульев путей:

1. Программное (ручное) снабжение каждой записи лога идентификаторами запроса и пользователя. Тут все понятно - закатываем рукава, берем велосипед и творим.

2. MDC (Mapped Diagnostic Context) в случае джавовских приложений. Идея MDC (есть в том или ином виде во всех популярных логерах, даже в стандартном спринговском logback, молчу уже про стильны-модны-молодежный log4j2) в использовании Thread Local коллекций пар ключ-значение, которые могут быть использованы по ключам в шаблонах логов (подробнее об этом ниже).

3.  Специализированные внешние инструменты трассировки и логирования. Из серии - такое только в мечтах. Почему? Крайне дорого для внедрения. Кому интересно, вот интересная статейка на хабре: тык
 

Mapped Diagnostic Context

Погрузимся в решение для всеми любимой жабы. Допустим, мы имеем классическое Spring-приложение, сконфигурированое Spring Boot-ом, а следовательно имеем классический logback из коробки. Наша цель - минимальными усилиями присвоить каждой записи логов идентификатор запроса и идентификатор пользователя.

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

Шаблон логов

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <property name="LOGS" value="./logs" />
    <appender name="Console"
              class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>
                %white(%d{ISO8601}) %highlight(%-5level) [%blue(%t)] RID: %X{requestId:-no} UID: %X{userId:-no} %yellow(%C{1.}): %msg%n%throwable
            </Pattern>
        </layout>
    </appender>
    <appender name="RollingFile"
              class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOGS}/spring-boot-logger.log</file>
        <encoder
                class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <Pattern>%white(%d{ISO8601}) %highlight(%-5level) [%blue(%t)] RID: %X{requestId:-no} UID: %X{userId:-no} %yellow(%C{1.}): %msg%n%throwable</Pattern>
        </encoder>
        <rollingPolicy
                class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- rollover daily and when the file reaches 10 MegaBytes -->
            <fileNamePattern>${LOGS}/archived/spring-boot-logger-%d{yyyy-MM-dd}.%i.log
            </fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy
                    class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>10MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
        </rollingPolicy>
    </appender>
    <!-- LOG everything at INFO level -->
    <root level="info">
        <appender-ref ref="RollingFile" />
        <appender-ref ref="Console" />
    </root>
</configuration>

В тегах Pattern мы видим вот такие корючки:

RID: %X{requestId:-no} UID: %X{userId:-no}

Конструкция %X{VARIABLE_NAME:-DEFAULT_VALUE} позволяет достать из MDC значение по ключу VARIABLE_NAME, если нужного значения не нашлось - используется значение по умолчанию DEFAULT_VALUE. Важно еще раз отметить, что MDC - штука Thread Local-ая, а значит в пары ключ-значения доступны только в пределах потока-обработчика.

Фильтр для заполнения MDC

import org.slf4j.MDC
import java.util.UUID
import javax.servlet.Filter
import javax.servlet.FilterChain
import javax.servlet.ServletRequest
import javax.servlet.ServletResponse
import javax.servlet.http.HttpServletRequest

const val RID_HEADER = "X-TORA-Request-ID"
const val UID_HEADER = "X-TORA-User-ID"

const val RID_MDC_KEY = "requestId"
const val UID_MDC_KEY = "userId"

class LoggingFilter: Filter {
    override fun doFilter(request: ServletRequest?, response: ServletResponse?, chain: FilterChain?) {
        val httpRequest = request!! as HttpServletRequest
        val filterChain = chain!!

        if (httpRequest.getHeader(RID_HEADER) != null) {
            MDC.put(RID_MDC_KEY, httpRequest.getHeader(RID_HEADER))
        } else {
            MDC.put(RID_MDC_KEY, UUID.randomUUID().toString())
        }


        if (httpRequest.getHeader(UID_HEADER) != null) {
           MDC.put(UID_MDC_KEY, httpRequest.getHeader(UID_HEADER))
        } else {
           MDC.put(UID_MDC_KEY, extractFromAuthHeader())
        }

        try {
            filterChain.doFilter(request, response)
        } finally {
            MDC.remove(RID_MDC_KEY)
            MDC.remove(UID_MDC_KEY)
        }
    }
}

Осталось только сообщить о фильтре Spring-у - тут на ваш вкус, аннотация WebFilter или Bean. Идея фильтра проста - если к нам пришли заголовки с RID (request ID) и UID (user ID), то используем эти значение, если нет - генерируем новые. Такой фильтр может быть встроен как в сервис, которые вызывает только фронт или внешняя система, так и в любой наш внутренний сервис. После чего все записи логов будут снабжены нужными нам идентификаторами. Simple?

 

Передача RID и UID в другие сервисы

Здесь уже нет универсального решения. Все зависит от библиотеки, которая используется для запросов к другим сервисам (или для асинхронного сообщения). Рассмотрим в качестве примера решение для OkHttp:

class OkHttpLoggingInterceptor: Interceptor {
    override fun intercept(chain: Interceptor.Chain): Response {
        val rid = MDC.get(RID_MDC_KEY)
        val uid = MDC.get(UID_MDC_KEY)

        val requestBuilder = chain.request()
            .newBuilder()
        if (rid != null) requestBuilder.header(RID_HEADER, MDC.get(RID_MDC_KEY))
        if (uid != null) requestBuilder.header(UID_HEADER, MDC.get(UID_MDC_KEY))

        return chain.proceed(requestBuilder.build())
    }
}

Самое замечательное в MDC: в случае синхронных запросов из потока обработки запроса мы можем из любого места кода обратиться к фасаду MDC и достать нужные нам значения и благодаря тому, что MDC - Thread Local у нас не будет конфликтов между разными запросами.

 

Всем удачи и полезных логов!