CircleCI で dotnet test、妙な挙動をすることは前回一つ紹介しました。
が、まさかまた一つネタが見つかるとは思わなかったです。
今回は dotnet test がこけた時の出力について。
目次
TL;DR
dotnet testに< /dev/nullを付けると出力も正常になる
まさかのこれと同じ対策で解消します。
問題
問題は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 で出力されていなかった一つ一つのテストが成功、失敗にかかわらず出力されるはずです。
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 のままです。
再現リポジトリ
再現リポジトリを組んであります。
ワークアラウンド
dotnet test に < /dev/null を付けると、dotnet test のデフォルトverbosityが minimal に正常化されます。
また、verbosity のオーバーライドも正常に機能するようになります。
進捗
microsoft/vstest に報告してあるので、根本対処されるかはIssueの結果次第です。
まとめ
知らないとこれはまるのでは。
英語含めて記事が全然ないところみると、.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
他に何か原因があるのかといろいろ調べたけど、ことごとく該当せず....
- dotnet test コマンド - .NET Core CLI | Microsoft Docs
- .NET Core tests produce no output · Issue #1141 · xunit/xunit
- c# - Xunit Unit Tests will not run - Stack Overflow
- dotnet test verbosity level for test output only · Issue #1773 · microsoft/vstest
- Make --verbosity case insensitive by nohwnd · Pull Request #2300 · microsoft/vstest
- Tests hang from dotnet test · Issue #2080 · microsoft/vstest
そういえば自分のプロジェクトで、この問題が出ず正常にできているものがあるのでなぜかを見てみると、まさかの < /dev/null をしていて前のIssueと同じ対処で解決できています。
ということで、原因はよくわからないけど < /dev/null で出力まで改善されるという謎結果に....
なお、Diagnostics Logを --diag:diag.txt で出してみてみると、<dev/null を指定しなくてもちゃんと verbosity が設定した値になっているので、 < /dev/null で治るのは make sense といえばそうですが、謎い。
しかし、なんで /dev/null で出力というか挙動が変わるんだ.... stdin なんて何か色ない限りhandleしないと思うんだけど....?
