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

bcmills · 2021-11-17T16:38:57Z

--- 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'

CC @findleyr

The text was updated successfully, but these errors were encountered:

gopherbot · 2021-11-17T16:45:21Z

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

This test is probably detecting a real bug that exclusively affects Windows. To avoid masking other bugs, let's skip the test on that platform until the bug is fixed. For golang/go#49646 Change-Id: I38c615d47454ecfd72b416fff2018973b3ae9259 Reviewed-on: https://go-review.googlesource.com/c/tools/+/364676 Trust: Bryan C. Mills <bcmills@google.com> Run-TryBot: Bryan C. Mills <bcmills@google.com> gopls-CI: kokoro <noreply+kokoro@google.com> TryBot-Result: Go Bot <gobot@golang.org> Reviewed-by: Robert Findley <rfindley@google.com>

findleyr · 2022-04-11T20:11:15Z

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 · 2022-04-11T20:17:31Z

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 · 2022-04-11T21:20:42Z

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

Running go mod vendor can result in vendor/modules.txt being transiently deleted while it is being updated. On Windows this introduces potential problems with file locking, if modules.txt is being read by another go process, such as an ongoing package load. Change the command to use RunGoCommandPiped, which executes serially within the gopls process. For golang/go#49646 Change-Id: If2d1fe5431122ba05014051a0e9c303cf7ee9cb2 Reviewed-on: https://go-review.googlesource.com/c/tools/+/399714 Run-TryBot: Robert Findley <rfindley@google.com> Reviewed-by: Bryan Mills <bcmills@google.com> gopls-CI: kokoro <noreply+kokoro@google.com> TryBot-Result: Gopher Robot <gobot@golang.org>

findleyr · 2022-04-19T15:46:41Z

Trying to check whether this is resolved, I am running the command above:

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

@bcmills I get far fewer results than you cited, even when using the master versions of fetchlogs and greplogs. The last match I see is from 2021-09-09. Am I doing something wrong?

bcmills · 2022-04-19T15:52:08Z

The last match I see is from 2021-09-09.

How far back have you fetched x/tools? (You may need to pass a large -n to fetchlogs to get a longer history.)

findleyr · 2022-04-19T15:53:08Z

@bcmills I get far fewer results than you cited

To be precise, I'm doing the following:

$ fetchlogs -repo tools
fetching https://build.golang.org/?mode=json&page=0&repo=golang.org%2Fx%2Ftools
fetchlogs: Loading data from log *maintner.netMutSource ...
fetchlogs: Downloading 11352894 bytes of https://storage.googleapis.com/golang-maintner-log/0129.7118f5afc9cbffce24b7e120f478e170a1acfab99e88df85e4f324ce.mutlog ...
fetchlogs: wrote /home/rfindley/.cache/golang-maintner/0129.7118f5afc9cbffce24b7e120f478e170a1acfab99e88df85e4f324ce.mutlog
fetchlogs: Downloading 16777076 bytes of https://storage.googleapis.com/golang-maintner-log/0130.3296b558ec374e1086e0552ed67a6e4043f9b5d4aded2a33b6a5c468.mutlog ...
fetchlogs: wrote /home/rfindley/.cache/golang-maintner/0130.3296b558ec374e1086e0552ed67a6e4043f9b5d4aded2a33b6a5c468.mutlog
fetchlogs: Downloading 16177082 bytes of https://maintner.golang.org/logs/131 ...
fetchlogs: wrote /home/rfindley/.cache/golang-maintner/0131.growing.mutlog
fetchlogs: Reloaded data from log *maintner.netMutSource.
fetching https://build.golang.org/?mode=json&page=1&repo=golang.org%2Fx%2Ftools
$ greplogs --dashboard -md -l -e 'FAIL: TestInconsistentVendoring'
[2021-09-09T13:25:25-c163c31/windows-amd64-2016](https://build.golang.org/log/2fb1ca7a3c233d7db524155cf299b48f4c4e1e0f)
[2021-08-18T17:22:40-bf6c7f2/windows-arm64-10](https://build.golang.org/log/73b5502b049fd92646149e429e20326d12f9a11d)

bcmills · 2022-04-19T15:55:48Z

Yeah, the default -n is only 300, and for the subrepos each go commit counts as one IIRC.

findleyr · 2022-04-19T16:05:57Z

Aha, thanks. I think for that reason I was only seeing the older failures in my cache. Now I see the same as you. It seem statistically significant based on the prior frequency that this has not failed since being re-enabled 8 days ago. It might be good to give it another week, but I'm going to close this now so that I don't have to follow up in a week :) If it starts flaking again presumably we'll find an re-open this issue.

bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Nov 17, 2021

gopherbot added the Tools This label describes issues relating to any tools in the x/tools repository. label Nov 17, 2021

bcmills added gopls Issues related to the Go language server, gopls. and removed Tools This label describes issues relating to any tools in the x/tools repository. labels Nov 17, 2021

gopherbot added this to the Unreleased milestone Nov 17, 2021

bcmills added OS-Windows Tools This label describes issues relating to any tools in the x/tools repository. labels Nov 17, 2021

findleyr modified the milestones: Unreleased, gopls/unplanned Nov 17, 2021

findleyr closed this as completed Apr 19, 2022

findleyr modified the milestones: gopls/unplanned, gopls/v0.8.3 Aug 14, 2022

golang locked and limited conversation to collaborators Aug 14, 2023

gopherbot added the FrozenDueToAge label Aug 14, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

bcmills commented Nov 17, 2021

gopherbot commented Nov 17, 2021

findleyr commented Apr 11, 2022

bcmills commented Apr 11, 2022

gopherbot commented Apr 11, 2022

findleyr commented Apr 19, 2022

bcmills commented Apr 19, 2022

findleyr commented Apr 19, 2022

bcmills commented Apr 19, 2022

findleyr commented Apr 19, 2022

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

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

Comments

bcmills commented Nov 17, 2021

gopherbot commented Nov 17, 2021

findleyr commented Apr 11, 2022

bcmills commented Apr 11, 2022

gopherbot commented Apr 11, 2022

findleyr commented Apr 19, 2022

bcmills commented Apr 19, 2022

findleyr commented Apr 19, 2022

bcmills commented Apr 19, 2022

findleyr commented Apr 19, 2022