Weird progress indicators started appearing in stdout

[martinstenhoff]

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]

This issue talks about some new console logger in .Net9
#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]

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]

The forced TerminalLogger came from dotnet/sdk#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]

@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 :(
#10841
#10579

[KalleOlaviNiemitalo]

#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.

#10579

The fix #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]

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.

[marcpopMSFT]

@baronfel is MSBuild planning on some updates here?

[MD-V]

This also currently breaks .NET custom providers in pulumi:

I1113 09:01:30.634581 44896 log.go:73] Got plugin response: stdout:"\x1b]9;4;3;\x1b\\" I1113 09:01:30.634581 44896 log.go:73] Waiting for plugin message I1113 09:01:30.636850 44896 log.go:73] Got plugin response: stdout:"\x1b]9;4;0;\x1b\\" I1113 09:01:30.636850 44896 log.go:73] Waiting for plugin message I1113 09:01:30.818760 44896 log.go:73] Got plugin response: stdout:"61683\n" I1113 09:01:30.818760 44896 log.go:73] Waiting for plugin message I1113 09:01:30.818760 44896 deployment_executor.go:256] deploymentExecutor.Execute(...): error handling event: could not load provider for resource urn:pulumi:engineering_app_dev_1::engineering_app_azure::internalprovider:resources:appsettings::apiAppSettings: could not create provider urn:pulumi:engineering_app_dev_1::engineering_app_azure::pulumi:providers:internalprovider::default::effc6bd2-4b36-4c51-9b0d-175fc9573a81: load plugin for internalprovider provider 'urn:pulumi:engineering_app_dev_1::engineering_app_azure::pulumi:providers:internalprovider::default': internalprovider (resource) plugin [C:\Projects\Projekte\Engineering\Infrastructure\Pulumi\internalprovider\pulumi-resource-internalprovider.exe] wrote a non-numeric port to stdout ('0'): strconv.Atoi: parsing "\x1b]9;4;3;\x1b\\\x1b]9;4;0;\x1b\\61683": invalid syntax I1113 09:01:30.818760 44896 eventsink.go:86] eventSink::Error(<{%reset%}>could not load provider for resource urn:pulumi:engineering_app_dev_1::engineering_app_azure::internalprovider:resources:appsettings::apiAppSettings: could not create provider urn:pulumi:engineering_app_dev_1::engineering_app_azure::pulumi:providers:internalprovider::default::effc6bd2-4b36-4c51-9b0d-175fc9573a81: load plugin for internalprovider provider 'urn:pulumi:engineering_app_dev_1::engineering_app_azure::pulumi:providers:internalprovider::default': internalprovider (resource) plugin [C:\Projects\Projekte\Engineering\Infrastructure\Pulumi\internalprovider\pulumi-resource-internalprovider.exe] wrote a non-numeric port to stdout ('0'): strconv.Atoi: parsing "\x1b]9;4;3;\x1b\\\x1b]9;4;0;\x1b\\61683": invalid syntax<{%reset%}>)

Workaround:
Put a global.json with .NET 8 SDK specified in the directory of the custom provider

[sailro]

We have a host application, running .net programs. For easier debugging we do the following:

• run directly the compiled .net program (when running in production)
• use dotnet run --project (when running in "dev mode")

And of course those programs are using the console to exchange data with the host.

So when upgrading to net 9, happily writing escape codes in the console without any switch to disable this new behavior, everything is broken. 💔

Where we can spot the effect of:
https://github.com/dotnet/sdk/pull/42240/files#diff-6860155f1838e13335d417fc2fed7b13ac5ddf3b95d3548c6646618bc59e89e7R11

cc @baronfel

[sailro]

^cc @MichalPavlik

It's a real breaker for a lot of scenarios, unfortunately. (like azdo/github workflow output when dotnet run is used for steps, log files, etc.)

[julienp]

This also currently breaks .NET custom providers in pulumi:

Indeed, we just ran into this when trying to add tests for .NET 9.0 in Pulumi's CI. As a workaround we'll strip the control characters pulumi/pulumi#17783

I'd love to see an upstream fix for this in the next release.

[MichalPavlik]

This will happen when using dotnet run with terminal that doesn't support ANSI escape codes. I prioritized this issue, and I will fix it soon.
Unfortunately, there is no way how to disable TL when starting dotnet run, right @baronfel?

[sailro]

@MichalPavlik:

• it is impacting terminals without ANSI escape code support indeed but also all redirected streams (like redirecting stdout to a file). Or even applications using console to exchange data. It's really a breaking issue right now. A lot of testing scenarios / debugging phases are using dotnet run instead of a compiled assembly.

• there is no workaround, both --tl:off or setting MSBUILDTERMINALLOGGER to off are not working when using dotnet run

[MichalPavlik]

@sailro, that's right. I'm working on a fix that additionally respects the MSBUILDTERMINALLOGGER variable.

[baronfel]

@MichalPavlik some context:

There are up to three builds that happen during dotnet run currently:

• an implicit msbuild /t:Restore that is handled entirely by MSBuild
• an implicit msbuild (default Target) that is handled entirely by MSBuild
• an implicit msbuild /t:Some_Target_Name_I_Forget that is called by the CLI via the MSBuild API

The purpose of the third build is to be completely invisible unless there are diagnostics reported from the third build. The third build's console logger setup should ideally be exactly matched to that of the first two builds, but the CLI doesn't know what MSBuild's logging argument configuration is to attempt to recreate it via the API. This is a long-running disjoint/mismatch between MSBuild and the CLI because MSBuild doesn't expose any knowledge about its argument parsing, but it's a particular pain point here for this use case.

So there are two requests here I think,:

• make sure that there's some programmatic way to ensure that the TL doesn't emit the 'processing' control codes
• see if there's a way to make it easier for the CLI to tell which console-based logger (Console or TL) we should use to stay in sync with the implicit restore and build that happens during run.

[KalleOlaviNiemitalo]

There might also be something fixable on whether those control sequences are emitted to standard output or standard error.

[willdean]

To me, additional confusion comes from this document: https://learn.microsoft.com/en-us/dotnet/core/whats-new/dotnet-9/sdk#terminal-logger

• It contains a list of commands that use the terminal logger by default which doesn't include dotnet run
• But then dotnet run docs show it does take the --tl option and defaults to "auto", so the linked document should probably include dotnet run
• And then dotnet run doesn't (fully?) respect --tl anyway.

TBH I thought we'd given up spraying VT100 escape codes into output in the 1990s, I'm not sure why we have to go through this again.