[NETSDKE2E] Only "build succeed" log is displayed after running .net format project with "test.cmd" command.

[vdanche]

Issue Description

Only "build succeed" log is displayed after running .net format project with "test.cmd" command.

Steps to Reproduce

1.install Net 9.0.100-preview.3.24157.13 SDK on window11-x64.
2.Checkout the dotnet-format repo. git clone https://github.com/dotnet/format.git
3.Update the gobal.json by removing the "sdk" configuration.
before

After

4.Run Restore.cmd.
5.Run Build.cmd.
6.Run Test.cmd.

Expected Behavior

Restore/build and test project without any issue and the log can be displayed well.

Actual Behavior

4. After restore.cmd, duplicate "Build succeeded" info displays, this issue seems similar with the bug 9614, and it has been fixed, will check in Monday's build.
5. Build successfully and log displays well.
6. Only "build succeed" log is displayed after running .NET format project with "test.cmd" command, but we can see about test succeed log in previous log template.

previous log template

dotnet --info
C:\Windows\system32>dotnet --info
.NET SDK:
Version: 9.0.100-preview.3.24157.13
Commit: 34940c02d7
Workload version: 9.0.100-manifests.4c56e492
MSBuild version: 17.10.0-preview-24127-03+6f44380e4

Runtime Environment:
OS Name: Windows
OS Version: 10.0.20348
OS Platform: Windows
RID: win-x64
Base Path: C:\Program Files\dotnet\sdk\9.0.100-preview.3.24157.13\

.NET workloads installed:
There are no installed workloads to display.

Host:
Version: 9.0.0-preview.3.24156.25
Architecture: x64
Commit: 8330db9986

.NET SDKs installed:
9.0.100-preview.3.24157.13 [C:\Program Files\dotnet\sdk]

.NET runtimes installed:
Microsoft.AspNetCore.App 9.0.0-preview.3.24156.20 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.NETCore.App 9.0.0-preview.3.24156.25 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.WindowsDesktop.App 9.0.0-preview.3.24156.27 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]

Other architectures found:
x86 [C:\Program Files (x86)\dotnet]

Analysis

No response

Versions & Configurations

No response

[vdanche]

is it an expected behavior for only "Build succeeded" log displaying after running test.cmd?

[rainersigwald]

It's expected for the current behavior but not desirable. @AR-May can you look at this repro and confirm your work for #9667 works here too?

For now you can add

-tl:false

To the build command line to get back to older behavior.

[AR-May]

I took a look at this repro.

So, first of all, the Restore.cmd. It calls MSBuild twice, first to restore toolset and then to do the project restore. That's why we see two "Build succeeded" lines. Before, the first call of MSBuild was silenced by setting "/clp:ErrorsOnly;NoSummary" which works only for console logger, since it is a console logger parameter. Instead, if this call needs to be silenced, I suggest passing "/v:q" to set verbosity for any logger that will be used. So, when my change takes place, the terminal logger will respect this setting.

The Build.cmd seems to have a good output.

The Test.cmd does not have a custom test output. The fix for that is to increase the TL verbosity to detailed passing -v:d in this script. When my change for respecting verbosity takes place, it will also show the high-prio messages:

PS C:\Users\alinama\work\msbuild\test_repos\format> .\Test.cmd
  dotnet-format.UnitTests succeeded (345.1s)
    echo === COMMAND LINE === > C:\Users\alinama\work\msbuild\test_repos\format\artifacts\log\Debug\dotnet-format.UnitTests_net9.0_x64.log
                   echo "C:\Program Files\dotnet\dotnet.exe" test C:\Users\alinama\work\msbuild\test_repos\format\artifacts\bin\dotnet-format.UnitTests\Debug\net9.0\dotnet-format.UnitTests.dll --logger:"console;verbosity=normal" --logger:"trx;LogFileName=dotnet-format.UnitTests_net9.0_x64.trx" --logger:"html;LogFileName=dotnet-format.UnitTests_net9.0_x64.html" "--ResultsDirectory:C:\Users\alinama\work\msbuild\test_repos\format\artifacts\TestResults\Debug" "--Framework:.NETCoreApp,Version=v9.0" >> "C:\Users\alinama\work\msbuild\test_repos\format\artifacts\log\Debug\dotnet-format.UnitTests_net9.0_x64.log" 2>&1 >> C:\Users\alinama\work\msbuild\test_repos\format\artifacts\log\Debug\dotnet-format.UnitTests_net9.0_x64.log
    Running tests: C:\Users\alinama\work\msbuild\test_repos\format\artifacts\bin\dotnet-format.UnitTests\Debug\net9.0\dotnet-format.UnitTests.dll [net9.0|x64]
    "C:\Program Files\dotnet\dotnet.exe" test C:\Users\alinama\work\msbuild\test_repos\format\artifacts\bin\dotnet-format.UnitTests\Debug\net9.0\dotnet-format.UnitTests.dll --logger:"console;verbosity=normal" --logger:"trx;LogFileName=dotnet-format.UnitTests_net9.0_x64.trx" --logger:"html;LogFileName=dotnet-format.UnitTests_net9.0_x64.html" "--ResultsDirectory:C:\Users\alinama\work\msbuild\test_repos\format\artifacts\TestResults\Debug" "--Framework:.NETCoreApp,Version=v9.0" >> "C:\Users\alinama\work\msbuild\test_repos\format\artifacts\log\Debug\dotnet-format.UnitTests_net9.0_x64.log" 2>&1
    Tests succeeded: C:\Users\alinama\work\msbuild\test_repos\format\artifacts\bin\dotnet-format.UnitTests\Debug\net9.0\dotnet-format.UnitTests.dll [net9.0|x64]

Build succeeded in 346.3s

I am not sure how the line "echo === COMMAND LINE === >" was skipped before, probably with one more console logger setting. Nevertheless, is such output fine for your goals?

[AR-May]

Should be completed by PR #9810.

[vdanche]

@AR-May it still repro on today's build-9.0.100-preview.4.24206.1(runtime-9.0.0-preview.4.24204.3), we'll keep tracking.

[AR-May]

@AR-May it still repro on today's build-9.0.100-preview.4.24206.1(runtime-9.0.0-preview.4.24204.3), we'll keep tracking.

It takes some time to propagate changes to dotnet. I can see that msbuild with my change is still not inserted there. Let's wait a bit more. Please do not forget that you also need to replace the build parameters /clp:ErrorsOnly;NoSummary with /v:q to make it apply to both Terminal Logger and Console Logger.

[vdanche]

@AR-May checked on 9.0.100-preview.4.24221.5, the issue still repro. you mean we need to add /v:q when running restore.cmd/build.cmd/test.cmd?

Run restore.cmd /v:q, dup build succeed still repro, but the bug #9614 is fixed.
Run Test.cmd /v:q, only "build succeed" log is displayed after running .NET format project with "test.cmd"

8.0 template as below

[AR-May]

@vdanche adding the /v:q parameter to the call of restore.cmd does not help because such parameter is not propagated inside the script to all msbuild calls. Here is the call of restore that shows the extra Build succeeded and the verbosity parameter is not propagated to it. It is probably because the authors wanted this run to be always silenced and not dependent on a verbosity passed by user of the script. And when the console logger was on by default it was silenced, by the console logger specific parameters: /clp:ErrorsOnly;NoSummary. Now that terminal logger is default, a full output shows and it is no more silenced. You will need to fix this place of the script to make the fix work.

[vdanche]

@AR-May I have replaced /clp:ErrorsOnly;NoSummary with /v:q in file tools.ps1(C:\Users\v-danche\format\eng\common), but still repro. Is there anything else we need to do?

[AR-May]

@vdanche hmm, when I checked the fix, it worked. It has been a while, I might have forgotten some details about the fix, or maybe I made some mistake when I checked it. I will re-check.

[AR-May]

@vdanche I checked again the restore command and the fix with adding /v:q to the specified line works for me:

PS C:\Users\alinama\work\msbuild\test_repos\format> .\Restore.cmd
Restore complete (0.9s)

Build succeeded in 4.6s

Can you try to verify this again? I see couple of possible reasons it did not work for you: maybe the file was not saved (happens to me often) or the wrong version of sdk was installed? I see that it downloads preview 1 sdk.

As for the test.cmd, you need to set the detailed verbosity, not the quiet: Test.cmd /v:d

[vdanche]

@vdanche I checked again the restore command and the fix with adding /v:q to the specified line works for me:

PS C:\Users\alinama\work\msbuild\test_repos\format> .\Restore.cmd
Restore complete (0.9s)

Build succeeded in 4.6s

Can you try to verify this again? I see couple of possible reasons it did not work for you: maybe the file was not saved (happens to me often) or the wrong version of sdk was installed? I see that it downloads preview 1 sdk.

As for the test.cmd, you need to set the detailed verbosity, not the quiet: Test.cmd /v:d

@AR-May Thank you very much
Yes, it downloads preview 1 sdk, we need to modify dotnet tools version "net9 preview 1" to 9.0.100-preview.4.24253.11 manually in globaljson file, we try it again, we can get the correct log.

Details steps as below,
1.install Net 9.0.100-preview.4.24253.11 SDK on window11-x64.
2.Checkout the dotnet-format repo. git clone https://github.com/dotnet/format.git
3.Update the gobal.json by removing the "sdk" configuration.
before

After
and modify dotnet tools version "net9 preview 1" to 9.0.100-preview.4.24253.11

4. replaced /clp:ErrorsOnly;NoSummary with /v:q in file tools.ps1(C:\Users\v-danche\format\eng\common) and save
   

5.Run Restore.cmd.
6.Run Build.cmd.
7.Run Test.cmd /v:d

[AR-May]

@vdanche good. I thought a bit more about the fix for the restore.cmd. I will recommend instead of replacing /clp:ErrorsOnly;NoSummary with /v:q, just add /tlp:verbosity=q to the call. In this case if Terminal Logger is not used (for example, the output redirected to a file), the behavior of the console logger would be guaranteed as before the fix. And if the Terminal Logger would be used, it will fix the problem.

[vdanche]

@vdanche good. I thought a bit more about the fix for the restore.cmd. I will recommend instead of replacing /clp:ErrorsOnly;NoSummary with /v:q, just add /tlp:verbosity=q to the call. In this case if Terminal Logger is not used (for example, the output redirected to a file), the behavior of the console logger would be guaranteed as before the fix. And if the Terminal Logger would be used, it will fix the problem.

@AR-May we just try to add /tlp:verbosity=q in tools.ps1(C:\Users\v-danche\format\eng\common), we also can get the correct log. Thanks