ネストされた診断コンテキスト（NDC）を使用したJavaロギング

投稿日: 2019-10-18 2022-10-31
タグ: Log4j2, Logging

1. 概要

ネストされた診断コンテキスト（NDC）は、インターリーブされたログメッセージをさまざまなソースから区別するのに役立つメカニズムです。 NDCは、各ログエントリに固有のコンテキスト情報を追加する機能を提供することでこれを実現します。

この記事では、さまざまなJavaロギングフレームワークでのNDCの使用とその使用法/サポートについて説明します。

2. 診断コンテキスト

WebアプリケーションやRESTAPIなどの一般的なマルチスレッドアプリケーションでは、各クライアント要求は異なるスレッドによって処理されます。このようなアプリケーションから生成されるログは、すべてのクライアント要求とソースが混在したものになります。これにより、ログのビジネス上の意味を理解したり、デバッグしたりすることが困難になります。

ネストされた診断コンテキスト（NDC）は、スレッドごとにコンテキスト情報のスタックを管理します。 NDCのデータは、コード内のすべてのログリクエストで利用でき、データがスコープ内にない場所でも、すべてのログメッセージでログに記録するように構成できます。各ログメッセージのこのコンテキスト情報は、ソースとコンテキストによってログを区別するのに役立ちます。

Mapped Diagnostic Context（MDC）も、スレッドごとに、ただしマップとして情報を管理します。

3. サンプルアプリケーションのNDCスタック

NDCスタックの使用法を示すために、投資アカウントに送金するRESTAPIの例を見てみましょう。

入力として必要な情報は、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プロジェクトにあります。

サンプルアプリケーションでは、データtransactionIdおよびownerは、特定のリクエストを処理しているスレッドのNDCスタックに配置されます。このデータは、そのスレッドのすべてのログメッセージで利用できます。このようにして、それぞれの固有のトランザクションを追跡し、各ログメッセージの関連するコンテキストを特定できます。

4. Log4jのNDC

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の内容は、log4j.propertiesのアペンダーが使用するConversionPatternの%xオプションを使用して、ログメッセージに表示できます。

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

RESTAPIを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. Log4j2のNDC

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構成ファイル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はJBossLoggingでサポートされています。

デフォルトでは、JBossLoggingはClassLoader を検索して、バックエンド/プロバイダーの可用性を次の優先順位で検索します：JBoss LogManager、Log4j 2、Log4j、SLF4J、およびJDKLogging。

ロギングプロバイダーとしてのJBossLogManagerは、通常、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プロジェクトにあります。

getdocs

13036