Ведение журнала Java с вложенным диагностическим контекстом (NDC)

4 ноября 2018 г. · 6 мин. чтения

1. Обзор

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

В этой статье мы рассмотрим использование NDC и его использование/поддержку в различных средах журналирования Java.

2. Диагностические контексты

В типичном многопоточном приложении, таком как веб-приложение или REST API, каждый клиентский запрос обслуживается отдельным потоком. Журналы, созданные таким приложением, будут представлять собой смесь всех клиентских запросов и источников. Это затрудняет понимание журналов или их отладку с точки зрения бизнеса.

Вложенный диагностический контекст (NDC) управляет стеком контекстной информации для каждого потока. Данные в NDC доступны для каждого запроса журнала в коде и могут быть настроены для регистрации с каждым сообщением журнала — даже в тех местах, где данные не входят в область действия. Эта контекстная информация в каждом сообщении журнала помогает различать журналы по их источнику и контексту.

Сопоставленный диагностический контекст (MDC) также управляет информацией для каждого потока, но в виде карты.

3. Стек NDC в примере приложения

Чтобы продемонстрировать использование стека NDC, давайте рассмотрим пример REST API, который отправляет деньги на инвестиционный счет.

Информация, необходимая в качестве входных данных, представлена в инвестиционном классе:

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 .

В примере приложения данные transactionId и owner помещаются в стек NDC в потоке, обрабатывающем данный запрос. Эти данные доступны в каждом сообщении журнала в этом потоке. Таким образом, можно отследить каждую уникальную транзакцию и определить соответствующий контекст каждого сообщения журнала.

4. НДЦ в 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);
    }
}

Содержимое NDC можно отобразить в сообщениях журнала с помощью параметра %x в ConversionPattern , используемом appender в log4j.properties :

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. НДЦ в Log4j 2

NDC в Log4j 2 называется стеком контекста потока:

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, воспользуемся параметром %x в файле конфигурации Log4j 2 log4j2.xml :

<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.foreach.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 будет искать в ClassLoader доступность внутренних серверов/поставщиков в следующем порядке приоритета: 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 .

1. Обзор​

2. Диагностические контексты​

3. Стек NDC в примере приложения​

4. НДЦ в Log4j​

5. НДЦ в Log4j 2​

6. NDC в логировании фасадов (JBoss Logging)​

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