search

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

MSBuild binary log missing tool command line logged in ToolTask #624

Closed rainersigwald closed 1 year ago

rainersigwald commented 1 year ago

Issue moved from dotnet/msbuild#8075

From @gpwen on Wednesday, October 19, 2022 3:22:44 PM

Issue Description

When analyzing build log from a ToolTask derived custom MSBuild task, it's found that the full command line log entries are missing in binary log, The same log entries can be found in console log or file log with verbose level above minimal.

ToolTask will log the full command line it executes with the ToolTask.LogToolCommand(...) method, which will eventually log the command line with a TaskCommandLineEventArgs instance. Unfortunately, it seems such log entries cannot be found in MSBuild binary log, or not record as real log entries.

Steps to Reproduce

  1. Take any MSBuild binary log for building of a C# library project;
  2. Load the binary log *.binlog with MSBuild Structured Log Viewer;
  3. Search "$task csc";
  4. There is no log entry for the actual csc command been executed, just a CommandLineArguments property on the csc task, which is not the same thing. For example, ToolTask.Execute() could be called multiple times from derived class. CommandLineArguments can only record the last state of those calls, while the real TaskCommandLineEventArgs log entry can record all of them.

As comparison, file log with verbose level above minimal will have the following log entry:

C:\Program Files\Microsoft Visual Studio\2022\Enterprise\MSBuild\Current\Bin\Roslyn\csc.exe /noconfig /unsafe- /checked- ...

The command line used for testing is shown below (PowerShell). It will generated a binary log msbuild.binlog and a reference file log build.log:

$vs_where = "C:\Program Files (x86)\Microsoft Visual Studio\Installer\vswhere.exe"
$ms_build = &$vs_where -version "[17.0,999.0)" -Requires Microsoft.Component.MSBuild -Find MSBuild\**\Bin\amd64\MSBuild.exe | Select-Object -First 1
&$ms_build -r -m -v:m -bl -p:Configuration=Release -p:Platform=AnyCPU `
    -flp:"LogFile=build.log;Verbosity=normal;Encoding=UTF-8" `
    path\to\project.csproj

Expected Behavior

MSBuild binary log should contain full command line of external tool executed by ToolTask as separate log entry.

Actual Behavior

Full command line log entries from ToolTask cannot be find in MSBuild binary log.

Analysis

N/A

Versions & Configurations

MSBuild version: 17.2.1.25201 MSBuild Structured Log Viewer Version: 2.1.730

rainersigwald commented 1 year ago

Issue moved from dotnet/msbuild#8075

From @BenVillalobos on Thursday, October 20, 2022 5:24:41 PM

There is no log entry for the actual csc command been executed, just a CommandLineArguments property on the csc task, which is not the same thing

Isn't it, though? We looked at this and created a simple repro project and didn't notice a difference in the binlog (with the CommandLineArguments property) and the actual log file. They both logged the same thing, one of them is just under the "CommandLineArguments" property.

For example, ToolTask.Execute() could be called multiple times from derived class. CommandLineArguments can only record the last state of those calls, while the real TaskCommandLineEventArgs log entry can record all of them.

So is the actual request to ensure the binlog displays the cmd for every instance of Execute()?

We do see this behavior in our local repros, so it looks like the binlog viewer does not log every instance of the cmd when executing, meanwhile the logs do. Note you can replay the binlog msbuild my.binlog /flp:v=diag and see the correct logging done when execute is called multiple times. So, the data is stored correctly, just not displayed correctly.

rainersigwald commented 1 year ago

Issue moved from dotnet/msbuild#8075

From @rainersigwald on Thursday, October 20, 2022 5:25:00 PM

4. There is no log entry for the actual csc command been executed

What makes you think this?

4. For example, ToolTask.Execute() could be called multiple times from derived class. CommandLineArguments can only record the last state of those calls, while the real TaskCommandLineEventArgs log entry can record all of them.

I made a trivial tooltask with

        protected override string GenerateFullPathToTool()
        {
            return @"S:\repro\dotnet\msbuild\issues\8075\silly\bin\Debug\net7.0\silly.exe";
        }

        public override bool Execute()
        {
            base.Execute();
            return base.Execute();
        }

And I see the message twice in console output:

❯ msbuild .\Test.proj -bl -v:n -clp:nosummary     
MSBuild version 17.5.0-preview-22513-03+b3bd0870c for .NET Framework
Build started 10/20/2022 12:23:34 PM.
Project "S:\repro\dotnet\msbuild\issues\8075\Test.proj" on node 1 (default targets).
lakesjt:
  S:\repro\dotnet\msbuild\issues\8075\silly\bin\Debug\net7.0\silly.exe
  S:\repro\dotnet\msbuild\issues\8075\silly\bin\Debug\net7.0\silly.exe 
Done Building Project "S:\repro\dotnet\msbuild\issues\8075\Test.proj" (default targets).

and also from the binlog:

❯ msbuild .\msbuild.binlog -v:n
MSBuild version 17.5.0-preview-22513-03+b3bd0870c for .NET Framework
BinLogFilePath=S:\repro\dotnet\msbuild\issues\8075\msbuild.binlog
CurrentUICulture=en-US
Build started 10/20/2022 12:23:34 PM.
Project "S:\repro\dotnet\msbuild\issues\8075\Test.proj" on node 1 (default targets).
lakesjt:
  S:\repro\dotnet\msbuild\issues\8075\silly\bin\Debug\net7.0\silly.exe
  S:\repro\dotnet\msbuild\issues\8075\silly\bin\Debug\net7.0\silly.exe
Done Building Project "S:\repro\dotnet\msbuild\issues\8075\Test.proj" (default targets).
rainersigwald commented 1 year ago

Issue moved from dotnet/msbuild#8075

From @gpwen on Friday, October 21, 2022 3:33:05 AM

@BenVillalobos, thank you very much for the quick reply.

You're right I think binlog should log (well, display) all Execute() command lines, since those are actually written as log entries. Well, since those are actually stored somewhere in the binlog, just not displayed correctly by the structured log viewer, so this is actually a problem with the viewer. My bad since I believed the viewer showed me the original data (it really showed a lot). Now I know it interprets the data differently.

This is the last glitch when applying binlog for custom task debugging, thank your guys very much for addressing that!

rainersigwald commented 1 year ago

Issue moved from dotnet/msbuild#8075

From @gpwen on Friday, October 21, 2022 4:03:40 AM

Actually, can we move this issue report to "MSBuild Binary and Structured Log Viewer"? Even though I did get everything in binlog, I still need to search through huge amount of text to get to those logs from the task I'm checking. It's really messy when concurrent building enabled (like always). The structured viewer helped a lot by showing all relevant log entries for the task in one place. It greatly reduced the time to get to the bottom. It's just this one painful glitch with ToolTask. The real command line been issued is the most important thing about ToolTask, it's really helpful if that can be shown in more accurate way.

KirillOsenkov commented 1 year ago

@gpwen this is now fixed and deployed in 2.1.731. Thanks for reporting!

gpwen commented 1 year ago

Thank you very much for the quick fix! I've verified all command lines issued by ToolTask will be displayed correctly with version 2.1.731.

Thank you very much for this excellent tool! It's especially helpful in custom MSBuild tasks/targets development. With binary log and the viewer, it's so easy to find relevant information of the task/target, and correlate them with common targets/tasks distributed with MSBuild. That saved a lot of searching and guessing. I really wish I have used this tool earlier, it would surely save me a lot of time.

Thanks again for creating this marvelous tool!