search

ikvmnet / ikvm

A Java Virtual Machine and Bytecode-to-IL Converter for .NET
Other
1.15k stars 109 forks source link

Internal MSBuild errors #425

Closed danielcweber closed 8 months ago

danielcweber commented 9 months ago

We regularly encounter one or both of the below error messages during a build with MavenReferences.

Running dotnet test with --disable-parallel won't help.

The repo is private but I can grant access to the runs if needed.

Thanks a lot!

MSBUILD : error MSB1025: An internal failure occurred while running MSBuild.
Microsoft.Build.Framework.InternalErrorException: MSB0001: Internal MSBuild Error: Request 1040 expected to be in state Executing but state is actually Yielding
   at Microsoft.Build.Shared.ErrorUtilities.ThrowInternalError(String message, Object[] args)
   at Microsoft.Build.BackEnd.Scheduler.ReportResult(Int32 nodeId, BuildResult result)
   at Microsoft.Build.Execution.BuildManager.HandleResult(Int32 node, BuildResult result)
   at Microsoft.Build.Execution.BuildManager.ProcessPacket(Int32 node, INodePacket packet)
   at Microsoft.Build.Execution.BuildManager.ProcessWorkQueue(Action action)
--- End of stack trace from previous location ---
   at Microsoft.Build.Execution.BuildManager.EndBuild()
   at Microsoft.Build.CommandLine.MSBuildApp.BuildProject(String projectFile, String[] targets, String toolsVersion, Dictionary`2 globalProperties, Dictionary`2 restoreProperties, ILogger[] loggers, LoggerVerbosity verbosity, DistributedLoggerRecord[] distributedLoggerRecords, Int32 cpuCount, Boolean enableNodeReuse, TextWriter preprocessWriter, TextWriter targetsWriter, Boolean detailedSummary, ISet`1 warningsAsErrors, ISet`1 warningsNotAsErrors, ISet`1 warningsAsMessages, Boolean enableRestore, ProfilerLogger profilerLogger, Boolean enableProfiler, Boolean interactive, ProjectIsolationMode isolateProjects, GraphBuildOptions graphBuildOptions, Boolean lowPriority, Boolean question, String[] inputResultsCaches, String outputResultsCache, String[] commandLine)

MSBUILD : error MSB1025: An internal failure occurred while running MSBuild.
Unhandled exception: Microsoft.Build.Framework.InternalErrorException: MSB0001: Internal MSBuild Error: Request 1040 expected to be in state Executing but state is actually Yielding
   at Microsoft.Build.CommandLine.MSBuildApp.BuildProject(String projectFile, String[] targets, String toolsVersion, Dictionary`2 globalProperties, Dictionary`2 restoreProperties, ILogger[] loggers, LoggerVerbosity verbosity, DistributedLoggerRecord[] distributedLoggerRecords, Int32 cpuCount, Boolean enableNodeReuse, TextWriter preprocessWriter, TextWriter targetsWriter, Boolean detailedSummary, ISet`1 warningsAsErrors, ISet`1 warningsNotAsErrors, ISet`1 warningsAsMessages, Boolean enableRestore, ProfilerLogger profilerLogger, Boolean enableProfiler, Boolean interactive, ProjectIsolationMode isolateProjects, GraphBuildOptions graphBuildOptions, Boolean lowPriority, Boolean question, String[] inputResultsCaches, String outputResultsCache, String[] commandLine)
Microsoft.Build.Framework.InternalErrorException: MSB0001: Internal MSBuild Error: Request 1040 expected to be in state Executing but state is actually Yielding
   at Microsoft.Build.CommandLine.MSBuildApp.Execute(String[] commandLine)
   at Microsoft.Build.CommandLine.MSBuildApp.BuildProject(String projectFile, String[] targets, String toolsVersion, Dictionary`2 globalProperties, Dictionary`2 restoreProperties, ILogger[] loggers, LoggerVerbosity verbosity, DistributedLoggerRecord[] distributedLoggerRecords, Int32 cpuCount, Boolean enableNodeReuse, TextWriter preprocessWriter, TextWriter targetsWriter, Boolean detailedSummary, ISet`1 warningsAsErrors, ISet`1 warningsNotAsErrors, ISet`1 warningsAsMessages, Boolean enableRestore, ProfilerLogger profilerLogger, Boolean enableProfiler, Boolean interactive, ProjectIsolationMode isolateProjects, GraphBuildOptions graphBuildOptions, Boolean lowPriority, Boolean question, String[] inputResultsCaches, String outputResultsCache, String[] commandLine)
   at Microsoft.Build.CommandLine.MSBuildApp.Main(String[] args)
   at Microsoft.Build.CommandLine.MSBuildApp.Execute(String[] commandLine)
   at Microsoft.DotNet.Cli.Utils.MSBuildForwardingAppWithoutLogging.ExecuteInProc(String[] arguments)
danielcweber commented 9 months ago

This is from a different build:

Microsoft.Build.Framework.InternalErrorException: MSB0001: Internal MSBuild Error: Must be in Active state to wait for blocking request.  Config: 264 State: Complete
   at Microsoft.Build.Shared.ErrorUtilities.ThrowInternalError(String message, Object[] args)
   at Microsoft.Build.BackEnd.BuildRequestEntry.WaitForBlockingRequest(Int32 blockingGlobalRequestId)
   at Microsoft.Build.BackEnd.BuildRequestEngine.IssueUnsubmittedRequests()
   at Microsoft.Build.BackEnd.BuildRequestEngine.<>c__DisplayClass64_0.<Builder_OnBlockedRequest>b__0()
   at Microsoft.Build.BackEnd.BuildRequestEngine.<>c__DisplayClass72_0.<QueueAction>b__0()

)
 ---> Microsoft.Build.Framework.InternalErrorException: MSB0001: Internal MSBuild Error: MSB0001: Internal MSBuild Error: Must be in Active state to wait for blocking request.  Config: 264 State: Complete
=============
Microsoft.Build.Framework.InternalErrorException: MSB0001: Internal MSBuild Error: Must be in Active state to wait for blocking request.  Config: 264 State: Complete
   at Microsoft.Build.Shared.ErrorUtilities.ThrowInternalError(String message, Object[] args)
   at Microsoft.Build.BackEnd.BuildRequestEntry.WaitForBlockingRequest(Int32 blockingGlobalRequestId)
   at Microsoft.Build.BackEnd.BuildRequestEngine.IssueUnsubmittedRequests()
   at Microsoft.Build.BackEnd.BuildRequestEngine.<>c__DisplayClass64_0.<Builder_OnBlockedRequest>b__0()
   at Microsoft.Build.BackEnd.BuildRequestEngine.<>c__DisplayClass72_0.<QueueAction>b__0()

 ---> Microsoft.Build.Framework.InternalErrorException: MSB0001: Internal MSBuild Error: Must be in Active state to wait for blocking request.  Config: 264 State: Complete
   at Microsoft.Build.Shared.ErrorUtilities.ThrowInternalError(String message, Object[] args)
   at Microsoft.Build.BackEnd.BuildRequestEntry.WaitForBlockingRequest(Int32 blockingGlobalRequestId)
   at Microsoft.Build.BackEnd.BuildRequestEngine.IssueUnsubmittedRequests()
   at Microsoft.Build.BackEnd.BuildRequestEngine.<>c__DisplayClass64_0.<Builder_OnBlockedRequest>b__0()
   at Microsoft.Build.BackEnd.BuildRequestEngine.<>c__DisplayClass72_0.<QueueAction>b__0()
   --- End of inner exception stack trace ---
   at Microsoft.Build.Shared.ErrorUtilities.ThrowInternalError(String message, Exception innerException, Object[] args)
   at Microsoft.Build.BackEnd.BuildRequestEngine.<>c__DisplayClass72_0.<QueueAction>b__0()
   at System.Threading.Tasks.Dataflow.ActionBlock`1.ProcessMessage(Action`1 action, KeyValuePair`2 messageWithId)
   at System.Threading.Tasks.Dataflow.Internal.TargetCore`1.ProcessMessagesLoopCore()
   --- End of inner exception stack trace ---
   at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
   at System.Threading.Tasks.Task.Wait(Int32 millisecondsTimeout, CancellationToken cancellationToken)
   at System.Threading.Tasks.Task.Wait()
   at Microsoft.Build.BackEnd.BuildRequestEngine.CleanupForBuild()
   at Microsoft.Build.Execution.OutOfProcNode.HandleShutdown(ExceptC:\Users\runneradmin\.nuget\packages\ikvm\8.6.4\buildTransitive\IKVM.Tasks.targets(33,9): warning : warning IKVMC0100: Class "io.netty.util.collection.IntObjectMap" not found [D:\a\Gremlinq.Extensions\Gremlinq.Extensions\src\Providers.TinkerGraph\Gremlinq.ion& exception)
   at Microsoft.Build.Execution.OutOfProcNode.Run(Boolean enableReuse, Boolean lowPriority, Exception& shutdownException)
   at Microsoft.Build.CommandLine.MSBuildApp.StartLocalNode(CommandLineSwitches commandLineSwitches, Boolean lowprioExtensions.Providers.TinkerGraph.csproj::TargetFramework=net6.0]
rity)
   at Microsoft.Build.CommandLine.MSBuildApp.ProcessCommandLineSwitches(CommandLineSwitches switchesFromAutoResponseFile, CommandLineSwitches switchesNotFromAutoResponseFile, String& projectFile, String[]& targets, String& toolsVersion, Dictionary`2& globalProperties, ILogger[]& loggers, LoggerVerbosity& verbosity, LoggerVerbosity& originalVerbosity, List`1& distributedLoggerRecords, Int32& cpuCount, Boolean& enableNodeReuse, TextWriter& preprocessWriter, TextWriter& targetsWriter, Boolean& detailedSummary, ISet`1& warningsAsErrors, ISet`1& warningsNotAsErrors, ISet`1& warningsAsMessages, Boolean& enableRestore, Boolean& interactive, ProfilerLogger& profilerLogger, Boolean& enableProfiler, Dictionary`2& restoreProperties, ProjectIsolationMode& isolateProjects, GraphBuildOptions& graphBuild, String[]& inputResultsCaches, String& outputResultsCache, Boolean& lowPriority, Boolean& question, Boolean recursing, String commandLine)
   at Microsoft.Build.CommandLine.MSBuildApp.Execute(String[] commandLine)
danielcweber commented 9 months ago

It seems to work if I restrict the multi-target build to .NET7 7.0 only, though I don't know if it's an issue of .NET 5.0 or 6.0, or if that only makes parallelism go away.

wasabii commented 9 months ago

Should be fixed in 8.7.0-dev.531 in internal NuGet today. Building for prerelease right now.

danielcweber commented 8 months ago

Unfortunately, we're still getting errors on a Windows CI build, though they might not even be related to the original issue described here.

C:\Users\runneradmin\.nuget\packages\ikvm\8.7.0-pre.1\buildTransitive\IKVM.Tasks.targets(31,9): error MSB4018: The "IkvmCompiler" task failed unexpectedly.
C:\Users\runneradmin\.nuget\packages\ikvm\8.7.0-pre.1\buildTransitive\IKVM.Tasks.targets(31,9): error MSB4018: System.ArgumentException: Process with an Id of 4528 is not running.
C:\Users\runneradmin\.nuget\packages\ikvm\8.7.0-pre.1\buildTransitive\IKVM.Tasks.targets(31,9): error MSB4018:    at System.Diagnostics.Process.GetProcessById(Int32 processId, String machineName)
C:\Users\runneradmin\.nuget\packages\ikvm\8.7.0-pre.1\buildTransitive\IKVM.Tasks.targets(31,9): error MSB4018:    at IKVM.Tools.Runner.Importer.IkvmImporterLauncher.ExecuteAsync(IkvmImporterOptions options, CancellationToken cancellationToken) in /_/src/IKVM.Tools.Runner/Importer/IkvmImporterLauncher.cs:line 335
C:\Users\runneradmin\.nuget\packages\ikvm\8.7.0-pre.1\buildTransitive\IKVM.Tasks.targets(31,9): error MSB4018:    at IKVM.MSBuild.Tasks.IkvmCompiler.ExecuteAsync(IkvmToolTaskDiagnosticWriter writer, CancellationToken cancellationToken) in /_/src/IKVM.MSBuild.Tasks/IkvmCompiler.cs:line 27
C:\Users\runneradmin\.nuget\packages\ikvm\8.7.0-pre.1\buildTransitive\IKVM.Tasks.targets(31,9): error MSB4018:    at IKVM.MSBuild.Tasks.IkvmToolExecTask.Execute() in /_/src/IKVM.MSBuild.Tasks/IkvmToolExecTask.cs:line 105
C:\Users\runneradmin\.nuget\packages\ikvm\8.7.0-pre.1\buildTransitive\IKVM.Tasks.targets(31,9): error MSB4018:    at Microsoft.Build.BackEnd.TaskExecutionHost.Microsoft.Build.BackEnd.ITaskExecutionHost.Execute()
C:\Users\runneradmin\.nuget\packages\ikvm\8.7.0-pre.1\buildTransitive\IKVM.Tasks.targets(31,9): error MSB4018:    at Microsoft.Build.BackEnd.TaskBuilder.ExecuteInstantiatedTask(ITaskExecutionHost taskExecutionHost, TaskLoggingContext taskLoggingContext, TaskHost taskHost, ItemBucket bucket, TaskExecutionMode howToExecuteTask)
wasabii commented 8 months ago

That's the real error. The first one you posted was an error dealing with the error, so it was masking the real underlying cause.

So, what's happening here is still a bit unclear. It's trying to run ikvmc.exe. And that process is exiting unexpectidly, and quickly. So, when it tries to attach to it, it fails to attach (since it exited before attach). Making a new change that deals with that. This next change will probably still fail for you, but it should fail later, at least getting to the exit code of ikvmc.exe.

I am surprised you aren't seeing output from ikvmc.exe. It should be trapping it's output and showing it as MSBuild messages. Is there any build output you're seeing right now related to ikvmc.exe, but before the exception you are showing?

If there aren't, it makes me think your build server might have some policy set up to prevent executing executables within a NuGet package? Is that possible?

danielcweber commented 8 months ago

I'm afraid there is no other output related to ikvmc, except for lots of IKVMC0100 warnings.

Observations so far:

So there's maybe two instances of ikvmc.exe running which interfere?

I'll update this thread as I make more observations.

danielcweber commented 8 months ago

Update: On Windows, a single target build succeeds, but then the tests fail. Does the latest preview need another explicit NuGet dependency?

Edit: Again, Linux is just fine.

2023-10-13T17:50:30.0649853Z ----- Inner Stack Trace -----
2023-10-13T17:50:30.0650021Z    at java.lang.Object..ctor()
2023-10-13T17:50:30.0650190Z    at java.lang.Class..ctor(Type type)
2023-10-13T17:50:30.0650536Z    at __<MethodAccessor>__Class__.ctor(Type)
2023-10-13T17:50:30.0650931Z    at IKVM.Runtime.Accessors.Java.Lang.ClassAccessor.Init(Type type)
2023-10-13T17:50:30.0651125Z    at IKVM.Runtime.ClassLiteral`1.GetValue()
2023-10-13T17:50:30.0651318Z    at IKVM.Runtime.ClassLiteral`1.get_Value()
2023-10-13T17:50:30.0651640Z    at InvokeStub_ClassLiteral`1.get_Value(Object, Object, IntPtr*)
2023-10-13T17:50:30.0652189Z    at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr)
2023-10-13T17:50:30.0652354Z ----- Inner Stack Trace -----
2023-10-13T17:50:30.0652552Z    at java.io.FileInputStream.__<clinit>()
2023-10-13T17:50:30.0652771Z    at java.lang.System.initializeSystemClass()
2023-10-13T17:50:30.0653031Z    at __<MethodAccessor>__System__initializeSystemClass()
2023-10-13T17:50:30.0653586Z    at IKVM.Runtime.Accessors.Java.Lang.SystemAccessor.InvokeInitializeSystemClass()
2023-10-13T17:50:30.0653779Z    at IKVM.Runtime.JVM.EnsureInitialized()
2023-10-13T17:50:30.0653948Z    at java.lang.Object..cctor()
2023-10-13T17:50:30.0654102Z ----- Inner Stack Trace -----
2023-10-13T17:50:30.0654470Z    at IKVM.Runtime.BootstrapClassLoader..ctor(RuntimeContext context)
2023-10-13T17:50:30.0654908Z    at IKVM.Runtime.RuntimeClassLoaderFactory.GetBootstrapClassLoader()
2023-10-13T17:50:30.0655568Z    at IKVM.Runtime.RuntimeClassLoaderFactory.GetClassLoaderWrapper(ClassLoader javaClassLoader)
2023-10-13T17:50:30.0656030Z    at IKVM.Runtime.RuntimeClassLoader.FromCallerID(CallerID callerID)
2023-10-13T17:50:30.0656626Z    at IKVM.Runtime.JNI.JNIFrame.GetFuncPtr(CallerID callerID, String clazz, String name, String sig)
2023-10-13T17:50:30.0656805Z    at java.io.FileInputStream.initIDs()
2023-10-13T17:50:30.0656991Z    at java.io.FileInputStream..cctor()
2023-10-13T17:50:30.0657149Z ----- Inner Stack Trace -----
2023-10-13T17:50:30.0657411Z    at IKVM.Runtime.LibJava..ctor()
2023-10-13T17:50:30.0657598Z    at IKVM.Runtime.LibJava..cctor()
2023-10-13T17:50:30.0658356Z   Failed Gremlinq.Extensions.Providers.TinkerGraph.Tests.ExecutionTests.Where_property_lower_than_string_3 [< 1 ms]
2023-10-13T17:50:30.0658477Z   Error Message:
2023-10-13T17:50:30.0659163Z    System.AggregateException : One or more errors occurred. (Exception has been thrown by the target of an invocation.)
2023-10-13T17:50:30.0659864Z ---- System.Reflection.TargetInvocationException : Exception has been thrown by the target of an invocation.
2023-10-13T17:50:30.0660538Z -------- System.TypeInitializationException : The type initializer for 'java.lang.Object' threw an exception.
2023-10-13T17:50:30.0661291Z ------------ System.TypeInitializationException : The type initializer for 'java.io.FileInputStream' threw an exception.
2023-10-13T17:50:30.0662013Z ---------------- System.TypeInitializationException : The type initializer for 'IKVM.Runtime.LibJava' threw an exception.
2023-10-13T17:50:30.0662424Z -------------------- IKVM.Runtime.InternalException : Could not load libjava.
wasabii commented 8 months ago

IKVMC0100

That's what I mean. What are those?

On Windows, a single target build succeeds, but then the tests fail. Does the latest preview need another explicit NuGet dependency?

This seems like a distinct issue.

Next to IKVM.Runtime in your produced project output, do you have an ikvm/ directory, and ikvm.properties file? Inside the ikvm/ directory should be a number of platform names. You're running this on Windows, assuming x64, so win-x64/ should exist. And within that should be bin/iava.dll?

danielcweber commented 8 months ago

That's what I mean. What are those?

I set up a repro project, but I can't yet get it to fail. The IKVMC0100 messages are pretty much the same as on my failing build.

I'll keep trying to make the minimal repro fail.

You're running this on Windows, assuming x64, so win-x64/ should exist. And within that should be bin/iava.dll?

Yes, it's all there.

danielcweber commented 8 months ago

I ran a diagnostic dotnet build/test, but 1GB of text just yields

The "Microsoft.TestPlatform.Build.Tasks.VSTestTask" task returned false but did not log an error..

In the end, I think it's just a memory limitation that keeps ikvmc.exe from executing that often (it executes 165 times during the build/test).

The Could not load libjava persists even locally but I'm not blocked, the current stable is just fine.

Thanks a lot for you effort. If I can provide any further insights, please let me know.

wasabii commented 8 months ago

So one of the thing I noticed with the repro project is numerous messages about missing classes. I suspect these aren't related to the issue you're hitting, but things you'll run into later. It looks like a number of libraries you're using have underspecified dependencies in Maven, and a number of dependencies marked optional you might actually require. But, that's a different topic.

I still cannot reproduce your issue.

Yes, ikvmc will run once per jar file to convert. Looks like the references you're pulling in include about 60 dependencies. And you're building for both net6 and net7, so that's 120 total runs. But, they're not going to run at the same time. It's one after the other. So, unless you have some massive memory limitation, I don't know. Have you been able to obtain an error message that makes you think this is memory related?

The could not load libjava message, still no clue on.

danielcweber commented 8 months ago

I'll keep trying to reduce my full project to the most minimal version that'll still fail. Hopefully it'll yield some insights. Might take a while though. Thanks for keeping up!

danielcweber commented 8 months ago

I was unable to pinpoint it to a single cause, the more I take away from the full project the more flaky the build becomes, but there's only one thing that seems to fix it for good: use

dotnet build
dotnet test --no-build

instead of just

dotnet test

I don't know if dotnet test by itself introduces any parallelism in building, or whether it starts testing while building, or whether doing all at once is just too memory intensive for a GitHub actions hosted runner, but it seems to do the trick.

wasabii commented 8 months ago

Have you actually received an OutOfMemoryException or some other indication that memory is the issue? With the latest version, you should at least be able to get some sort of output on failure. Even the exit code of ikvmc.exe might help.

danielcweber commented 8 months ago

I created a gist with the windows portion of a GitHub actions run. I can't spot any actual messages about an exit code of a prematurely terminated ikvmc.exe.

It's run with IKVM 8.6.4. Newer previews seem to build and start the tests which all fail with the above mentioned "Could not load libjava.".

wasabii commented 8 months ago

The link you posted is the same issue described initially, which we already fixed in the prerelease. But since you're not using the prerelease version, you're back at that same problem.

danielcweber commented 8 months ago

Got it. With the latest preview, we get a failing MsBuild when multi-targeting and .NET 5 is one of the targets. IKVM requires at least .NET 6. So I think this is solved. I can deal with the missing libjava on Windows later. Thanks for bearing with me.

Could you include a runtime check and output a clear message about the wrong runtime? There's only a single hint in the build output:

C:\Users\runneradmin\.nuget\packages\ikvm.msbuild\8.7.0-pre.1\buildTransitive\IKVM.MSBuild.targets(44,9): error : Could not locate IKVM.Runtime.dll.

Apart from that, there's nothing that hints at the package incompatibility. I'm not sure whether dotnet restore should already fail or how these things are usually handled.

wasabii commented 8 months ago

Hmm. Will check on that. Restore is supposed to warn but let you try anyways in my understanding.