Can't read .binlog file in .NET 6 Preview 2

[jonathanpeppers]

Issue Description

We have some integration test code that fails to read .binlog files, such as:

var duration = TimeSpan.Zero;
using var fileStream = File.OpenRead("msbuild.binlog");
using var gzip = new GZipStream(fileStream, CompressionMode.Decompress);
using var binaryReader = new BinaryReader(gzip);
int fileFormatVersion = binaryReader.ReadInt32();
var buildReader = new BuildEventArgsReader(binaryReader, fileFormatVersion);
BuildEventArgs args;
var started = new Stack<DateTime>();
while ((args = buildReader.Read()) != null)
{
	if (args is ProjectStartedEventArgs projectStarted)
	{
		started.Push(projectStarted.Timestamp);
	}
	else if (args is ProjectFinishedEventArgs projectFinished)
	{
		duration += projectFinished.Timestamp - started.Pop();
	}
}

if (duration == TimeSpan.Zero)
	throw new InvalidDataException($"No project build duration found!");

There might be a way to clean up this code (let me know), but BuildEventArgsReader.Read() returns null on the first call.

This was working in .NET 6 Preview 1.

Steps to Reproduce

Try the example project, just build & run it in VS with the right .NET 6.0.100-preview.2.21114.3 installed:

msbuild-binlog.zip

This project attempts to parse a .binlog that was produced on my machine -- it was a build of a .NET 6 Android application. Both the sample project above and .binlog were using the same .NET version.

Expected Behavior

BuildEventArgsReader.Read() returns something.

Actual Behavior

BuildEventArgsReader.Read() returns null.

Versions & Configurations

Windows 10, using .NET 6.0.100-preview.2.21114.3

Installed from: https://dotnetcli.azureedge.net/dotnet/Sdk/6.0.100-preview.2.21114.3/dotnet-sdk-6.0.100-preview.2.21114.3-win-x64.exe

Attach a binlog

See the .zip above.

[KirillOsenkov]

The version of the binlog file format has increased, so older MSBuild can't read it anymore.

There are a couple of ways to fix this. You can look into using MSBuildLocator (https://github.com/microsoft/msbuildlocator) to load the latest MSBuild binaries at runtime that support this format. It's a bit tricky, see here for a sample:
#3434 (comment)

Alternatively, you can switch to the MSBuild.StructuredLogger NuGet package, https://www.nuget.org/packages/MSBuild.StructuredLogger. It has a copy of BuildEventArgsReader that is up-to-date with the latest. Maybe easier than using MSBuild for this scenario. I recommend this:

  <ItemGroup>
    <PackageReference Include="MSBuild.StructuredLogger" Version="2.1.303" />
  </ItemGroup>

using System;
using System.Collections.Generic;
using System.IO;
using Microsoft.Build.Framework;
using Microsoft.Build.Logging.StructuredLogger;

namespace msbuild_binlog
{
	class Program
	{
		static void Main()
		{
			var reader = new BinLogReader();
			var records = reader.ReadRecords("msbuild.binlog");

			TimeSpan duration = TimeSpan.Zero;
			var started = new Stack<DateTime>();
			foreach (var record in records)
			{
				if (record.Args is ProjectStartedEventArgs projectStarted)
				{
					started.Push(projectStarted.Timestamp);
				}
				else if (record.Args is ProjectFinishedEventArgs projectFinished)
				{
					duration += projectFinished.Timestamp - started.Pop();
				}
			}

			if (duration == TimeSpan.Zero)
				throw new InvalidDataException($"No project build duration found!");

			Console.WriteLine(duration);
		}
	}
}

[KirillOsenkov]

Actually here's a better way to do it:

using System;
using System.IO;
using System.Linq;
using Microsoft.Build.Logging.StructuredLogger;

namespace msbuild_binlog
{
	class Program
	{
		static void Main()
		{
			var build = BinaryLog.ReadBuild("msbuild.binlog");
			var duration = build
				.FindChildrenRecursive<Project>()
				.Aggregate(TimeSpan.Zero, (duration, project) => duration + project.Duration);

			if (duration == TimeSpan.Zero)
				throw new InvalidDataException($"No project build duration found!");

			Console.WriteLine(duration);
		}
	}
}

This way the library will pair up starts and finishes for multi-core builds correctly (you can have mismatched project started for projects building on different nodes).

[jonathanpeppers]

Ok, to summarize, the 16.9.0 Microsoft.Build.* packages on NuGet are not new enough to parse the new .binlog format.

Thanks for the example above, it's working for us, thanks!

[KirillOsenkov]

Yes, binlog format is actively changing between 16.9 and 16.10 so you may need to keep bumping MSBuild.StructuredLogger NuGet if this breaks again

[jonathanpeppers]

FYI @KirillOsenkov I'm seeing a new one on .NET 6 Preview 3:

System.NotSupportedException : Unsupported log file format. Latest supported version is 10, the log file has version 11.

So we must already need a new MSBuild.StructuredLogger, thanks!

[KirillOsenkov]

Yes, and I'm working on a PR that will further bump the version to 12, just to keep you on your toes!

[KirillOsenkov]

btw would love to see build duration comparison and binlog size comparison between .NET 5 and .NET 6 previews for your codebase!

[jonathanpeppers]

I don't know that we will have .NET 5 to compare against -- we are still partially using msbuild (not fully using dotnet build) to build xamarin/xamarin-android. We have logs of small test app projects, but that might be it.

We could certainly compare building dotnet/maui with .NET 6 preview 1 vs newer previews, though.

[KirillOsenkov]

Nah, that’s fine. Just thought if you had a history of binlogs readily available from CI, but no biggie.