Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

dotnet build ignores /v verbosity flag in .NET 9.0.0-preview.7 #43069

Open
perlun opened this issue Aug 29, 2024 · 18 comments
Open

dotnet build ignores /v verbosity flag in .NET 9.0.0-preview.7 #43069

perlun opened this issue Aug 29, 2024 · 18 comments
Assignees
Labels
untriaged Request triage from a team member

Comments

@perlun
Copy link

perlun commented Aug 29, 2024

Describe the bug

dotnet build ignores /v verbosity flag in .NET 9.0.0-preview.7

To Reproduce

Run dotnet build SomeProject.sln /v:d

On .NET 8 (by temporarily downgrading the dotnet-host package using apt-get install dotnet-host=8.0.8-1), this correctly increases the verbosity level to d[etailed]. On .NET 9, the setting seems to be ignored. The output is seemingly the same as in n[ormal] mode.

Adding the --debug flag also has no effect, on .NET 9.

Exceptions (if any)

None

Further technical details

  • Include the output of dotnet --info:

Seen on both Windows (11?) and Debian GNU/Linux (my machine). Output for the latter from below:

.NET SDK:
 Version:           9.0.100-preview.7.24407.12
 Commit:            d672b8a045
 Workload version:  9.0.100-manifests.a8e34f65
 MSBuild version:   17.12.0-preview-24374-02+48e81c6f1

Runtime Environment:
 OS Name:     debian
 OS Version:  12
 OS Platform: Linux
 RID:         linux-x64
 Base Path:   /usr/share/dotnet/sdk/9.0.100-preview.7.24407.12/

.NET workloads installed:
Configured to use loose manifests when installing new manifests.
There are no installed workloads to display.

Host:
  Version:      9.0.0-preview.7.24405.7
  Architecture: x64
  Commit:       static

.NET SDKs installed:
  7.0.410 [/usr/share/dotnet/sdk]
  8.0.401 [/usr/share/dotnet/sdk]
  9.0.100-preview.7.24407.12 [/usr/share/dotnet/sdk]

.NET runtimes installed:
  Microsoft.AspNetCore.App 7.0.20 [/usr/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 8.0.8 [/usr/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 9.0.0-preview.7.24406.2 [/usr/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 7.0.20 [/usr/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 8.0.8 [/usr/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 9.0.0-preview.7.24405.7 [/usr/share/dotnet/shared/Microsoft.NETCore.App]

Other architectures found:
  None

Environment variables:
  Not set

global.json file:
  Not found

Learn more:
  https://aka.ms/dotnet/info

Download .NET:
  https://aka.ms/dotnet/download
  • The IDE (VS / VS Code/ VS4Mac) you're running on, and its version: JetBrains Rider 2024.1.1, but these issues are seen when using the dotnet CLI.
Copy link

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

@dotnet-issue-labeler dotnet-issue-labeler bot added the untriaged Request triage from a team member label Aug 29, 2024
Copy link

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

@baronfel
Copy link
Member

Do you have a repro project or some kind of logs to show a compare or contract? My best guess without any more information is that Terminal Logger (the default logger in .NET 9 for MSBuild) doesn't show the output you're used to. Try -v diag or disabling Terminal Logger entirely with -tl. In general, we do not suggest using the MSBuild console output for detailed build investigations - instead we suggest generating binlogs with -bl and investigating those with the Structured Log Viewer, which has full knowledge of the build and is much more readable.

@perlun
Copy link
Author

perlun commented Aug 30, 2024

Sorry @baronfel, didn't have any public repro but I tested now with a blank web project and it seems easily reproducible. Creating a blank project in a new, empty directory:

~/git/tmp/dotnet-build-verbosity-debugging 
❯ dotnet new web
The template "ASP.NET Core Empty" was created successfully.

Processing post-creation actions...
Restoring /home/plundberg/git/tmp/dotnet-build-verbosity-debugging/dotnet-build-verbosity-debugging.csproj:
Restore succeeded.

I tested a few different approaches new:

dotnet build output

~/git/tmp/dotnet-build-verbosity-debugging 
❯ dotnet build
Restore complete (0.3s)
You are using a preview version of .NET. See: https://aka.ms/dotnet-support-policy
  dotnet-build-verbosity-debugging succeeded (0.9s) → bin/Debug/net9.0/dotnet-build-verbosity-debugging.dll

Build succeeded in 1.5s

dotnet build /v:diag output

~/git/tmp/dotnet-build-verbosity-debugging 
❯ dotnet build /v:diag
/usr/share/dotnet/sdk/9.0.100-preview.7.24407.12/MSBuild.dll -nologo -consoleloggerparameters:Summary -distributedlogger:Microsoft.DotNet.Tools.MSBuild.MSBuildLogger,/usr/share/dotnet/sdk/9.0.100-preview.7.24407.12/dotnet.dll*Microsoft.DotNet.Tools.MSBuild.MSBuildForwardingLogger,/usr/share/dotnet/sdk/9.0.100-preview.7.24407.12/dotnet.dll -maxcpucount -restore -tlp:default=auto -verbosity:m /v:diag ./dotnet-build-verbosity-debugging.csproj
Restore complete (0.3s)
    Determining projects to restore...
    All projects are up-to-date for restore.
You are using a preview version of .NET. See: https://aka.ms/dotnet-support-policy
  dotnet-build-verbosity-debugging succeeded (0.2s) → bin/Debug/net9.0/dotnet-build-verbosity-debugging.dll

Build succeeded in 0.8s

With -tl flag

~/git/tmp/dotnet-build-verbosity-debugging 
❯ dotnet build /v:diag -tl
/usr/share/dotnet/sdk/9.0.100-preview.7.24407.12/MSBuild.dll -nologo -consoleloggerparameters:Summary -distributedlogger:Microsoft.DotNet.Tools.MSBuild.MSBuildLogger,/usr/share/dotnet/sdk/9.0.100-preview.7.24407.12/dotnet.dll*Microsoft.DotNet.Tools.MSBuild.MSBuildForwardingLogger,/usr/share/dotnet/sdk/9.0.100-preview.7.24407.12/dotnet.dll -maxcpucount -restore -tl -tlp:default=auto -verbosity:m /v:diag ./dotnet-build-verbosity-debugging.csproj
Restore complete (0.3s)
    Determining projects to restore...
    All projects are up-to-date for restore.
You are using a preview version of .NET. See: https://aka.ms/dotnet-support-policy
  dotnet-build-verbosity-debugging succeeded (0.2s) → bin/Debug/net9.0/dotnet-build-verbosity-debugging.dll

Build succeeded in 0.8s

Manually adding a -consoleloggerparameters:Verbosity=diag

(Note that this switches to running MSBuild.dll manually, for adding/overriding these flags)

~/git/tmp/dotnet-build-verbosity-debugging 
❯ dotnet /usr/share/dotnet/sdk/9.0.100-preview.7.24407.12/MSBuild.dll -nologo -consoleloggerparameters:Verbosity=diag -distributedlogger:Microsoft.DotNet.Tools.MSBuild.MSBuildLogger,/usr/share/dotnet/sdk/9.0.100-preview.7.24407.12/dotnet.dll*Microsoft.DotNet.Tools.MSBuild.MSBuildForwardingLogger,/usr/share/dotnet/sdk/9.0.100-preview.7.24407.12/dotnet.dll -maxcpucount -restore -tl -tlp:default=auto /v:diag ./dotnet-build-verbosity-debugging.csproj
/usr/share/dotnet/sdk/9.0.100-preview.7.24407.12/MSBuild.dll -nologo -consoleloggerparameters:Verbosity=diag -distributedlogger:Microsoft.DotNet.Tools.MSBuild.MSBuildLogger,/usr/share/dotnet/sdk/9.0.100-preview.7.24407.12/dotnet.dll*Microsoft.DotNet.Tools.MSBuild.MSBuildForwardingLogger,/usr/share/dotnet/sdk/9.0.100-preview.7.24407.12/dotnet.dll -maxcpucount -restore -tl -tlp:default=auto /v:diag ./dotnet-build-verbosity-debugging.csproj
Restore complete (0.3s)
    Determining projects to restore...
    All projects are up-to-date for restore.
You are using a preview version of .NET. See: https://aka.ms/dotnet-support-policy
  dotnet-build-verbosity-debugging succeeded (0.2s) → bin/Debug/net9.0/dotnet-build-verbosity-debugging.dll

Build succeeded in 0.8s

Manually adding -tlp:default=auto;verbosity=diag;showCommandLine

~/git/tmp/dotnet-build-verbosity-debugging 
❯ dotnet /usr/share/dotnet/sdk/9.0.100-preview.7.24407.12/MSBuild.dll -nologo -distributedlogger:Microsoft.DotNet.Tools.MSBuild.MSBuildLogger,/usr/share/dotnet/sdk/9.0.100-preview.7.24407.12/dotnet.dll*Microsoft.DotNet.Tools.MSBuild.MSBuildForwardingLogger,/usr/share/dotnet/sdk/9.0.100-preview.7.24407.12/dotnet.dll -maxcpucount -restore -tl /v:diag "-tlp:default=auto;verbosity=diag;showCommandLine" ./dotnet-build-verbosity-debugging.csproj 
/usr/share/dotnet/sdk/9.0.100-preview.7.24407.12/MSBuild.dll -nologo -distributedlogger:Microsoft.DotNet.Tools.MSBuild.MSBuildLogger,/usr/share/dotnet/sdk/9.0.100-preview.7.24407.12/dotnet.dll*Microsoft.DotNet.Tools.MSBuild.MSBuildForwardingLogger,/usr/share/dotnet/sdk/9.0.100-preview.7.24407.12/dotnet.dll -maxcpucount -restore -tl -tlp:default=auto;verbosity=diag;showCommandLine /v:diag ./dotnet-build-verbosity-debugging.csproj
Restore complete (0.3s)
    Determining projects to restore...
    All projects are up-to-date for restore.
You are using a preview version of .NET. See: https://aka.ms/dotnet-support-policy
  dotnet-build-verbosity-debugging succeeded (0.2s) → bin/Debug/net9.0/dotnet-build-verbosity-debugging.dll

Build succeeded in 0.7s

In general, we do not suggest using the MSBuild console output for detailed build investigations - instead we suggest generating binlogs with -bl and investigating those with the Structured Log Viewer, which has full knowledge of the build and is much more readable.

Thanks for this suggestion. 👍 Haven't tried that. I'm on Linux so using the prebuilt binaries won't work, but it does seem possible to run on Linux in fact: KirillOsenkov/MSBuildStructuredLog#616 (comment).

Either way, it would be interesting to understand why the console output is missing. 🤔

@tmds
Copy link
Member

tmds commented Aug 30, 2024

To disable the terminal logger you need: -tl:off.

If that gives you the missing output, then this is a dup of #42835.

@tmds
Copy link
Member

tmds commented Sep 5, 2024

@perlun are you able to get the expected output by adding the -tl:off argument?

@perlun
Copy link
Author

perlun commented Sep 10, 2024

Sorry for the late reply @tmds. Verified now - yes; -tl:off does indeed work as intended. 🎉

Should we make /v:diag emit a warning if the Terminal Logger is enabled (or even go as far as auto-disabling it)? 🤔 It feels a bit counterintuitive that the user tries to enable more diagnostics but the dotnet (MSBuild) system just "ignores" that setting. I wonder if this (our current semantics) wouldn't actually cause a bit of confusion once .NET 9 is GA. Thoughts?

I think my main point is that this (our current semantics) is a change from how it's been working in the past. I guess it could also be solved by documenting this in some relevant place(s), to make people more aware of it.

@tmds
Copy link
Member

tmds commented Sep 10, 2024

I agree, setting the verbosity argument should be enough to enable verbose output. I assume the current behavior is an unintended UX regression from adopting the terminal logger.

I would also hope this gets addressed in the 9.0.1xx SDK.

Can we close this as a dup of #42835?

@baronfel
Copy link
Member

One thing I'm unclear of is which specific lines you were expecting to see that -v diag in terminal logger didn't show.

@tmds
Copy link
Member

tmds commented Sep 10, 2024

On a dotnet new console template, adding the -v diag argument

.NET 9 preview 7 gives:

$ dotnet build -v diag
/var/home/tmds/Downloads/dotnet9-p7/sdk/9.0.100-preview.7.24407.12/MSBuild.dll -nologo -consoleloggerparameters:Summary -distributedlogger:Microsoft.DotNet.Tools.MSBuild.MSBuildLogger,/var/home/tmds/Downloads/dotnet9-p7/sdk/9.0.100-preview.7.24407.12/dotnet.dll*Microsoft.DotNet.Tools.MSBuild.MSBuildForwardingLogger,/var/home/tmds/Downloads/dotnet9-p7/sdk/9.0.100-preview.7.24407.12/dotnet.dll -maxcpucount -restore -tlp:default=auto -verbosity:m -verbosity:diag ./console.csproj
Restore complete (1.6s)
    Determining projects to restore...
    All projects are up-to-date for restore.
You are using a preview version of .NET. See: https://aka.ms/dotnet-support-policy
  console succeeded (0.7s) → bin/Debug/net8.0/console.dll

Build succeeded in 3.6s

While .NET 8 prints out 57k lines.

@baronfel
Copy link
Member

@tmds yes, I understand it doesn't show as much. That's the explicit design goal. Too much output is confusing to users, and we want to give a better idea of what's happening now, and guide users to binlogs for detailed investigations.

We can tweak the behavior though, which is why I'm asking specifically: what kinds of output are missing from the default experiences that you would like to see? "everything" isn't a clear enough answer.

@tmds
Copy link
Member

tmds commented Sep 10, 2024

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

I expect to see what matches that MSBuild verbosity level.

Personally, when I use verbosity on any tool, I tend to set it high because I'm trying to get as much information as I can to debug an issue. Then I filter through what I got.

and guide users to binlogs for detailed investigations.

May be I should make more of an effort to embrace the x-plat MSBuild Structured Log Viewer...

From the cli it should still remain possible to get verbose logging and use that to investigate without needing some IDE/GUI tool.

@baronfel
Copy link
Member

baronfel commented Sep 10, 2024

From the cli it should still remain possible to get verbose logging and use that to investigate without needing some IDE/GUI tool.

It is :) if you need investigations, use the text logger and/or bin logger. For people like you that are very informed, I think binlogs would be even better since you can write tooling on top of them in a way that's impossible for the console logger. That's our answer right now. For the 80-90%+ users that aren't you though we want TL to give you the overview with a nice veneer of usability.

We definitely need to update the CLI argument descriptions to highlight that these values are relative per-logger, though.

May be I should make more of an effort to embrace the x-plat MSBuild Structured Log Viewer...

Also yes, you 100% should try this out. It makes all kinds of MSbuild analysis so much easier and faster.

@tmds
Copy link
Member

tmds commented Sep 11, 2024

My preferred behavior would be to turn of the terminal logger when a verbosity argument is set. I think this matches the use-case: user is debugging their build.

It seems the current behavior is intentional, so we can close this issue (and #42835).

@perlun
Copy link
Author

perlun commented Sep 13, 2024

It seems the current behavior is intentional, so we can close this issue (and #42835).

Intentional it is indeed, but it's still a nasty regression. 😛 We already have people like me and @MarcoRossignoli who posted these issues, and it's likely that more people will run into this as .NET 9 goes live.

At the very least, we should make this very significant change in how /v:diag behaves between .NET 8 and 9 way more clearer in the docs/CLI help/etc. (but to be frank, I would prefer it if those who are challenging the status quo makes the effort of figuring out how to communicate those changes in a proper way, particularly since flags like /v:diag has been there for quite a while now.)

As for your question @baronfel:

One thing I'm unclear of is which specific lines you were expecting to see that -v diag in terminal logger didn't show.

IIRC, I was debugging an issue where I was setting MSBuild constants dynamically based on conditions. I wanted to see things like what values RuntimeIdentifier and NETCoreSdkPortableRuntimeIdentifier had when I was running my build. (Surprisingly, the latter of those can be set to linux-x64 even though you are -r win-x64, i.e. cross-building. RuntimeIdentifier gets set properly but NETCoreSdkPortableRuntimeIdentifier seems to stay with the Linux-value. Yes, I know it's a different issue than the one we're discussing here. 🙂)

It's fine to suggest binlogs and such, but it still seems to be a bit more work than just msbuild /v:diag | code - to open it up in VS Code. It's hard to beat the ease of just "getting the logs" and be able to poke around with them that way. But for more advanced use cases, I'm sure that properly looking at the binlogs is probably much more efficient. (hey, how about a binlog analyzer extension for VS Code...? 😉)

@baronfel
Copy link
Member

hey, how about a binlog analyzer extension for VS Code...? 😉)

@lambdageek has got a present for you: https://marketplace.visualstudio.com/items?itemName=lambdageek.msbuild-structured-log-viewer

@jrdodds
Copy link

jrdodds commented Oct 19, 2024

I have reports that are generated by MSBuild with -v:n and the Message task that are only sometimes redirected to a file. To get text output of my messages I need to use -tl:off -v:n. Is there a better way?

It appears there is no control of the verbosity of TL with respect to the Importance of messages. With TL there is no equivalent of -v:n. Is that correct?

Is there a way for a project to indicate it is not compatible with TL?

I expect that the answers are no, yes, and no, respectively.

@jrdodds
Copy link

jrdodds commented Oct 19, 2024

hey, how about a binlog analyzer extension for VS Code...? 😉)

@lambdageek has got a present for you: https://marketplace.visualstudio.com/items?itemName=lambdageek.msbuild-structured-log-viewer

Are there other binlog tools available or coming? Other than Kirill Osenkov's structured log viewer and the VSCode extension based on it?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
untriaged Request triage from a team member
Projects
None yet
Development

No branches or pull requests

5 participants