NullReferenceException when Replaying binlog produced on linux

[ericstj]

I'm building some automation that uses the BinLogReader API.

In my unit tests for this component, they are failing to consume binlogs from a simple project built on linux.

I've attached a minimal repo: repro-binlog-replay.zip

Output:

=== Replay() ===
  OnException: ArgumentNullException: Value cannot be null. (Parameter 'format')
  Stack trace :    at System.ArgumentNullException.Throw(String paramName)
   at System.String.FormatHelper(IFormatProvider provider, String format, ReadOnlySpan`1 args)
   at System.String.Format(String format, Object[] args)
   at Microsoft.Build.Logging.StructuredLogger.BuildEventArgsReader.FormatResourceStringIgnoreCodeAndKeyword(String resource, String[] arguments) in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BuildEventArgsReader.Viewer.cs:line 213
   at Microsoft.Build.Logging.StructuredLogger.BuildEventArgsReader.GetPropertyReassignmentMessage(String propertyName, String newValue, String previousValue, String location) in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BuildEventArgsReader.Viewer.cs:line 72
   at Microsoft.Build.Logging.StructuredLogger.BuildEventArgsReader.ReadPropertyReassignmentEventArgs() in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BuildEventArgsReader.cs:line 1397
   at Microsoft.Build.Logging.StructuredLogger.BuildEventArgsReader.ReadBuildEventArgs(BinaryLogRecordKind recordKind) in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BuildEventArgsReader.cs:line 334
   at Microsoft.Build.Logging.StructuredLogger.BuildEventArgsReader.Read() in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BuildEventArgsReader.cs:line 246
   at Microsoft.Build.Logging.StructuredLogger.BinLogReader.Replay(Stream stream, Progress progress) in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BinLogReader.cs:line 91
  Events dispatched: 19
  *** Replay stopped early due to exception ***

=== ReadRecords() ===
  Records read: 3814, errors: 1

BUG CONFIRMED: Replay() dispatched 19 events then stopped.
ReadRecords() successfully read 3814 records from the same file.

[KirillOsenkov]

In your tool, can you call Strings.Initialize() early on?

[KirillOsenkov]

it's an unfortunate gotcha that it's not being called by default, so both the viewer and the tools have to call it. The culture is usually stored in the binlog itself, so Strings.Initialize should normally get called once we encounter that message, but apparently not?

[KirillOsenkov]

this is where it's called when it sees the Culture message:

MSBuildStructuredLog/src/StructuredLogger/BinaryLogger/BuildEventArgsReader.Viewer.cs

Line 119 in cf34266

Strings.Initialize(culture);

[KirillOsenkov]

ah, in the binlog provided the MSBuild is too old and it doesn't emit the Culture message yet:
MSBuild version = "17.11.48+02bf66295"

[KirillOsenkov]

It is also unfortunate that ReadRecordsFromDecompressedStream() calls Strings.Initialize() but Replay() doesn't :(

just an omission I think

[KirillOsenkov]

or maybe until recently we were able to get away without resource strings in Replay(), since it's a pretty low-level API that doesn't do much with strings. PropertyReassignment must have been the first one to accidentally take a dependency on resource strings.

[KirillOsenkov]

I think calling Initialize twice with the same culture is pretty much cheap and idempotent, so we should just go ahead and call it from Replay(), so even if existing Replay callers call it too it's not going to hurt much

[ericstj]

Yep, I landed on just calling Strings.Initialize as a workaround. This does fix it. Any suggestion for which culture to use? This tool shouldn't care about messages, might even be better to standardize to some sort of invariant. I guess the default en-US is fine.

[KirillOsenkov]

yes the default is right. If the binlog has culture it will reset it properly.

[ericstj]

Got it. Thank you @KirillOsenkov.

I also found I should hook OnException otherwise exceptions were silently ignored and results truncated. This was unexpected and seems like bad API design. I think the reader should proceed processing the next record. If you have "halting" behavior the exception should be thrown. Or have a handler that can mark an exception "handled" to control halt/throw/continue behavior.

[KirillOsenkov]

do you have a repro/example for exception?