Open robertborr opened 5 years ago
Looks like we could nullref in that method if we were passed null:
It's coming from a ProjectStartedEventArgs
And that ctor mostly just passes along the passed-in item list which I wouldn't expect to have any null entries.
@robertborr Does this repro consistently?
We just hit this in another Linux build.
https://dev.azure.com/dnceng/public/_build/results?buildId=81583
Note that the callstack shown differs by 1 line after Write(ITaskItem item) call. It has item.CloneCustomMetadata in the callstack, which tells me that item wouldn't be null in that case.
2019-01-28T21:50:31.9837577Z Microsoft.Build.Exceptions.InternalLoggerException: The build stopped unexpectedly because of an unexpected logger failure. ---> System.NullReferenceException: Object reference not set to an instance of an object.
+ 2019-01-28T21:50:31.9838228Z at Microsoft.Build.Execution.ProjectItemInstance.TaskItem.CloneCustomMetadata()
2019-01-28T21:50:31.9838392Z at Microsoft.Build.Logging.BuildEventArgsWriter.Write(ITaskItem item)
2019-01-28T21:50:31.9838539Z at Microsoft.Build.Logging.BuildEventArgsWriter.WriteItems(IEnumerable items)
2019-01-28T21:50:31.9838676Z at Microsoft.Build.Logging.BuildEventArgsWriter.Write(ProjectStartedEventArgs e)
2019-01-28T21:50:31.9838827Z at Microsoft.Build.Logging.BuildEventArgsWriter.Write(BuildEventArgs e)
2019-01-28T21:50:31.9838971Z at Microsoft.Build.Logging.BinaryLogger.Write(BuildEventArgs e)
2019-01-28T21:50:31.9839121Z at Microsoft.Build.Logging.BinaryLogger.EventSource_AnyEventRaised(Object sender, BuildEventArgs e)
2019-01-28T21:50:31.9839279Z at Microsoft.Build.Evaluation.ProjectCollection.ReusableLogger.AnyEventRaisedHandler(Object sender, BuildEventArgs e)
2019-01-28T21:50:31.9839452Z at Microsoft.Build.BackEnd.Logging.EventSourceSink.RaiseAnyEvent(Object sender, BuildEventArgs buildEvent)
2019-01-28T21:50:31.9839907Z --- End of inner exception stack trace ---
2019-01-28T21:50:31.9840084Z at Microsoft.Build.Exceptions.InternalLoggerException.Throw(Exception innerException, BuildEventArgs e, String messageResourceName, Boolean initializationException, String[] messageArgs)
2019-01-28T21:50:31.9840288Z at Microsoft.Build.BackEnd.Logging.EventSourceSink.RaiseAnyEvent(Object sender, BuildEventArgs buildEvent)
2019-01-28T21:50:31.9840463Z at Microsoft.Build.BackEnd.Logging.EventSourceSink.RaiseStatusEvent(Object sender, BuildStatusEventArgs buildEvent)
2019-01-28T21:50:31.9840644Z at Microsoft.Build.BackEnd.Logging.EventSourceSink.RaiseProjectStartedEvent(Object sender, ProjectStartedEventArgs buildEvent)
2019-01-28T21:50:31.9840800Z at Microsoft.Build.BackEnd.Logging.EventSourceSink.Consume(BuildEventArgs buildEvent)
2019-01-28T21:50:31.9840960Z at Microsoft.Build.BackEnd.Logging.EventSourceSink.Consume(BuildEventArgs buildEvent, Int32 sinkId)
2019-01-28T21:50:31.9841160Z at Microsoft.Build.BackEnd.Logging.EventRedirectorToSink.Microsoft.Build.Framework.IEventRedirector.ForwardEvent(BuildEventArgs buildEvent)
2019-01-28T21:50:31.9841349Z at Microsoft.Build.BackEnd.Logging.CentralForwardingLogger.EventSource_AnyEventRaised(Object sender, BuildEventArgs buildEvent)
2019-01-28T21:50:31.9841512Z at Microsoft.Build.BackEnd.Logging.EventSourceSink.RaiseAnyEvent(Object sender, BuildEventArgs buildEvent)
2019-01-28T21:50:32.0326589Z Build failed (exit code '1').
There are two implementations of CloneCustomMetadata()
... ProjectItemInstance and TaskItem. I assume the logger gets the former:
public IDictionary CloneCustomMetadata()
{
Dictionary<string, string> clonedMetadata = new Dictionary<string, string>(MSBuildNameIgnoreCaseComparer.Default);
foreach (ProjectMetadataInstance metadatum in MetadataCollection)
{
clonedMetadata[metadatum.Name] = metadatum.EvaluatedValue;
}
return clonedMetadata;
}
clonedMetadata
cannot be null. Also since MetadataCollection
getter is not on the stack, and looks too big to inline I assume the NullReferenceException does not come from within it. And by inspection, it will never return null either. So either the dictionary contains a null metadatum
- and from a quick look (I didn't look carefully), it should not, because it uses key
off each entry as its internal key - or something else is happening.
Implementation of CloneCustomMetadata()
in TaskItem, if that's relevant, is similar, again the source and target collection is checked for null.
Suggestion - some unprotected concurrent read and write to the backing dictionary here, either source or destination. That can often manifest as a NullReferenceException when accessing a dictionary. Since there's definitely multithreading going on here, perhaps one thread didn't properly "let go" of this item before it got to the logging thread?
If that's a possibility, as well as code inspection, another possibility is swapping out the relevant Dictionary<K,V>
's with some custom dictionary that immediatley breaks into the debugger when a write occurs to it concurrent with another read (or write). That might possibly, in stress runs, cause this issue to happen locally, and make it possible to find the "other" callstack.
@chabiss has a consistent repro of this.
Sorry, no his stack is different:
MSBUILD : error MSB4015: The build stopped unexpectedly because the "ReusableLogger" logger failed unexpectedly during shutdown.
System.IO.Compression.ZLibException: The stream state of the underlying compression routine is inconsistent.
at System.IO.Compression.DeflaterZLib.Deflate(FlushCode flushCode)
at System.IO.Compression.DeflaterZLib.ReadDeflateOutput(Byte[] outputBuffer, FlushCode flushCode, Int32& bytesRead)
at System.IO.Compression.DeflaterZLib.System.IO.Compression.IDeflater.GetDeflateOutput(Byte[] outputBuffer)
at System.IO.Compression.DeflateStream.WriteDeflaterOutput(Boolean isAsync)
at System.IO.Compression.DeflateStream.InternalWrite(Byte[] array, Int32 offset, Int32 count, Boolean isAsync)
at System.IO.Compression.DeflateStream.Write(Byte[] array, Int32 offset, Int32 count)
at System.IO.Compression.GZipStream.Write(Byte[] array, Int32 offset, Int32 count)
at System.IO.Stream.WriteByte(Byte value)
at System.IO.BinaryWriter.Write(Byte value)
at Microsoft.Build.Logging.BuildEventArgsWriter.Write7BitEncodedInt(BinaryWriter writer, Int32 value)
at Microsoft.Build.Logging.BuildEventArgsWriter.WriteBlob(BinaryLogRecordKind kind, Byte[] bytes)
at Microsoft.Build.Logging.BinaryLogger.Shutdown()
at Microsoft.Build.Evaluation.ProjectCollection.ReusableLogger.Shutdown()
at Microsoft.Build.BackEnd.Logging.LoggingService.ShutdownLogger(ILogger logger)
@AArnott is seeing this in Razzle:
MSBUILD : error MSB4015: The build stopped unexpectedly because the "ReusableLogger" logger failed unexpectedly during shutdown.
System.IO.Compression.ZLibException: The stream state of the underlying compression routine is inconsistent.
at System.IO.Compression.DeflaterZLib.Deflate(FlushCode flushCode)
at System.IO.Compression.DeflaterZLib.ReadDeflateOutput(Byte[] outputBuffer, FlushCode flushCode, Int32& bytesRead)
at System.IO.Compression.DeflaterZLib.System.IO.Compression.IDeflater.GetDeflateOutput(Byte[] outputBuffer)
at System.IO.Compression.DeflateStream.WriteDeflaterOutput(Boolean isAsync)
at System.IO.Compression.DeflateStream.InternalWrite(Byte[] array, Int32 offset, Int32 count, Boolean isAsync)
at System.IO.Compression.DeflateStream.Write(Byte[] array, Int32 offset, Int32 count)
at System.IO.Compression.GZipStream.Write(Byte[] array, Int32 offset, Int32 count)
at System.IO.Stream.WriteByte(Byte value)
at System.IO.BinaryWriter.Write(Byte value)
at Microsoft.Build.Logging.BuildEventArgsWriter.Write7BitEncodedInt(BinaryWriter writer, Int32 value)
at Microsoft.Build.Logging.BuildEventArgsWriter.WriteBlob(BinaryLogRecordKind kind, Byte[] bytes)
at Microsoft.Build.Logging.BinaryLogger.Shutdown()
at Microsoft.Build.Evaluation.ProjectCollection.ReusableLogger.Shutdown()
at Microsoft.Build.BackEnd.Logging.LoggingService.ShutdownLogger(ILogger logger)
What I saw was caused by a DEVPATH that pointed to a bad file. Thanks, @KirillOsenkov
@aarnott let me know if you think there’s a way to harden against this case and give a better error message instead of crashing.
There's really not. The environment caused a mismatched system.dll to be loaded.
Happened again in corefx: https://dnceng.visualstudio.com/public/_build/results?buildId=339171&view=logs
(Minimized the conversation about separate issue with internal VS builds that also happened to manifest with a logger exception. That issue was not a bug in msbuild, but a severe misconfiguration of the internal build environment causing incorrect framework assemblies.)
The fact that it's intermittent suggests to me that Dan is right and it's an unprotected Dictionary access (race condition). If some metadata.Name was actually null we'd see it reliably all the time.
Just locking around it would probably be expensive?
Hi, I'm blocked by this issue. May I know if there is any workaround here? Thanks!
I encountered this issue when I build our projects (starting from changing TFM to netcoreapp5.0). I got my first few builds run successfully. But after that, builds constantly failed on Linux and Mac for this issue. The first build: https://dev.azure.com/devdiv/DevDiv/_build/results?buildId=3219078&view=logs The failed build: https://dev.azure.com/devdiv/DevDiv/_build/results?buildId=3223655 https://dev.azure.com/devdiv/DevDiv/_build/results?buildId=3219861 https://dev.azure.com/devdiv/DevDiv/_build/results?buildId=3221751 All the failed builds have following error messages:
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.ArgumentException: An item with the same key has already been added. Key: TargetFrameworkVersion
at System.Collections.Generic.Dictionary`2.TryInsert(TKey key, TValue value, InsertionBehavior behavior)
at System.Collections.Generic.Dictionary`2.Add(TKey key, TValue value)
at Microsoft.DotNet.Tools.MSBuild.MSBuildLogger.FormatAndSend(ITelemetry telemetry, TelemetryEventArgs args) in /_/src/dotnet/commands/dotnet-msbuild/MSBuildLogger.cs:line 98
at Microsoft.DotNet.Tools.MSBuild.MSBuildLogger.OnTelemetryLogged(Object sender, TelemetryEventArgs args) in /_/src/dotnet/commands/dotnet-msbuild/MSBuildLogger.cs:line 114
at Microsoft.Build.BackEnd.Logging.EventSourceSink.RaiseTelemetryEvent(Object sender, TelemetryEventArgs 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.RaiseTelemetryEvent(Object sender, TelemetryEventArgs 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.DotNet.Tools.MSBuild.MSBuildForwardingLogger.<Initialize>b__16_0(Object sender, TelemetryEventArgs args) in /_/src/dotnet/commands/dotnet-msbuild/MSBuildForwardingLogger.cs:line 23
at Microsoft.Build.BackEnd.Logging.EventSourceSink.RaiseTelemetryEvent(Object sender, TelemetryEventArgs buildEvent)
@heng-liu your callstack is different, it looks like a bug in Microsoft.DotNet.Tools.MSBuild.MSBuildLogger.FormatAndSend
@wli3 another example of an issue with the MSBuildLogger.FormatAndSend. I tagged on on a different issue for this earlier today.
@heng-liu that is a separate issue. https://github.com/dotnet/sdk/issues/3868
Thanks all for your help!
Hello. Experiencing same issue while trying to compile cmake based project.
Using external cmake-3.19.1-win64-x64
install.
Here is the dotnet.exe --info
:
Version: 5.0.100
Commit: 5044b93829
Среда выполнения:
OS Name: Windows
OS Version: 10.0.18363
OS Platform: Windows
RID: win10-x64
Base Path: C:\Program Files\dotnet\sdk\5.0.100\
Host (useful for support):
Version: 5.0.0
Commit: cf258a14b7
.NET SDKs installed:
3.1.201 [C:\Program Files\dotnet\sdk]
5.0.100 [C:\Program Files\dotnet\sdk]
.NET runtimes installed:
Microsoft.AspNetCore.All 2.1.23 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
Microsoft.AspNetCore.App 2.1.23 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 3.1.3 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 3.1.9 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 5.0.0 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.NETCore.App 2.1.23 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 3.1.3 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 3.1.8 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 3.1.9 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 5.0.0 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.WindowsDesktop.App 3.1.3 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
Microsoft.WindowsDesktop.App 3.1.8 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
Microsoft.WindowsDesktop.App 3.1.9 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
Microsoft.WindowsDesktop.App 5.0.0 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
To install additional .NET runtimes or SDKs:
https://aka.ms/dotnet-download
Clean VS 2019 install.
Microsoft Visual Studio Community 2019
Version 16.8.2
VisualStudio.16.Release/16.8.2+30717.126
Microsoft .NET Framework
Version 4.8.03752
Installed Version: Community
Visual C++ 2019 00435-60000-00000-AA055
Microsoft Visual C++ 2019
ASP.NET and Web Tools 2019 16.8.553.28003
ASP.NET and Web Tools 2019
Azure App Service Tools v3.0.0 16.8.553.28003
Azure App Service Tools v3.0.0
C# Tools 3.8.0-5.20567.16+53c5d7d3cf13d88978744a32a27c5f8350a8400a
C# components used in the IDE. Depending on your project type and settings, a different version of the compiler may be used.
Common Azure Tools 1.10
Provides common services for use by Azure Mobile Services and Microsoft Azure Tools.
IntelliCode Extension 1.0
IntelliCode Visual Studio Extension Detailed Info
Microsoft JVM Debugger 1.0
Provides support for connecting the Visual Studio debugger to JDWP compatible Java Virtual Machines
Microsoft MI-Based Debugger 1.0
Provides support for connecting Visual Studio to MI compatible debuggers
Microsoft Visual C++ Wizards 1.0
Microsoft Visual C++ Wizards
Microsoft Visual Studio VC Package 1.0
Microsoft Visual Studio VC Package
NuGet Package Manager 5.8.0
NuGet Package Manager in Visual Studio. For more information about NuGet, visit https://docs.nuget.org/
ProjectServicesPackage Extension 1.0
ProjectServicesPackage Visual Studio Extension Detailed Info
Test Adapter for Boost.Test 1.0
Enables Visual Studio's testing tools with unit tests written for Boost.Test. The use terms and Third Party Notices are available in the extension installation directory.
Test Adapter for Google Test 1.0
Enables Visual Studio's testing tools with unit tests written for Google Test. The use terms and Third Party Notices are available in the extension installation directory.
Visual Basic Tools 3.8.0-5.20567.16+53c5d7d3cf13d88978744a32a27c5f8350a8400a
Visual Basic components used in the IDE. Depending on your project type and settings, a different version of the compiler may be used.
Visual F# Tools 16.8.0-beta.20507.4+da6be68280c89131cdba2045525b80890401defd
Microsoft Visual F# Tools
Visual Studio Code Debug Adapter Host Package 1.0
Interop layer for hosting Visual Studio Code debug adapters in Visual Studio
Visual Studio Tools for CMake 1.0
Visual Studio Tools for CMake
Hello,
We are having similar issue with MSBuild 17.1.0
(from VS 2022 17.1.2 installation) when using maximum CPU count, i.e. /m
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.NullReferenceException: Object reference not set to an instance of an object. at Microsoft.Build.BackEnd.Logging.ParallelConsoleLogger.WriteMessageAligned(String message, Boolean prefixAlreadyWritten, Int32 prefixAdjustment) at Microsoft.Build.BackEnd.Logging.ParallelConsoleLogger.PrintTargetNamePerMessage(BuildMessageEventArgs e, Boolean lightenText) at Microsoft.Build.BackEnd.Logging.ParallelConsoleLogger.PrintMessage(BuildMessageEventArgs e, Boolean lightenText) at Microsoft.Build.BackEnd.Logging.ParallelConsoleLogger.MessageHandler(Object sender, BuildMessageEventArgs e) at Microsoft.Build.Logging.ConsoleLogger.MessageHandler(Object sender, BuildMessageEventArgs e) at ColorLogger.ColorLogger.MessageHandler(Object sender, BuildMessageEventArgs e) in C:\Users\bouchraREKHADDA\source\repos\ColorLogger\ColorLogger.cs:line 140 at Microsoft.Build.Evaluation.ProjectCollection.ReusableLogger.MessageRaisedHandler(Object sender, BuildMessageEventArgs e) at Microsoft.Build.BackEnd.Logging.EventSourceSink.RaiseMessageEvent(Object sender, BuildMessageEventArgs 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.RaiseMessageEvent(Object sender, BuildMessageEventArgs 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)
A full reproduction repository can be found here bouchraRekhadda/ColorLogger
Any update please on the above request ? Thank you in advance.
In corefx build https://dnceng.visualstudio.com/internal/_build/results?buildId=79263 failed with this issue. The connected issue is : https://github.com/dotnet/core-eng/issues/5071 The issue seems to be similar to