Version 2.1.820 throws occasional errors reading recent binary logs

[jaredpar]

Encountered this bug when I had automation that was generating a number of binary logs by effectively running the following commands:

> dotnet new console 
> dotnet build -bl 

Then reading in the resulting binary log via BinaryLog.ReadRecords. That would eventually throw the following style of error:

Unhandled exception. System.AggregateException: One or more errors occurred. (String record number 7258 is invalid: string index 242921296 is not within 3564.) (String record number 7254 is invalid: string index 242921296 is not within 3562.)
 ---> System.IO.InvalidDataException: String record number 7258 is invalid: string index 242921296 is not within 3564.
   at Microsoft.Build.Logging.StructuredLogger.BuildEventArgsReader.GetStringFromRecord(Int32 index) in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BuildEventArgsReader.cs:line 1228
   at Microsoft.Build.Logging.StructuredLogger.BuildEventArgsReader.ReadDeduplicatedString() in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BuildEventArgsReader.cs:line 1203
   at Microsoft.Build.Logging.StructuredLogger.BuildEventArgsReader.ReadBuildEventArgsFields(Boolean readImportance) in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BuildEventArgsReader.cs:line 890
   at Microsoft.Build.Logging.StructuredLogger.BuildEventArgsReader.ReadTaskCommandLineEventArgs() in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BuildEventArgsReader.cs:line 692
   at Microsoft.Build.Logging.StructuredLogger.BuildEventArgsReader.Read() in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BuildEventArgsReader.cs:line 152
   at Microsoft.Build.Logging.StructuredLogger.BinLogReader.ReadRecordsFromDecompressedStream(Stream decompressedStream)+MoveNext() in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BinLogReader.cs:line 275
   at System.Collections.Generic.List`1..ctor(IEnumerable`1 collection)
   at System.Linq.Enumerable.ToList[TSource](IEnumerable`1 source)
   at Program.<>c__DisplayClass0_0.<<Main>$>g__RunTest|1(Int32 iteration) in C:\Users\jaredpar\temp\BinlogRepro\Program.cs:line 41       
   at Program.<>c__DisplayClass0_1.<<Main>$>b__3() in C:\Users\jaredpar\temp\BinlogRepro\Program.cs:line 20
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location 

Eventually I was able to reproduce this in a much more concise way: effectively building in parallel and calling BinaryLog.ReadRecords on the results. I don't know if the parallel aspect is relevant or not but this approach repros the bug consistently. The setup is have a project file with the following format:

<Project Sdk="Microsoft.NET.Sdk">

  <PropertyGroup>
    <OutputType>Exe</OutputType>
    <TargetFramework>net8.0</TargetFramework>
    <ImplicitUsings>enable</ImplicitUsings>
    <Nullable>enable</Nullable>
  </PropertyGroup>

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

</Project>

Then use the following code to reproduce the bug.

Note: this bug goes away when I move the MSBuild.StructuredLog reference to 2.1.844. So it's possible this bug is fixed already but I wanted to file in case it wasn't (also cause after 2 hours of debugging I wanted something to show for it 😉).

Most of my tests centered around 7.0.400 SDK but I also saw this happening on 8.0 Preview 7.

[KirillOsenkov]

Yes, this is known, need to move to 844. There was a brief window where the format was corrupted. See release notes for 844.

[KirillOsenkov]

#697 (comment)

[jaredpar]

Well at least I found a real bug and didn't imagine it. :)