[Bug]: getItem/getProperty output can contain unrelated junk

[rolfbjarne]

Issue Description

getItem/getProperty output can contain unrelated junk

Steps to Reproduce

$ mkdir getproptest && cd getproptest
$ dotnet new console
$ rm ~/.dotnet/*Sentinel
$ dotnet build /getProperty:OutputPath

Expected Behavior

bin\Debug/net8.0/

Actual Behavior

Welcome to .NET 8.0!
---------------------
SDK Version: 8.0.100-rc.2.23502.2

Telemetry
---------
The .NET tools collect usage data in order to help us improve your experience. It is collected by Microsoft and shared with the community. You can opt-out of telemetry by setting the DOTNET_CLI_TELEMETRY_OPTOUT environment variable to '1' or 'true' using your favorite shell.

Read more about .NET CLI Tools telemetry: https://aka.ms/dotnet-cli-telemetry

----------------
Installed an ASP.NET Core HTTPS development certificate.
To trust the certificate, run 'dotnet dev-certs https --trust'
Learn about HTTPS: https://aka.ms/dotnet-https

----------------
Write your first app: https://aka.ms/dotnet-hello-world
Find out what's new: https://aka.ms/dotnet-whats-new
Explore documentation: https://aka.ms/dotnet-docs
Report issues and find source on GitHub: https://github.com/dotnet/core
Use 'dotnet --help' to see available commands or visit: https://aka.ms/dotnet-cli
--------------------------------------------------------------------------------------
An issue was encountered verifying workloads. For more information, run "dotnet workload update".
bin\Debug/net8.0/

Analysis

I've also gotten the "Workload updates are available. Run dotnet workload list for more information." message at the end in some cases (which I believe shows up once per day), and broke the json parsing I was trying to do.

Ideally getItem/getProperty arguments would take another argument specifying the output path, because relying on stdout not containing any other random junk is unreliable, and quite unsuitable for scripting.

Versions & Configurations

$ dotnet --version
8.0.100-rc.2.23502.2

[ltrzesniewski]

Shouldn't the welcome message be printed to stderr instead?

(see

sdk/src/Cli/dotnet/Program.cs

Line 322 in 5c2e1fe

var reporter = Reporter.Output;

which currently targets it to stdout)

[baronfel]

Yes, I'd track this as a change to the SDK (though the suggestion to write results to a specified file is also good). The SDK historically hasn't been a good citizen with regards to polluting stdout, and we should make it better in that regard.

[jrdodds]

The welcome and workload update messages are from dotnet and not msbuild. Using the stand-alone version of msbuild, instead of the version of msbuild that is embedded in dotnet, eliminates the messages.

e.g.

dotnet pathToLocalBuild/msbuild/artifacts/bin/bootstrap/net8.0/MSBuild/MSBuild.dll -getProperty:OutputPath 

But that's not a practical workaround.

The -v|--verbosity option is passed to msbuild but not honored by dotnet itself. dotnet doesn't seem to have an option for 'quiet' output.

[baronfel]

@jrdodds dotnet does have a verbosity flag that is generally used:

-v, --verbosity <LEVEL>              Set the MSBuild verbosity level. Allowed values are q[uiet], m[inimal], n[ormal],
                                       d[etailed], and diag[nostic].

and the q/quiet level is intended to represent silence. However, the first-run message and workload update message don't use that for Reasons ™️. There are environment variables to control both the first-run message and the workload notification behavior:

• DOTNET_NOLOGO
• DOTNET_CLI_WORKLOAD_UPDATE_NOTIFY_DISABLE

I would suggest that folks who want to have a clean scripting experience set those to help ensure consistency until we can get the SDK to have more consistent output.

[jrdodds]

Thanks @baronfel. I had tested -v and noted that it had no effect on the welcome message.

[YuliiaKovalova]

Team Triage: this output belongs to sdk repo.

[rolfbjarne]

Fixing all the places that write to stdout will be a game of whack-a-mole...

$ mkdir getproptest && cd getproptest
$ dotnet new console
$ export MSBUILDDEBUGEXPANSION=1
$ dotnet build /getProperty:OutputPath
Expanding: [MSBuild]::GetDirectoryNameOfFileAbove($(MSBuildProjectDirectory), '$(_DirectoryBuildPropsFile)')
Expanding: [System.IO.Path]::IsPathRooted($(MSBuildProjectExtensionsPath))
[...]
Expanding: .StartsWith($([MSBuild]::EnsureTrailingSlash($(MSBuildProjectDirectory))))
Expanding: [MSBuild]::EnsureTrailingSlash($(MSBuildProjectDirectory))
bin\Debug/net8.0/

[baronfel]

I don't disagree, but I think it's a thing we should be aiming towards across the stack.

[rolfbjarne]

I would suggest that folks who want to have a clean scripting experience set those to help ensure consistency until we can get the SDK to have more consistent output.

I don't think I'll trust getItem/getProperty for scripting unless I can get the output written to a file, since any random number of things can write to stdout (in particular tasks can do whatever they want, including straight out calling Console.WriteLine, which is a fairly common debugging technique after all, and it would be quite annoying to have scripting output fail because someone (me!) accidentally left in a Console.WriteLine somewhere).

[tmds]

Ideally getItem/getProperty arguments would take another argument specifying the output path, because relying on stdout not containing any other random junk is unreliable, and quite unsuitable for scripting.

+1

Besides other things garbling stdout, also from a use-case perspective, it is sometimes desired to let MSBuild show the usual output while also retrieving properties.

[jrdodds]

... it is sometimes desired to let MSBuild show the usual output while also retrieving properties.

For the -getItem, -getProperty, and -getTargetResult switches there is an implicit -v:q. There is no 'usual' output from MSBuild. (As noted prior, the "junk" is not from MSBuild itself.)

For the -getItem and -getProperty switches, the evaluation phase is performed but not the execution phase. Even if there was output, there won't be output from Message tasks because they won't be executed.

If you combine -getTargetResult with either or both -getItem and -getProperty, there will be an execution phase. The requested targets and their dependencies will be executed. The value of requested items and/or properties will be as they are after the targets have executed.

[jrdodds]

... tasks can do whatever they want, including straight out calling Console.WriteLine, which is a fairly common debugging technique ...

Granted a task can call Console.WriteLine but I hope that's not a common debugging technique.

For printf style debugging, a task should use Log.LogMessage(). You can specify MessageImportance.Low and leave the logging in.

[tmds]

For the -getItem, -getProperty, and -getTargetResult switches there is an implied -v:q. There is no 'usual' output from MSBuild. (As noted prior, the "junk" is not from MSBuild itself.)

Yes, I'm suggesting it is a feature that there is no implied -v:q when the evaluation gets written to a file.

The regular MSBuild stdout is useful to have, also when evaluating properties.

[jrdodds]

What output are you expecting or looking for? There is no output during the evaluation phase at normal verbosity. You would need detailed or diagnostic.

[tmds]

In my case, I'm invoking

dotnet publish -p PublishProfile=DefaultContainer --getProperty:GeneratedContainerDigest

and I'd like the default output to appear to show how the operation is progressing.
And when the operation completed successfully, I want to use the image digest (from GeneratedContainerDigest).

[jrdodds]

Regarding writing values to files, every target in a project is an entry point. You can define a WriteMyPropertyToFile target and just call it directly.

[jrdodds]

@tmds I assume you want to pipe the digest to another process? What if you used -binaryLogger? All your default output goes to the binlog and the value of GeneratedContainerDigest goes to stdout.

dotnet publish -p PublishProfile=DefaultContainer -getProperty:GeneratedContainerDigest -binaryLogger

[tmds]

I want the default output to appear on stdout so it is part of the CI log.

[jrdodds]

It sounds like you shouldn't use -getProperty.

Add a target that runs at the end of the publish. If you want the digest on stdout, use a Message task to output the digest. If you want the digest in a file, use a WriteLinesToFile task.

As conceived and currently implemented, -getProperty is a different animal from what you want. And I'm not talking about missing a file specifier option. Part of the intent for -getProperty and -getItem is to get properties and items from a project without executing the project, i.e. interrogating a project for the evaluation phase value of an item or property. You want to use -getProperty with running Publish but for that use case -getProperty is completely redundant with just extending/customizing your project.

[tmds]

It sounds like you shouldn't use -getProperty.

This is an intended use for -getProperty.

It's actually literally the example used to demonstrate SDK project evaluation support: https://learn.microsoft.com/en-us/dotnet/core/whats-new/dotnet-8#cli-based-project-evaluation.

[baronfel]

Tom's right - a major reason for making the feature is to support tooling that can't always easily drive or extend the build via custom targets. At this very moment Aspire apps deploy to Azure via azd using this feature.

[jrdodds]

So if you have a CI environment that doesn't support binary logs - you're screwed?

(Apparently azd deploy executes dotnet publish /t:PublishContainer and reads the stdout.)

[tmds]

@baronfel as I mentioned earlier on this ticket, I'd like to be able to get the default standard output while also using the project evaluation. The solution is the same as for this bug report: be able to write the evaluation output to a separate file.
Should I create a separate issue to describe it as a feature request?

[jrdodds]

dotnet/msbuild#3911 included a -resultsFile switch that didn't make it into the code.

[tmds]

Should I create a separate issue to describe it as a feature request?

I've created dotnet/msbuild#9617.

[Forgind]

I'm hearing two proposals here:

1. Permit passing an output file to -get* to get it to output specifically to that file. In that case, permit normal printing to stdout (i.e., do not disable other loggers.)
2. Have some cases in which DOTNET_NOLOGO and DOTNET_CLI_WORKLOAD_UPDATE_NOTIFY_DISABLE are effectively turned on by default.

Those both sound reasonable to me. The first one was something people had proposed when I was first working on get*, but no one could give me a convincing reason it was actually useful. The reasons given in this issue were more convincing to me, at least, so I wouldn't mind adding that to my todo list.

Afterwards, I'll have to look to see at what point we log those first use messages relative to when we parse the command line. If we parse the command line first, I think it should be pretty easy to special case -get* such that that automatically turns on those flags. If we emit those messages first, that one might be tricky...

Does that sound like a correct summary?

[jrdodds]

FWIW I have a different thought on the issue.

Legacy-wise MSBuild has had as output: errors and messages which have been mapped to stderr and stdout, respectively.

-getItem, -getProperty, and -getTargetResult produce a new type of output that could be called 'results'. With 'messages' and 'results' as virtual outputs either, both, or neither could be mapped to stdout.

Instead of supporting passing output files to each of -getItem, -getProperty, and -getTargetResult, command line parameters could be added to set where the 'messages' and where the 'results' are written to.

In a future release the default for 'messages' could be a bin log file and the default for 'results' could be stdout.

[marcpopMSFT]

For now, I'm not sure we can route other output to stderr by default as the default powershell in windows will treat any stderr output as an error in the command.

We think minimum verbosity might be the way to achieve this where we require the consumer to specify -v:min and then exclude everything but the eval output. Thoughts on that potential option?

[jrdodds]

I assume that

... I'm not sure we can route other output to stderr by default ...

is a response to the question asked by @ltrzesniewski in November

Shouldn't the welcome message be printed to stderr instead?

To the point being made: The welcome message is not an error and Windows Powershell is not alone. It's just one example of the many programs on all supported OSs that will interpret anything/everything on stderr as an error.

[baronfel]

stderr is a very common sidebar communications channel for not-just-error information. clig.dev has some guidelines for its use:

Return zero exit code on success, non-zero on failure. Exit codes are how scripts determine whether a program succeeded or failed, so you should report this correctly. Map the non-zero exit codes to the most important failure modes.

Send output to stdout. The primary output for your command should go to stdout. Anything that is machine readable should also go to stdout—this is where piping sends things by default.

Send messaging to stderr. Log messages, errors, and so on should all be sent to stderr. This means that when commands are piped together, these messages are displayed to the user and not fed into the next command.

This helps ensure that piping and reuse of command output is clean. It's a shame that Windows Powershell doesn't support this manner of programming, but it is the state of the world we live in. Purely for my own information I'd love to hear about other non-Windows-Powershell shells that interpret stderr in such a strict, non-standard way.

[jrdodds]

If the desire is to follow clig.dev then perhaps all messages should go to stderr, stdout should be used for results from the get* switches, and there should be a compatibility mode switch for the legacy behavior.

[baronfel]

That is indeed my desired end state, but there's a lot of work involved in the meantime to audit and catalogue all of the stdout usage in the CLI today.
In addition we'd need to have a very solid design for detection of which shells need the legacy fallback behavior.

[Forgind]

Legacy-wise MSBuild has had as output: errors and messages which have been mapped to stderr and stdout, respectively.

Just for the record, MSBuild differentiates between red messages that go to stdout, yellow messages that go to stdout, and normal-colored messages that go to stdout. MSBuild hasn't historically put anything in stderr at all—that was actually a new feature from the change to permit get* switches to avoid clogging up stdout even if there are errors.

[Forgind]

dotnet/msbuild#9640

[rolfbjarne]

Ideally getItem/getProperty arguments would take another argument specifying the output path, because relying on stdout not containing any other random junk is unreliable, and quite unsuitable for scripting.

My wish came true (dotnet/msbuild#9640), so for me this can be closed now.