Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Bug]: MSB4242: SDK Resolver Failure due to System.Threading.AbandonedMutexException #12159

Closed
kartheekp-ms opened this issue Oct 13, 2022 · 19 comments · Fixed by NuGet/NuGet.Client#4859
Assignees
Labels
Functionality:Restore Priority:1 High priority issues that must be resolved in the current sprint. Product:dotnet.exe Type:Bug
Milestone

Comments

@kartheekp-ms
Copy link
Contributor

kartheekp-ms commented Oct 13, 2022

NuGet Product Used

dotnet.exe

Product Version

SDK 6.0.402

Worked before?

No response

Impact

I'm unable to use this version

Repro Steps & Context

Tracking issue for dotnet/sdk#28488. Essentially, this issue can be hit if solution has multiple projects trying to download custom SDKs using NuGet resolver functionality.

Verbose Logs

No response

@kartheekp-ms kartheekp-ms added Priority:1 High priority issues that must be resolved in the current sprint. Type:Bug Functionality:Restore Product:dotnet.exe labels Oct 13, 2022
@kartheekp-ms kartheekp-ms self-assigned this Oct 13, 2022
@kartheekp-ms
Copy link
Contributor Author

@kartheekp-ms
Copy link
Contributor Author

kartheekp-ms commented Oct 14, 2022

Sorry for the inconvenience caused by this bug. For folks who are hitting this issue, as a workaround, would it be possible to execute dotnet nuget --version command before running the restore. In that way we don't hit the race condition that is causing these failures intermittently.

alexrp added a commit to vezel-dev/cathode that referenced this issue Oct 15, 2022
alexrp added a commit to vezel-dev/celerity that referenced this issue Oct 15, 2022
alexrp added a commit to vezel-dev/zig-sdk that referenced this issue Oct 15, 2022
@alexrp
Copy link

alexrp commented Oct 16, 2022

I just ran into another failure that seems like it could be related (this is with the aforementioned workaround applied): https://github.com/vezel-dev/niru/actions/runs/3260762897/jobs/5354602659#step:4:15

Package "sourcelink" failed to restore, due to Microsoft.DotNet.ToolPackage.ToolPackageException: The tool package could not be restored.
   at Microsoft.DotNet.Tools.Tool.Install.ProjectRestorer.Restore(FilePath project, PackageLocation packageLocation, String verbosity)
   at Microsoft.DotNet.ToolPackage.ToolPackageInstaller.InstallPackageToExternalManagedLocation(PackageLocation packageLocation, PackageId packageId, VersionRange versionRange, String targetFramework, String verbosity)
   at Microsoft.DotNet.Tools.Tool.Restore.ToolRestoreCommand.InstallPackages(ToolManifestPackage package, Nullable`1 configFile)

This one seems rare - it's the first time I've seen it since applying the workaround and it didn't happen on a subsequent run.

@breidikl
Copy link

The workaround has been working in our environment so far, thanks.

@VemundH
Copy link

VemundH commented Oct 18, 2022

I initially reported here: https://developercommunity.visualstudio.com/t/NuGet---race-condition-NuGetCommonMigr/10175710
Looks like the same issue

@cliffchapmanrbx
Copy link

Thanks for getting this fixed! Our team just ran into it as well. Is there a good place to set up a notification for when this ships? Or a particular dotnet SDK version it'll end up in we can watch out for?

@kartheekp-ms
Copy link
Contributor Author

kartheekp-ms commented Nov 9, 2022

As far as I know, customers can hit this bug only if they have multiple projects trying to download custom SDKs using NuGet resolver functionality.

@cliffchapmanrbx
Copy link

As far as I know, customers can hit this bug only if they have multiple projects trying to download custom SDKs using NuGet resolver functionality.

Yes, we have multiple projects trying to download custom SDKs using NuGet.

@kartheekp-ms
Copy link
Contributor Author

kartheekp-ms commented Nov 16, 2022

@breidikl @cliffchapmanrbx @alexrp @VemundH @brunolins16 - sorry for the direct ping. This issue is fixed in preview versions of .NET 8. Would it be possible to install preview versions of .NET 8 & check whether the restore succeeds or not? Thanks for your help in advance.
https://github.com/dotnet/installer/blob/main/README.md#table

@cliffchapmanrbx
Copy link

Thank you for the information!

Our current automation harness makes it a little difficult to test this in-situ, I will see if we can construct an isolated environment to test it.

@brunolins16
Copy link

@kartheekp-ms Is that issue fixed in .NET 7 as well?

@kartheekp-ms
Copy link
Contributor Author

Is that issue fixed in .NET 7 as well?

@brunolins16 - Not yet. The fix is currently in .NET 8 preview versions. Hence asking the community to help us to validate the fix by installing .NET 8 preview version.

@kartheekp-ms
Copy link
Contributor Author

kartheekp-ms commented Nov 19, 2022

NuGet's CI build also failed with this error message while running cross verification tests job.

Run Cross Verify Tests (stop on error)

View raw log

Starting: Run Cross Verify Tests (stop on error)
==============================================================================
Task         : PowerShell
Description  : Run a PowerShell script
Version      : 1.2.3
Author       : Microsoft Corporation
Help         : [More Information](https://go.microsoft.com/fwlink/?LinkID=613736)
==============================================================================
. 'C:\Users\VssAdministrator\AppData\Local\Temp\081d613b-729c-4cc0-860e-a8b23716ad52.ps1' 
  Determining projects to restore...
##[error]Unhandled exception. System.Threading.AbandonedMutexException: The wait completed due to an abandoned mutex.
   at System.Threading.WaitHandle.WaitOneNoCheck(Int32 millisecondsTimeout)
   at System.Threading.WaitHandle.WaitOne(TimeSpan timeout, Boolean exitContext)
   at NuGet.Common.Migrations.MigrationRunner.Run()
   at NuGet.CommandLine.XPlat.Program.MainInternal(String[] args, CommandOutputLogger log)
   at NuGet.CommandLine.XPlat.Program.Main(String[] args)

image

@kartheekp-ms
Copy link
Contributor Author

kartheekp-ms commented Nov 22, 2022

Another NuGet's CI build also failed with this error message while running cross verify tests job.

Run Cross Verify Tests (stop on error)

[View raw log](https://devdiv.visualstudio.com/0bdbc590-a062-4c3f-b0f6-9383f67865ee/_apis/build/builds/6997210/logs/133)

Starting: Run Cross Verify Tests (stop on error)
==============================================================================
Task         : PowerShell
Description  : Run a PowerShell script
Version      : 1.2.3
Author       : Microsoft Corporation
Help         : [More Information](https://go.microsoft.com/fwlink/?LinkID=613736)
==============================================================================
. 'C:\Users\VssAdministrator\AppData\Local\Temp\04ff27a5-dc15-4dc5-a390-16aad32157d0.ps1' 
  Determining projects to restore...
##[error]Unhandled exception. System.Threading.AbandonedMutexException: The wait completed due to an abandoned mutex.
   at System.Threading.WaitHandle.WaitOneNoCheck(Int32 millisecondsTimeout)
   at System.Threading.WaitHandle.WaitOne(TimeSpan timeout, Boolean exitContext)
   at NuGet.Common.Migrations.MigrationRunner.Run()
   at NuGet.CommandLine.XPlat.Program.MainInternal(String[] args, CommandOutputLogger log)
   at NuGet.CommandLine.XPlat.Program.Main(String[] args)
Unhandled exception. System.Threading.AbandonedMutexException: The wait completed due to an abandoned mutex.
   at System.Threading.WaitHandle.WaitOneNoCheck(Int32 millisecondsTimeout)
   at System.Threading.WaitHandle.WaitOne(TimeSpan timeout, Boolean exitContext)
   at NuGet.Common.Migrations.MigrationRunner.Run()
   at NuGet.CommandLine.XPlat.Program.MainInternal(String[] args, CommandOutputLogger log)
   at NuGet.CommandLine.XPlat.Program.Main(String[] args)

cc @dominoFire

@kartheekp-ms
Copy link
Contributor Author

Another NuGet's CI build failed with the same error message. cc @erdembayar

image

@brunolins16
Copy link

@kartheekp-ms we are getting different errors during the migrations. Do you think it is related?

Pipeline:
https://dev.azure.com/dnceng-public/public/_build/results?buildId=102152&view=logs&j=b72e85ab-3386-5aa9-6405-3837662d9688&t=5d75deca-26a1-543d-80c0-3108c555a3cb
PR: https://github.com/dotnet/aspnetcore/pull/45461/checks?check_run_id=9898841275

2022-12-05T18:42:53.1844981Z   Determining projects to restore...
2022-12-05T18:42:55.3973271Z �[39;49m�[31m/mnt/vss/_work/1/s/.dotnet/sdk/8.0.100-alpha.1.22531.1/NuGet.targets(132,5): error MSB4018: The "RestoreTask" task failed unexpectedly. [/tmp/88fd2929-aece-48eb-9b51-32ecd3394fd9/restore.csproj] [/mnt/vss/_work/1/s/.packages/microsoft.dotnet.arcade.sdk/8.0.0-beta.22575.1/tools/Tools.proj]
2022-12-05T18:42:55.4229281Z ##[error].dotnet/sdk/8.0.100-alpha.1.22531.1/NuGet.targets(132,5): error MSB4018: (NETCORE_ENGINEERING_TELEMETRY=Restore) The "RestoreTask" task failed unexpectedly. [/tmp/88fd2929-aece-48eb-9b51-32ecd3394fd9/restore.csproj]
2022-12-05T18:42:55.4249527Z �[39;49m�[31m/mnt/vss/_work/1/s/.dotnet/sdk/8.0.100-alpha.1.22531.1/NuGet.targets(132,5): error MSB4018: System.IO.IOException: The system cannot open the device or file specified. : 'NuGet-Migrations' [/tmp/88fd2929-aece-48eb-9b51-32ecd3394fd9/restore.csproj] [/mnt/vss/_work/1/s/.packages/microsoft.dotnet.arcade.sdk/8.0.0-beta.22575.1/tools/Tools.proj]
2022-12-05T18:42:55.4258516Z ##[error].dotnet/sdk/8.0.100-alpha.1.22531.1/NuGet.targets(132,5): error MSB4018: (NETCORE_ENGINEERING_TELEMETRY=Restore) System.IO.IOException: The system cannot open the device or file specified. : 'NuGet-Migrations' [/tmp/88fd2929-aece-48eb-9b51-32ecd3394fd9/restore.csproj]
2022-12-05T18:42:55.4264481Z �[39;49m�[31m/mnt/vss/_work/1/s/.dotnet/sdk/8.0.100-alpha.1.22531.1/NuGet.targets(132,5): error MSB4018: at System.Threading.Mutex.CreateMutexCore(Boolean initiallyOwned, String name, Boolean& createdNew) [/tmp/88fd2929-aece-48eb-9b51-32ecd3394fd9/restore.csproj] [/mnt/vss/_work/1/s/.packages/microsoft.dotnet.arcade.sdk/8.0.0-beta.22575.1/tools/Tools.proj]
2022-12-05T18:42:55.4275185Z ##[error].dotnet/sdk/8.0.100-alpha.1.22531.1/NuGet.targets(132,5): error MSB4018: (NETCORE_ENGINEERING_TELEMETRY=Restore) at System.Threading.Mutex.CreateMutexCore(Boolean initiallyOwned, String name, Boolean& createdNew) [/tmp/88fd2929-aece-48eb-9b51-32ecd3394fd9/restore.csproj]
2022-12-05T18:42:55.4279966Z �[39;49m�[31m/mnt/vss/_work/1/s/.dotnet/sdk/8.0.100-alpha.1.22531.1/NuGet.targets(132,5): error MSB4018: at System.Threading.Mutex..ctor(Boolean initiallyOwned, String name) [/tmp/88fd2929-aece-48eb-9b51-32ecd3394fd9/restore.csproj] [/mnt/vss/_work/1/s/.packages/microsoft.dotnet.arcade.sdk/8.0.0-beta.22575.1/tools/Tools.proj]
2022-12-05T18:42:55.4287482Z ##[error].dotnet/sdk/8.0.100-alpha.1.22531.1/NuGet.targets(132,5): error MSB4018: (NETCORE_ENGINEERING_TELEMETRY=Restore) at System.Threading.Mutex..ctor(Boolean initiallyOwned, String name) [/tmp/88fd2929-aece-48eb-9b51-32ecd3394fd9/restore.csproj]
2022-12-05T18:42:55.4294697Z �[39;49m�[31m/mnt/vss/_work/1/s/.dotnet/sdk/8.0.100-alpha.1.22531.1/NuGet.targets(132,5): error MSB4018: at NuGet.Common.Migrations.MigrationRunner.Run() [/tmp/88fd2929-aece-48eb-9b51-32ecd3394fd9/restore.csproj] [/mnt/vss/_work/1/s/.packages/microsoft.dotnet.arcade.sdk/8.0.0-beta.22575.1/tools/Tools.proj]
2022-12-05T18:42:55.4301739Z ##[error].dotnet/sdk/8.0.100-alpha.1.22531.1/NuGet.targets(132,5): error MSB4018: (NETCORE_ENGINEERING_TELEMETRY=Restore) at NuGet.Common.Migrations.MigrationRunner.Run() [/tmp/88fd2929-aece-48eb-9b51-32ecd3394fd9/restore.csproj]
2022-12-05T18:42:55.4306707Z �[39;49m�[31m/mnt/vss/_work/1/s/.dotnet/sdk/8.0.100-alpha.1.22531.1/NuGet.targets(132,5): error MSB4018: at NuGet.Build.Tasks.RestoreTask.Execute() [/tmp/88fd2929-aece-48eb-9b51-32ecd3394fd9/restore.csproj] [/mnt/vss/_work/1/s/.packages/microsoft.dotnet.arcade.sdk/8.0.0-beta.22575.1/tools/Tools.proj]
2022-12-05T18:42:55.4314752Z ##[error].dotnet/sdk/8.0.100-alpha.1.22531.1/NuGet.targets(132,5): error MSB4018: (NETCORE_ENGINEERING_TELEMETRY=Restore) at NuGet.Build.Tasks.RestoreTask.Execute() [/tmp/88fd2929-aece-48eb-9b51-32ecd3394fd9/restore.csproj]
2022-12-05T18:42:55.4319646Z �[39;49m�[31m/mnt/vss/_work/1/s/.dotnet/sdk/8.0.100-alpha.1.22531.1/NuGet.targets(132,5): error MSB4018: at Microsoft.Build.BackEnd.TaskExecutionHost.Microsoft.Build.BackEnd.ITaskExecutionHost.Execute() [/tmp/88fd2929-aece-48eb-9b51-32ecd3394fd9/restore.csproj] [/mnt/vss/_work/1/s/.packages/microsoft.dotnet.arcade.sdk/8.0.0-beta.22575.1/tools/Tools.proj]
2022-12-05T18:42:55.4327412Z ##[error].dotnet/sdk/8.0.100-alpha.1.22531.1/NuGet.targets(132,5): error MSB4018: (NETCORE_ENGINEERING_TELEMETRY=Restore) at Microsoft.Build.BackEnd.TaskExecutionHost.Microsoft.Build.BackEnd.ITaskExecutionHost.Execute() [/tmp/88fd2929-aece-48eb-9b51-32ecd3394fd9/restore.csproj]
2022-12-05T18:42:55.4333214Z �[39;49m�[31m/mnt/vss/_work/1/s/.dotnet/sdk/8.0.100-alpha.1.22531.1/NuGet.targets(132,5): error MSB4018: at Microsoft.Build.BackEnd.TaskBuilder.ExecuteInstantiatedTask(ITaskExecutionHost taskExecutionHost, TaskLoggingContext taskLoggingContext, TaskHost taskHost, ItemBucket bucket, TaskExecutionMode howToExecuteTask) [/tmp/88fd2929-aece-48eb-9b51-32ecd3394fd9/restore.csproj] [/mnt/vss/_work/1/s/.packages/microsoft.dotnet.arcade.sdk/8.0.0-beta.22575.1/tools/Tools.proj]
2022-12-05T18:42:55.4343392Z ##[error].dotnet/sdk/8.0.100-alpha.1.22531.1/NuGet.targets(132,5): error MSB4018: (NETCORE_ENGINEERING_TELEMETRY=Restore) at Microsoft.Build.BackEnd.TaskBuilder.ExecuteInstantiatedTask(ITaskExecutionHost taskExecutionHost, TaskLoggingContext taskLoggingContext, TaskHost taskHost, ItemBucket bucket, TaskExecutionMode howToExecuteTask) [/tmp/88fd2929-aece-48eb-9b51-32ecd3394fd9/restore.csproj]
2022-12-05T18:42:56.3098031Z   
2022-12-05T18:42:56.3127467Z   Package "dotnet-serve" failed to restore, due to Microsoft.DotNet.ToolPackage.ToolPackageException: The tool package could not be restored.
2022-12-05T18:42:56.3129341Z      at Microsoft.DotNet.Tools.Tool.Install.ProjectRestorer.Restore(FilePath project, PackageLocation packageLocation, String verbosity)
2022-12-05T18:42:56.3131966Z      at Microsoft.DotNet.ToolPackage.ToolPackageInstaller.InstallPackageToExternalManagedLocation(PackageLocation packageLocation, PackageId packageId, VersionRange versionRange, String targetFramework, String verbosity)
2022-12-05T18:42:56.3134155Z      at Microsoft.DotNet.Tools.Tool.Restore.ToolRestoreCommand.InstallPackages(ToolManifestPackage package, Nullable`1 configFile)
2022-12-05T18:42:56.3141284Z   
2022-12-05T18:42:56.3142951Z   Tool 'dotnet-dump' (version '6.0.322601') was restored. Available commands: dotnet-dump
2022-12-05T18:42:56.3144776Z   Tool 'dotnet-ef' (version '8.0.0-alpha.1.22605.6') was restored. Available commands: dotnet-ef
2022-12-05T18:42:56.3146492Z   Tool 'microsoft.playwright.cli' (version '1.2.3') was restored. Available commands: playwright

@kartheekp-ms
Copy link
Contributor Author

@brunolins16 - A similar was issue reported in dotnet/runtime#78062 (comment). May be this error has the same root cause mentioned in dotnet/runtime#36823 which was created as a follow-up for PowerShell/PSReadLine#1464.

@nikolaidk
Copy link

nikolaidk commented Jan 20, 2023

Got the same error in devops pipeline. Error seems related, in my case, to 'tools' that comes with 'ubuntu-latest' image :

No error running:
MSBuild version 17.4.0+18d5aef85 for .NET

Fails when running:
MSBuild version 17.4.1+9a89d02ff for .NET

FIX in my situation. Changed from ubuntu-latest to ubuntu-20.04 and installed net6.0 and net7.0 in seperate steps:
....
vmImage: 'ubuntu-20.04'
....

  • task: UseDotNet@2
    condition: true
    displayName: Use .NET 6.0
    inputs:
    packageType: 'sdk'
    version: '6.0.x'
  • task: UseDotNet@2
    condition: true
    displayName: Use .NET 7.0
    inputs:
    packageType: 'sdk'
    version: '7.0.x'
    ....

ERROR:
MSBuild version 17.4.1+9a89d02ff for .NET
Successfully created package '/home/vsts/work/1/s/packages/Shared.GeneratedCode.Utils.0.0.385.484.nupkg'.
Successfully created package '/home/vsts/work/1/s/packages/Shared.GeneratedCode.Utils.0.0.385.484.symbols.nupkg'.
MSBuild version 17.4.1+9a89d02ff for .NET
/usr/share/dotnet/sdk/7.0.102/Sdks/NuGet.Build.Tasks.Pack/build/NuGet.Build.Tasks.Pack.targets(221,5): warning NU5128: Some target frameworks declared in the dependencies group of the nuspec and the lib/ref folder do not have exact matches in the other location. Consult the list of actions below: [/home/vsts/work/1/s/Shared.GeneratedCode/Shared.GeneratedCode.csproj]
/usr/share/dotnet/sdk/7.0.102/Sdks/NuGet.Build.Tasks.Pack/build/NuGet.Build.Tasks.Pack.targets(221,5): warning NU5128: - Add lib or ref assemblies for the netstandard2.0 target framework [/home/vsts/work/1/s/Shared.GeneratedCode/Shared.GeneratedCode.csproj]
Successfully created package '/home/vsts/work/1/s/packages/Shared.GeneratedCode.0.0.385.484.nupkg'.
Successfully created package '/home/vsts/work/1/s/packages/Shared.GeneratedCode.0.0.385.484.symbols.nupkg'.
System.Threading.AbandonedMutexException: The wait completed due to an abandoned mutex.
##[error]PowerShell exited with code '1'.

AFTER FIX:

Time Elapsed 00:00:07.74
MSBuild version 17.4.1+9a89d02ff for .NET
Successfully created package '/home/vsts/work/1/s/packages/Shared.GeneratedCode.Utils.0.0.385.494.nupkg'.
Successfully created package '/home/vsts/work/1/s/packages/Shared.GeneratedCode.Utils.0.0.385.494.symbols.nupkg'.
MSBuild version 17.4.1+9a89d02ff for .NET
/opt/hostedtoolcache/dotnet/sdk/7.0.102/Sdks/NuGet.Build.Tasks.Pack/build/NuGet.Build.Tasks.Pack.targets(221,5): warning NU5128: Some target frameworks declared in the dependencies group of the nuspec and the lib/ref folder do not have exact matches in the other location. Consult the list of actions below: [/home/vsts/work/1/s/Shared.GeneratedCode/Shared.GeneratedCode.csproj]
/opt/hostedtoolcache/dotnet/sdk/7.0.102/Sdks/NuGet.Build.Tasks.Pack/build/NuGet.Build.Tasks.Pack.targets(221,5): warning NU5128: - Add lib or ref assemblies for the netstandard2.0 target framework [/home/vsts/work/1/s/Shared.GeneratedCode/Shared.GeneratedCode.csproj]
Successfully created package '/home/vsts/work/1/s/packages/Shared.GeneratedCode.0.0.385.494.nupkg'.
Successfully created package '/home/vsts/work/1/s/packages/Shared.GeneratedCode.0.0.385.494.symbols.nupkg'.
MSBuild version 17.4.1+9a89d02ff for .NET
Determining projects to restore...
Restored /home/vsts/work/1/s/Shared.Test.Init/Shared.Test.Init.csproj (in 197 ms).
Shared.Test.Init -> /home/vsts/work/1/s/Shared.Test.Init/bin/Debug/net7.0/Shared.Test.Init.dll

Build succeeded.
0 Warning(s)
0 Error(s)

@kartheekp-ms
Copy link
Contributor Author

The patch fixing this issue has been released in February 2023 .NET SDK servicing release.

https://dotnet.microsoft.com/en-us/download/dotnet/6.0
https://dotnet.microsoft.com/en-us/download/dotnet/7.0

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Functionality:Restore Priority:1 High priority issues that must be resolved in the current sprint. Product:dotnet.exe Type:Bug
Projects
None yet
Development

Successfully merging a pull request may close this issue.

7 participants