x/tools/gopls/internal/regtest/misc: frequent TestInconsistentVendoring failures on Windows

[bcmills]

--- FAIL: TestInconsistentVendoring (0.29s)
    --- FAIL: TestInconsistentVendoring/singleton (0.29s)
        vendor_test.go:63: no quick fixes were applied
FAIL
FAIL	golang.org/x/tools/gopls/internal/regtest/misc	166.557s

It appears that go mod vendor can't delete vendor/modules.txt because something else in the test is holding it open.
(Ideally perhaps go mod vendor should overwrite the file in-place instead of deleting and recreating it, but that seems like a separate bug.)

greplogs --dashboard -md -l -e 'FAIL: TestInconsistentVendoring'

2021-11-16T19:18:26-8122e49-b954f58/windows-386-2008
2021-11-12T00:16:15-c116b72-7bed3c7/windows-386-2008
2021-11-05T19:01:13-4ab7496-93bab8a/windows-386-2008
2021-11-02T20:34:09-182bbdc-f9cb33c/windows-386-2008
2021-11-02T19:48:11-f6440c8-1011e26/windows-386-2008
2021-10-30T00:47:26-a6c6f4b-d19c5bd/windows-amd64-2016
2021-10-25T23:28:03-f916b54-e9eb66d/windows-amd64-2016
2021-10-25T20:40:31-5a40697-c580180/windows-amd64-race
2021-10-12T22:12:04-94178a2-732f6fa/windows-386-2008
2021-09-21T20:39:31-b98090b-48cf96c/windows-amd64-2016
2021-09-17T23:04:15-2758b04-07b30a4/windows-386-2008
2021-09-15T14:06:14-4ba3eff-e4dfd78/windows-amd64-2016
2021-09-14T19:06:02-258ee27-21a4e67/windows-386-2008
2021-09-09T13:49:11-c163c31-021fc24/windows-amd64-2016
2021-08-20T18:45:25-bf6c7f2-0f25251/windows-arm64-10
2021-08-15T19:56:18-a55d515-717894c/windows-386-2008
2021-08-15T15:51:49-a55d515-48dfddb/windows-386-2008
2021-08-03T16:06:16-594b3a2-7921829/windows-386-2008
2021-08-02T20:16:24-45eff0f-accf363/windows-amd64-race
2021-07-07T16:41:12-7edcfe5-c96833e/windows-amd64-2016
2021-06-30T22:02:09-f0847e0-4711bf3/windows-amd64-2016
2021-05-19T13:04:45-17b3466-658b5e6/linux-arm-scaleway
2021-05-10T21:56:33-0185c7e-07d8cba/linux-arm-scaleway
2021-05-06T19:28:34-c0140e8-07d8cba/linux-arm-scaleway
2021-05-06T03:14:34-08a4f34-ba7cac4/linux-arm-scaleway
2021-05-06T02:57:18-f4a4129-ba7cac4/linux-arm-scaleway
2021-05-05T22:35:07-dd255f2-ba7cac4/linux-arm-scaleway
2021-05-05T21:11:25-68c6cab-ba7cac4/linux-arm-scaleway
2021-05-05T20:44:55-68c6cab-c0a7ecf/linux-arm-scaleway
2021-05-05T01:45:45-7cab0ef-c0a7ecf/linux-arm-scaleway
2021-05-04T19:12:24-f03daea-c0a7ecf/linux-arm-scaleway
2021-05-03T21:45:16-42984c4-72ccabc/linux-arm-scaleway
2021-05-03T20:05:58-19b1717-72ccabc/linux-arm-scaleway
2021-05-03T16:36:24-3e17c62-72ccabc/linux-arm-scaleway
2021-04-30T14:46:28-291330a-72ccabc/linux-arm-scaleway
2021-04-29T13:06:21-28c1392-5aed4ce/linux-arm-scaleway
2021-04-28T21:52:02-800adbe-5aed4ce/linux-arm-scaleway
2021-04-28T19:13:50-16b25d2-ad989c7/linux-arm-scaleway
2021-04-28T01:46:37-16b25d2-06c9756/linux-arm-scaleway
2021-04-27T20:55:22-7c72a84-06c9756/linux-arm-scaleway
2021-04-27T19:53:45-d0768c9-06c9756/linux-arm-scaleway
2021-04-27T15:36:10-6397a11-06c9756/linux-arm-scaleway
2021-04-27T12:58:28-fe1c548-06c9756/linux-arm-scaleway
2021-04-27T04:02:17-735ed62-06c9756/linux-arm-scaleway
2021-04-26T20:11:56-e3dc99f-06c9756/linux-arm-scaleway

CC @findleyr

[gopherbot]

Change https://golang.org/cl/364676 mentions this issue: gopls/internal/regtest/misc: skip TestInconsistentVendoring on Windows

[findleyr]

Ok, looked into this. Here is my analysis.

Consider the following section of logs:

[Trace - 19:38:17.553 PM] Sending request 'workspace/executeCommand - (3)'.
Params: {"command":"gopls.vendor","arguments":[{"URI":"file:///C:/Users/gopher/AppData/Local/Temp/gopls-regtest-2529229009/TestInconsistentVendoring/singleton/work/go.mod"}]}


[Trace - 19:38:17.554 PM] Received request 'window/workDoneProgress/create - (8)'.
Params: {"token":"1136060433075388333"}


[Trace - 19:38:17.554 PM] Sending response 'window/workDoneProgress/create - (8)' in 0ms.
Result: 


[Trace - 19:38:17.554 PM] Received notification '$/progress'.
Params: {"token":"1136060433075388333","value":{"kind":"begin","title":"Running go mod vendor","cancellable":true,"message":"Running..."}}


[Trace - 19:38:17.555 PM] Received notification 'window/logMessage'.
Params: {"type":1,"message":"2021/11/16 19:38:17 workspace packages: diagnosing file:///C:/Users/gopher/AppData/Local/Temp/gopls-regtest-2529229009/TestInconsistentVendoring/singleton/work/go.mod: err: exit status 1: stderr: go: inconsistent vendoring in C:\\Users\\gopher\\AppData\\Local\\Temp\\gopls-regtest-2529229009\\TestInconsistentVendoring\\singleton\\work:\n\tgolang.org/x/hello@v1.2.3: is explicitly required in go.mod, but not marked as explicit in vendor/modules.txt\n\n\tTo ignore the vendor directory, use -mod=readonly or -mod=mod.\n\tTo sync the vendor directory, run:\n\t\tgo mod vendor\n: packages.Load error\n"}


[Trace - 19:38:17.555 PM] Received request 'window/workDoneProgress/create - (9)'.
Params: {"token":"7460344659616510194"}


[Trace - 19:38:17.555 PM] Sending response 'window/workDoneProgress/create - (9)' in 0ms.
Result: 


[Trace - 19:38:17.555 PM] Received notification '$/progress'.
Params: {"token":"7460344659616510194","value":{"kind":"begin","title":"Load","message":"Loading query=[file=C:\\Users\\gopher\\AppData\\Local\\Temp\\gopls-regtest-2529229009\\TestInconsistentVendoring\\singleton\\work\\a\\a1.go]"}}


[Trace - 19:38:17.643 PM] Received notification '$/progress'.
Params: {"token":"1136060433075388333","value":{"kind":"end","message":"failed"}}


[Error - Received] 19:38:17.643 PM #3 err: exit status 1: stderr: go: downloading golang.org/x/hello v1.2.3
go mod vendor: remove C:\Users\gopher\AppData\Local\Temp\gopls-regtest-2529229009\TestInconsistentVendoring\singleton\work\vendor\modules.txt: The process cannot access the file because it is being used by another process.

In this segment of the logs, we see that asynchronous diagnostics run on a1.go, while the go mod vendor command is executing. These diagnostics trigger a file load for a1.go, since the initial workspace load failed, and the likely scenario is that go list for this file load was holding modules.txt while go mod vendor tried to delete it. The final message is the failure of go mod vendor due to file locking.

It looks like we can just change the go mod vendor command to use "gocommand.RunPiped" rather than "gocommand.Run".

[bcmills]

The locking behavior would definitely explain the Windows-specific failure mode — file locks on Windows are enforced, whereas on Unix platforms they're only advisory.

Switching to RunPiped seems at least worth a shot!

[gopherbot]

Change https://go.dev/cl/399714 mentions this issue: internal/lsp: run go mod vendor exclusively to avoid file contention