1. 概要

このチュートリアルでは、 Mapped Diagnostic Context (MDC)を使用して、アプリケーションのログを改善する方法について説明します。

マップされた診断コンテキストは、ログが実際に発生するスコープでは利用できない可能性があるが、プログラムの実行をより適切に追跡するのに実際に役立つ情報でログメッセージを強化する方法を提供します。

2. MDCを使用する理由

送金するソフトウェアを書かなければならないとしましょう。

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

転送を実行するには、単純な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.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 + ".");
    }
}

ここで注意すべき主な問題は、ログメッセージの作成時に、転送オブジェクトにアクセスできないことです。アクセスできるのは金額のみであり、トランザクションIDまたは送信者のいずれもログに記録できません。

コンソールにログオンするために、通常の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 を使用するには、 executeor.submit()を予期しているため、Log4JTransferServiceの実行をアダプターでラップする必要があることに注意してください。実行可能

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

複数の転送を同時に管理するデモアプリケーションを実行すると、ログが思ったほど役に立たないことがすぐにわかります。

ログに記録される有用な情報は、転送された金額とその特定の転送を実行しているスレッドの名前だけであるため、各転送の実行を追跡するのは複雑です。

さらに、関連するログ行は基本的に同じように見えるため、同じスレッドで実行される同じ量の2つの異なるトランザクションを区別することはできません。

...
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. Log4jのMDC

Log4jのMDCを使用すると、ログメッセージが実際に書き込まれるときに、アペンダーがアクセスできる情報でマップのような構造を埋めることができます。

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に保存したばかりの情報を出力してみましょう。

ログに記録する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

ここで、アプリケーションを実行すると、各行に処理中のトランザクションに関する情報も含まれているため、アプリケーションの実行を追跡するのがはるかに簡単になります。

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. Log4j2のMDC

Log4j2でもまったく同じ機能を利用できるので、その使用方法を見てみましょう。

まず、Log4j2を使用してログを記録するTransferServiceサブクラスを設定します。

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を使用するコードを変更してみましょう。これは、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();
    }
}

この場合も、 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.baeldung.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. SLF4J/ログバックのMDC

MDC は、基盤となるロギングライブラリでサポートされていることを条件に、SLF4Jでも使用できます。

これまで見てきたように、LogbackとLog4jはどちらもMDCをサポートしているため、標準のセットアップで使用するために特別なことは何も必要ありません。

通常のTransferServiceサブクラスを準備しましょう。今回は、JavaのSimpleLoggingFacadeを使用します。

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

SLF4JのMDCのフレーバーを使用してみましょう。

この場合、構文とセマンティクスは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.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>

この場合も、 log.info()メソッドでこの情報が明示的に提供されていなくても、MDCの情報がログに記録されたメッセージに適切に追加されていることがわかります。

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

MDCをサポートしないロギングシステムにSLF4Jバックエンドを設定した場合、関連するすべての呼び出しが副作用なしにスキップされることに注意してください。

6. MDCとスレッドプール

MDC実装は通常、ThreadLocalsを使用してコンテキスト情報を格納します。これは、スレッドセーフを実現するための簡単で合理的な方法です。

ただし、スレッドプールでMDCを使用する場合は注意が必要です。

ThreadLocalベースのMDCとスレッドプールの組み合わせがどのように危険であるかを見てみましょう。

  1. スレッドプールからスレッドを取得します。
  2. 次に、 MDC.put()または ThreadContext.put()を使用して、いくつかのコンテキスト情報をMDCに格納します。
  3. 一部のログでこの情報を使用していますが、どういうわけかMDCコンテキストをクリアするのを忘れていました。
  4. 借用したスレッドはスレッドプールに戻ります。
  5. しばらくすると、アプリケーションはプールから同じスレッドを取得します。
  6. 前回MDCをクリーンアップしなかったため、このスレッドは前回の実行からのデータをまだ所有しています。

これにより、実行間に予期しない不整合が発生する可能性があります。

これを防ぐ1つの方法は、各実行の最後にMDCコンテキストをクリーンアップすることを常に忘れないことです。 このアプローチは通常、厳密な人間による監視が必要であるため、エラーが発生しやすくなります。

もう1つのアプローチは、 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で最も広く使用されている3つのロギングフレームワークによってサポートされています。

いつものように、ソースはGitHubから入手できます。