KirillOsenkov / MSBuildStructuredLog

A logger for MSBuild that records a structured representation of executed targets, tasks, property and item values.
MIT License
1.41k stars 188 forks source link

PropertyReassignment Resource string null #736

Closed JanKrivanek closed 2 months ago

JanKrivanek commented 6 months ago

Comntext

Binlogtool started failing in the internal AzDO pipeline (example [internal link]):

Unhandled exception. System.ArgumentNullException: Value cannot be null. (Parameter 'format')
   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 175
   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 1096
   at Microsoft.Build.Logging.StructuredLogger.BuildEventArgsReader.Read() in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BuildEventArgsReader.cs:line 194
   at Microsoft.Build.Logging.StructuredLogger.BinaryLogReplayEventSource.Replay(BinaryReader binaryReader, CancellationToken cancellationToken) in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BinaryLogReplayEventSource.cs:line 150
   at Microsoft.Build.Logging.StructuredLogger.BinaryLogReplayEventSource.Replay(Stream sourceFileStream, CancellationToken cancellationToken) in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BinaryLogReplayEventSource.cs:line 47
   at StructuredLogger.Utils.BinlogRedactor.ProcessBinlog(String inputFileName, String outputFileName, Boolean skipEmbeddedFiles) in C:\MSBuildStructuredLog\src\StructuredLogger.Utils\BinlogRedactor.cs:line 114
   at StructuredLogger.Utils.BinlogRedactor.RedactSecrets(BinlogRedactorOptions redactorOptions, Progress progress) in C:\MSBuildStructuredLog\src\StructuredLogger.Utils\BinlogRedactor.cs:line 69
   at BinlogTool.Redact.Run(List`1 inputs, List`1 tokens, Boolean inPlace, Boolean recurse) in C:\MSBuildStructuredLog\src\BinlogTool\Redact.cs:line 53
   at BinlogTool.Program.Main(String[] args) in C:\MSBuildStructuredLog\src\BinlogTool\Program.cs:line 125

Further info

AFK now so cannot analyze (will do later this week), but we've merged fix recently that should express property reassignment via PropertyReassignmentEventArgs instead of a plain message - so I guess a resource for the event is missing (though it is here: https://github.com/KirillOsenkov/MSBuildStructuredLog/blob/main/src/StructuredLogger/Strings/Strings.json#L37)

KirillOsenkov commented 6 months ago

Need to call Strings.Initialize() from BinlogTool, I'm on it

KirillOsenkov commented 6 months ago

Uploaded binlogtool 1.0.9

KirillOsenkov commented 6 months ago

Arcade fix: https://github.com/dotnet/arcade/pull/14313

teo-tsirpanis commented 4 months ago

@KirillOsenkov I am seeing this on Linux after updating the SDK to 8.0.201 (link). It does not fail on Windows.

As a workaround I am going to manually invoke Strings.Initialize with reflection.

KirillOsenkov commented 4 months ago

which version of StructuredLogger.dll is being used there? This should be fixed, let's get to the bottom of why this is not fixed.

teo-tsirpanis commented 4 months ago

I am on version 2.2.206. This is the binlog that failed to be inspected.

KirillOsenkov commented 4 months ago

just to confirm, at runtime, when the exception happens, can you verify that the actual .dll that throws the exception is the one you expect? could it be that you need to clean and it's an old version that's running?

teo-tsirpanis commented 4 months ago

Verified from VSCode's debug console that the StructuredLogger.dll that got loaded is the one in the directory of my program, and that the version of that dll is 2.2.206.14838.

KirillOsenkov commented 4 months ago

could you paste the full callstack please? maybe even a repro?

teo-tsirpanis commented 4 months ago

The callstack is this:

Unhandled exception. Fake.Core.BuildFailedException: Target 'RunFSharpUnitTests' failed.
 ---> System.AggregateException: One or more errors occurred. (Value cannot be null. (Parameter 'format'))
 ---> System.ArgumentNullException: Value cannot be null. (Parameter 'format')
   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 198
   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 1276
   at Microsoft.Build.Logging.StructuredLogger.BuildEventArgsReader.ReadBuildEventArgs(BinaryLogRecordKind recordKind) in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BuildEventArgsReader.cs:line 329
   at Microsoft.Build.Logging.StructuredLogger.BuildEventArgsReader.Read() in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BuildEventArgsReader.cs:line 246
   at Microsoft.Build.Logging.StructuredLogger.BinLogReader.ReadRecordsFromDecompressedStream(BuildEventArgsReader reader, Boolean includeAuxiliaryRecords)+MoveNext() in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BinLogReader.cs:line 440
   at Microsoft.FSharp.Collections.Internal.IEnumerator.choose@171.System.Collections.IEnumerator.MoveNext() in D:\workspace\_work\1\s\src\fsharp\FSharp.Core\seq.fs:line [178](https://github.com/teo-tsirpanis/Farkle/actions/runs/7965498109/job/21745138018#step:7:179)
   at Microsoft.FSharp.Collections.SeqModule.ToList[T](IEnumerable`1 source)
   at Fake.DotNet.MSBuildBinLog.getErrorsAndWarnings(String binLogFilePath)
   at Fake.DotNet.MSBuild.handleAfterRun(String command, FSharpOption`1 binLogPath, Int32 exitCode, String project)
   at Fake.DotNet.DotNet.test(FSharpFunc`2 setParams, String project)
   at Build.runFSharpUnitTests[a](a _arg1) in /home/runner/work/Farkle/Farkle/eng/build.fs:line 208
   at Build.initTargets@420-10.Invoke(TargetParameter arg00@)
   at Fake.Core.TargetModule.runSimpleInternal(TargetContext context, Target target)
   --- End of inner exception stack trace ---
   --- End of inner exception stack trace ---
   at Fake.Core.TargetModule.raiseIfError(OptionalTargetContext context)
   at Fake.Core.TargetModule.runOrDefaultWithArguments(String defaultTarget)
   at Build.main(String[] argv) in /home/runner/work/Farkle/Farkle/eng/build.fs:line 490

The F# function that reads the binlog is in https://github.com/fsprojects/FAKE/blob/master/src/app/Fake.DotNet.MSBuild/BinLog.fs.

To reproduce you can clone https://github.com/teo-tsirpanis/Farkle/tree/3a70e21ce78774dbafdeea6ac267d24dc55fd9a2 (the commit just before my workaround) and run dotnet run --project eng/Farkle.Build.fsproj -- -tTest.

KirillOsenkov commented 2 months ago

related: https://github.com/fsprojects/FAKE/issues/2744#issuecomment-2062589696

KirillOsenkov commented 2 months ago

The fix should be included next time we publish the NuGet package, hopefully soon. The current workaround is to call Strings.Initialize() manually. Calling it twice is benign as the method is idempotent.

KirillOsenkov commented 2 months ago

This fix is available in https://www.nuget.org/packages/MSBuild.StructuredLogger/2.2.240