JUnit JupiterのAutomatic Extension Detectionを使って簡単にテストのログにコンテキストを付与する

今回使った実装を使えば、どういうテストで実行された処理なのかが明確に分かるようになります。

使い方です。

class MdcExtensionTest {

  @Test
  public void test() {
    assertThat(MDC.get("test.displayName")).isNotNull();
    assertThat(MDC.get("test.id")).isNotNull();
  }

}

使い方は、テストを書くだけです。（この表現には誇張があります。）

冗談はさておき、今回の記事では、JUnit JupiterのAutomatic Extension Detectionを使ってテストのログにコンテキストを付与してみます。

また、今回の記事は以下の流れで説明します

はじめに
どう見やすくするか
今回実装したExtensionの実装
最初のサンプルはどうやって動いていたのか
JUnit JupiterのAutomatic Extension Detectionを有効にする
ログを追加して試してみる

はじめに

まず初めに、Gradleから吐き出される以下のようなテストのレポートを見たことをある方はいますか？

f:id:reteria:20200122095950p:plain

見たことない人もいるかもしれないので改めて注意して見て欲しい部分があります。それは、Standard Outputの部分です。

f:id:reteria:20200122100049p:plain

これ、1つのテストクラス（!= テスト）で発生した標準出力をまとめてくれています。しかし、この状態では、どのテストでログが出力されたのかは、テストとログを眺めながら調べることでしか分かりません。

そこで、この記事では、よりテストのログを活用するために、MDCにテストのコンテキストを注入することでよりテストのログを見やすくしてみます。

MDCはslf4jのAPIにありますが、Mapped Diagnostic Contextの略です。 MDCについての詳しい説明は slf4jの実装であるlogbackのドキュメントを読むと良いでしょう。

第8章診断コンテキスト

どう見やすくするか

以下のステップを踏むことでよりテストのログがどのテストから出力されたのか分かりやすくなるはずです。

JUnit JupiterのExtensionを使ってMDCに値を設定する
ログに MDCの値を出力するようにする

また、どんな値をMDCに設定していると見やすいかと考えると以下のようなものが考えられます。

テストクラス名
テスト名
テストのID

他にもあるかもしれませんが、ここでは上記の値をMDCに設定して試してみます。

今回実装したExtensionの実装

今回実装したExtensionの実装は以下のようなシンプルなコードです。

@AutoService(Extension.class)
public class MdcExtension implements BeforeEachCallback, AfterEachCallback {

  @Override
  public void beforeEach(ExtensionContext context) throws Exception {
    final Optional<String> classNameOpt = context.getTestClass()
      .map(Class::getName);
    classNameOpt.ifPresent(className -> MDC.put("test.class", className));
    if (!classNameOpt.isPresent()) {
      context.getTestInstance()
        .ifPresent(instance -> MDC.put("test.class", instance.getClass()
          .getName()));
    }
    MDC.put("test.displayName", context.getDisplayName());
     // context.getUniqueId()もあるが、uuidのような文字列ではないのでここではUUIDを使っている
    MDC.put("test.id", UUID.randomUUID().toString());
  }

  @Override
  public void afterEach(ExtensionContext context) throws Exception {
    MDC.remove("test.displayName");
    MDC.remove("test.class");
    MDC.remove("test.id");
  }
}

beforeEachでMDCに値を設定して afterEachでクリーンアップしているだけですね。

感の良い方はここで気づくと思うんですが JUnit JupiterのAutomatic Extension DetectionはServiceLoaderの仕組みを使っています。

最初のサンプルはどうやって動いていたのか

まず。最初のサンプルはどうやって動いていたのか説明すると以下のようなステップを踏むことで、個別のテストにExtensionの記述をすることなく Extensionを暗黙的に使うことができます。

JUnit JupiterのAutomatic Extension Detectionを有効にする
ServiceLoaderの設定を含むライブラリを依存関係に含める

では、次はJUnit JupiterのAutomatic Extension Detectionの有効の仕方を見ていきます。

JUnit JupiterのAutomatic Extension Detectionを有効にする方法

まず、JUnit JupiterのAutomatic Extension Detectionはデフォルトでは有効になっていません。そのため、このAutomatic Extension Detectionを有効にする方法を見ていきます。

公式のリファレンスとしては以下の箇所に説明がありますがこの記事にも書いておきます。 JUnit 5 User Guide

まず、テストの起動方法によって変わる方法として、以下のような設定方法があります。

Console Launcherを使っている人は --config オプション
Gradleを使っている人は systemProperty や systemProperties から
Mavenを使っている人は Maven Surefire Pluginの configurationParametersから

また、テストの起動方法によらない設定方法として以下があります。

JVMのシステムプロパティ
クラスパスのルートに置かれた、junit-platform.properties

今回は、junit-platform.propertiesを使って説明します。他の設定方法については、ドキュメントを参照してください。

Automatic Extension Detectionを有効にするには、以下のように junit-platform.properties に記述を加えれば良いです。

junit.jupiter.extensions.autodetection.enabled=true

また、Automatic Extension DetectionではServiceLoader経由でExtensionを探索します。 ServiceLoaderの利用方法等については他の記事に任せるのでググってください。

ログを追加して試してみる

では、最初のサンプルにログを追加して試してみます。

雑な感じで用意したlogback-test.xmlを以下に示します。

<configuration>

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>
                %d{yyyy-MM-dd HH:mm:ss} %-5level class: %X{test.class} id: %X{test.id} test: %X{test.displayName} %logger{36} - %msg%n
            </Pattern>
        </layout>
    </appender>


    <root level="info">
        <appender-ref ref="STDOUT"/>
    </root>

</configuration>

また、最初のテストにログを追加しました。

class MdcExtensionTest {

  Logger log = LoggerFactory.getLogger(MdcExtensionTest.class);

  @Test
  public void test() {
    assertThat(MDC.get("test.displayName")).isNotNull();
    assertThat(MDC.get("test.id")).isNotNull();
    log.info("MDCExtension test is end.");
  }

}

以下のようなログが出力されました。

2020-01-22 09:46:59 INFO  class: com.github.wreulicke.bricks.junit.jupiter.MdcExtensionTest id: 5ead17d4-b107-4541-b6a5-9c4cd5c05f7a test: test() c.g.w.b.j.jupiter.MdcExtensionTest - MDCExtension test is end.

まとめ

今回の記事では、JUnit JupiterのAutomatic Extension Detectionを使って Extensionを自動的に適用することで、個別のテストにExtensionの設定を記述することなくテストのログにMDCを介してコンテキストを付与してみました。これで、テストのログが少し追いかけやすくなるのではないでしょうか。

また、今回はやらなかったんですが、JUnit5のExtensionの様々なCallbackでログを出力すればどのステップで失敗したのか、みたいな情報も調べられるかもしれません。

終わり。

追記:

記事書いて思ったけど、テストのレポートで出力がクラス毎に分かれてるなら MDCにクラス名入れなくても良かったかも？