cmd/go: "cannot access the file because it is being used by another process" flakes on Windows

[FiloSottile]

#!watchflakes
default <- pkg == "cmd/go" && test == "TestScript" && `The process cannot access the file because it is being used by another process.`

I am getting a lot of these flakes on the Windows TryBots, three just in the last day, and they are getting kinda tedious.

=== RUN   TestScript
vcs-test.golang.org rerouted to http://127.0.0.1:49858
https://vcs-test.golang.org rerouted to https://127.0.0.1:49859
go test proxy running at GOPROXY=http://127.0.0.1:49860/mod
    script_test.go:54: remove C:\b\s\w\ir\x\t\cmd-go-test-3977021774\vcstest3518644654\auth\or401\.access: The process cannot access the file because it is being used by another process.

https://ci.chromium.org/ui/p/golang/builders/try/gotip-windows-amd64/b8726767142354977169/overview
https://ci.chromium.org/ui/p/golang/builders/try/gotip-windows-386/b8726850438465216129/overview
https://ci.chromium.org/ui/p/golang/builders/try/gotip-windows-amd64/b8726734771386763217/overview

AFAICT, there is no tracking issue, just a sea of TestScript testflakes issues, with this specific message showing up about 3 weeks ago in #66337, which has a catch-all pkg == "cmd/go" && test == "TestScript" testflakes definition.

#66337 (comment)
#66337 (comment)
#66337 (comment)
#66337 (comment)

[FiloSottile]

Aside from fixing the specific issue, is there something that could be improved in flakes monitoring? Maybe testflakes could also monitor TryBot reruns for the same commit? Or it could be more granular for large tests such as TestScript?

[ianlancetaylor]

CC @golang/windows @matloob @samthanawalla

[dmitshur]

AFAICT, there is no tracking issue, just a sea of TestScript testflakes issues, with this specific message showing up about 3 weeks ago in #66337, which has a catch-all pkg == "cmd/go" && test == "TestScript" testflakes definition.

The Watchflakes wiki page suggests:

The newly created issue’s pattern is often too broad and should be edited to make it more specific to the actual failure. Sending a failure to the lowest-numbered matching issue ensures that creating a broad default pattern for a new failure does not “steal” failures from earlier issues, nor does it spam the new issue with unrelated failures in the same test that are already separately tracked.

Watchflakes places newly created issues in the Test Flakes project and adds the NeedsInvestigation label. These issues start out with no status (not Active, not Done). Issues with no status need to be inspected by a person, who should usually refine the pattern to capture the salient information about the failure. Issues that have been checked can then be moved to Active. [...]

The pattern in #66337 is definitely broad, and it hasn't progressed beyond the NeedsInvestigation / no status state yet. If it's narrowed down to something that doesn't match these errors, then it creates room for this failure mode to be tracked in another issue.

is there something that could be improved in flakes monitoring? Maybe testflakes could also monitor TryBot reruns for the same commit? [...]

I suggest filing a separate x/build/cmd/watchflakes issue for that change. It would need someone interested to find time and work on it, but it's more likely to be forgotten as part of this issue.

(Edit: It's useful to know which of the flaky tests are contributing most to development friction and reducing velocity, so thanks for reporting this.)

[FiloSottile]

One more, https://ci.chromium.org/ui/p/golang/builders/try/gotip-windows-amd64/b8726732876617875553/overview.

(Sorry to whine, but I had changes fall through the cracks because I AutoSubmit+1'd them after the Code-Review+2, and instead of making their journey through go.dev/s/needs-review and to submission, got stuck on flakes.)

[ianlancetaylor]

Interestingly, the line where the error is being reported is the call to srv.Close in a testing cleanup function registered by TestScript.

	t.Cleanup(func() {
		if err := srv.Close(); err != nil {
			t.Fatal(err)
		}
	})

Looking at the (*vcstest.Server).Close method, it's likely that the error is coming from a call to os.RemoveAll.

[FiloSottile]

The pattern in #66337 is definitely broad, and it hasn't progressed beyond the NeedsInvestigation / no status state yet. If it's narrowed down to something that doesn't match these errors, then it creates room for this failure mode to be tracked in another issue.

Ok, I think I made this issue the watchflakes tracking issue for this error message.

Edit: actually, if lowest-numbered wins, I think the old catchall will win.

[matloob]

So I'm not super familiar with this code, but I think the problem is in the vcweb handler in cmd/go/internal/vcweb/auth.go. I think we should be closing the accessFile, but we don't seem to be doing that. Leaving the file open when we try to delete it would cause this issue on Windows.

[ianlancetaylor]

@matloob Thanks for the pointer. That code is clearly incorrect, and I'll send a CL, but I don't understand why the problem would have just started appearing a few weeks ago.

[gopherbot]

Change https://go.dev/cl/640175 mentions this issue: cmd/go/internal/vcweb: close the .access file

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "cmd/go" && test == "TestScript" && `The process cannot access the file because it is being used by another process.`

2024-12-12 17:06 go1.24-windows-386 release-branch.go1.24@817d7bdc cmd/go.TestScript [ABORT] (log)

=== RUN   TestScript
vcs-test.golang.org rerouted to http://127.0.0.1:49842
https://vcs-test.golang.org rerouted to https://127.0.0.1:49843
go test proxy running at GOPROXY=http://127.0.0.1:49844/mod
    script_test.go:54: remove C:\b\s\w\ir\x\t\cmd-go-test-3795577681\vcstest3943647372\auth\or401\.access: The process cannot access the file because it is being used by another process.

2024-12-12 20:58 gotip-windows-amd64 go@14e5093e cmd/go.TestScript [ABORT] (log)

=== RUN   TestScript
vcs-test.golang.org rerouted to http://127.0.0.1:49834
https://vcs-test.golang.org rerouted to https://127.0.0.1:49835
go test proxy running at GOPROXY=http://127.0.0.1:49836/mod
    script_test.go:54: remove C:\b\s\w\ir\x\t\cmd-go-test-1581749979\vcstest1397970513\auth\or401\.access: The process cannot access the file because it is being used by another process.

2024-12-26 20:33 gotip-windows-386 go@cce75da3 cmd/go.TestScript [ABORT] (log)

=== RUN   TestScript
vcs-test.golang.org rerouted to http://127.0.0.1:49881
https://vcs-test.golang.org rerouted to https://127.0.0.1:49882
go test proxy running at GOPROXY=http://127.0.0.1:49883/mod
    script_test.go:54: remove C:\b\s\w\ir\x\t\cmd-go-test-2796287422\vcstest2369482085\auth\or401\.access: The process cannot access the file because it is being used by another process.

2024-12-30 17:19 gotip-windows-386 go@fd5e0d26 cmd/go.TestScript [ABORT] (log)

=== RUN   TestScript
vcs-test.golang.org rerouted to http://127.0.0.1:53883
https://vcs-test.golang.org rerouted to https://127.0.0.1:53884
go test proxy running at GOPROXY=http://127.0.0.1:53885/mod
    script_test.go:54: remove C:\b\s\w\ir\x\t\cmd-go-test-2286365711\vcstest4207156862\auth\or401\.access: The process cannot access the file because it is being used by another process.

— watchflakes

[ianlancetaylor]

CL 640175 is submitted. Let's see if the problem keeps happening.