Deadlock when LogBuildStarted() handler throws

[rainersigwald]

This was reported internally related to a .NET Native project compiled using ilc.exe, which invokes MSBuild programmatically.

BuildManager.BeginBuild attempts to LogBuildStarted while holding a lock. Ordinarily LogBuildStarted sends a signal to another thread and log processing happens there, and the main thread waits until the event is processed before returning (and releasing the lock).

The problem arises when an ILogger that handles the BuildStartedEvent throws an exception. That exception gets caught and rethrown (twice) before making it to the LoggingEventProcessor semi-graceful shutdown block, which dumps the exception to a file, and then attempts to marshal the exception back onto the thread that called Project.Build so that the caller can catch and handle it. Unfortunately, OnThreadException tries to acquire the BuildManager synclock before noting in the BuildSubmission that a fatal exception occurred. Since the main thread is holding the lock, the process is now deadlocked.

This was reported on and reproduces in the MSBuild that ships as part of the framework as well as the latest.

[rainersigwald]

Repro: https://github.com/rainersigwald/msbuild/commit/1e68623c7cd9e2b694bb743f26ecdc48a7d6e844

Interestingly, a logger that throws in the same way does not deadlock MSBuild.exe when added as a command-line logger. That works:

o:\msbuild>C:\Windows\Microsoft.NET\Framework\v4.0.30319\MSBuild.exe /logger:ThrowingLogger,O:\msbuild\src\LoggerThatThrowsOnBuildStarted\bin\Debug\LoggerThatThrowsOnBuildStarted.dll build.proj
Microsoft (R) Build Engine version 4.6.1038.0
[Microsoft .NET Framework, version 4.0.30319.42000]
Copyright (C) Microsoft Corporation. All rights reserved.

Build started 5/18/2016 3:52:58 PM.
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.NotImplementedException: The method or operation is not implemented.
   at ilc.ThrowingLogger.<>c.<Initialize>b__11_0(Object sender, BuildEventArgs e) in O:\msbuild\src\LoggerThatThrowsOnBuildStarted\ThrowingLogger.cs:line 73
   at Microsoft.Build.Evaluation.ProjectCollection.ReusableLogger.AnyEventRaisedHandler(Object sender, BuildEventArgs e)
   at Microsoft.Build.Framework.AnyEventHandler.Invoke(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.RaiseBuildStartedEvent(Object sender, BuildStartedEventArgs 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)