KirillOsenkov / MSBuildStructuredLog

A logger for MSBuild that records a structured representation of executed targets, tasks, property and item values.
MIT License
1.42k stars 188 forks source link

The binlog for a static_assert excludes the most important piece of information #622

Closed rainersigwald closed 1 year ago

rainersigwald commented 1 year ago

Issue moved from dotnet/msbuild#8019


From @dmachaj on Friday, September 30, 2022 5:11:03 PM

Issue Description

We use some header files that have static asserts in them (see https://github.com/microsoft/wil). When those static asserts are violated there is a build break. The error output has the file/line information for the static_assert in WIL. However, the most important information is the file/line of the code in our project that uses WIL. This output is in the console but is missing from msbuild and the binlog file.

Steps to Reproduce

  1. Using Visual Studio 2022 17.3 create an empty Windows Console application project.
  2. Fill in the files as described below.
  3. msbuild MSBuildOutputReproProject.sln /bl
  4. Open the msbuild.binlog file in the MSBuild Structured Log Viewer

ConsoleApplication1.cpp

#include <iostream>
#include "StaticAssertHeader.h"

int main()
{
    std::cout << "Hello World!\n";
    DoStuff(1);
    DoStuff(1.0);
}

StaticAssertHeader.h

#pragma once

template <typename T>
void DoStuff(T value)
{
    static_assert(std::is_same<T, int>());
}

Console output

  ConsoleApplication1.cpp
v:\code\MSBuildOutputReproProject\ConsoleApplication1\StaticAssertHeader.h(6,39): error C2338: static_assert failed: 's
td::is_same<T, int>()' [v:\code\MSBuildOutputReproProject\ConsoleApplication1\ConsoleApplication1.vcxproj]
v:\code\MSBuildOutputReproProject\ConsoleApplication1\ConsoleApplication1.cpp(11): message : see reference to function
template instantiation 'void DoStuff<double>(T)' being compiled [v:\code\MSBuildOutputReproProject\ConsoleApplication1\
ConsoleApplication1.vcxproj]
          with
          [
              T=double
          ]

Binlog content

v:\code\MSBuildOutputReproProject\ConsoleApplication1\StaticAssertHeader.h(6,39): error C2338: static_assert failed: 'std::is_same<T, int>()' [v:\code\MSBuildOutputReproProject\ConsoleApplication1\ConsoleApplication1.vcxproj]
see reference to function template instantiation 'void DoStuff<double>(T)' being compiled
        with
        [
            T=double
        ]
The command exited with code 2.

Note that ConsoleApplication1.cpp(11) is missing from the binlog. This is the most important piece of information in the output.

Expected Behavior

The binlog should contain the full set of compiler output. It is missing the most important line with the file/line information.

Actual Behavior

The file/line information for the calling code is missing. Without this it is not possible to locate the error in a large code base. I must pipe the output to a txt file and search it for the errors. That is a much worse experience than using the binlog viewer.

Analysis

Versions & Configurations

MSBuild version 17.3.1+2badb37d1 for .NET Framework 17.3.1.41501

This device is running Windows 11 (2022 update).

rainersigwald commented 1 year ago

Issue moved from dotnet/msbuild#8019


From @Scottj1s on Monday, October 3, 2022 3:52:17 PM

The good news is that the desired information is indeed captured in the binlog:

msbuild /bl repro.sln ... msbuild.exe msbuild.binlog /noconlog /flp:v=diag;logfile=diag.log type diag.log ... D:\Samples\RawConsoleApp\header.h(7,39): error C2338: static_assert failed: 'std::is_same<T, int>()' [D:\Samples\RawConsoleApp\RawConsoleApp.vcxproj] D:\Samples\RawConsoleApp\RawConsoleApp.cpp(10): message : see reference to function template instantiation 'void DoStuff(T)' being compiled [D:\Samples\RawConsoleApp\RawConsoleApp.vcxproj] (TaskId:29) with (TaskId:29) [ (TaskId:29) T=double (TaskId:29) ] (TaskId:29)

rainersigwald commented 1 year ago

Issue moved from dotnet/msbuild#8019


From @dmachaj on Monday, October 3, 2022 9:16:54 PM

In that case is it being captured at the wrong output level (e.g. diagnostic but should be minimal)? Full diagnostic output is far too verbose in most cases.

rainersigwald commented 1 year ago

Issue moved from dotnet/msbuild#8019


From @rainersigwald on Monday, October 3, 2022 9:42:51 PM

No, it's there in minimal:

❯ msbuild .\msbuild.binlog -v:m
MSBuild version 17.4.0-preview-22477-01+fcc478938 for .NET Framework
  ConsoleApplication1.cpp
S:\repro\dotnet\msbuild\issues\8019\ConsoleApplication1\StaticAssertHeader.h(6,39): error C2338: static_assert failed:
'std::is_same<T, int>()' [S:\repro\dotnet\msbuild\issues\8019\ConsoleApplication1\ConsoleApplication1.vcxproj]
S:\repro\dotnet\msbuild\issues\8019\ConsoleApplication1\ConsoleApplication1.cpp(8,16): message : see reference to funct
ion template instantiation 'void DoStuff<double>(T)' being compiled [S:\repro\dotnet\msbuild\issues\8019\ConsoleApplica
tion1\ConsoleApplication1.vcxproj]
          with
          [
              T=double
          ]

This looks like a rendering problem by the log viewer (my guess is it's not rendering file/line info for Message events, only warning/error). I'll move the bug.

KirillOsenkov commented 1 year ago

Good bug. The binlog viewer didn't have special support for CriticalBuildMessageEventArgs. Turns out the CL task emits it and it's a pretty exotic message type that we apparently haven't encountered much before.

Fixed now: image

And now you can also navigate to the source location if the source file is on the same machine or embedded into the binlog.

KirillOsenkov commented 1 year ago

Fixed in e0aea0c6e063e2e2400fcfbf6ac4223059e2e52d

KirillOsenkov commented 1 year ago

FYI @yuehuang010 - this becomes its own node type CriticalBuildMessage instead of TimedMessage. I looked through the Cpp-specific logic and it shouldn't break anything, but FYI just in case.

yuehuang010 commented 1 year ago

Critical messages "notes" printed by the compiler. I have to do special logic to handle grouping to support multiline.

KirillOsenkov commented 1 year ago

Published in 2.1.728

dmachaj commented 1 year ago

Wow that was impressively fast. I just got a notice that there is a new version of the log viewer. When restarted it has your fix. I now see the expected information 👍