tech.guitarrapc.cóm

Technical updates

CircleCI 上で dotnet test の verbosity がオーバーライドできない問題とその対処

CircleCI で dotnet test、妙な挙動をすることは前回1つ紹介しました。

tech.guitarrapc.com

が、まさかまた1つネタが見つかるとは思わなかったです。

今回は dotnet test がこけた時の出力について。

更新

2020/6/17 本件の修正がマージされて修正されました。やったね。

github.com

目次

TL;DR

  • dotnet test< /dev/null を付けると出力も正常になる

まさかのこれと同じ対策で解消します。

tech.guitarrapc.com

問題

問題は2つあります。

  • CircleCI 上で dotnet test をしたときに、verbosity が quiet として実行される。(dotnet test のデフォルトverbosity は minimal)
  • CircleCI 上で dotnet test のConsole Logger の verbosity をオーバーライド指定して実行しても quiet から変わらない

dotnet test のおさらい

問題を把握するためには、dotnet test の基本的な挙動を把握しておく必要があります。 ざっくり説明します。

ローカルで適当に xUnit のプロジェクトを作って、適当に失敗する Factを作りdotnet test で実行すると、テストの失敗個所が表示されます。 このテストの失敗個所が表示されるのは、verbosity レベルが minimal 以上の時で、dotnet test はデフォルトで minimal に設定されています。

$ dotnet test

Test run for C:\git\guitarrapc\dotnet-test-lab\tests\XUnitTestProject1\bin\Debug\netcoreapp3.1\XUnitTestProject1.dll(.NETCoreApp,Version=v3.1)
Microsoft (R) Test Execution Command Line Tool Version 16.3.0
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...

A total of 1 test files matched the specified pattern.
[xUnit.net 00:00:01.61]     XUnitTestProject1.UnitTest1.BoolFailTest [FAIL]
  X XUnitTestProject1.UnitTest1.BoolFailTest [7ms]
  Error Message:
   Assert.False() Failure
Expected: False
Actual:   True
  Stack Trace:
     at XUnitTestProject1.UnitTest1.BoolFailTest() in C:\git\guitarrapc\dotnet-test-lab\tests\XUnitTestProject1\UnitTest1.cs:line 33

Test Run Failed.
Total tests: 4
     Passed: 3
     Failed: 1
 Total time: 2.9317 Seconds

この結果の解像度をオーバーライドすることは、dotnet test 自体、あるいは Test Loggerごとに設定可能です。

  • dotnet test 自体のverbosity をオーバーライドするなら--verbosity 引数を使って dotnet test --verbosity [quiet|minimal|normal|detailed] を指定します
  • dotnet test の特定のテストロガーをオーバーライドするなら --logger:ロガー名;verbosity=[quiet|minimal|normal|detailed] を指定します

dotnet test 自体のverbosity を上げると、ビルドログなど見たくないログも増えてしまうのであまり好まれないと思います。 そのため通常は、Consoleロガーのverbosity だけ挙げて対処するでしょう。

たとえばConsoleLoggerのverbosity を normal にするならこのように指定します。 normal にしてお手元で実行すると、今まで dotnet test で出力されていなかった1つ一つのテストが成功、失敗にかかわらず出力されるはずです。

dotnet test "--logger:Console;verbosity=normal"

このことから、押さえておくべきは2つです。

  • dotnet test をverbosity 指定なしに実行したときは minimal を期待している
  • もし verbosity がちがった場合でも、--logger:console;verbosity=minimal などでオバーライドできることを期待している

何が問題なのか

CircleCI 上でローカルと同じように dotnet test を実行すると、失敗したテストの詳細が表示されないことに気がつきます。 これは verbosity が quiet の時の表示と合致し、ローカルでも dotnet test --verbosity quiet とすると再現します。 つまり、指定していないのになぜか verbosity がminimal ではなく quiet になっています。

$ dotnet test -c Debug

Test run for /root/project/tests/XUnitTestProject1/bin/Debug/netcoreapp3.1/XUnitTestProject1.dll(.NETCoreApp,Version=v3.1)
VSTest: Starting vstest.console...
VSTest: Arguments: dotnet exec /usr/share/dotnet/sdk/3.1.100/vstest.console.dll --testAdapterPath:/root/.nuget/packages/coverlet.collector/1.2.0/build/netstandard1.0/ --framework:.NETCoreApp,Version=v3.1 --logger:Console;verbosity=minimal --Diag:/root/project/bin/default/log.txt /root/project/tests/XUnitTestProject1/bin/Debug/netcoreapp3.1/XUnitTestProject1.dll
Microsoft (R) Test Execution Command Line Tool Version 16.3.0
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...

A total of 1 test files matched the specified pattern.
[xUnit.net 00:00:00.49]     XUnitTestProject1.UnitTest1.BoolFailTest [FAIL]
Test run in progress.VSTest: Exit code: 1

Exited with code exit status 1

また、このverbosityをオーバーライドしようとしても minimal から変更されず quiet 時の出力のままです。

#!/bin/bash -eo pipefail
dotnet test -c Debug "--logger:Console;verbosity=minimal"

Test run for /root/project/tests/XUnitTestProject1/bin/Debug/netcoreapp3.1/XUnitTestProject1.dll(.NETCoreApp,Version=v3.1)
VSTest: Starting vstest.console...
VSTest: Arguments: dotnet exec /usr/share/dotnet/sdk/3.1.100/vstest.console.dll --testAdapterPath:/root/.nuget/packages/coverlet.collector/1.2.0/build/netstandard1.0/ --framework:.NETCoreApp,Version=v3.1 --logger:Console;verbosity=minimal --Diag:/root/project/bin/default/log.txt /root/project/tests/XUnitTestProject1/bin/Debug/netcoreapp3.1/XUnitTestProject1.dll
Microsoft (R) Test Execution Command Line Tool Version 16.3.0
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...

A total of 1 test files matched the specified pattern.
[xUnit.net 00:00:00.49]     XUnitTestProject1.UnitTest1.BoolFailTest [FAIL]
Test run in progress.VSTest: Exit code: 1

Exited with code exit status 1

これはもちろん、dotnet test -c Debug --verbosity=minimal でも変わらず quiet のままです。

再現リポジトリ

再現リポジトリを組んであります。

github.com

ワークアラウンド

dotnet test< /dev/null を付けると、dotnet test のデフォルトverbosityが minimal に正常化されます。

また、verbosity のオーバーライドも正常に機能するようになります。

進捗

microsoft/vstest に報告してあるので、根本対処されるかはIssueの結果次第です。

github.com

まとめ

知らないとこれはまるのでは。

英語含めて記事が全然ないところみると、.NET で CircleCI やはり利用少ない気配があります。 知ってたけど。

前なら Azure Pipeline、今なら GitHub Actions を使う人が多くなっていくんだろうなぁと感じます。 これは Microsoft のdocs などでの露出に誘導されてるのも多分にあるんですかね? と思ったり思わなかったり。

余談: 調査する

当初、CircleCI ではなく ubuntu か何か環境問題か? と思ったのですが、ローカルで dotnet test したり、Docker 上でCircleCI と同じ dotnet-sdk:3.1 イメージを使ってテストを実行しても再現せず正常に指定した verbosity でオーバーライドができます。 この時点で環境問題の可能性は消えます。Dockerさいこー。

コードを確認すると、--Logger:"Console;verbosity=minimal" を渡せば解釈されることがわかります。

            var verbosityExists = parameters.TryGetValue(ConsoleLogger.VerbosityParam, out string verbosity);
            if (verbosityExists && Enum.TryParse(verbosity, true, out Verbosity verbosityLevel))
            {
                this.verbosityLevel = verbosityLevel;
            }

vstest/ConsoleLogger.cs at 5ef1f3b60404588b91fabb4fab22304ac88b108a · microsoft/vstest

他に何か原因があるのかといろいろ調べたけど、ことごとく該当せず...。

そういえば自分のプロジェクトで、この問題が出ず正常にできているものがあるのでなぜかを見てみると、まさかの < /dev/null をしていて前のIssueと同じ対処で解決できています。

tech.guitarrapc.com

ということで、原因はよくわからないけど < /dev/null で出力まで改善されるという謎結果に...。

なお、Diagnostics Logを --diag:diag.txt で出してみてみると、<dev/null を指定しなくてもちゃんと verbosity が設定した値になっているので、 < /dev/null で治るのは make sense といえばそうですが、謎い。

しかし、なんで /dev/null で出力というか挙動が変わるんだ.... stdin なんて何か色ない限りhandleしないと思うんだけど....?