HostWriter: ResourceUpdate fails non-deterministically

[DamianEdwards]

Steps to reproduce

1. Create a new web app: dotnet new webapp
2. Repeatedly build the app from the CLI with no changes: dotnet build

Expected behavior

No errors

Actual behavior

Randomly see the following error (twice in the last 20 builds just now):

C:\src\local\BuildPerf\WebApp3.0> dotnet build Microsoft (R) Build Engine version 16.3.0-preview-19325-02+eca7818b1 for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

 Restore completed in 19.81 ms for C:\src\local\BuildPerf\WebApp3.0\WebApp3.0.csproj.
 You are using a preview version of .NET Core. See: https://aka.ms/dotnet-core-preview
C:\Program Files\dotnet\sdk\3.0.100-preview7-012649\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(358,5): error MSB4018: The "CreateAppHost" task failed unexpectedly. [C:\src\local\BuildPerf\WebApp3.0\WebApp3.0.csproj]
C:\Program Files\dotnet\sdk\3.0.100-preview7-012649\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(358,5): error MSB4018: Microsoft.NET.Build.Tasks.ResourceUpdater+HResultException: 8007006E [C:\src\local\BuildPerf\WebApp3.0\WebApp3.0.csproj]
C:\Program Files\dotnet\sdk\3.0.100-preview7-012649\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(358,5): error MSB4018: at Microsoft.NET.Build.Tasks.ResourceUpdater.ThrowExceptionForLastWin32Error() in /_/src/Tasks/Microsoft.NET.Build.Tasks/ResourceUpdater.cs:line 436 [C:\src\local\BuildPerf\WebApp3.0\WebApp3.0.csproj]
C:\Program Files\dotnet\sdk\3.0.100-preview7-012649\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(358,5): error MSB4018: at Microsoft.NET.Build.Tasks.ResourceUpdater.Update() in /_/src/Tasks/Microsoft.NET.Build.Tasks/ResourceUpdater.cs:line 324 [C:\src\local\BuildPerf\WebApp3.0\WebApp3.0.csproj]
C:\Program Files\dotnet\sdk\3.0.100-preview7-012649\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(358,5): error MSB4018: at Microsoft.NET.Build.Tasks.AppHost.Create(String appHostSourceFilePath, String appHostDestinationFilePath, String appBinaryFilePath, Boolean windowsGraphicalUserInterface, String intermediateAssembly, Logger log) in /_/src/Tasks/Microsoft.NET.Build.Tasks/AppHost.cs:line 82 [C:\src\local\BuildPerf\WebApp3.0\WebApp3.0.csproj]
C:\Program Files\dotnet\sdk\3.0.100-preview7-012649\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(358,5): error MSB4018: at Microsoft.NET.Build.Tasks.CreateAppHost.ExecuteCore() in /_/src/Tasks/Microsoft.NET.Build.Tasks/CreateAppHost.cs:line 38 [C:\src\local\BuildPerf\WebApp3.0\WebApp3.0.csproj]
C:\Program Files\dotnet\sdk\3.0.100-preview7-012649\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(358,5): error MSB4018: at Microsoft.NET.Build.Tasks.TaskBase.Execute() in /_/src/Tasks/Common/TaskBase.cs:line 38 [C:\src\local\BuildPerf\WebApp3.0\WebApp3.0.csproj]
C:\Program Files\dotnet\sdk\3.0.100-preview7-012649\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(358,5): error MSB4018: at Microsoft.Build.BackEnd.TaskExecutionHost.Microsoft.Build.BackEnd.ITaskExecutionHost.Execute() [C:\src\local\BuildPerf\WebApp3.0\WebApp3.0.csproj]
C:\Program Files\dotnet\sdk\3.0.100-preview7-012649\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(358,5): error MSB4018: at Microsoft.Build.BackEnd.TaskBuilder.ExecuteInstantiatedTask(ITaskExecutionHost taskExecutionHost, TaskLoggingContext taskLoggingContext, TaskHost taskHost, ItemBucket bucket, TaskExecutionMode howToExecuteTask) [C:\src\local\BuildPerf\WebApp3.0\WebApp3.0.csproj]

Build FAILED.

C:\Program Files\dotnet\sdk\3.0.100-preview7-012649\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(358,5): error MSB4018: The "CreateAppHost" task failed unexpectedly. [C:\src\local\BuildPerf\WebApp3.0\WebApp3.0.csproj]
C:\Program Files\dotnet\sdk\3.0.100-preview7-012649\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(358,5): error MSB4018: Microsoft.NET.Build.Tasks.ResourceUpdater+HResultException: 8007006E [C:\src\local\BuildPerf\WebApp3.0\WebApp3.0.csproj]
C:\Program Files\dotnet\sdk\3.0.100-preview7-012649\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(358,5): error MSB4018: at Microsoft.NET.Build.Tasks.ResourceUpdater.ThrowExceptionForLastWin32Error() in /_/src/Tasks/Microsoft.NET.Build.Tasks/ResourceUpdater.cs:line 436 [C:\src\local\BuildPerf\WebApp3.0\WebApp3.0.csproj]
C:\Program Files\dotnet\sdk\3.0.100-preview7-012649\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(358,5): error MSB4018: at Microsoft.NET.Build.Tasks.ResourceUpdater.Update() in /_/src/Tasks/Microsoft.NET.Build.Tasks/ResourceUpdater.cs:line 324 [C:\src\local\BuildPerf\WebApp3.0\WebApp3.0.csproj]
C:\Program Files\dotnet\sdk\3.0.100-preview7-012649\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(358,5): error MSB4018: at Microsoft.NET.Build.Tasks.AppHost.Create(String appHostSourceFilePath, String appHostDestinationFilePath, String appBinaryFilePath, Boolean windowsGraphicalUserInterface, String intermediateAssembly, Logger log) in /_/src/Tasks/Microsoft.NET.Build.Tasks/AppHost.cs:line 82 [C:\src\local\BuildPerf\WebApp3.0\WebApp3.0.csproj]
C:\Program Files\dotnet\sdk\3.0.100-preview7-012649\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(358,5): error MSB4018: at Microsoft.NET.Build.Tasks.CreateAppHost.ExecuteCore() in /_/src/Tasks/Microsoft.NET.Build.Tasks/CreateAppHost.cs:line 38 [C:\src\local\BuildPerf\WebApp3.0\WebApp3.0.csproj]
C:\Program Files\dotnet\sdk\3.0.100-preview7-012649\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(358,5): error MSB4018: at Microsoft.NET.Build.Tasks.TaskBase.Execute() in /_/src/Tasks/Common/TaskBase.cs:line 38 [C:\src\local\BuildPerf\WebApp3.0\WebApp3.0.csproj]
C:\Program Files\dotnet\sdk\3.0.100-preview7-012649\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(358,5): error MSB4018: at Microsoft.Build.BackEnd.TaskExecutionHost.Microsoft.Build.BackEnd.ITaskExecutionHost.Execute() [C:\src\local\BuildPerf\WebApp3.0\WebApp3.0.csproj]
C:\Program Files\dotnet\sdk\3.0.100-preview7-012649\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets(358,5): error MSB4018: at Microsoft.Build.BackEnd.TaskBuilder.ExecuteInstantiatedTask(ITaskExecutionHost taskExecutionHost, TaskLoggingContext taskLoggingContext, TaskHost taskHost, ItemBucket bucket, TaskExecutionMode howToExecuteTask) [C:\src\local\BuildPerf\WebApp3.0\WebApp3.0.csproj]
 0 Warning(s)
 1 Error(s)

Time Elapsed 00:00:02.58

Environment data

dotnet --info output:

.NET Core SDK (reflecting any global.json):
 Version: 3.0.100-preview7-012649
 Commit: 3f4ab7f5c5

Runtime Environment:
 OS Name: Windows
 OS Version: 10.0.18362
 OS Platform: Windows
 RID: win10-x64
 Base Path: C:\Program Files\dotnet\sdk\3.0.100-preview7-012649\

Host (useful for support):
 Version: 3.0.0-preview7-27826-04
 Commit: 5c4d829254

.NET Core SDKs installed:
 2.1.700-preview-009618 [C:\Program Files\dotnet\sdk]
 2.1.800-preview-009677 [C:\Program Files\dotnet\sdk]
 2.1.800-preview-009696 [C:\Program Files\dotnet\sdk]
 2.2.204 [C:\Program Files\dotnet\sdk]
 3.0.100-preview7-012649 [C:\Program Files\dotnet\sdk]

.NET Core runtimes installed:
 Microsoft.AspNetCore.All 2.1.9 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
 Microsoft.AspNetCore.All 2.1.11 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
 Microsoft.AspNetCore.All 2.2.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
 Microsoft.AspNetCore.App 2.1.9 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
 Microsoft.AspNetCore.App 2.1.11 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
 Microsoft.AspNetCore.App 2.2.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
 Microsoft.AspNetCore.App 3.0.0-preview7.19326.10 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
 Microsoft.NETCore.App 2.1.9 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
 Microsoft.NETCore.App 2.1.11 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
 Microsoft.NETCore.App 2.2.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
 Microsoft.NETCore.App 3.0.0-preview7-27826-04 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
 Microsoft.WindowsDesktop.App 3.0.0-preview7-27826-04 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]

To install additional .NET Core runtimes or SDKs:
 https://aka.ms/dotnet-download

[livarcocc]

@peterhuene can you take a look?

[peterhuene]

0x8007006E is cannot open the file specified. Not entirely sure if that's because it doesn't exist or a sharing violation. My guess would be on the latter since it's intermittent (perhaps something external to the build is interfering?).

[peterhuene]

We have a lot of tests that create and customize the apphost on Windows and I haven't seen flaky CI with this. I'll attempt to repro it.

[livarcocc]

Anti-virus?

[peterhuene]

I ran dotnet build 100 times in my VM with 3.0.100-preview7-012687 and had no failures.

@DamianEdwards are you seeing this on a particular machine or multiple machines?

[DamianEdwards]

@peterhuene was seeing this on only one machine so far, but haven't tried to repro it on my other machine.

[peterhuene]

@DamianEdwards I'm still not able to reproduce this.

The API call is EndUpdateResource and the error code is 110 (ERROR_OPEN_FAILED). It seems that some antivirus software may interfere with this API.

As I don't have any MSIT-controlled Windows machines (and it's been a decade since I last did), I don't know what we're using for antivirus on corpnet these days.

Would it be possible to check if its the real-time protection of the antivirus software that's interfering with the build?

[peterhuene]

I'm updating the CreateAppHost task to be more resilient to a temporarily locked intermediate apphost, like MSBuild handles file copying. Hopefully this will help alleviate this problem.

[wli3]

I have a repro too during app building on blazor server app, but not consistent. I ran git clean -fxd. and open the sln with VS then F5.

Severity	Code	Description	Project	File	Line	Suppression State
Error	MSB4018	The "CreateAppHost" task failed unexpectedly.
System.IO.IOException: The process cannot access the file 'C:\work\appbuilding\emojisearch.blazor\emojisearch.blazor\obj\Debug\netcoreapp3.0\emojisearch.blazor.exe' because it is being used by another process.
 at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
 at System.IO.FileStream.Init(String path, FileMode mode, FileAccess access, Int32 rights, Boolean useRights, FileShare share, Int32 bufferSize, FileOptions options, SECURITY_ATTRIBUTES secAttrs, String msgPath, Boolean bFromProxy, Boolean useLongPath, Boolean checkHost)
 at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize)
 at System.IO.File.OpenFile(String path, FileAccess access, SafeFileHandle& handle)
 at System.IO.File.SetLastWriteTimeUtc(String path, DateTime lastWriteTimeUtc)
 at Microsoft.NET.HostModel.AppHost.HostWriter.CreateAppHost(String appHostSourceFilePath, String appHostDestinationFilePath, String appBinaryFilePath, Boolean windowsGraphicalUserInterface, String assemblyToCopyResorcesFrom)
 at Microsoft.NET.Build.Tasks.CreateAppHost.ExecuteCore() in /_/src/Tasks/Microsoft.NET.Build.Tasks/CreateAppHost.cs:line 35
 at Microsoft.NET.Build.Tasks.TaskBase.Execute() in /_/src/Tasks/Common/TaskBase.cs:line 47
 at Microsoft.Build.BackEnd.TaskExecutionHost.Microsoft.Build.BackEnd.ITaskExecutionHost.Execute()
 at Microsoft.Build.BackEnd.TaskBuilder.<ExecuteInstantiatedTask>d__26.MoveNext()	emojisearch.blazor	C:\Program Files\dotnet\sdk\3.0.100-preview9-013654\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.Sdk.targets	359	

[peterhuene]

Would it be possible to use procmon to see if we can figure out who is opening the file? I've never been able to reproduce the issue in a VM.

[wli3]

good point, let me try several times more