TestNG で実行中のテストメソッドをリスナで可視化する

## TestNG あるある「ここはどこ？」

コンソール上で TestNG のテストをふつうに流すと，どのテストメソッドを実行中かといった情報を何も出してくれません．
全部のテストがすんなり流れてくれるならそれで構わないのですが，

```
% mvn clean test
[INFO] Scanning for projects...
(中略)
[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[INFO] Running TestSuite
```

↑ たまにこんな表示のまま固まってしまって，どのテストでハングしているかもわからず途方にくれることがあります．

というわけで，そんな困ったことにならないように，TestNG でどのテストを実行中かをコンソール上に出力させる方法を紹介します．
対処後に出力されるログのイメージはこんな感じです:

```
[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[INFO] Running TestSuite
[CustomTestListener] [INFO] Running: com.example.calc.test.CalcTest#testAdd(0, 0, 0)
[CustomTestListener] [INFO] Running: com.example.calc.test.CalcTest#testAdd(0, 1, 1)
```

この記事では，以下の 3 つの方法を紹介します．

* 方法 1: テストメソッドにログを直接仕込む
* 方法 2: テストクラスの `@BeforeMethod` メソッドにログを仕込む
* 方法 3: リスナを追加して `onTestStart` メソッドにログを仕込む (← この記事のメイン)

## サンプルコード

この記事で使用するサンプルコードは GitHub に置いてあります．

* https://github.com/wgag/testng-listener-sample

## 方法 1: テストメソッドにログを直接仕込む

テストメソッドそのものに直接ログを仕込むという，素朴で安直な方法です．
ログを出したいメソッドが限られている場合はいいですが，数が多いと大変なことに...

```java
public class CalcTest {
    @Test(dataProvider = "testAdd")
    public void testAdd(int x, int y, int expected) {
        // テストメソッドの情報をログに出力
        LOGGER.info(String.format(
        "Running: com.example.calc.test.CalcTest#testAdd(%d, %d, %d)", x, y, expected));

        Calc calc = new Calc();
        assertEquals(calc.add(x, y), expected);
    }
    // ...
}
```

```
[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[INFO] Running TestSuite
[CalcTest] [INFO] Running: com.example.calc.test.CalcTest#testAdd(0, 0, 0)
[CalcTest] [INFO] Running: com.example.calc.test.CalcTest#testAdd(0, 1, 1)
```

## 方法 2: テストクラスの `@BeforeMethod` メソッドにログを仕込む

テストクラスに `@BeforeMethod` アノテーションを付けたメソッドを定義し，その中にログを仕込みます．
テストクラスをちょこっといじれば済むので，とっかかりやすくわかりやすいリーズナブルな方法ではないでしょうか．

```java
import org.testng.annotations.BeforeMethod;

public class CalcTest {
    @BeforeMethod
    public void beforeMethod(Method method, Object[] data) {
        // テストメソッドの情報をログに出力
        LOGGER.info(String.format(
            "Running: %s#%s(%s)",
            method.getDeclaringClass().getCanonicalName(),
            method.getName(),
            Arrays.stream(data).map(x -> x.toString()).collect(Collectors.joining(", "))));
    }
    // ...
}
```

```
[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[INFO] Running TestSuite
[CalcTest] [INFO] Running: com.example.calc.test.CalcTest#testAdd(0, 0, 0)
[CalcTest] [INFO] Running: com.example.calc.test.CalcTest#testAdd(0, 1, 1)
```

## 方法 3: リスナを追加して `onTestStart` メソッドにログを仕込む

TestNG のリスナを追加して，リスナの `onTestStart` メソッドでログを仕込むという方法です．
リスナを設定するという手間はありますが，設定がグローバルに効くので，ターゲットのテストメソッドが多い場合とかに有効です．
また，テストクラスをいじらなくても済むので，テストセットを変更できない場合 (TCK を実行する場合とか) にも役に立ちます．

TestNG のリスナは，`ITestListener` インタフェースを実装した以下のようなクラスとして用意します．

```java
import org.testng.ITestContext;
import org.testng.ITestListener;
import org.testng.ITestResult;

public class CustomTestListener implements ITestListener {
    private static final Logger LOGGER = Logger.getLogger(CustomTestListener.class);

    public void onTestStart(ITestResult result) {
        // テストメソッドの情報をログに出力
        LOGGER.info(String.format(
            "Running: %s#%s(%s)",
            result.getMethod().getTestClass().getName(),
            result.getMethod().getMethodName(),
            Arrays.stream(result.getParameters()).map(x -> x.toString()).collect(Collectors.joining(", "))));
    }

    public void onTestSuccess(ITestResult result) { }
    public void onTestFailure(ITestResult result) { }
    public void onTestSkipped(ITestResult result) { }
    public void onTestFailedButWithinSuccessPercentage(ITestResult result) { }
    public void onStart(ITestContext context) { }
    public void onFinish(ITestContext context) { }
}
```

また，リスナを TestNG に登録するために，`testng.xml` を編集するか，テストクラスに `@Listeners` アノテーションを指定します．
`testng.xml` でリスナを登録する場合は，以下のように書きます．

```xml
<suite>
    <listeners>
        <listener class-name="com.example.calc.test.util.CustomTestListener"/>
    </listeners>
   <!-- ... -->
</suite>
```

テストクラスに `@Listeners` アノテーションを指定する場合は，以下のように書きます．

```java
import org.testng.annotations.Listeners;

@Listeners({ CustomTestListener.class })
public class CalcTest {
    // ...
}
```

期待されるログの出力はこんな感じです．

```
[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[INFO] Running TestSuite
[CustomTestListener] [INFO] Running: com.example.calc.test.CalcTest#testAdd(0, 0, 0)
[CustomTestListener] [INFO] Running: com.example.calc.test.CalcTest#testAdd(0, 1, 1)
```

## まとめ

TestNG で実行中のテストを可視化する方法を紹介しました．
この記事で紹介したように方法はいろいろあるので，ケースバイケースで試してみてください！

## 参考文献

* [TestNG Documentation](https://testng.org/doc/documentation-main.html)