Binlog causes detailed summary messages output to console

[ilabutin]

Steps to reproduce

Create simple project and no other files in the directory:

<Project>
  <Target Name="Build">
    <Message Text="Hello"/>
  </Target>
</Project>

Run following command:

msbuild

The output is:

Microsoft (R) Build Engine version 15.9.20+g88f5fadfbe for .NET Framework
Copyright (C) Microsoft Corporation. All rights reserved.

Build started 29.05.2019 16:29:26.
Project "D:\temp\test.proj" on node 1 (default targets).
Build:
  Hello
Done Building Project "D:\temp\test.proj" (default targets).


Build succeeded.
    0 Warning(s)
    0 Error(s)

Time Elapsed 00:00:00.04

Now run the following command:

msbuild /bl

The output is:

Microsoft (R) Build Engine version 15.9.20+g88f5fadfbe for .NET Framework
Copyright (C) Microsoft Corporation. All rights reserved.

C:\Program Files (x86)\Microsoft Visual Studio\2017\Enterprise\MSBuild\15.0\bin\msbuild.exe /bl .\test.proj
Build started 29.05.2019 16:30:05.
Project "D:\temp\test.proj" on node 1 (default targets).
Build:
  Hello
Done Building Project "D:\temp\test.proj" (default targets).

Deferred Messages

  Detailed Build Summary
  ======================


  ============================== Build Hierarchy (IDs represent configurations) =====================================================
  Id                  : Exclusive Time   Total Time   Path (Targets)
  -----------------------------------------------------------------------------------------------------------------------------------
  0                   : 0.040s           0.040s       D:\temp\test.proj ()

  ============================== Node Utilization (IDs represent configurations) ====================================================
  Timestamp:            1        Duration   Cumulative
  -----------------------------------------------------------------------------------------------------------------------------------
  636947334050280982:   0        0,040s     0,040s
  -----------------------------------------------------------------------------------------------------------------------------------
  Utilization:          100,0    Average Utilization: 100,0

Build succeeded.
    0 Warning(s)
    0 Error(s)

Time Elapsed 00:00:00.06

Expected behavior

When binlog is enabled the command line output still does not include these detailed summary messages unless explicitly enabled for console logger.

Generalizing that I would say that logic "enable detailed summary if diagnostics logging is enabled" should work only when diagnostics logging was enabled explicitly by end-user from command line and not when some logger decides it wants more verbose logging compared to what user asked for.

Environment data

msbuild /version output:

Microsoft (R) Build Engine version 15.9.20+g88f5fadfbe for .NET Framework
Copyright (C) Microsoft Corporation. All rights reserved.

15.9.20.62856

I'd be happy to work on the fix, but I need some understanding whether this is really a bug or not. And then probably some high-level idea of how to fix properly.

[hamorphis]

The detailed summary at the end contains thousands of # which messes my GitLab log completely.

`Deferred Messages

Detailed Build Summary

============================== Build Hierarchy (IDs represent configurations) =====================================================
Id : Exclusive Time Total Time Path (Targets)

0 : 74.654s 670.927s C:\GitLab-Runner\builds\1a14f271\0\revit\vray4revit\Build\scripts\full_build.proj ()
| 1 : 315.817s 315.817s C:\GitLab-Runner\builds\1a14f271\0\revit\vray4revit\Build\scripts\build_solution.proj ()
| 2 : 167.251s 263.976s C:\GitLab-Runner\builds\1a14f271\0\revit\vray4revit\Build\scripts\build_installer.proj ()
| | 3 : 1.791s 1.791s C:\GitLab-Runner\builds\1a14f271\0\revit\vray4revit\Build\scripts\sign.proj ()
| | 4 : 1.397s 1.397s C:\GitLab-Runner\builds\1a14f271\0\revit\vray4revit\Build\scripts\sign.proj ()
| | 5 : 1.433s 1.433s C:\GitLab-Runner\builds\1a14f271\0\revit\vray4revit\Build\scripts\sign.proj ()
| | 6 : 1.462s 1.462s C:\GitLab-Runner\builds\1a14f271\0\revit\vray4revit\Build\scripts\sign.proj ()
| | 7 : 1.681s 1.681s C:\GitLab-Runner\builds\1a14f271\0\revit\vray4revit\Build\scripts\sign.proj ()
| | 8 : 1.520s 1.520s C:\GitLab-Runner\builds\1a14f271\0\revit\vray4revit\Build\scripts\sign.proj ()
| | 9 : 0.894s 0.894s C:\GitLab-Runner\builds\1a14f271\0\revit\vray4revit\Build\scripts\sign.proj ()
| | 10 : 0.986s 0.986s C:\GitLab-Runner\builds\1a14f271\0\revit\vray4revit\Build\scripts\sign.proj ()
| | 11 : 3.124s 3.124s C:\GitLab-Runner\builds\1a14f271\0\revit\vray4revit\Build\scripts\sign.proj ()
| . 12 : 82.434s 82.434s C:\GitLab-Runner\builds\1a14f271\0\revit\vray4revit\Build\scripts\sign.proj ()
. 13 : 16.475s 16.475s C:\GitLab-Runner\builds\1a14f271\0\revit\vray4revit\Build\scripts\upload_to_nightlies.proj ()

============================== Node Utilization (IDs represent configurations) ====================================================
Timestamp: 1 Duration Cumulative

636964481725909927: 0 0.982s 0.982s ###################
636964481735734692: 1 315.814s 316.796s ############################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################
636964484893869695: 0 73.457s 390.253s #############################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################
636964485628439737: 2 16.936s 407.189s ##################################################################################################################################################################################################################################################################################################################################################
636964485797798862: 3 1.791s 408.980s ###################################
636964485815704965: 2 0.005s 408.984s
636964485815753910: 4 1.397s 410.382s ###########################
636964485829728493: 2 0.002s 410.384s
636964485829751057: 5 1.433s 411.817s ############################
636964485844083938: 2 0.002s 411.819s
636964485844103387: 6 1.462s 413.282s #############################
636964485858725106: 2 0.002s 413.284s
636964485858745133: 7 1.681s 414.965s #################################
636964485875559377: 2 0.002s 414.967s
636964485875578868: 8 1.520s 416.487s ##############################
636964485890776238: 2 0.003s 416.490s
636964485890805096: 9 0.894s 417.384s #################
636964485899748392: 2 0.002s 417.386s
636964485899770557: 10 0.986s 418.372s ###################
636964485909632322: 2 4.231s 422.603s ####################################################################################
636964485951938073: 11 3.123s 425.726s ##############################################################
636964485983167480: 2 146.064s 571.790s #########################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################
636964487443810758: 12 82.435s 654.225s ################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################
636964488268157542: 2 0.004s 654.229s
636964488268195522: 0 0.226s 654.455s ####
636964488270456365: 13 16.475s 670.930s #########################################################################################################################################################################################################################################################################################################################################
636964488435208175: 0 0.006s 670.936s

Utilization: 100.0 Average Utilization: 100.0
`

[KirillOsenkov]

I absolutely agree that this is undesired behavior, apologies for that.

As long as any logger turns the detailed summary on (and the BinaryLogger needs to turn this on) then all loggers will receive the detailed summary. The BuildManager sends out the build summary as a disparate set of build messages to all loggers:
https://github.com/Microsoft/msbuild/blob/08d1cb5532d98dd4b9f2f4ecdb7c9c7a037aed1c/src/Build/BackEnd/BuildManager/BuildManager.cs#L1916-L1919

We'll have to think carefully how to fix this because it's tricky. Not sure yet what a good solution here is, but once again, to iterate, I do agree that the user experience is not great here.

[KirillOsenkov]

And this is where the detailed summary is turned on when at least one logger has set the verbosity to diagnostic: https://github.com/Microsoft/msbuild/blob/08d1cb5532d98dd4b9f2f4ecdb7c9c7a037aed1c/src/MSBuild/XMake.cs#L2950-L2953

[KirillOsenkov]

We could potentially use the approach from here:
#3253
so that each logger could specify whether it wants the detailed summary or not. Perhaps we should have a separate DetailedSummaryBuildEventArgs that we could send to the loggers and each logger could either process it or throw it away.

[zsd4yr]

As a workaround with the binarylog parameter, I think we just need a way to set /detailedsummary to false

[KirillOsenkov]

I apologize for such a long delay, a PR is now available to allow force detailed summary off: #6338

[ilabutin]

@KirillOsenkov No way you should apologize! Thanks for the fix and for all the work you do on the build tools and the MSBuild Log Viewer.

[rainersigwald]

Being able to turn it off now is good but we should reconsider tweaking the default as in #6338 (comment)

[yuehuang010]

+1 for default off.

[KirillOsenkov]

yes it’s been bugging me for console