Exception in BinaryLog.ReadBuild() after Migrating to .NET 9 and Updating MSBuild.StructuredLogger

[rkieslinger]

Since migrating our project from .NET 8 to .NET 9 and updating the MSBuild.StructuredLogger NuGet package from version 2.2.356 to 2.2.386, we frequently encounter an exception at BinaryLog.ReadBuild(). Below is the stack trace:

System.AggregateException: One or more errors occurred. (Unable to sort because the IComparer.Compare() method returns inconsistent results. Either a value does not compare equal to itself, or one value repeatedly compared to another value yields different results. IComparer: ''.)
 ---> System.ArgumentException: Unable to sort because the IComparer.Compare() method returns inconsistent results. Either a value does not compare equal to itself, or one value repeatedly compared to another value yields different results. IComparer: ''.
   at System.Collections.Generic.GenericArraySortHelper`2.Sort(Span`1 keys, Span`1 values, IComparer`1 comparer)
   at Microsoft.Build.Collections.ArrayDictionary`2.Sort() in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\ArrayDictionary.cs:line 223
   at Microsoft.Build.Logging.StructuredLogger.Construction.AddPropertiesSorted(Folder propertiesFolder, TreeNode project, IEnumerable properties) in C:\MSBuildStructuredLog\src\StructuredLogger\Construction\Construction.cs:line 1163
   at Microsoft.Build.Logging.StructuredLogger.Construction.<>c__DisplayClass37_0.<StatusEventRaised>g__AddGlobalProperties|2() in C:\MSBuildStructuredLog\src\StructuredLogger\Construction\Construction.cs:line 583
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
   --- End of inner exception stack trace ---
   at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
   at System.Threading.Tasks.Task.Wait(Int32 millisecondsTimeout, CancellationToken cancellationToken)
   at Microsoft.Build.Logging.StructuredLogger.Build.WaitForBackgroundTasks() in C:\MSBuildStructuredLog\src\StructuredLogger\ObjectModel\Build.cs:line 285
   at Microsoft.Build.Logging.StructuredLogger.BinaryLog.ReadBuild(Stream stream, Progress progress, Byte[] projectImportsArchive, ReaderSettings readerSettings) in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLog.cs:line 164
   at Microsoft.Build.Logging.StructuredLogger.BinaryLog.ReadBuild(String filePath, Progress progress, ReaderSettings readerSettings) in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLog.cs:line 46
   at System.Threading.Tasks.Task`1.InnerInvoke()
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location ---
   at XXX.DevOps.Butler.Core.Jobs.FireAndForget.BuildAnalysisJob.ReadBinaryLogAsync(String binLogFilePath, CancellationToken cancellationToken) in D:\55\s\src\XXX.DevOps.Butler.Core\Jobs\FireAndForget\BuildAnalysisJob.cs:line 125
   at XXX.DevOps.Butler.Core.Jobs.FireAndForget.BuildAnalysisJob.CreateBuildAnalysisEntityAsync(Build build, Timeline timeline, String binaryLogFilePath, PerformContext context, CancellationToken cancellationToken) in D:\55\s\src\XXX.DevOps.Butler.Core\Jobs\FireAndForget\BuildAnalysisJob.cs:line 78
   at XXX.DevOps.Butler.Core.Jobs.FireAndForget.BuildAnalysisJob.ExecuteAsync(Int32 id, PerformContext context, CancellationToken cancellationToken) in D:\55\s\src\XXX.DevOps.Butler.Core\Jobs\FireAndForget\BuildAnalysisJob.cs:line 44
   at InvokeStub_TaskAwaiter.GetResult(Object, Object, IntPtr*)
   at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr)

Since we are using Hangfire, we can rerun a job if it fails. If we encounter the aforementioned exception, the reruns almost always succeed.

[KirillOsenkov]

Do you have a simple small binlog with no secrets that exhibits the issue? Any chance you could email it to me at my first name dot last name at microsoft? Please don't share it if it contains any private information or secrets.

[rkieslinger]

Unfortunately, no. As I mentioned in my initial post, rerunning the job almost always resolves the issue. I tested a binlog that failed on the first attempt by loading it with BinaryLog.ReadBuild() 50 times in a row in a sample console application on my local computer, and it worked every time.

I believe I can easily work around the issue by configuring my Hangfire job to automatically rerun if it fails, but I'm still curious about the root cause.

[rkieslinger]

Could the size of the binlogs become an issue? They are currently around 60 MB. When opening a log in the MSBuild Structured Log Viewer, it states:

Total opening time: 33.642 s, Loading: 17.196 s, Analyzing: 2.478 s, Indexing: 11.128 s, Reading files: 785 ms, Allocated: 15 077 423 632 bytes, Nodes: 87 744 450, Strings: 263 925

[KirillOsenkov]

No, the problem is with some property name or value. MSBuild logs all properties and their values on either ProjectEvaluationFinishedEventArgs or ProjectStartedEventArgs. When reading these properties it sorts them, and sometimes that comparer misbehaves, I don't know why.

[KirillOsenkov]

could be related to machine culture/language

[KirillOsenkov]

This could be a bug in .NET 9, we just call Array.Sort(): https://github.com/KirillOsenkov/MSBuildStructuredLog/blob/c140e9dd07ef9b2a12257f80873cfcf8126046ad/src/StructuredLogger/BinaryLogger/ArrayDictionary.cs#L230