dotnet / sdk

Core functionality needed to create .NET Core projects, that is shared between Visual Studio and CLI
https://dot.net/core
MIT License
2.71k stars 1.07k forks source link

Weird progress indicators started appearing in stdout #44610

Open martinstenhoff opened 5 days ago

martinstenhoff commented 5 days ago

Why have I started seeing the following character sequence (which seems to some progress indicator) whenever I pipe dotnet program output to a file now?

\x1b]9;4;3;\x1b\\\x1b]9;4;0;\x1b\\

Program.cs:

Console.WriteLine("Hello, World!");

dotnet run > output.txt

output.txt:

]9;4;3;\]9;4;0;\Hello, World!
❯ dotnet --version
9.0.100-rc.2.24474.11
Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.22631
 OS Platform: Windows
 RID:         win-x64
 Base Path:   C:\Program Files\dotnet\sdk\9.0.100-rc.2.24474.11\
martinstenhoff commented 4 days ago

This issue talks about some new console logger in .Net9 https://github.com/dotnet/msbuild/issues/9950

I still see these characters in the output file if build and run are done in separate steps:

dotnet build -c Release
dotnet run -c Release --no-build -v q > .\output.txt

And it happens in both Command Prompt and Powershell terminal

KalleOlaviNiemitalo commented 4 days ago

This seems to be coming from how dotnet run calls MSBuild to run the ComputeRunArguments target; output.txt sometimes includes "ComputeRunArguments (0,0s)".

$ cat -A output.txt
^[]9;4;3;^[\^[[?25l^[[1F^M$
  conc ^[[120G^[[26DComputeRunArguments (0,0s)^M$
^[[?25h^[[2F^M$
^[[J^[]9;4;0;^[\Hello, World!^M$

But surprisingly, setting MSBUILDTERMINALLOGGER=off in the environment or adding -terminalLogger:off to the dotnet run command line does not remove these.

Actually, dotnet run explicitly instantiates the terminal logger instead of letting MSBuild check whether the -terminalLogger option was specified, whether the environment variable was set, and whether output was redirected: https://github.com/dotnet/sdk/blob/8e29df2c37578a31d6a23317afd4ba4504463783/src/Cli/dotnet/commands/dotnet-run/RunCommand.cs#L336-L339

KalleOlaviNiemitalo commented 4 days ago

The forced TerminalLogger came from https://github.com/dotnet/sdk/pull/42240. I think test/Microsoft.NET.Build.Tests/GivenThatWeWantToControlGeneratedAssemblyInfo.cs would have detected the bug if the pull request hadn't also made it ignore the progress indicators.

martinstenhoff commented 4 days ago

@KalleOlaviNiemitalo thanks for the investigation :)

Seems like this has been raised before and we'll have to live with this for some time after GA :( https://github.com/dotnet/msbuild/issues/10841 https://github.com/dotnet/msbuild/issues/10579

KalleOlaviNiemitalo commented 4 days ago

dotnet/msbuild#10841

That is for older versions of Windows that don't recognise the control sequences. I assume the fix would be to check the version number. That won't help with redirection.

dotnet/msbuild#10579

The fix https://github.com/dotnet/msbuild/pull/10678 makes MSBuild configure the Windows console to process control sequences if TerminalLogger is used directly, and restore the original modes later. This also doesn't help with redirected output, where MSBuild should not write the control sequences at all. Although the code checks whether output is redirected, and does not configure the console in that case, it writes the control sequences anyway.

KalleOlaviNiemitalo commented 4 days ago

A low-risk fix would be to make dotnet-run check whether output has been redirected, and not add the TerminalLogger in that case; instead add a console logger that is configured to output only errors and warnings, and those to stderr rather than stdout.

In the longer term, I hope dotnet-run can let MSBuild create the logger objects (based on command-line options, environment variables, and redirection), and then use the same objects across restore/build/run.