Вопросов о работе сервисов на этапах разработки, тестирования и поддержки очень много и все они на первый взгляд непохожи: «Что произошло?», «Был ли запрос?», «Какой формат даты?», «Почему сервис не отвечает?» и т.д.

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

Об одеяле и особенностях решения — далее.

В чём проблема логирования

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

• Лог приложения — его алиби.
  Доказать успешность работы приложения может, чаще всего, только он. Состояния у микросервиса нет, смежные системы подвижны и привередливы. «Повторить», «воссоздать», «перепроверить» – всё это трудно и/или невыполнимо. Лог должен быть достаточно информативен, чтобы в любой момент времени ответить на вопрос: «Что произошло?». Лог должен быть понятен всем: разработчику, тестировщику, иногда аналитику, иногда администратору, иногда первой линии поддержки – всякое случается.
• Микросервисы — это про многопоточку.
  Приходящие в сервис запросы (или запрашиваемые сервисом данные) чаще всего обрабатываются несколькими потоками. Лог всех потоков, как правило, перемешан. Вы хотите отличать параллельные потоки и отличать «последовательные» потоки? Один и тот же поток переиспользуется для последовательной обработки запросов, раз за разом выполняя свою логику для разных наборов данных. Эти «последовательные» потоки из другой плоскости, но их границы должны быть чёткими для читателя.
• Лог должен сохранять оригинальный формат данных.
  Если в действительности сервисы перекидываются XML'ем, то соответствующий лог должен хранить XML. Это не всегда компактно и не всегда красиво (зато удобно). Проще убедиться в успехе, проще проанализировать неудачу. В отдельных случаях, лог может использоваться для ручного воспроизведения или повторной обработки запроса.
• Часть данных в логе требует особого отношения.
  Входящие данные (запросы), исходящие данные (ответы), запросы к сторонним системам и ответы от них часто требуется хранить отдельно. К ним предъявляются особые требования: по сроку хранения или надёжности. Кроме того, эти данные могут иметь внушительный объём по сравнению с типичной строкой лога.
• Часть данных не для лога.
  Из регулярного лога обычно должны быть исключены: бинарные данные (массивы байт, base64, ..), персональные данные клиентов / партнеров / прочих физических и юридических лиц. Это всегда индивидуальная история, но систематическая и ручному контролю не поддаётся.

Почему не руками

Взять org.slf4j.Logger (к нему Logback с Appender’ами любой масти) и писать в лог всё, что потребуется. Входы в основные методы, выходы, если нужно, отразить пойманные ошибки, какие-то данные. Это ведь необходимо? Да, но:

• Объём кода необоснованно (необыкновенно) растёт. На первых порах это не сильно бросается в глаза, если логировать только самое основное (удачной поддержки, кстати, при таком подходе).
• Вызывать руками логгер быстро становится лень. Объявлять static поле с логгером тоже лень (ладно, это может сделать за нас Lombok). Мы, разработчики, ленивы. И мы прислушиваемся к своей лени, это благородная лень: она настойчиво меняет мир к лучшему.
• Микросервисы оказываются не со всех сторон хороши. Да, они маленькие и миленькие, но есть обратная сторона: их много! Отдельное приложение от начала и до конца зачастую пишет один разработчик. У него перед глазами не маячит legacy. Счастливый, не обремененный навязанными правилами, разработчик считает долгом изобрести свой формат лога, свой принцип и свои правила. Затем, блестяще реализует изобретение. В каждом классе по-разному. Это проблема? Колоссальная.
• Рефакторинг сломает ваш лог. Даже всемогущая Idea его не спасёт. Актуализировать лог в той же степени невозможно, как невозможно актуализировать Javadoc. Javadoc при этом хотя бы читают только разработчики (нет, никто не читает), но аудитория логов гораздо шире и командой разработки не ограничивается.
• MDC (Mapped Diagnostic Context) — неотъемлемая часть многопоточного приложения. Ручное заполнение MDC требует своевременной его очистки по окончанию выполнения работы в потоке. Иначе вы рискуете связать одним ThreadLocal – не относящиеся друг к другу данные. Руками и глазами это проконтролировать, осмелюсь утверждать, невозможно.

И вот как мы решаем эти проблемы в своих приложениях.

Что такое Eclair, и что он умеет

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

Основная цель — сделать лог понятным всем участникам процесса разработки. Поэтому, удобством написания кода польза от Eclair не заканчивается, а только начинается.

Eclair логирует аннотированные методы и параметры:

• логирует вход в метод / выход из метода / исключения / аргументы / возвращаемые методом значения
• фильтрует исключения, чтобы логировать их специфично типам: только там, где это нужно
• варьирует «подробность» лога, исходя из настроек приложения для текущей локации: например, в самом подробном случае печатает значения аргументов (всех или некоторых), в самом кратком варианте — только факт входа в метод
• печатает данные как JSON / XML / в любом другом формате (из коробки готов работать с Jackson, JAXB): понимает, какой формат наиболее предпочтителен для определённого параметра
• понимает SpEL (Spring Expression Language) для декларативной установки и авто-очистки MDC
• пишет в N логгеров, «логгер» в понимании Eclair — это bean в контексте, реализующий interface EclairLogger: указать логгер, который должен обработать аннотацию, можно по имени, по алиасу или по умолчанию
• подсказывает программисту о некоторых ошибках в использовании аннотаций: например, Eclair знает, что работает на динамических прокси (со всеми вытекающими особенностями), поэтому может подсказать, что аннотация на private методе никогда не сработает
• воспринимает мета-аннотации (как их называет Spring): можно определять свои аннотации для логирования, пользуясь немногочисленными базовыми аннотациями — для сокращения кода
• умеет маскировать «чувствительные» данные при распечатке: из коробки XPath-экранирование XML'я
• пишет лог в «ручном» режиме, определяет invoker'а и «разворачивает» аргументы, реализующие Supplier: давая возможность инициализировать аргументы «лениво»

Как подключить Eclair

Исходный код опубликован у нас в GitHub'е под лицензией Apache 2.0.

Для подключения вам потребуется Java 8, Maven и Spring Boot 1.5+. Артефакт размещён в Maven Central Repository:

<dependency>
    <groupId>ru.tinkoff</groupId>
    <artifactId>eclair-spring-boot-starter</artifactId>
    <version>0.8.3</version>
</dependency>

Стартер содержит стандартную реализацию EclairLogger, использующую инициализированную Spring Boot’ом систему логирования с некоторым выверенным набором настроек.

Примеры

Здесь приведены некоторые примеры типичного использования библиотеки. Сначала даётся фрагмент кода, затем соответствующий ему лог в зависимости от доступности определенного уровня логирования. Более полный набор примеров можно найти на Wiki проекта в разделе Examples.

Самый простой пример

По умолчанию применяется уровень DEBUG.

@Log
void simple() {
}

Если доступен уровень	… то лог будет таким
TRACE DEBUG	DEBUG [] r.t.e.e.Example.simple > DEBUG [] r.t.e.e.Example.simple <
INFO WARN ERROR	-

Подробность лога зависит от доступного уровня логирования

Доступный в текущей локации уровень логирования влияет на подробность лога. Чем «ниже» доступный уровень (т.е. чем ближе к TRACE), тем лог подробнее.

@Log(INFO)
boolean verbose(String s, Integer i, Double d) {
    return false;
}

Уровень	Лог
TRACE DEBUG	INFO [] r.t.e.e.Example.verbose > s="s", i=4, d=5.6 INFO [] r.t.e.e.Example.verbose < false
INFO	INFO [] r.t.e.e.Example.verbose > INFO [] r.t.e.e.Example.verbose <
WARN ERROR	-

Тонкая настройка логирования исключений

Типы логируемых исключений могут быть отфильтрованы. Залогированы будут отобранные исключения и их потомки. В этом примере NullPointerException будет залогирован на уровне WARN, Exception на уровне ERROR (по умолчанию), а Error не будет залогирован совсем (потому что Error не включён в фильтр первой аннотации @Log.error и явно исключён из фильтра второй аннотации).

@Log.error(level = WARN, ofType = {NullPointerException.class, IndexOutOfBoundsException.class})
@Log.error(exclude = Error.class)
void filterErrors(Throwable throwable) throws Throwable {
    throw throwable;
}

// рассмотрен лог вызовов с разными аргументами
filterErrors(new NullPointerException());
filterErrors(new Exception());
filterErrors(new Error());

Уровень	Лог
TRACE DEBUG INFO WARN	WARN  [] r.t.e.e.Example.filterErrors ! java.lang.NullPointerException java.lang.NullPointerException: null     at r.t.e.e.ExampleTest.filterErrors(ExampleTest.java:0) .. ERROR [] r.t.e.e.Example.filterErrors ! java.lang.Exception java.lang.Exception: null     at r.t.e.e.ExampleTest.filterErrors(ExampleTest.java:0) ..
ERROR	ERROR [] r.t.e.e.Example.filterErrors ! java.lang.Exception java.lang.Exception: null     at r.t.e.e.ExampleTest.filterErrors(ExampleTest.java:0) ..

Настроить каждый параметр отдельно

@Log.in(INFO)
void parameterLevels(@Log(INFO) Double d,
                     @Log(DEBUG) String s,
                     @Log(TRACE) Integer i) {
}

Уровень	Лог
TRACE	INFO [] r.t.e.e.Example.parameterLevels > d=9.4, s="v", i=7
DEBUG	INFO [] r.t.e.e.Example.parameterLevels > d=9.4, s="v"
INFO	INFO [] r.t.e.e.Example.parameterLevels > 9.4
WARN ERROR	-

Выбрать и настроить формат распечатки

«Принтеры», отвечающие за формат распечатки, могут конфигурироваться pre- и post-процессорами. В приведённом примере maskJaxb2Printer сконфигурирован так, что элементы, соответствующие XPath-выражению "//s", маскируются при помощи "********". В то же время jacksonPrinter печатает Dto «as is».

@Log.out(printer = "maskJaxb2Printer")
Dto printers(@Log(printer = "maskJaxb2Printer") Dto xml,
             @Log(printer = "jacksonPrinter") Dto json,
             Integer i) {
    return xml;
}

Уровень	Лог
TRACE DEBUG	DEBUG [] r.t.e.e.Example.printers >     xml=<dto><i>5</i><s>********</s></dto>, json={"i":5,"s":"password"} DEBUG [] r.t.e.e.Example.printers <     <dto><i>5</i><s>********</s></dto>
INFO WARN ERROR	-

Несколько логгеров в контексте

Метод логируется при помощи нескольких логгеров одновременно: логгером по умолчанию (аннотированным при помощи @Primary) и логгером auditLogger. Определить несколько логгеров можно, если вы хотите разделить логируемые события не только по уровням (TRACE — ERROR), но и направить их в разные хранилища. Например, основной логгер может писать лог в файл на диск при помощи slf4j, а auditLogger может писать особый срез данных в отличное хранилище (например в Kafka) в своём специфичном формате.

@Log
@Log(logger = "auditLogger")
void twoLoggers() {
}

Управление MDC

MDC, установленные при помощи аннотации, автоматически удаляются после выхода из аннотированного метода. Значение записи в MDC может вычисляться динамически при помощи SpEL. В примере приведены: статичная строка, воспринимаемая константой, вычисление выражения 1 + 1, обращение к бину jacksonPrinter, вызов static метода randomUUID.
MDC с атрибутом global = true не удаляются после выхода из метода: как видно единственная запись, оставшаяся в MDC до конца лога, — это sum.

@Log
void outer() {
    self.mdc();
}

@Mdc(key = "static", value = "string")
@Mdc(key = "sum", value = "1 + 1", global = true)
@Mdc(key = "beanReference", value = "@jacksonPrinter.print(new ru.tinkoff.eclair.example.Dto())")
@Mdc(key = "staticMethod", value = "T(java.util.UUID).randomUUID()")
@Log
void mdc() {
    self.inner();
}

@Log.in
void inner() {
}

Лог при выполнении приведённого выше кода:
DEBUG [] r.t.e.e.Example.outer >
DEBUG [beanReference={"i":0,"s":null}, sum=2, static=string, staticMethod=01234567-89ab-cdef-ghij-klmnopqrstuv] r.t.e.e.Example.mdc >
DEBUG [beanReference={"i":0,"s":null}, sum=2, static=string, staticMethod=01234567-89ab-cdef-ghij-klmnopqrstuv] r.t.e.e.Example.inner >
DEBUG [beanReference={"i":0,"s":null}, sum=2, static=string, staticMethod=01234567-89ab-cdef-ghij-klmnopqrstuv] r.t.e.e.Example.mdc <
DEBUG [sum=2] r.t.e.e.Example.outer <

Установка MDC на основе параметров

Если задавать MDC при помощи аннотации на параметре, то аннотированный параметр доступен как корневой объект evaluation-контекста. Здесь "s" — это поле класса Dto с типом String.

@Log.in
void mdcByArgument(@Mdc(key = "dto", value = "#this")
                   @Mdc(key = "length", value = "s.length()") Dto dto) {
}

Лог при выполнении приведённого выше кода:
DEBUG [length=8, dto=Dto{i=12, s='password'}] r.t.e.e.Example.mdcByArgument > dto=Dto{i=12, s='password'}

Ручное логирование

Для «ручного» логирования достаточно внедрить реализацию ManualLogger. Передаваемые аргументы, реализующие interface Supplier, будут «развёрнуты» только при необходимости.

@Autowired
private ManualLogger logger;

@Log
void manual() {
    logger.info("Eager logging: {}", Math.PI);
    logger.debug("Lazy logging: {}", (Supplier) () -> Math.PI);
}

Уровень	Лог
TRACE DEBUG	DEBUG [] r.t.e.e.Example.manual > INFO  [] r.t.e.e.Example.manual - Eager logging: 3.141592653589793 DEBUG [] r.t.e.e.Example.manual - Lazy logging: 3.141592653589793 DEBUG [] r.t.e.e.Example.manual <
INFO	INFO [] r.t.e.e.Example.manual - Eager logging: 3.141592653589793
WARN ERROR	-

Чего не делает Eclair

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

Пример конфигурации EclairLogger, направляющего лог в Logback-логгер со специфичным Appender'ом:

@Bean
public EclairLogger eclairLogger() {
    LoggerFacadeFactory factory = loggerName -> {
        ch.qos.logback.classic.LoggerContext context = (LoggerContext) LoggerFactory.getILoggerFactory();
        ch.qos.logback.classic.Logger logger = context.getLogger(loggerName);
        // Appender<ILoggingEvent> appender = ?
        // logger.addAppender(appender);
        return new Slf4JLoggerFacade(logger);
    };
    return new SimpleLogger(factory, LoggingSystem.get(SimpleLogger.class.getClassLoader()));
}

Это решение не для всех

Перед тем, как начать пользоваться Eclair как основным инструментом для логирования, стоит ознакомиться с рядом особенностей этого решения. Эти «особенности» обусловлены тем, что в основе Eclair лежит стандартный для Spring механизм проксирования.

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

— StackTrace «раздуется» ещё чуть больше. Если вы не привыкли к длинным stackTrace’ам от Spring’овых прокси, для вас это может стать неприятностью. По столь же очевидной причине затруднится отладка проксированных классов.

— Не всякий класс и не всякий метод может быть проксирован: private методы проксировать не удастся, для логирования цепочки методов в одном bean’е потребуется self, проксировать что-либо, не являющееся bean’ом, вы не сможете и т.д.

Напоследок

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

Критика, мысли, подсказки, ссылки – любое ваше участие в жизни проекта я горячо приветствую! Буду рад, если сочтёте Eclair полезным для своих проектов.