Bundle_extraction_is_reused intermittently fails with "text file is busy"

[runfoapp]

Runfo Tracking Issue: Bundle_extraction_is_reused intermittently fails with "text file is busy"

Build	Definition	Kind	Run Name

Build Result Summary

Day Hit Count	Week Hit Count	Month Hit Count
0	0	0

[Dotnet-GitSync-Bot]

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

Tagging subscribers to this area: @agocke, @vitek-karas
See info in area-owners.md if you want to be subscribed.

Details

Issue Details

Description:	Runfo Tracking Issue: Bundle_extraction_is_reused intermittently fails with "text file is busy" Build Definition Kind Run Name 885716 runtime PR 44656 Installer-coreclr-Linux_x64-Release 883403 runtime PR 42972 Installer-coreclr-Linux_x64-Release Build Result Summary Day Hit Count Week Hit Count Month Hit Count 1 2 2
Author:	runfoapp[bot]
Assignees:	-
Labels:	area-Single-File, untriaged
Milestone:	-

[eerhardt]

This failed again here:

https://dev.azure.com/dnceng/public/_build/results?buildId=913629&view=logs&j=488ba465-33f8-5af3-b422-ec6526547df5&t=6c6997ae-4d39-5a90-21e3-089719c051c1&l=525

https://dev.azure.com/dnceng/public/_build/results?buildId=913629&view=ms.vss-test-web.build-test-results-tab&runId=29085272&resultId=100002&paneView=debug

Error message
System.ComponentModel.Win32Exception : Text file busy


Stack trace
   at System.Diagnostics.Process.ForkAndExecProcess(String filename, String[] argv, String[] envp, String cwd, Boolean redirectStdin, Boolean redirectStdout, Boolean redirectStderr, Boolean setCredentials, UInt32 userId, UInt32 groupId, UInt32[] groups, Int32& stdinFd, Int32& stdoutFd, Int32& stderrFd, Boolean usesTerminal, Boolean throwOnNoExec)
   at System.Diagnostics.Process.StartCore(ProcessStartInfo startInfo)
   at System.Diagnostics.Process.Start()
   at Microsoft.DotNet.Cli.Build.Framework.Command.Start() in /_/src/installer/tests/TestUtils/Command.cs:line 199
   at Microsoft.DotNet.Cli.Build.Framework.Command.Execute(Boolean fExpectedToFail) in /_/src/installer/tests/TestUtils/Command.cs:line 239
   at Microsoft.DotNet.Cli.Build.Framework.Command.Execute() in /_/src/installer/tests/TestUtils/Command.cs:line 171
   at AppHost.Bundle.Tests.StaticHost.Can_Run_SingleFile_App_With_StatiHost() in /_/src/installer/tests/Microsoft.NET.HostModel.Tests/AppHost.Bundle.Tests/StaticHost.cs:line 44

[vitek-karas]

The last thing we do on the executable before we call Process.Start (which fails) is this:

runtime/src/installer/managed/Microsoft.NET.HostModel/AppHost/HostWriter.cs

Lines 175 to 177 in dbe5e2a

	// Memory-mapped write does not updating last write time
	RetryUtil.RetryOnIOError(() =>
	File.SetLastWriteTimeUtc(appHostPath, DateTime.UtcNow));

The Retry has logic to try 500 times (with a short sleep) and if it still fails - then throw. So unless something is really weird, then the SetLastWriteTimeUtc actually succeeded before it's done.

I don't know Linux file system enough to be able to tell if the SetLastWriteTime even requires the file to be "non-busy" - if it can work on "busy" files, then the one we call which actually modifies the content of the file is this:

runtime/src/installer/managed/Microsoft.NET.HostModel/AppHost/BinaryUtils.cs

Lines 68 to 74 in dbe5e2a

	using (var mappedFile = MemoryMappedFile.CreateFromFile(filePath))
	{
	using (var accessor = mappedFile.CreateViewAccessor())
	{
	SearchAndReplace(accessor, searchPattern, patternToReplace, pad0s);
	}
	}

This has usings around the right stuff - so it should close the file once it's done.

[eerhardt]

Failed again here:

https://dev.azure.com/dnceng/public/_build/results?buildId=916830&view=logs&j=488ba465-33f8-5af3-b422-ec6526547df5&t=6c6997ae-4d39-5a90-21e3-089719c051c1&l=536

https://dev.azure.com/dnceng/public/_build/results?buildId=916830&view=ms.vss-test-web.build-test-results-tab&runId=29156076&resultId=100011&paneView=debug

[agocke]

I think some more info would be helpful. I'm going to try to run strace and get the syscall log to see if I can figure out what's going on under the hood here.

We'll also need to move this entire test into staging unfortunately -- it's too noisy to continue running in all PRs.