1. 概述

嵌套诊断上下文(Nested Diagnostic Context,NDC)是一种机制,用于帮助区分来自不同源的交错日志消息。NDC通过提供在每个日志条目中添加独特上下文信息的能力来实现这一点。

在这篇文章中,我们将探讨NDC的使用及其在各种Java日志框架中的应用。

2. 诊断上下文

在一个典型的多线程应用中,如Web应用或REST API,每个客户端请求由不同的线程处理。这种应用产生的日志会包含所有客户端请求和来源的混合,这使得理解和调试日志变得困难。

嵌套诊断上下文(NDC)按线程基础管理一个上下文信息堆栈。代码中的每个日志请求都可以访问NDC中的数据,并且可以配置在每次生成日志时都包含这些数据,即使数据的范围不适用。每个日志消息中的上下文信息有助于通过其来源和上下文区分日志。

Mapped Diagnostic Context(MDC)也按线程管理信息,但以映射的形式。

3. 示例应用中的NDC堆栈

为了演示NDC堆栈的使用,让我们以一个向投资账户转账的REST API为例。

所需输入的信息由一个Investment类表示:

public class Investment {
    private String transactionId;
    private String owner;
    private Long amount;

    public Investment (String transactionId, String owner, Long amount) {
        this.transactionId = transactionId;
        this.owner = owner;
        this.amount = amount;
    }
    
    // standard getters and setters
}

转账操作通过InvestmentService执行。这些类的完整源代码可以在这个GitHub项目中找到。

在示例应用中,数据transactionIdowner在处理给定请求的线程的NDC堆栈中设置。该线程中的每个日志消息都包含这些数据。这样,每个唯一的交易都能被追踪,每个日志消息的相关上下文也能被识别出来。

4. NDC在Log4j中的使用

Log4j提供了一个名为NDC的类,它提供了管理NDC堆栈中数据的静态方法。基本用法如下:

  • 进入上下文时,使用NDC.push()在当前线程中添加上下文数据。
  • 离开上下文时,使用NDC.pop()取出上下文数据。
  • 在退出线程时,调用NDC.remove()从线程中移除诊断上下文并确保内存释放(自Log4j 1.3起,这已不再必要)。

在示例应用中,我们将在代码中的相关位置使用NDC添加/删除上下文数据:

import org.apache.log4j.NDC;

@RestController
public class Log4JController {
    @Autowired
    @Qualifier("Log4JInvestmentService")
    private InvestmentService log4jBusinessService;

    @RequestMapping(
      value = "/ndc/log4j", 
      method = RequestMethod.POST)
    public ResponseEntity<Investment> postPayment(
      @RequestBody Investment investment) {
        
        NDC.push("tx.id=" + investment.getTransactionId());
        NDC.push("tx.owner=" + investment.getOwner());

        log4jBusinessService.transfer(investment.getAmount());

        NDC.pop();
        NDC.pop();

        NDC.remove();

        return 
          new ResponseEntity<Investment>(investment, HttpStatus.OK);
    }
}

log4j.properties中使用的appender的ConversionPattern中使用%x选项,可以在日志消息中显示NDC的内容:

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

让我们将REST API部署到Tomcat。样本请求:

POST /logging-service/ndc/log4j
{
  "transactionId": "4",
  "owner": "Marc",
  "amount": 2000
}

我们可以看到日志输出中的诊断上下文信息:

48569 [http-nio-8080-exec-3]  INFO Log4JInvestmentService 
  - Preparing to transfer 2000$. 
  - [tx.id=4 tx.owner=Marc]
49231 [http-nio-8080-exec-4]  INFO Log4JInvestmentService 
  - Preparing to transfer 1500$. 
  - [tx.id=6 tx.owner=Samantha]
49334 [http-nio-8080-exec-3]  INFO Log4JInvestmentService 
  - Has transfer of 2000$ completed successfully ? true. 
  - [tx.id=4 tx.owner=Marc] 
50023 [http-nio-8080-exec-4]  INFO Log4JInvestmentService 
  - Has transfer of 1500$ completed successfully ? true. 
  - [tx.id=6 tx.owner=Samantha]
...

5. NDC在Log4j 2中的使用

在Log4j 2中,NDC被称为线程上下文堆栈:

import org.apache.logging.log4j.ThreadContext;

@RestController
public class Log4J2Controller {
    @Autowired
    @Qualifier("Log4J2InvestmentService")
    private InvestmentService log4j2BusinessService;

    @RequestMapping(
      value = "/ndc/log4j2", 
      method = RequestMethod.POST)
    public ResponseEntity<Investment> postPayment(
      @RequestBody Investment investment) {
        
        ThreadContext.push("tx.id=" + investment.getTransactionId());
        ThreadContext.push("tx.owner=" + investment.getOwner());

        log4j2BusinessService.transfer(investment.getAmount());

        ThreadContext.pop();
        ThreadContext.pop();

        ThreadContext.clearAll();

        return 
          new ResponseEntity<Investment>(investment, HttpStatus.OK);
    }
}

与Log4j类似,我们可以在log4j2.xml的配置文件中使用%x选项:

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

日志输出:

204724 [http-nio-8080-exec-1]  INFO Log4J2InvestmentService 
  - Preparing to transfer 1500$. 
  - [tx.id=6, tx.owner=Samantha]
205455 [http-nio-8080-exec-2]  INFO Log4J2InvestmentService 
  - Preparing to transfer 2000$. 
  - [tx.id=4, tx.owner=Marc]
205525 [http-nio-8080-exec-1]  INFO Log4J2InvestmentService 
  - Has transfer of 1500$ completed successfully ? false. 
  - [tx.id=6, tx.owner=Samantha]
206064 [http-nio-8080-exec-2]  INFO Log4J2InvestmentService 
  - Has transfer of 2000$ completed successfully ? true. 
  - [tx.id=4, tx.owner=Marc]
...

6. NDC在日志封装器(JBoss Logging)中的使用

像SLF4J这样的日志封装器提供了与各种日志框架的集成。NDC在SLF4J中不被支持(但包含在slf4j-ext模块中)。JBoss Logging是一个日志桥接,类似于SLF4J。NDC在JBoss Logging中被支持。

默认情况下,JBoss Logging会按照以下优先级顺序搜索类加载器中后端/提供者的可用性:JBoss LogManager、Log4j 2、Log4j、SLF4J和JDK Logging。

作为日志提供者的JBoss LogManager通常在WildFly应用服务器内部使用。在我们的例子中,JBoss的日志桥接会选择下一个优先级(即Log4j 2)作为日志提供者。

首先,我们在pom.xml中添加所需的依赖:

<dependency>
    <groupId>org.jboss.logging</groupId>
    <artifactId>jboss-logging</artifactId>
    <version>3.3.0.Final</version>
</dependency>

最新的依赖版本可以在这里查看。

接下来,让我们在NDC堆栈中添加上下文信息:

import org.jboss.logging.NDC;

@RestController
public class JBossLoggingController {
    @Autowired
    @Qualifier("JBossLoggingInvestmentService")
    private InvestmentService jbossLoggingBusinessService;

    @RequestMapping(
      value = "/ndc/jboss-logging", 
      method = RequestMethod.POST)
    public ResponseEntity<Investment> postPayment(
      @RequestBody Investment investment) {
        
        NDC.push("tx.id=" + investment.getTransactionId());
        NDC.push("tx.owner=" + investment.getOwner());

        jbossLoggingBusinessService.transfer(investment.getAmount());

        NDC.pop();
        NDC.pop();

        NDC.clear();

        return 
          new ResponseEntity<Investment>(investment, HttpStatus.OK);
    }
}

日志输出:

17045 [http-nio-8080-exec-1]  INFO JBossLoggingInvestmentService 
  - Preparing to transfer 1,500$. 
  - [tx.id=6, tx.owner=Samantha]
17725 [http-nio-8080-exec-1]  INFO JBossLoggingInvestmentService 
  - Has transfer of 1,500$ completed successfully ? true. 
  - [tx.id=6, tx.owner=Samantha]
18257 [http-nio-8080-exec-2]  INFO JBossLoggingInvestmentService 
  - Preparing to transfer 2,000$. 
  - [tx.id=4, tx.owner=Marc]
18904 [http-nio-8080-exec-2]  INFO JBossLoggingInvestmentService 
  - Has transfer of 2,000$ completed successfully ? true. 
  - [tx.id=4, tx.owner=Marc]
...

7. 总结

我们已经看到了诊断上下文如何以有意义的方式关联日志——无论是从业务角度看还是为了调试目的。这是一种非常有价值的增强日志的技术,尤其是在多线程应用中。

本文所使用的示例可以在GitHub项目中找到。