windows-amd64 build flakiness: "compile.exe: Access is denied."

[dagood]

---- Running command: [cmd.exe /c make.bat]
Building Go cmd/dist using C:\Users\VssAdministrator\.go-stage-0\1.16.5\go
Building Go toolchain1 using C:\Users\VssAdministrator\.go-stage-0\1.16.5\go.
Building Go bootstrap cmd/go (go_bootstrap) using Go toolchain1.
Building Go toolchain2 using go_bootstrap and Go toolchain1.
Building Go toolchain3 using go_bootstrap and Go toolchain2.
go install cmd/compile: copying C:\Users\VSSADM~1\AppData\Local\Temp\go-build3426272395\b098\exe\a.out.exe: open D:\a\1\s\pkg\tool\windows_amd64\compile.exe: Access is denied.
go tool dist: FAILED: D:\a\1\s\pkg\tool\windows_amd64\go_bootstrap install -gcflags=all= -ldflags=all= -a -i cmd/asm cmd/cgo cmd/compile cmd/link: exit status 1

All instances I've found so far are on 1.17 branches:

https://dev.azure.com/dnceng/internal/_build/results?buildId=1433378&view=logs&j=b2ef2c90-30c2-5075-badc-2feb75a64cee&t=b6826774-f899-5802-9e9c-ca3c12e8a4c0&l=38

https://dev.azure.com/dnceng/internal/_build/results?buildId=1442944&view=logs&j=5a2439d3-40cd-5cda-520e-11af88128fb3&t=a1b03d73-1679-5340-7eef-275cc3387d35&l=83

https://dev.azure.com/dnceng/internal/_build/results?buildId=1433379&view=logs&j=5a2439d3-40cd-5cda-520e-11af88128fb3&t=a1b03d73-1679-5340-7eef-275cc3387d35&l=38

The first thing that comes to mind is some virus scan locking it, potentially related to the recent build pool migrations.

[dagood]

actions/runner-images#4086 (comment) (Sept 15) mentions an "internal monitor" they disabled when something similar showed up for someone else:

We have disabled an internal monitor. Could you please rerun builds and check results?

Maybe the monitor was turned back on, or something similar was implemented independently. (Or, maybe this is all unrelated and it's just Defender like we first thought.)

[dagood]

In my experience, Defender hits some kind of choke point when you move executable files around, and cmd/dist/build.go seems to do a lot of that in the multi-stage build, so that behavior probably aggravates any issues we'd normally have with Defender.

(Also in my experience, exclusion rules on Defender don't actually work with ATP (Advanced Threat Protection), so this is the kind of thing that's easy to think is solved because it's just a flaky problem but not actually have fixed.)

[dagood]

Apparently only one person ever has hit this other than us: (only Google result for "compile.exe: Access is denied.")

• 1.9\pkg\tool\windows_amd64\compile.exe: Access is denied. golang/go#21608

[dagood]

Here's one Quim hit in PR validation:

• https://dev.azure.com/dnceng/internal/_build/results?buildId=1493828&view=logs&j=c6b9ba5f-019e-581b-d1aa-804a22c99f8e&s=96ac2280-8cb4-5df5-99de-dd2da759617d&t=6d7e3d66-56dc-51c1-de51-1e08a106baa0&l=59

Here are a few in official builds:

• https://dev.azure.com/dnceng/internal/_build/results?buildId=1484424&view=logs&j=bd6dec30-d47a-585c-390f-1a34deb0ac5c&t=e9ea7c6f-353e-5410-6069-3b071ad61ae7&l=20
• https://dev.azure.com/dnceng/internal/_build/results?buildId=1494373&view=logs&j=e5e339c3-b8af-59dc-01c1-6845be16becd&t=284b3345-7d4a-5d09-a948-23c027033fe3&l=38
• https://dev.azure.com/dnceng/internal/_build/results?buildId=1482374&view=logs&j=bd6dec30-d47a-585c-390f-1a34deb0ac5c&t=e9ea7c6f-353e-5410-6069-3b071ad61ae7&l=20

[dagood]

I started a thread with FR: https://teams.microsoft.com/l/message/19:[email protected]/1638482594255?tenantId=72f988bf-86f1-41af-91ab-2d7cd011db47&groupId=4d73664c-9f2f-450d-82a5-c2f02756606d&parentMessageId=1638482594255&teamName=.NET%20Core%20Eng%20Services%20Partners&channelName=First%20Responders&createdTime=1638482594255

Basically, there's a script that's used in hosted agent image generation that's intended to turn off Defender: https://github.com/actions/virtual-environments/blob/main/images/win/scripts/Installers/Configure-Antivirus.ps1. But, generally speaking it's never really fully disabled.

This also could be caused by some Azure-specific scanning, not Defender.

I hit this kind of thing before and the only reasonable way forward was to retry:

• Windows builds sometimes fail with "light.exe : error LGHT0001: The process cannot access the file because it is being used by another process." dotnet/runtime#3618.

We can probably add some Windows-specific retry logic in our build to mitigate this flakiness.

---

To make the retries quick and not delay the build much, I believe we could add them to the individual copy call:

go/src/cmd/dist/build.go

Lines 1053 to 1059 in 677e561

	// copy copies the file src to dst, via memory (so only good for small files).
	func copyfile(dst, src string, flag int) {
	if vflag > 1 {
	errprintf("cp %s %s\n", src, dst)
	}
	writefile(readfile(src), dst, flag)
	}

But ideally we should avoid this--it seems to me like it would be hard to justify upstreaming such a niche mitigation. If there were more reports than golang/go#21608 and it were easier to point at this as the root cause, maybe this would be better.

---

We can add retries to the entire build command:

go/eng/_core/cmd/build/build.go

Line 112 in 677e561

buildCommandLine := append(shellPrefix, "make"+scriptExtension)

This means that if we hit a retry, we would be redoing some build work and potentially making it harder to notice other Windows-specific flakiness problems that come up elsewhere in the build. But, this way we only modify our own code, so we don't have to be concerned about upstreaming.

[qmuntal]

I think we are having this issue more than before because it reproduces in go1.17 but not in main, and I'm doing the FIPS work in go1.17.

Evidences:

• main jobs (40/40 succeeded)

  • https://dev.azure.com/dnceng/internal/_build/results?buildId=1495605
  • https://dev.azure.com/dnceng/internal/_build/results?buildId=1495608
  • https://dev.azure.com/dnceng/internal/_build/results?buildId=1495613
  • https://dev.azure.com/dnceng/internal/_build/results?buildId=1495630

• go1.17 jobs (11/20 succeeded):

  • https://dev.azure.com/dnceng/internal/_build/results?buildId=1495624
  • https://dev.azure.com/dnceng/internal/_build/results?buildId=1495635

I'm will try to find the commit that fixes the issue in case we can backport it, but I don't promise anything 😄

[dagood]

Yeah, I suppose doing a (rough) binary search would be reasonable if it's not too much effort. Maybe we should also try a build just before the release branch fork (no VERSION file) and just after, in case the build machine just doesn't like the number 17 in particular, or something along those lines. 😛

I'm concerned we'll end up with something inconclusive if it's a gradual issue not related to any single commit--e.g. if the build (under our infra) got more flaky after 1.16 and less flaky after 1.17, and 1.17 just happened to fork at a nasty spot for our particular environment. (The hypothesis I've had in mind for this is that our binary size, build time, and the scan throughput could be interacting just perfectly wrong so the scan doesn't complete in time.)