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 + ".");
    }
}

ここで注意すべき主な問題は、 – ログメッセージが作成されるとき、

Transfer

オブジェクトにアクセスすることは不可能です – トランザクション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();
    }
}


executor.submit()



Runnable

を必要とするため、

ExecutorService

を使用するには、

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


MDC

を紹介しましょう。

Log4jの

MDC

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

MDC構造体は、

ThreadLocal

変数と同じ方法で内部的に実行スレッドにアタッチされています。

だから、高レベルのアイデアは:

  1. MDCに作成したい情報を入力する

アペンダーに利用可能
。それからメッセージを記録する

  1. そして最後に、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を空にします。

MDCに保存した情報を印刷するように

log4j.properties

を変更しましょう。ログに記録したい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);
    }
}

それでは、実際にはLog4j2では

ThreadContext

と呼ばれるMDCを使用するコードを変更しましょう。

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

今度は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設定ファイル

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

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

6.まとめ

MDCには、主にいくつかの異なるスレッドを実行するとインターリーブされたログメッセージが表示され、それ以外の場合は読みにくいシナリオで、多くのアプリケーションがあります。

これまで見てきたように、これはJavaで最も広く使われている3つのロギングフレームワークによってサポートされています。

いつものように、あなたはソースhttps://github.com/eugenp/tutorials/tree/master/logging-modules/log-mdc[GitHubについて]を見つけるでしょう。