【調査】MSBuild でビルドした直後に dotnet test を実行するとリビルドされる

はじめに

初めまして。株式会社ラグザイアの笹原と申します。
弊社は今まで Ruby on Rails によるアプリケーション開発がメインでしたが2022年6月より .NET Framework, Windows Forms を使ったアプリケーションの開発も行っています。

今回は開発の中で起きたタイトル事象について調べた内容を記事にしました。
お時間ある方は最後まで見ていただけると幸いです。

背景

今回お話しする事象は GitHub Actions で自動テストを行うときに起こりました。
GitHub Actions のワークフローには下記のように Rebuild プロジェクトをビルドしてテストするというフローを書いていました。

      - name: Build Rebuild project
        run: MSBuild.exe Rebuild.csproj # <-- MSBuild でしかうまくビルドできないので dotnet test 前に MSBuild でビルドする 

      - name: Execute unit test
        run: dotnet test Rebuild.csproj # <-- ここでなぜかリビルドされてエラーとなってしまった

dotnet test を実行すれば本来ビルドも行ってくれるのですが、今回のプロジェクトは MSBuild でしかうまくビルドできないという事情があったため、先に MSBuild でビルドして dotnet test を実行していました。

想定では MSBuild で先にビルドしているので dotnet test 実行時にはリビルドはされずテストだけ実行されると思っていましたが実際にはリビルドが発生し、 dotnet でビルドが走るためビルドに失敗してエラーとなりました。

つまり、今回の事象は MSBuild でプロジェクトをビルドした直後に dotnet test コマンドを実行するとリビルドされるという事象です。また、この事象が起こるプロジェクトと起こらないプロジェクトがあることも分かりました。

イメージ

# 想定していた動き
# MSBuild でビルド
MSBuild.exe ./Rebuild.csproj
=> ビルドが完了
# dotnet test を実行
dotnet test ./Rebuild.csproj
=> MSBuild でビルド済みなのでテストだけ実行される

# 実際
# MSBuild でビルド
MSBuild.exe ./Rebuild.csproj
=> ビルドが完了
# dotnet test を実行
dotnet test ./Rebuild.csproj
=> なぜかリビルドされる…

原因

今回の事象ではキャッシュファイルが実行ファイルより新しいと判定されることでリビルドが起こっていました。キャッシュファイルは Hash の値が変わると更新されます。Hash はビルドするコードのファイルとビルドに必要なツールによって値が決定されます。

事象が起こったプロジェクトではビルドに必要なツールとしてMicrosoft.NET.Build.Extensions が使われているのですが、この Microsoft.NET.Build.Extensions の dll ファイルの参照先が MSBuild と dotnet で別モノになっていました。
MSBuild と dotnet で Microsoft.NET.Build.Extensions のファイルが別になっていると、ビルドに必要なツールが変わったと判定され Hash の値が変わります。Hash の値が変わるとキャッシュファイルが書き変えられます。
すると実行ファイルよりもキャッシュファイルのほうが新しくなるためリビルドされていました。

それに対して、リビルドが行われないプロジェクトではビルドに必要なツールとして Microsoft.NET.Build.Extensions が使われていませんでした。ビルド対象のファイル、ビルドに必要なツールが全く同じなので Hash の値も変わらずリビルドが起こりませんでした。

イメージ

注意: ファイル名やパス、Hash の値は適当です

MSBuild.exe Hoge.csproj を実行
ビルドしたいのは AAA.cs で使うツールは MSBuild/tool.dll やな
=> Hash の値は 1111 やで!
=> Hoge.exe を生成したで!

続けて dotnet test Hoge.csproj を実行
ビルドしたいのは AAA.cs で使うツールは dotnet/sdk/tool.dll ですね
=> Hash の値は 2222 です!
=> 既存のキャッシュファイルの Hash 値は 1111 で、今回の Hash は 2222 ですね。更新します!
=> キャッシュファイルの Hash 値を 2222 に書き換えました!
=> キャッシュファイルが実行ファイルよりも新しいのでリビルドしますね。いえーい。

MSBuild でビルドした直後に dotnet test していた理由

今回やりたかった事は GitHub Actions で dotnet test を実行するということでした。
dotnet test はビルドが必要な状況であればビルドを行ってからテストを行ってくれます。¹

しかし dotnet test ( dotnet build も同様) では .NET Framework のプロジェクトかつリソースファイルを含んでいる場合、うまくビルドできませんでした。²

エラー内容

C:\Program Files\dotnet\sdk\7.0.100\Microsoft.Common.CurrentVersion.targets(3923,5): error MSB4062: "Microsoft.Build.Tasks.AL" タスクをアセンブリ Microsoft.Build.Tasks.Core, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a から読み込めませんでした。 <UsingTask> 宣言が正しいこと、アセンブリとその依存関係が使用可能であること、および Microsoft.Build.Framework.ITask を実装するパブリック クラスがタスクに含まれていることを確認してください。 [Rebuild.csproj]

この件は、MSBuild であればビルドできることが分かったため MSBuild で先にビルドして dotnet test を実行すれば dotnet test 実行時にはビルドが走らずに、うまくテストが実行されると思っていました。
ですが実際にはリビルドが走りエラーとなることが分かり、今回の調査を行いました。

ちなみにもともとやりたかった GitHub Actions では dotnet test に --no-build オプションを指定してテスト前にビルドしないようにして解決しました。

GitHub Actions ワークフローの抜粋

      - name: Build Rebuild project
        run: MSBuild.exe Rebuild.csproj

      - name: Execute unit test
        run: dotnet test --no-build Rebuild.csproj

調査の記録

原因特定の調査記録を残しておきます。
以降、説明の都合上、リビルドが行われるプロジェクトを Rebuild プロジェクト、リビルドが行われないプロジェクトを NoRebuild プロジェクトとします。

再現確認

まずは Github Actions で発生した現象がローカル環境でも再現するか確認しました。

再現環境

OS 名:                 Microsoft Windows 11 Pro
OS バージョン:          10.0.22621 N/A ビルド 22621
MSBuild バージョン:     MSBuild version 17.4.0+18d5aef85 for .NET Framework 17.4.0.51802
.NET バージョン:        SDK バージョン: 7.0.100

まず MSBuild で build を実行しました。

MSBuild.exe .\Rebuild.csproj

結果、ビルドに成功しました。(プロジェクト名やパスは手修正で修正しています。以後も同様です。）

プロジェクト "Rebuild.csproj" (既定のターゲット) のビルドが完了しました。
ビルドに成功しました。

続いて dotnet test を実行します。

dotnet test .\Rebuild.sln

結果、エラーが発生しました。

エラー内容

C:\Program Files\dotnet\sdk\7.0.100\Microsoft.Common.CurrentVersion.targets(3923,5): error MSB4062: "Microsoft.Build.Tasks.AL" タスクをアセンブリ Microsoft.Build.Tasks.Core, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a から読み込めませんでした。 <UsingTask> 宣言が正しいこと、アセンブリとその依存関係が使用可能であること、および Microsoft.Build.Framework.ITask を実装するパブリック クラスがタスクに含まれていることを確認してください。 [Rebuild.csproj]

このエラーは dotnet build を実行しても起きました。（結果は省略）
よって dotnet test を実行した際にリビルドが走りエラーが起こったと考えられます。

ログの調査

このエラーは MSBuild コマンドでビルドすれば起きないので原因の深堀は今回は行いませんでした。
そもそも MSBuild コマンドでビルド直後に dotnet test してリビルドが行われなければ、今回のエラーは起きなかったはずです。

ここからは、なぜリビルドされるのか？に着目して原因を探していきます。
エラーは dotnet build が実行されて起こっているので以降は dotnet test ではなく dotnet build で検証を進めていきます。

詳細なログが欲しいので -v: diag オプションを使い、ファイルに結果を吐き出しました。

MSBuild のとき

MSBuild.exe .\Rebuild.csproj -v:diag > msbuild.log

dotnet のとき

dotnet build .\Rebuild.csproj -v diag > dotnet_build.log

余談ですが、私の環境だと↑でやると文字化けになったので↓のコマンドでログをとりました。
参考: https://stackoverflow.com/questions/48561374/dotnet-build-with-logger

dotnet build .\Rebuild.csproj /flp:v=diag /flp:logfile=dotnet_build.log

dotnet build のログ解析

dotnet_build.log の内容を確認していきます。7万8千行もありました（笑）。

あたり付け

さすがに見る気が起こらなかったのでオプションの詳細レベルをもっと下げて、どこらへんを見れば良いかあたりをつけます。詳細レベルを normal にすると実行されているタスク名が表示されますので、これであたりをつけてみました。

dotnet build .\Rebuild.csproj -v n

実行結果抜粋

  GenerateTargetFrameworkMonikerAttribute:
  すべての出力ファイルが入力ファイルに対して最新なので、ターゲット "GenerateTargetFrameworkMonikerAttribute" を省略します。
  CoreCompile:
    C:\Program Files\dotnet\dotnet.exe exec ~ 以下一部省略 ~
1>C:\Program Files\dotnet\sdk\7.0.100\Microsoft.Common.CurrentVersion.targets(3923,5): error MSB4062: "Microsoft.Build.Tasks.AL" タスクをアセンブリ Microsoft.Build.Tasks.Core, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a から読み込めませ
  んでした。 <UsingTask> 宣言が正しいこと、アセンブリとその依存関係が使用可能であること、および Microsoft.Build.Framework.ITask を実装するパブリック クラスがタスクに含まれていることを確認してください。 ~ 省略 ~
1>プロジェクト "Rebuild.csproj" (既定のターゲット) のビルドが終了しました -- 失敗。

ビルドに失敗しました。

すると CoreCompile というタスク内でエラーが起こっていることが分かりました。

CoreCompile がキーワードだと分かったので、dotnet_build.log の中身を CoreCompile で grep しました。すると気になる文章が見つかりました。

Rebuild プロジェクトに依存関係のあるプロジェクトの CoreCompile のログ部分

23330:14:03:23.029   3:6>ファイル "C:\Program Files\dotnet\sdk\7.0.100\Roslyn\Microsoft.CSharp.Core.targets" 内にある、プロジェクト "NoRebuild.csproj" からのターゲット "CoreCompile: (ターゲット ID: 97)" ( ターゲット "Compile" は依存):
23331:                   すべての出力ファイルが入力ファイルに対して最新なので、ターゲット "CoreCompile" を省略します。

上記は Rebuild プロジェクトに依存関係のあるプロジェクトの CoreCompile のログ部分です。
このログには すべての出力ファイルが入力ファイルに対して最新なので、ターゲット "CoreCompile" を省略します。 とありました。

対して Rebuild プロジェクトの PreCompile のログ部分をみると 入力ファイル "obj\Debug\Rebuild.csproj.CoreCompileInputs.cache" は出力ファイル "obj\Debug\Rebuild.exe" よりも新しいです。 とあります。
このことから、何らかの理由で Rebuild プロジェクトのキャッシュファイルが書き変わったことによってリビルドされたことが分かりました。

Rebuild プロジェクトの PreCompile のログ部分

68345:14:03:23.483   1:7>ファイル "C:\Program Files\dotnet\sdk\7.0.100\Roslyn\Microsoft.CSharp.Core.targets" 内にある、プロジェクト "Rebuild.csproj" からのターゲット "CoreCompile: (ターゲット ID: 137)" (ターゲット "Compile" は依存):
68346:                   ターゲット "CoreCompile" を完全にビルドしています。
68347:                   入力ファイル "obj\Debug\Rebuild.csproj.CoreCompileInputs.cache" は出力ファイル "obj\Debug\Rebuild.exe" よりも新しいです。

キャッシュファイルが更新される理由を探る

あたり付けにより次はキャッシュファイルに関するログを見れば良いことが分かりました。
dotnet_build.log の中身を CoreCompileInputs.cache で grep するとリビルドが起こらない NoRebuild プロジェクトに対し下記のログを見つけました

23311:                     コンテンツが変更されていないため、ファイル "NoRebuild.csproj.CoreCompileInputs.cache" への書き込みをスキップします。 (TaskId: 70)

これに対しリビルドが発生する Rebuild プロジェクトには同様のログがないことから、コンテンツが変更されて CoreCompileInputs.cache への書き込みが実行されたと予想できます。

ここで Rebuild プロジェクトの CoreCompileInputs.cache に関する処理をログから探します。
下記はキャッシュファイルに書き込みが行われたタスクのログです。

タスク "WriteLinesToFile" (TaskId: 82)
  タスク パラメーター:File=obj\Debug\Rebuild.csproj.CoreCompileInputs.cache (TaskId: 82)
  タスク パラメーター:Overwrite=True (TaskId: 82)
  タスク パラメーター:WriteOnlyWhenDifferent=True (TaskId: 82)
  タスク パラメーター:Lines=a354efb706fc0c860893ef7ea73400de584ca955 (TaskId: 82)
タスク "WriteLinesToFile" の実行が終了しました。 (TaskId: 82)
追加項目: FileWrites=obj\Debug\Rebuild.csproj.CoreCompileInputs.cache

このログにある「パラメーター」の内容に変化があるときにキャッシュファイルが更新されたと見なされリビルドされるのではないか？と予想しました。
パラメーターの File, Overwrite, WriteOnlyWhenDifferent の値が変わるというのは考えにくいので、Lines という値が怪しいと考えられます。

では MSBuild で最初にビルドされたときは、このパラメータはどのような値になっていたのかログファイルを確認します。
msbuild.log を確認すると下記のようになっていました。

タスク "WriteLinesToFile" (TaskId: 240)
  タスク パラメーター:WriteOnlyWhenDifferent=True (TaskId: 240)
  タスク パラメーター:Lines=16b0845bd9b1a75b69121f8706ea14700cc61cef (TaskId: 240)
  タスク パラメーター:Overwrite=True (TaskId: 240)
  タスク パラメーター:File=obj\Debug\Rebuild.csproj.CoreCompileInputs.cache (TaskId: 240)
タスク "WriteLinesToFile" の実行が終了しました。 (TaskId: 240)

dotnet_build.log と msbuild.log の結果を見比べると Lines の値が違うことが分かりました。

# dotnet build のとき
タスク パラメーター:Lines=a354efb706fc0c860893ef7ea73400de584ca955 (TaskId: 82)

# MSBuild のとき
タスク パラメーター:Lines=16b0845bd9b1a75b69121f8706ea14700cc61cef (TaskId: 240)

Lines の正体の調査

では Lines の値は何の値でしょうか？
Lines の値で log ファイル内を検索するとどうやら Hash の値ということがわかります。
そして Hash を決めるパラメータは ItemsToHash のファイルであることが分かりました。

タスク "Hash" (TaskId: 81)
  タスク パラメーター:
      ItemsToHash=
          AAA.cs
          ... 大量のファイル 以下略
  出力プロパティ: CoreCompileDependencyHash=a354efb706fc0c860893ef7ea73400de584ca955 (TaskId: 81)
タスク "Hash" の実行が終了しました。 (TaskId: 81)

Hash を決めるパラメータに差分がないか調査

そこで、msbuild.log と dotnet_build.log から タスク "Hash" の部分を抜き出し差分を見ます。

すると Microsoft.NET.Build.Extensions が使われていることが分かりました。さらに MSBuild と dotnet build とでは Microsoft.NET.Build.Extensions の dll ファイルの参照先が違うことが分かりました。

MSBuild => `\Microsoft Visual Studio\2022\Community\MSBuild\Microsoft\Microsoft.NET.Build.Extensions`
dotnet  => `\dotnet\sdk\7.0.100\Microsoft\Microsoft.NET.Build.Extensions`

これに対してリビルドが起きない NoRebuild プロジェクトについてもタスク "Hash" の部分を抜き出し差分を見ます。

すると Microsoft.NET.Build.Extensions が使われていないことが分かりました。
さらに、 MSBuild と dotnet build とでは ItemsToHash の内容に差分がないことが分かりました。

以上より下記流れによってリビルドが行われたことが分かりました。

1. 事象が起こったプロジェクトではビルドに必要なツールとしてMicrosoft.NET.Build.Extensions が使われている
2. この Microsoft.NET.Build.Extensions の dll ファイルの参照先が MSBuild と dotnet で別モノになっている
3. ビルドに必要なツールの参照先が違うとツールが変わったと判定され Hash の値が変わる
4. Hash の値が変わるとキャッシュファイルが書き変えられる
5. 実行ファイルよりもキャッシュファイルのほうが新しくなる
6. 実行ファイルよりもキャッシュファイルのほうが新しいのでリビルドされる

残る謎

では Microsoft.NET.Build.Extensions がビルドに必要なツールとなった理由は何でしょうか？
実はここについては今回調査できていません。
どなたか詳しい方がいらっしゃいましたらご意見いただけると幸いです。

調査してみての感想

さらっと書いてみましたが実は調査に1日半くらい時間を使いました…時間がかかった原因としては、最初からモリモリのログを見ていて「何も分からん」状態が続いたためです。本記事のようにログの詳細レベルを変えて当たりをつけていくという方法に気づいてから、やっと調査が進むようになりました。
改めて考えると当たり前の話ですが、まずはマクロな視点であたりを付けてから詳細検討に入ることが重要ですね。

うまくできたなと感じた点も書いておきます（笑）。
リビルドさせるプロジェクトとリビルドされないプロジェクトを比較したところはうまく調査できたな、と感じました。diff 表示をして明確に Microsoft.NET.Build.Extensions の dll ファイルの参照先が違うことに気づいたときはテンションが上がりました。

今回の記事が何かのお役に立てると嬉しいです。

1. https://learn.microsoft.com/ja-jp/dotnet/core/tools/dotnet-test#description ↩

2. https://blog.codeinside.eu/2019/11/30/build-dotnetcore-apps-with-msbuild-to-avoid-strange-netframeworkbased-errors/ ↩