Improved Java Logging with Mapped Diagnostic Context (MDC) – 用映射的诊断上下文（MDC）改进Java日志管理

最后修改: 2016年 11月 15日

中文/混合/英文(键盘快捷键：t)

1. Overview

1.概述

In this tutorial, we will explore the use of Mapped Diagnostic Context (MDC) to improve the application logging.

在本教程中，我们将探讨使用映射的诊断上下文（MDC）来改善应用程序的日志。

Mapped Diagnostic Context provides a way to enrich log messages with information that could be unavailable in the scope where the logging actually occurs but that can be indeed useful to better track the execution of the program.

映射的诊断上下文提供了一种方法来丰富日志信息，这些信息在实际发生日志的范围内可能是不可用的，但对于更好地跟踪程序的执行确实有用。

2. Why Use MDC

2.为什么使用MDC

Let’s suppose we have to write software that transfers money.

假设我们要写一个转移资金的软件。

We set up a Transfer class to represent some basic information — a unique transfer id and the name of the sender:

我们设置了一个Transfer类来表示一些基本信息–一个独特的传输ID和发送者的名字。

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;
    }
}

To perform the transfer, we need to use a service backed by a simple API:

为了执行转移，我们需要使用一个由简单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);
}

The beforeTransfer() and afterTransfer() methods can be overridden to run custom code right before and right after the transfer completes.

beforeTransfer()和afterTransfer()方法可以被重载，以便在传输完成之前和之后立即运行自定义代码。

We’re going to leverage beforeTransfer() and afterTransfer() to log some information about the transfer.

我们将利用beforeTransfer()和afterTransfer()来记录关于转移的一些信息。

Let’s create the service implementation:

让我们来创建服务的实现。

import org.apache.log4j.Logger;
import com.baeldung.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 + ".");
    }
}

The main issue to note here is that when the log message is created, it is not possible to access the Transfer object — only the amount is accessible, making it impossible to log either the transaction id or the sender.

这里需要注意的主要问题是，当创建日志信息时，不可能访问Transfer对象–只有金额可以访问，这使得无法记录交易ID或发送者。

Let’s set up the usual log4j.properties file to log on the console:

让我们设置通常的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

Finally, we’ll set up a small application that is able to run multiple transfers at the same time through an ExecutorService:

最后，我们将设置一个小程序，该程序能够通过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();
    }
}

Note that in order to use the ExecutorService, we need to wrap the execution of the Log4JTransferService in an adapter because executor.submit() expects a Runnable:

请注意，为了使用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());
    }
}

When we run our demo application that manages multiple transfers at the same time, we quickly see that the log is not as useful as we would like it to be.

当我们运行我们的演示应用程序，同时管理多个传输时，我们很快看到日志并不像我们希望的那样有用。

It’s complex to track the execution of each transfer because the only useful information being logged is the amount of money transferred and the name of the thread that is running that particular transfer.

追踪每笔转账的执行情况是很复杂的，因为被记录的唯一有用信息是转账金额和运行该特定转账的线程名称。

What’s more, it’s impossible to distinguish between two different transactions of the same amount run by the same thread because the related log lines look essentially the same:

更重要的是，不可能区分由同一线程运行的两个相同金额的不同事务，因为相关的日志行看起来基本相同。

...
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$.
...

Luckily, MDC can help.

幸运的是，MDC可以提供帮助。。

3. MDC in Log4j

3.Log4j中的MDC

MDC in Log4j allows us to fill a map-like structure with pieces of information that are accessible to the appender when the log message is actually written.

Log4j中的MDC允许我们在一个类似地图的结构中填充一些信息，这些信息在实际写入日志消息时可以被appender访问。

The MDC structure is internally attached to the executing thread in the same way a ThreadLocal variable would be.

MDC结构以ThreadLocal变量的相同方式在内部附加到执行线程。

Here’s the high-level idea:

这里有一个高层次的想法。

  1. Fill the MDC with pieces of information that we want to make available to the appender
  2. Then log a message
  3. And finally clear the MDC

The pattern of the appender should be changed in order to retrieve the variables stored in the MDC.

为了检索存储在MDC中的变量，应该改变appender的模式。

So, let’s change the code according to these guidelines:

因此，让我们根据这些准则来修改代码。

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() is used to add a key and a corresponding value in the MDC, while MDC.clear() empties the MDC.

MDC.put() 用于在 MDC 中添加一个键和一个相应的值，而 MDC.clear() 则是清空 MDC。

Let’s now change the log4j.properties to print the information that we’ve just stored in the MDC.

现在让我们修改 log4j.properties，以打印我们刚刚存储在 MDC 中的信息。

It is enough to change the conversion pattern, using the %X{} placeholder for each entry contained in the MDC we want to be logged:

只需改变转换模式，对我们想要记录的MDC中包含的每个条目使用%X{}占位符。

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

Now if we run the application, we’ll note that each line also carries the information about the transaction being processed, making it far easier for us to track the execution of the application:

现在，如果我们运行这个应用程序，我们会注意到每一行都带有正在处理的事务的信息，使我们更容易跟踪应用程序的执行。

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 in Log4j2

4.Log4j2中的MDC

The very same feature is available in Log4j2 too, so let’s see how to use it.

Log4j2中也有同样的功能，让我们看看如何使用它。

We’ll first set up a TransferService subclass that logs using 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);
    }
}

Let’s then change the code that uses the MDC, which is actually called ThreadContext in Log4j2:

然后让我们改变使用MDC的代码，它在Log4j2中实际上叫做ThreadContext。

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();
    }
}

Again, ThreadContext.put() adds an entry in the MDC and ThreadContext.clearAll() removes all the existing entries.

同样，ThreadContext.put()在MDC中添加了一个条目，ThreadContext.clearAll()删除了所有现有条目。

We still miss the log4j2.xml file to configure the logging.

我们仍然怀念用于配置日志的log4j2.xml文件。

As we can note, the syntax to specify which MDC entries should be logged is the same as the one used in Log4j:

我们可以注意到，指定哪些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.baeldung.log4j2" level="TRACE" />
        <AsyncRoot level="DEBUG">
            <AppenderRef ref="stdout" />
        </AsyncRoot>
    </Loggers>
</Configuration>

Again, let’s run the application, and we’ll see the MDC information being printed in the log:

再一次，让我们运行该应用程序，我们将看到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 in SLF4J/Logback

5.SLF4J/Logback中的MDC

MDC is available in SLF4J too, under the condition that it is supported by the underlying logging library.

MDC在SLF4J中也是可用的，条件是它被底层日志库支持。

Both Logback and Log4j support MDC, as we’ve just seen, so we need nothing special to use it with a standard set up.

正如我们刚刚看到的，Logback和Log4j都支持MDC，所以我们不需要什么特别的东西就可以在标准设置下使用它。

Let’s prepare the usual TransferService subclass, this time using the Simple Logging Facade for Java:

让我们准备一下通常的TransferService子类，这次使用Java的Simple Logging Facade。

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);
    }
}

Let’s now use the SLF4J’s flavor of MDC.

现在让我们使用SLF4J的风味的MDC。

In this case, the syntax and semantics are the same as in log4j:

在这种情况下，语法和语义与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();
    }
}

We have to provide the Logback configuration file, logback.xml:

我们必须提供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>

Again, we’ll see that the information in the MDC is properly added to the logged messages, even though this information is not explicitly provided in the log.info() method:

同样，我们将看到 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

It is worth noting that if we set up the SLF4J backend to a logging system that does not support MDC, all the related invocations will simply be skipped without side effects.

值得注意的是，如果我们将SLF4J的后端设置为不支持MDC的日志系统，那么所有相关的调用将被简单地跳过，不会产生副作用。

6. MDC and Thread Pools

6.MDC和线程池

MDC implementations typically use ThreadLocals to store the contextual information. That’s an easy and reasonable way to achieve thread-safety.

MDC 实现通常使用 ThreadLocals 来存储上下文信息。这是实现线程安全的一个简单而合理的方法。

However, we should be careful using MDC with thread pools.

然而，我们应该小心地将MDC与线程池一起使用。

Let’s see how the combination of ThreadLocal-based MDCs and thread pools can be dangerous:

让我们来看看基于ThreadLocal的MDC和线程池的组合会有什么危险。

  1. We get a thread from the thread pool.
  2. Then we store some contextual information in MDC using MDC.put() or ThreadContext.put().
  3. We use this information in some logs, and somehow we forgot to clear the MDC context.
  4. The borrowed thread comes back to the thread pool.
  5. After a while, the application gets the same thread from the pool.
  6. Since we didn’t clean up the MDC last time, this thread still owns some data from the previous execution.

This may cause some unexpected inconsistencies between executions.

这可能会导致执行之间出现一些意外的不一致。

One way to prevent this is to always remember to clean up the MDC context at the end of each execution. This approach usually needs rigorous human supervision and is therefore error-prone.

防止这种情况的一种方法是始终记得在每次执行结束后清理 MDC 上下文。这种方法通常需要严格的人工监督，因此容易出错。

Another approach is to use ThreadPoolExecutor hooks and perform necessary cleanups after each execution. 

另一种方法是使用ThreadPoolExecutor钩，并在每次执行后进行必要的清理。

To do that, we can extend the ThreadPoolExecutor class and override the afterExecute() hook:

要做到这一点，我们可以扩展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();
    }
}

This way, the MDC cleanup would automatically happen after each normal or exceptional execution.

这样一来，MDC的清理工作就会在每次正常或特殊执行后自动进行。

So, there is no need to do it manually:

因此，没有必要手动操作。

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

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

Now we can re-write the same demo with our new executor implementation:

现在我们可以用我们新的执行器实现来重写同一个演示。

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. Conclusion

7.结语

MDC has lots of applications, mainly in scenarios in which running several different threads causes interleaved log messages that would be otherwise hard to read.

MDC有很多应用，主要是在运行几个不同的线程导致交错的日志信息的情况下，否则很难阅读。

And as we’ve seen, it’s supported by three of the most widely used logging frameworks in Java.

正如我们所看到的，它被Java中最广泛使用的三个日志框架所支持。

As usual, the sources are available over on GitHub.

像往常一样，源代码可以在GitHub上找到over。