Some way to opt specific messages into printing in TerminalLogger

[rainersigwald]

TerminalLogger ignores most messages, even those logged at High priority, because historically those messages have been quite chatty. But sometimes they're important--for instance, the output of test runners in https://github.com/dotnet/runtime/issues/97211.

It'd be helpful if we either don't try to bypass priority (unfortunate since it'll make real build console output dramatically uglier) or provide a new mechanism for like "I really mean it please put this on the console output".

Right now it can be worked around if you're willing to junk up your high-pri message with the string --interactive, to trip into the special cases in #9407.

[baronfel]

Putting thoughts here for posterity, but many high-pri messages are status/progress - if we have an API for representing this concept specifically then the need for high priority messages may drop.

[rainersigwald]

The need for high pri messages, or the need to squelch them because Rainer thinks they're too chatty? For the case I'm looking at now they want persistent output (test output from a custom runner).

Of course, if most of the existing high-pri messages were status instead (per-project NuGet restore, exec task command lines and stdout, etc) we could respect priority again . . .

[MattKotsenas]

Another sample of a somewhat surprising omission in the TerminalLogger are NuGet.Client rules.

You can set up a trivial repro like this:

mkdir temp && cd temp && dotnet new classlib && dotnet pack

You'll see a console message like this

The package temp.1.0.0 is missing a readme. Go to https://aka.ms/nuget/authoring-best-practices/readme to learn why p
  ackage readmes are important.

That message is suppressed when using dotnet pack /tl.

These feel like they instead should be NU**** build warnings and then the "right thing" should happen, but I'm not familiar with the NuGet pack rules and how they work.

[baronfel]

The specific scenario of test results should not be considered for this issue - the test team have already been working on updating their usage of the Logger systems to display better in terminal logger: https://github.com/dotnet/msbuild/pull/9706

[rainersigwald]

The specific scenario of test results should not be considered for this issue

I don't agree--the fixes we're pursuing with the test team are great and I prefer them to whatever we come up with here, but there are other test runners (including custom one-off ones like dotnet/runtime has) and they should be able to work too.

[JanKrivanek]

One another scenario is users debugging their msbuild script with 'printf debugging'. I already got some internal and external ppl comming with 'are there incrementality changes?' or 'Are there verbosity changes?' questions caused by this

They put <Message Text="executed" Importance="high" />, see that in output - all is fine. Then they run into similar need when on 9.x - see no results, switch to 8.x, see the result and suspect 9.x logging or incrementality issue. This can lead to wasted time with discovering the behavior and frustration

[JanKrivanek]

IIRC at some point we considered limited space (rollover) per project for high-pri messages. Is this completely out of question now?

I'm worried the Importance="high" is more spread knowledge in community now, than the knowledge of binlog viewer and this will catch many users off guard.

[lambdageek]

IIRC at some point we considered limited space (rollover) per project for high-pri messages. Is this completely out of question now?

I really like this. Maybe something like this: give each project a 2 line allocation in the terminal output:

Foo.csproj: Older message
Foo.csproj: Newer message
Bar.csproj: Also an older message
Bar.csproj: Also a new message

The 1st and 3rd lines are greyed out because it is not the most recent output The 2nd line from Foo.csproj is in bold because it is the most recent output from any subproject. The 4th line is in normal color because it is the newest output from Bar.csproj but it isn't the newest output overall.

Then if Foo.csproj writes Third message, the output will "scroll" the Foo.csproj messages and the window will look like this:

Foo.csproj: Newer message 
Foo.csproj: Third message
Bar.csproj: Also an older message
Bar.csproj: Also a new message

And maybe overall the total number of projects that get to output is (terminal height - someConstant)/2 and then you drop off whatever project had the oldest messages. So if there are 40 chatty subprojects but I'm on a 25 line terminal, I only see about 10 of the most recent projects' outputs.

---

If you have more vertical space budget, you could even do something with Unicode line drawing characters to better format the output

┍ Foo.csproj ━━
│ Older message
└ Newer message
┍ Bar.csproj ━━
│ Also an older message
└ Also a new message

[baronfel]

Our current plan after a chat yesterday is as follows:

• make TL verbosity-aware
  • currently it doesn't respect verbosity knobs at all, and we already have a request to make it understand quiet, we should also make it understand normal, verbose, etc - these would apply to the static messages, batched for each successful project
• default TL verbosity to 'minimal', our current TL experience
• log messages according to user-requested verbosity in the 'static' portion of the display
  • this may result in long logs, but at least users would see the messages
• create/define our actual ephemeral-message/progress-reporting API the way we want it for the long-term
• work with other teams to migrate their usage of 'Message-as-progress-reporting' to the new ephemeral-message API
• over time, the difference between normal and minimal verbosity trends to zero

thoughts on this @lambdageek?

[lambdageek]

thoughts on this @lambdageek?

Seems like a fine plan.

My only two real strong opinions are:

1. Something like "add --interactive to your message output" or "set your Importance to Importance="very high" to really display the output" is a non-starter. Projects don't have enough context to know if they're globally important - giving them an opt out will just lead right back to overly-verbose output. I'm happy to see this isn't part of the plan.

2. I think this is possibly not a great idea:

   log messages according to user-requested verbosity in the 'static' portion of the display

   • this may result in long logs, but at least users would see the messages

   My intuition is that users don't need to see all the output - they just need to see that there was output. If they think it's important and they need to investigate a line that scrolled out of view, they can rerun the build with a binlog or the console logger. So I think I would (as a user) prefer to have a scrollable area for the output that just shows the N most recent messages.

[baronfel]

the problem is that we have two areas/kinds of display today:

• the static, per-project output
• the dynamic, build-engine-status area

neither of these are a perfect fit for the behavior you describe - because the static portion isn't ever rewritten.

the progress API we want to define would be something that maps to the kind of experience you're describing, and we want to get people onboarded to that.

[lambdageek]

because the static portion isn't ever rewritten

I see. well given that limitation I think your outlined approach makes sense.

I'm excited to see what the ephemeral/progress API looks like.

[lambdageek]

One other thought:

given that dotnet build keeps a build server process running, have you thought about always writing a binlog to temporary storage? And then maybe dotnet build --replay -tl:off -v:diag would show the most recent log (or the most recent log for the current directory/solution/project) using the console logger at whatever verbosity I want

$ dotnet build --tl:on
... [...] ...
        There were 25 suppressed lines of Importance="high" output
        rerun with `dotnet build --replay --tl:off` to see them
$ dotnet build --replay --tl:off
...
Hello there
...
$ 

[AR-May]

Always writing binary log has performance implications, since writing the binary log automatically increases the verbosity to maximum.