Улучшенное ведение журнала Java с сопоставленным диагностическим контекстом (MDC)

1. Обзор

В этом руководстве мы рассмотрим использование Mapped Diagnostic Context (MDC) для улучшения ведения журнала приложения.

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

2. Зачем использовать MDC

Предположим, нам нужно написать программу для перевода денег.

Мы настроили класс Transfer для представления некоторой базовой информации — уникального идентификатора перевода и имени отправителя:

public class Transfer {
    private String transactionId;
    private String sender;
    private Long amount;
    
    public Transfer(String transactionId, String sender, long amount) {
        this.transactionId = transactionId;
        this.sender = sender;
        this.amount = amount;
    }
    
    public String getSender() {
        return sender;
    }

    public String getTransactionId() {
        return transactionId;
    }

    public Long getAmount() {
        return amount;
    }
}

Чтобы выполнить передачу, нам нужно использовать сервис, поддерживаемый простым API:

public abstract class TransferService {

    public boolean transfer(long amount) {
        // connects to the remote service to actually transfer money
    }

    abstract protected void beforeTransfer(long amount);

    abstract protected void afterTransfer(long amount, boolean outcome);
}

Методы beforeTransfer() и afterTransfer() можно переопределить для запуска пользовательского кода непосредственно перед и сразу после завершения передачи.

Мы собираемся использовать функции beforeTransfer() и afterTransfer() для регистрации некоторой информации о передаче.

Создадим реализацию сервиса:

import org.apache.log4j.Logger;
import com.foreach.mdc.TransferService;

public class Log4JTransferService extends TransferService {
    private Logger logger = Logger.getLogger(Log4JTransferService.class);

    @Override
    protected void beforeTransfer(long amount) {
        logger.info("Preparing to transfer " + amount + "$.");
    }

    @Override
    protected void afterTransfer(long amount, boolean outcome) {
        logger.info(
          "Has transfer of " + amount + "$ completed successfully ? " + outcome + ".");
    }
}

Основная проблема, которую следует отметить здесь, заключается в том, что при создании сообщения журнала невозможно получить доступ к объекту « Перевод » — доступна только сумма, что делает невозможным регистрацию ни идентификатора транзакции, ни отправителя.

Настроим обычный файл log4j.properties для входа в консоль:

log4j.appender.consoleAppender=org.apache.log4j.ConsoleAppender
log4j.appender.consoleAppender.layout=org.apache.log4j.PatternLayout
log4j.appender.consoleAppender.layout.ConversionPattern=%-4r [%t] %5p %c %x - %m%n
log4j.rootLogger = TRACE, consoleAppender

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

public class TransferDemo {

    public static void main(String[] args) {
        ExecutorService executor = Executors.newFixedThreadPool(3);
        TransactionFactory transactionFactory = new TransactionFactory();
        for (int i = 0; i < 10; i++) {
            Transfer tx = transactionFactory.newInstance();
            Runnable task = new Log4JRunnable(tx);            
            executor.submit(task);
        }
        executor.shutdown();
    }
}

Обратите внимание, что для использования ExecutorService нам нужно обернуть выполнение Log4JTransferService в адаптер, потому что executor.submit() ожидает Runnable :

public class Log4JRunnable implements Runnable {
    private Transfer tx;
    
    public Log4JRunnable(Transfer tx) {
        this.tx = tx;
    }
    
    public void run() {
        log4jBusinessService.transfer(tx.getAmount());
    }
}

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

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

Более того, невозможно различить две разные транзакции на одну и ту же сумму, выполняемые одним и тем же потоком, потому что связанные строки журнала выглядят практически одинаково:

...
519  [pool-1-thread-3]  INFO Log4JBusinessService 
  - Preparing to transfer 1393$.
911  [pool-1-thread-2]  INFO Log4JBusinessService 
  - Has transfer of 1065$ completed successfully ? true.
911  [pool-1-thread-2]  INFO Log4JBusinessService 
  - Preparing to transfer 1189$.
989  [pool-1-thread-1]  INFO Log4JBusinessService 
  - Has transfer of 1350$ completed successfully ? true.
989  [pool-1-thread-1]  INFO Log4JBusinessService 
  - Preparing to transfer 1178$.
1245 [pool-1-thread-3]  INFO Log4JBusinessService 
  - Has transfer of 1393$ completed successfully ? true.
1246 [pool-1-thread-3]  INFO Log4JBusinessService 
  - Preparing to transfer 1133$.
1507 [pool-1-thread-2]  INFO Log4JBusinessService 
  - Has transfer of 1189$ completed successfully ? true.
1508 [pool-1-thread-2]  INFO Log4JBusinessService 
  - Preparing to transfer 1907$.
1639 [pool-1-thread-1]  INFO Log4JBusinessService 
  - Has transfer of 1178$ completed successfully ? true.
1640 [pool-1-thread-1]  INFO Log4JBusinessService 
  - Preparing to transfer 674$.
...

К счастью, MDC может помочь.

3. MDC в Log4j

MDC в Log4j позволяет нам заполнить структуру, подобную карте, фрагментами информации, доступной для приложения, когда сообщение журнала фактически записывается.

Структура MDC внутренне привязана к исполняющемуся потоку так же, как переменная ThreadLocal .

Вот идея высокого уровня:

1. Заполните MDC кусочками информации, которые мы хотим сделать доступными для приложения.
2. Затем запишите сообщение
3. И, наконец, очистить MDC

Шаблон добавления должен быть изменен, чтобы получить переменные, хранящиеся в MDC.

Итак, давайте изменим код в соответствии с этими рекомендациями:

import org.apache.log4j.MDC;

public class Log4JRunnable implements Runnable {
    private Transfer tx;
    private static Log4JTransferService log4jBusinessService = new Log4JTransferService();

    public Log4JRunnable(Transfer tx) {
        this.tx = tx;
    }

    public void run() {
        MDC.put("transaction.id", tx.getTransactionId());
        MDC.put("transaction.owner", tx.getSender());
        log4jBusinessService.transfer(tx.getAmount());
        MDC.clear();
    }
}

MDC.put() используется для добавления ключа и соответствующего значения в MDC, а MDC.clear() очищает MDC.

Давайте теперь изменим log4j.properties , чтобы распечатать информацию, которую мы только что сохранили в MDC.

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

log4j.appender.consoleAppender.layout.ConversionPattern=
  %-4r [%t] %5p %c{1} %x - %m - tx.id=%X{transaction.id} tx.owner=%X{transaction.owner}%n

Теперь, если мы запустим приложение, мы заметим, что каждая строка также содержит информацию об обрабатываемой транзакции, что значительно упрощает отслеживание выполнения приложения:

638  [pool-1-thread-2]  INFO Log4JBusinessService 
  - Has transfer of 1104$ completed successfully ? true. - tx.id=2 tx.owner=Marc
638  [pool-1-thread-2]  INFO Log4JBusinessService 
  - Preparing to transfer 1685$. - tx.id=4 tx.owner=John
666  [pool-1-thread-1]  INFO Log4JBusinessService 
  - Has transfer of 1985$ completed successfully ? true. - tx.id=1 tx.owner=Marc
666  [pool-1-thread-1]  INFO Log4JBusinessService 
  - Preparing to transfer 958$. - tx.id=5 tx.owner=Susan
739  [pool-1-thread-3]  INFO Log4JBusinessService 
  - Has transfer of 783$ completed successfully ? true. - tx.id=3 tx.owner=Samantha
739  [pool-1-thread-3]  INFO Log4JBusinessService 
  - Preparing to transfer 1024$. - tx.id=6 tx.owner=John
1259 [pool-1-thread-2]  INFO Log4JBusinessService 
  - Has transfer of 1685$ completed successfully ? false. - tx.id=4 tx.owner=John
1260 [pool-1-thread-2]  INFO Log4JBusinessService 
  - Preparing to transfer 1667$. - tx.id=7 tx.owner=Marc

4. MDC в Log4j2

Та же самая функция доступна и в Log4j2, поэтому давайте посмотрим, как ее использовать.

Сначала мы настроим подкласс TransferService , который ведет журнал с помощью Log4j2:

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class Log4J2TransferService extends TransferService {
    private static final Logger logger = LogManager.getLogger();

    @Override
    protected void beforeTransfer(long amount) {
        logger.info("Preparing to transfer {}$.", amount);
    }

    @Override
    protected void afterTransfer(long amount, boolean outcome) {
        logger.info("Has transfer of {}$ completed successfully ? {}.", amount, outcome);
    }
}

Давайте тогда изменим код, использующий MDC, который на самом деле называется ThreadContext в Log4j2:

import org.apache.log4j.MDC;

public class Log4J2Runnable implements Runnable {
    private final Transaction tx;
    private Log4J2BusinessService log4j2BusinessService = new Log4J2BusinessService();

    public Log4J2Runnable(Transaction tx) {
        this.tx = tx;
    }

    public void run() {
        ThreadContext.put("transaction.id", tx.getTransactionId());
        ThreadContext.put("transaction.owner", tx.getOwner());
        log4j2BusinessService.transfer(tx.getAmount());
        ThreadContext.clearAll();
    }
}

Опять же, ThreadContext.put() добавляет запись в MDC, а ThreadContext.clearAll() удаляет все существующие записи.

Нам по-прежнему не хватает файла log4j2.xml для настройки ведения журнала.

Как мы можем заметить, синтаксис для указания того, какие записи MDC должны быть зарегистрированы, такой же, как и в Log4j:

<Configuration status="INFO">
    <Appenders>
        <Console name="stdout" target="SYSTEM_OUT">
            <PatternLayout
              pattern="%-4r [%t] %5p %c{1} - %m - tx.id=%X{transaction.id} tx.owner=%X{transaction.owner}%n" />
        </Console>
    </Appenders>
    <Loggers>
        <Logger name="com.foreach.log4j2" level="TRACE" />
        <AsyncRoot level="DEBUG">
            <AppenderRef ref="stdout" />
        </AsyncRoot>
    </Loggers>
</Configuration>

Опять же, давайте запустим приложение, и мы увидим, что информация MDC печатается в журнале:

1119 [pool-1-thread-3]  INFO Log4J2BusinessService 
  - Has transfer of 1198$ completed successfully ? true. - tx.id=3 tx.owner=Samantha
1120 [pool-1-thread-3]  INFO Log4J2BusinessService 
  - Preparing to transfer 1723$. - tx.id=5 tx.owner=Samantha
1170 [pool-1-thread-2]  INFO Log4J2BusinessService 
  - Has transfer of 701$ completed successfully ? true. - tx.id=2 tx.owner=Susan
1171 [pool-1-thread-2]  INFO Log4J2BusinessService 
  - Preparing to transfer 1108$. - tx.id=6 tx.owner=Susan
1794 [pool-1-thread-1]  INFO Log4J2BusinessService 
  - Has transfer of 645$ completed successfully ? true. - tx.id=4 tx.owner=Susan

5. MDC в SLF4J/Logback

MDC также доступен в SLF4J при условии, что он поддерживается базовой библиотекой протоколирования.

И Logback, и Log4j поддерживают MDC, как мы только что видели, поэтому нам не нужно ничего особенного, чтобы использовать его со стандартной настройкой.

Подготовим обычный подкласс TransferService , на этот раз используя Simple Logging Facade для Java:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

final class Slf4TransferService extends TransferService {
    private static final Logger logger = LoggerFactory.getLogger(Slf4TransferService.class);

    @Override
    protected void beforeTransfer(long amount) {
        logger.info("Preparing to transfer {}$.", amount);
    }

    @Override
    protected void afterTransfer(long amount, boolean outcome) {
        logger.info("Has transfer of {}$ completed successfully ? {}.", amount, outcome);
    }
}

Давайте теперь воспользуемся разновидностью MDC от SLF4J.

В этом случае синтаксис и семантика такие же, как и в log4j:

import org.slf4j.MDC;

public class Slf4jRunnable implements Runnable {
    private final Transaction tx;
    
    public Slf4jRunnable(Transaction tx) {
        this.tx = tx;
    }
    
    public void run() {
        MDC.put("transaction.id", tx.getTransactionId());
        MDC.put("transaction.owner", tx.getOwner());
        new Slf4TransferService().transfer(tx.getAmount());
        MDC.clear();
    }
}

Мы должны предоставить файл конфигурации Logback, logback.xml :

<configuration>
    <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>%-4r [%t] %5p %c{1} - %m - tx.id=%X{transaction.id} tx.owner=%X{transaction.owner}%n</pattern>
    </encoder>
    </appender>
    <root level="TRACE">
        <appender-ref ref="stdout" />
    </root>
</configuration>

Опять же, мы увидим, что информация в MDC правильно добавляется к зарегистрированным сообщениям, хотя эта информация явно не предоставляется в методе log.info() :

1020 [pool-1-thread-3]  INFO c.b.m.s.Slf4jBusinessService 
  - Has transfer of 1869$ completed successfully ? true. - tx.id=3 tx.owner=John
1021 [pool-1-thread-3]  INFO c.b.m.s.Slf4jBusinessService 
  - Preparing to transfer 1303$. - tx.id=6 tx.owner=Samantha
1221 [pool-1-thread-1]  INFO c.b.m.s.Slf4jBusinessService 
  - Has transfer of 1498$ completed successfully ? true. - tx.id=4 tx.owner=Marc
1221 [pool-1-thread-1]  INFO c.b.m.s.Slf4jBusinessService 
  - Preparing to transfer 1528$. - tx.id=7 tx.owner=Samantha
1492 [pool-1-thread-2]  INFO c.b.m.s.Slf4jBusinessService 
  - Has transfer of 1110$ completed successfully ? true. - tx.id=5 tx.owner=Samantha
1493 [pool-1-thread-2]  INFO c.b.m.s.Slf4jBusinessService 
  - Preparing to transfer 644$. - tx.id=8 tx.owner=John

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

6. MDC и пулы потоков

Реализации MDC обычно используют ThreadLocal для хранения контекстной информации. Это простой и разумный способ добиться потокобезопасности.

Однако мы должны быть осторожны, используя MDC с пулами потоков.

Давайте посмотрим, чем может быть опасна комбинация MDC на основе ThreadLocal и пулов потоков:

1. Мы получаем поток из пула потоков.
2. Затем мы сохраняем некоторую контекстную информацию в MDC, используя MDC.put() или ThreadContext.put() .
3. Мы используем эту информацию в некоторых логах, и как-то забыли очистить контекст MDC.
4. Заимствованный поток возвращается в пул потоков.
5. Через некоторое время приложение получает тот же поток из пула.
6. Поскольку в прошлый раз мы не очищали MDC, этот поток по-прежнему владеет некоторыми данными из предыдущего выполнения.

Это может вызвать некоторые неожиданные несоответствия между выполнениями.

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

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

Для этого мы можем расширить класс ThreadPoolExecutor и переопределить хук afterExecute() :

public class MdcAwareThreadPoolExecutor extends ThreadPoolExecutor {

    public MdcAwareThreadPoolExecutor(int corePoolSize, 
      int maximumPoolSize, 
      long keepAliveTime, 
      TimeUnit unit, 
      BlockingQueue<Runnable> workQueue, 
      ThreadFactory threadFactory, 
      RejectedExecutionHandler handler) {
        super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory, handler);
    }

    @Override
    protected void afterExecute(Runnable r, Throwable t) {
        System.out.println("Cleaning the MDC context");
        MDC.clear();
        org.apache.log4j.MDC.clear();
        ThreadContext.clearAll();
    }
}

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

Таким образом, нет необходимости делать это вручную:

@Override
public void run() {
    MDC.put("transaction.id", tx.getTransactionId());
    MDC.put("transaction.owner", tx.getSender());

    new Slf4TransferService().transfer(tx.getAmount());
}

Теперь мы можем переписать ту же демонстрацию с нашей новой реализацией исполнителя:

ExecutorService executor = new MdcAwareThreadPoolExecutor(3, 3, 0, MINUTES, 
  new LinkedBlockingQueue<>(), Thread::new, new AbortPolicy());
        
TransactionFactory transactionFactory = new TransactionFactory();

for (int i = 0; i < 10; i++) {
    Transfer tx = transactionFactory.newInstance();
    Runnable task = new Slf4jRunnable(tx);

    executor.submit(task);
}

executor.shutdown();

7. Заключение

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

И, как мы видели, он поддерживается тремя наиболее широко используемыми платформами ведения журналов в Java.

Как обычно, исходники доступны на GitHub .