Windows: MSB4016 error on build

[rgwood]

Hi, I'm following the instructions from the README but I'm running into an MSBuild failure when I try to run dotnet-releaser build. I've put together a minimal repro here.

Steps to Reproduce

Create a console app:

dotnet new console

Initialize the dotnet-releaser config:

dotnet-releaser new --project ReleaserRepro.csproj

Run dotnet-releaser build, observe the "Failing to run dotnet msbuild" error:

❯ dotnet-releaser build --force dotnet-releaser.toml
info: dotnet-releaser[0]
      Loading configuration from C:\Users\reill\source\releaser-repro\dotnet-releaser.toml
fail: dotnet-releaser[1]
      The changelog.path was not setup
info: dotnet-releaser[2]
      Adding default profile for platform [win-x64] with [Zip] package
      Adding default profile for platform [win-arm] with [Zip] package
      Adding default profile for platform [win-arm64] with [Zip] package
      Adding default profile for platform [linux-x64] with [Deb, Tar] packages
      Adding default profile for platform [linux-arm] with [Deb, Tar] packages
      Adding default profile for platform [linux-arm64] with [Deb, Tar] packages
      Adding default profile for platform [rhel-x64] with [Rpm, Tar] packages
      Adding default profile for platform [osx-x64] with [Tar] package
      Adding default profile for platform [osx-arm64] with [Tar] package

fail: dotnet-releaser[3]
      Failing to run dotnet msbuild -p:Configuration=Release -p:CustomAfterMicrosoftCommonTargets="C:\Users\reill\.dotnet\tools\.store\dotnet-releaser\0.1.0\dotnet-releaser\0.1.0\tools\net6.0\any\dotnet-releaser.targets" -nologo -logger:BinaryLogger,"C:\Users\reill\.dotnet\tools\.store\dotnet-releaser\0.1.0\dotnet-releaser\0.1.0\tools\net6.0\any\dotnet-releaser-binary-logger.dll";"C:\Users\reill\AppData\Local\Temp\tmpC534.tmp.binlog" -t:DotNetReleaserGetPackageInfo C:\Users\reill\source\releaser-repro\ReleaserRepro.csproj. Reason: MSBUILD : error MSB4016: The build stopped unexpectedly because the "ReusableLogger" logger failed unexpectedly during initialization. Object reference not set to an instance of an object.

Version Info

dotnet-releaser v0.1.0, Windows 11, and the .NET 6 SDK that comes installed with VS 2022 17.1.0 Preview 4:

.NET SDK (reflecting any global.json):
 Version:   6.0.200-preview.22055.15
 Commit:    a3c3a2bf3b

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.22000
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Program Files\dotnet\sdk\6.0.200-preview.22055.15\

Host (useful for support):
  Version: 6.0.1
  Commit:  3a25a7f1cc

P.S. Thank you so much for making dotnet-releaser - it fills a really important gap in the .NET OSS ecosystem!

[rgwood]

Might be a Windows-specific issue, dotnet-releaser gets much further on Linux (Debian 11 x64, .NET 6.0.101).

[xoofx]

Thanks for testing. It looks like it's probably the net6.0 preview that is failing with something here.

@KirillOsenkov I'm using StructuredLogger here (from NuGet MSBuild.StructuredLogger 2.1.545, though it looks like a bit old...), but does it ring a bell this error with ReusableLogger?

error MSB4016: The build stopped unexpectedly because the "ReusableLogger" logger failed unexpectedly during initialization. Object reference not set to an instance of an object.

[KirillOsenkov]

It doesn't, and I can't repro on my machine, but I'd certainly be the right person to investigate this and it's likely my fault somehow :) Do you have a full call stack?

You can use the Child Process Attach VS extension:
https://marketplace.visualstudio.com/items?itemName=vsdbgplat.MicrosoftChildProcessDebuggingPowerTool

Then debug dotnet-releaser.exe with Mixed mode (Managed + Native) in VS, enable Child Process Attach, enable first-chance exceptions (Debug -> Exceptions -> All .NET exceptions), then debug and it will get you a call stack of the exception. Paste that callstack here (and ideally the source location where it happens) and we can investigate further.

It looks like a bug in MSBuild currently (nothing a user is doing should be causing a NullRef in MSBuild), but we need to understand what is going on first (and whether it's MSBuild or the SDK).

Excellent repro steps @rgwood, I appreciate good bugs when I see them!

[KirillOsenkov]

This is what I see on my machine:

[rgwood]

Happy to try debugging in VS but I'm not entirely sure how (I've just been using the CLI outside of VS).

Would I need to clone this repo or is there a way to debug the dotnet-releaser.exe I installed as a global tool?

edit: on second thought I'll just clone the repo, that should be quick to try

[rgwood]

@KirillOsenkov I've installed the extension but I'm not getting a call stack when I debug. Does this look right?

Mixed-mode debugging enabled:

Child Process Debugging enabled:

All CLR exceptions enabled:

Debugging with F5 fails as expected but VS never breaks on an exception:

[KirillOsenkov]

There's a way to debug an .exe in VS if you don't have the sources. In VS, open the .exe as a Project (File -> Open Project), it will open as a pseudo-project, you can right-click the "project" in Solution Explorer, open Properties, fill out the arguments, working directory, environment variables, debug engine (has to be Mixed for Child Process Attach to work), then just F5.

This trick is generally useful if you don't have the source.

Or you can attach to an already running process, but it's less convenient and since JIT optimizes all modules on load by default, you won't see any variables in the locals window.

[KirillOsenkov]

Can you try to uncheck Tools -> Options -> Debugging -> Just my code? But it's strange, I'd expect it to work. When it runs, do you see additional processes showing up in Debug -> Windows -> Processes?

It may be that it isn't really attaching to the spawned dotnet msbuild process?

[KirillOsenkov]

Also you can try setting the MSBuildDebugEngine environment variable, it will dump binlogs for everything. Not sure if that will help here or not.

[rgwood]

Disabling Just My Code worked!

System.NullReferenceException
  HResult=0x80004003
  Message=Object reference not set to an instance of an object.
  Source=StructuredLogger
  StackTrace:
   at Microsoft.Build.Logging.StructuredLogger.BuildEventArgsWriter.GetMessageFlags(BuildMessageEventArgs e, BuildEventArgsFieldFlags flags, Boolean writeMessage, Boolean writeImportance) in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BuildEventArgsWriter.cs:line 667

[xoofx]

oh oh, some reflection going on here 😄 Seems that the field arguments was renamed 2 months ago 😨

Edit: Commit changing this field is here

[xoofx]

Thanks for reproducing the bug @rgwood and investigating it!

[xoofx]

Do you have many places like this in StructuredLogger @KirillOsenkov ? Does it mean that to completely protect it against such changes, we would need MSBuild to expose proper public API for these?

[xoofx]

Could these reflections be more protected by putting them separately somewhere with a validator that could check frequently with a recent MSBuild DLL?

[KirillOsenkov]

Ouch.

And fantastic job @rgwood, this is really helpful.

I guess we haven't seen this because not a lot of people use the BinaryLogger copy from StructuredLogger.dll (almost everyone uses the original from MSBuild). Yeah, let's think about what's the right thing to do is here.

I filed KirillOsenkov/MSBuildStructuredLog#556 so feel free to watch that for further development. For now the cheapest tactical fix is to probe for both field names and use the one that's not null.

[KirillOsenkov]

@xoofx would you please try to update to https://www.nuget.org/packages/MSBuild.StructuredLogger/2.1.617 and see if this fixes the issue?

Thanks!

[KirillOsenkov]

And to answer your question about why Reflection is necessary - these fields shouldn't be exposed to the general public, but I need access for obscure reasons (binary serialization). Maybe it's worth thinking about opening them up, but in MSBuild land, once we open anything up, we can never change it, so we've been cautious about making more foundational stuff public. The perf improvement two months ago that broke my reflection wouldn't have been possible had we had those fields public.

[xoofx]

@xoofx would you please try to update to https://www.nuget.org/packages/MSBuild.StructuredLogger/2.1.617 and see if this fixes the issue?

I couldn't reproduce it as I avoid installing previews on my dev machine. But I will ship a new version of dotnet-releaser with it! Thanks for the quick fix!

[rgwood]

Attempting to confirm the fix. The error is gone on dotnet-releaser v0.1.2 but now it seems to be failing silently for some reason:

❯ dotnet-releaser build --force dotnet-releaser.toml
info: dotnet-releaser[0]
      Loading configuration from C:\Users\reill\source\releaser-repro\dotnet-releaser.toml
fail: dotnet-releaser[1]
      The changelog.path was not setup
info: dotnet-releaser[2]
      Adding default profile for platform [win-x64] with [Zip] package
      Adding default profile for platform [win-arm] with [Zip] package
      Adding default profile for platform [win-arm64] with [Zip] package
      Adding default profile for platform [linux-x64] with [Deb, Tar] packages
      Adding default profile for platform [linux-arm] with [Deb, Tar] packages
      Adding default profile for platform [linux-arm64] with [Deb, Tar] packages
      Adding default profile for platform [rhel-x64] with [Rpm, Tar] packages
      Adding default profile for platform [osx-x64] with [Tar] package
      Adding default profile for platform [osx-arm64] with [Tar] package

info: dotnet-releaser[3]
      Package to build: PackageInfo { Name = ReleaserRepro, Version = 1.0.0, Description = Package Description, License = No license found, ProjectUrl = https://github.com/github_user_or_org_here/github_repo_here }

dotnet-releaser exits after that, and there is nothing in the artifacts-dotnet-releaser folder.

[KirillOsenkov]

Would you try to debug again with Child Processes and first chance exceptions?

[xoofx]

I think the error is The changelog.path was not setup in the log above, so in dotnet-releaser. Gonna push a fix because it's supposed to skip it when it is not set.

[rgwood]

Confirmed that build succeeds on v0.1.2 if I add this to the config:

[changelog]
publish = false

[xoofx]

Great. The changelog issue should be fixed in 0.1.3+

[rgwood]

Yup, confirmed that build (usually) works with the default config on v0.1.3. Thank you both for fixing things so quickly!

I am running into occasional build failures related to StructuredLogger but I can raise that in another issue elsewhere if it would help:

info: dotnet-releaser[24]
      Building target platform [linux-arm64] / [tar] package
fail: dotnet-releaser[25]
      Failing to run dotnet msbuild -p:PublishTrimmed=true -p:PublishSingleFile=true -p:SelfContained=true -p:PublishReadyToRun=true -p:CopyOutputSymbolsToPublishDirectory=false -p:SkipCopyingSymbolsToOutputDirectory=true -p:RuntimeIdentifier=linux-arm64 -p:Configuration=Release -p:CustomAfterMicrosoftCommonTargets=C:\Users\reill\.dotnet\tools\.store\dotnet-releaser\0.1.3\dotnet-releaser\0.1.3\tools\net6.0\any\dotnet-releaser.targets -nologo "-logger:BinaryLogger,\"C:\Users\reill\.dotnet\tools\.store\dotnet-releaser\0.1.3\dotnet-releaser\0.1.3\tools\net6.0\any\dotnet-releaser-binary-logger.dll\";\"C:\Users\reill\AppData\Local\Temp\tmp48E8.tmp.binlog\"" -t:Restore C:\Users\reill\source\releaser-repro\ReleaserRepro.csproj. Reason: MSBUILD : error MSB4017: The build stopped unexpectedly because of an unexpected logger failure.
      Microsoft.Build.Exceptions.InternalLoggerException: The build stopped unexpectedly because of an unexpected logger failure.
       ---> System.InvalidOperationException: Collection was modified; enumeration operation may not execute.
         at System.Collections.Generic.Dictionary`2.Enumerator.MoveNext()
         at Microsoft.Build.Internal.Utilities.EnumerateItems(IEnumerable items, Action`1 callback) in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\Utilities.cs:line 86
         at Microsoft.Build.Logging.StructuredLogger.BuildEventArgsWriter.WriteProjectItems(IEnumerable items) in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BuildEventArgsWriter.cs:line 852
         at Microsoft.Build.Logging.StructuredLogger.BuildEventArgsWriter.Write(ProjectEvaluationFinishedEventArgs e) in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BuildEventArgsWriter.cs:line 283
         at Microsoft.Build.Logging.StructuredLogger.BuildEventArgsWriter.WriteCore(BuildEventArgs e) in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BuildEventArgsWriter.cs:line 196
         at Microsoft.Build.Logging.StructuredLogger.BuildEventArgsWriter.Write(BuildEventArgs e) in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BuildEventArgsWriter.cs:line 137
         at Microsoft.Build.Logging.StructuredLogger.BinaryLogger.Write(BuildEventArgs e) in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BinaryLogger.cs:line 249
         at Microsoft.Build.Logging.StructuredLogger.BinaryLogger.EventSource_AnyEventRaised(Object sender, BuildEventArgs e) in C:\MSBuildStructuredLog\src\StructuredLogger\BinaryLogger\BinaryLogger.cs:line 239
         at Microsoft.Build.Evaluation.ProjectCollection.ReusableLogger.AnyEventRaisedHandler(Object sender, BuildEventArgs e)
         at Microsoft.Build.BackEnd.Logging.EventSourceSink.RaiseAnyEvent(Object sender, BuildEventArgs buildEvent)
         --- End of inner exception stack trace ---
         at Microsoft.Build.Exceptions.InternalLoggerException.Throw(Exception innerException, BuildEventArgs e, String messageResourceName, Boolean initializationException, String[] messageArgs)
         at Microsoft.Build.BackEnd.Logging.EventSourceSink.RaiseAnyEvent(Object sender, BuildEventArgs buildEvent)
         at Microsoft.Build.BackEnd.Logging.EventSourceSink.RaiseStatusEvent(Object sender, BuildStatusEventArgs buildEvent)
         at Microsoft.Build.BackEnd.Logging.EventSourceSink.Consume(BuildEventArgs buildEvent)
         at Microsoft.Build.BackEnd.Logging.EventSourceSink.Consume(BuildEventArgs buildEvent, Int32 sinkId)
         at Microsoft.Build.BackEnd.Logging.EventRedirectorToSink.Microsoft.Build.Framework.IEventRedirector.ForwardEvent(BuildEventArgs buildEvent)
         at Microsoft.Build.BackEnd.Logging.CentralForwardingLogger.EventSource_AnyEventRaised(Object sender, BuildEventArgs buildEvent)
         at Microsoft.Build.BackEnd.Logging.EventSourceSink.RaiseAnyEvent(Object sender, BuildEventArgs buildEvent)

[KirillOsenkov]

Thanks, I’ve filed KirillOsenkov/MSBuildStructuredLog#558 and will investigate it there.

[xoofx]

One thing you said @KirillOsenkov that I wanted to clarify:

I guess we haven't seen this because not a lot of people use the BinaryLogger copy from StructuredLogger.dll (almost everyone uses the original from MSBuild). Yeah, let's think about what's the right thing to do is here.

The reason I'm using StructuredLogger binary logger is to make more guarantee that I can read the results from any kind of dotnet+msbuild version. Based also on this comment from the readme:

Alternatively (useful for older versions of MSBuild) you can attach the logger to any MSBuild-based build using the logger library

So does it make sense to use StructuredLogger like this in my case or should I use instead the MSBuild built-in version?

[KirillOsenkov]

I think it’ll be better to just use -bl (the logger built into MSBuild). It has been supported since 15.3 (2017). Both the viewer as well as StructuredLogger.dll support reading binlogs of any version. I was wondering why you’re using StructuredLogger.dll. I don’t think you’ll support ancient MSBuilds such as 14.0?

[xoofx]

I think it’ll be better to just use -bl (the logger built into MSBuild). It has been supported since 15.3 (2017). Both the viewer as well as StructuredLogger.dll support reading binlogs of any version. I was wondering why you’re using StructuredLogger.dll. I don’t think you’ll support ancient MSBuilds such as 14.0?

Oh, ok, so I thought that using the logger of StructuredLogger would make sure that I could actually re-read it after. If you say that using MSBuild gives more guarantee then definitely, I will revert that. It will remove the hack I had to go through to have the StructuredLogger dll still packed on the side.

[xoofx]

Removed by commit e0825f8

[KirillOsenkov]

Plus, I think even StructuredLogger.dll of recent versions has lost any hope of working with MSBuild < 16.0, so there’s really no scenario I can think of where StructuredLogger.dll should be used for recording.

On the other hand it’s main usage is for reading binlogs (it is used by the viewer) as well as API (to read and analyze binlogs)

It all stems from historical reasons when MSBuild didn’t have /bl built-in. Now /bl is ubiquitous in any MSBuild since 2017 so the copy in StructureLogger.dll is redundant. I still keep it up-to-date (poorly, as we have seen) just in case.

[xoofx]

Plus, I think even StructuredLogger.dll of recent versions has lost any hope of working with MSBuild < 16.0, so there’s really no scenario I can think of where StructuredLogger.dll should be used for recording.

Great, thanks! I have removed using it from 0.1.8+