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

Sporadic Restore error: The process cannot access the file 'edpys1ay.f5i' because it is being used by another process. #13917

Open
thomasdgx opened this issue Nov 12, 2024 · 1 comment
Labels

Comments

@thomasdgx
Copy link

thomasdgx commented Nov 12, 2024

NuGet Product Used

MSBuild.exe

Product Version

MSBuild Version 17.8.5+b5265ef37 / NuGet Client Version 6.8.1.2

Worked before?

don't know

Impact

It bothers me. A fix would be nice

Repro Steps & Context

On our build server we observe sporadically some file access issues (see exception below) during the NuGet restore task.

Context:

  • OsName : Microsoft Windows Server 2025 Standard
  • OsVersion : 10.0.26304
  • MSBuild Version 17.8.5+b5265ef37
  • NuGet Client Version 6.8.1.2

The NuGet.targets(156,5) seems to point to the restore task.

There seems to be a race condition in the PackageExtractor. The filename 'edpys1ay.f5i' suggests that it is about a temporary file (Path.GetRandomFileName()).

MsBuild invokes NuGet restore with parallel threads. And since its running on a build server there are multiple MsBuild processes with restore running at the same time. A second build could also be in the middle of NuGet restore.

Further notes:

After the file access error happened other builds fail with NuGet package cache issues (see Follow up exception below). I think these type of exceptions are follow up errors from the first one.

Actually this corruption in the global package folder breaks many subsequent builds on that particular build server.

Verbose Logs

When running with MsBuild detailed log we get a callstack

	C:\Program Files\Microsoft Visual Studio\2022\Enterprise\Common7\IDE\CommonExtensions\Microsoft\NuGet\NuGet.targets(156,5): error : The process cannot access the file 'edpys1ay.f5i' because it is being used by another process. [...csproj]
	  System.IO.IOException: The process cannot access the file 'edpys1ay.f5i' because it is being used by another process.
	     at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
	     at System.IO.FileInfo.Delete()
	     at NuGet.Packaging.PackageExtractor.<>c__DisplayClass5_0.<<InstallFromSourceAsync>b__0>d.MoveNext()
	  --- End of stack trace from previous location where exception was thrown ---
	     at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
	     at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
	     at NuGet.Common.ConcurrencyUtilities.<ExecuteWithFileLockedAsync>d__5`1.MoveNext()
	  --- End of stack trace from previous location where exception was thrown ---
	     at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
	     at NuGet.Common.ConcurrencyUtilities.<ExecuteWithFileLockedAsync>d__5`1.MoveNext()
	  --- End of stack trace from previous location where exception was thrown ---
	     at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
	     at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
	     at NuGet.Packaging.PackageExtractor.<InstallFromSourceAsync>d__5.MoveNext()
	  --- End of stack trace from previous location where exception was thrown ---
	     at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
	     at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
	     at NuGet.Commands.ProjectRestoreCommand.<InstallPackageAsync>d__16.MoveNext()
	  --- End of stack trace from previous location where exception was thrown ---
	     at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
	     at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
	     at NuGet.Commands.ProjectRestoreCommand.<>c__DisplayClass15_1.<<InstallPackagesAsync>b__4>d.MoveNext()
	  --- End of stack trace from previous location where exception was thrown ---
	     at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
	     at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
	     at NuGet.Commands.ProjectRestoreCommand.<InstallPackagesAsync>d__15.MoveNext()
	  --- End of stack trace from previous location where exception was thrown ---
	     at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
	     at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
	     at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task)
	     at NuGet.Commands.ProjectRestoreCommand.<TryRestoreAsync>d__9.MoveNext()
	  --- End of stack trace from previous location where exception was thrown ---
	     at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
	     at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
	     at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task)
	     at NuGet.Commands.RestoreCommand.<ExecuteRestoreAsync>d__86.MoveNext()
	  --- End of stack trace from previous location where exception was thrown ---
	     at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
	     at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
	     at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task)
	     at NuGet.Commands.RestoreCommand.<ExecuteAsync>d__68.MoveNext()
	  --- End of stack trace from previous location where exception was thrown ---
	     at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
	     at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
	     at NuGet.Commands.RestoreRunner.<ExecuteAsync>d__7.MoveNext()
	  --- End of stack trace from previous location where exception was thrown ---
	     at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
	     at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
	     at NuGet.Commands.RestoreRunner.<ExecuteAndCommitAsync>d__6.MoveNext()
	  --- End of stack trace from previous location where exception was thrown ---
	     at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
	     at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
	     at NuGet.Commands.RestoreRunner.<CompleteTaskAsync>d__9.MoveNext()
	  --- End of stack trace from previous location where exception was thrown ---
	     at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
	     at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
	     at NuGet.Commands.RestoreRunner.<RunAsync>d__2.MoveNext()
	  --- End of stack trace from previous location where exception was thrown ---
	     at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
	     at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
	     at NuGet.Commands.RestoreRunner.<RunAsync>d__0.MoveNext()
	  --- End of stack trace from previous location where exception was thrown ---
	     at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
	     at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
	     at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task)
	     at NuGet.Build.Tasks.BuildTasksUtility.<RestoreAsync>d__12.MoveNext()
	  --- End of stack trace from previous location where exception was thrown ---
	     at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
	     at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
	     at NuGet.Build.Tasks.RestoreTask.<ExecuteAsync>d__47.MoveNext()


Follow up exception (not the same build log). This comes from subsequent builds:


C:\Program Files\Microsoft Visual Studio\2022\Enterprise\Common7\IDE\CommonExtensions\Microsoft\NuGet\NuGet.targets(156,5): error NU5037: The package is missing the required nuspec file. Path: C:\Users\<myuser>\.nuget\packages\<myPackageName>\<someversion> [<mycsproj>]
  NuGet.Packaging.Core.PackagingException: The package is missing the required nuspec file. Path: C:\Users\<myuser>\.nuget\packages\<myPackageName>\<someversion>
     at NuGet.Packaging.PackageFolderReader.GetNuspecFile()
     at NuGet.Packaging.PackageReaderBase.GetNuspec()
     at NuGet.Protocol.LocalPackageFileCache.GetNuspec(String manifestPath, String expandedPath)
     at NuGet.Protocol.LocalPackageFileCache.<>c__DisplayClass7_1.<GetOrAddNuspec>b__1()
     at System.Lazy`1.CreateValue()
@thomasdgx
Copy link
Author

Issue happened again. In between I patched the NuGet.Packaging.dll to get a little more context:

We see two MsBuild processes running at the same time

Process 1 (Build started 11/14/2024 10:02:06 PM.)

  1. Acquiring lock for the installation of myPackage
  2. Acquired lock for the installation of myPackage
  3. Installed myPackage from ...

Process 2 (Build started 11/14/2024 10:02:07 PM.)

  1. Acquiring lock for the installation of myPackage
  2. Acquired lock for the installation of myPackage
  3. Clean target path C:\Users<myuser>.nuget\packages<myPackage><myVersion>

  System.IO.IOException: The process cannot access the file 'aalodcx1.kjm' because it is being used by another process.
     at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
     at System.IO.FileInfo.Delete()
     at NuGet.Packaging.PackageExtractor.<>c__DisplayClass5_2.<<InstallFromSourceAsync>b__0>d.MoveNext()

Unfortunately the msbuild log does not contain timestamps.

Note: I patched the NuGet.Packaging.dll to confirm that we actually process that delete branch in code NuGet.Client\src\NuGet.Core\NuGet.Packaging\PackageExtractor.cs - line 644

         // We do not stop the package extraction after this point
         // based on CancellationToken, but things can still be stopped if the process is killed.
         if (Directory.Exists(targetPath))
         {
               logger.LogVerbose($"*** Clean target path {targetPath} for {packageIdentity.Id} {packageIdentity.Version}");

We see a race condition when two processes want to restore the same package at the same time. On the first glance the PackageExtractor code looks correct. It uses a guard mechanism to synchronize multiple processes. However there seems to be some race condition, that the second process File.Exist returns false, although it should be there from the first process.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants