cmd/go: indexed packages not invalidated when location of parent go.mod file changes #53586

findleyr · 2022-06-28T18:04:56Z

We have two concerning test failures on the builders, which seem to have the same root cause:

darwin-amd64-10_14: https://build.golang.org/log/88d3fe6fbcfe0ba7110aac537e5cdcae51737d4d
openbsd-386-70: https://build.golang.org/log/79c6a4815792817f70a447fecb4557aa33b90ff0

Both of these are concerning because gopls is failing to find package metadata for a file, even after reloading (and apparently successfully loading file data).

It's suprising that files are left orphaned by the initial metadata load (in a typical run, they aren't). It's also suprising that the reloads (via reloadOrphanedFiles) do not correctly result in the requisite file associations. Logging in those test failures indicates that ~~the loaded packages include the orphaned files, yet they continue to be reloaded~~ (EDIT: my eyes deceived me, the paths don't match! See below).

This is likely related to my recent changes to metadata graph building. I'd like to understand this before releasing gopls@v0.9.0. Unfortunately, it seems exceedingly rare; I will see if I can add more instrumentation and reproduce via slowbots.

CC @adonovan

findleyr · 2022-06-28T18:41:40Z

Ok, two new failures just occurred on darwin builders:
https://build.golang.org/log/2a5d73ac2f31f441c1b3a939c5c29addd21f9c1c
https://build.golang.org/log/438b80942ea9ff3a766b43d9fe90516aed97e69a

All things considered this is good news, because hopefully additional instrumentation will allow root causing. Unfortunately, this means this really must block the v0.9.0 release; unless we convince ourselves that there is something incorrect about the setup of internal/lsp tests, this failure rate is certainly high enough to affect our users.

The increased frequency also makes it more likely that a recent change contributed to these failures.

gopherbot · 2022-06-28T18:51:49Z

Change https://go.dev/cl/414854 mentions this issue: internal/lsp: add additional instrumentation around package loading

Add some additional logging to help debug golang/go#53586 For golang/go#53586 Change-Id: I0574fb01be47b265cd6e412855794bc2cb836dff Reviewed-on: https://go-review.googlesource.com/c/tools/+/414854 gopls-CI: kokoro <noreply+kokoro@google.com> Reviewed-by: Alan Donovan <adonovan@google.com> TryBot-Result: Gopher Robot <gobot@golang.org> Run-TryBot: Robert Findley <rfindley@google.com> Auto-Submit: Robert Findley <rfindley@google.com>

findleyr · 2022-06-29T21:06:43Z

Aha! I only just now noticed the asymmetry between query and result, in the test logs

2022/06/28 11:27:39 go/packages.Load
    snapshot=1
    directory=/var/folders/9w/4l2_g3kx01x199n37fbmv3s80000gn/T/workdir-host-darwin-10_14/tmp/gopls-workspace-mod3193680098
    query=[file=/var/folders/9w/4l2_g3kx01x199n37fbmv3s80000gn/T/workdir-host-darwin-10_14/tmp/TestLSP_MultiModule32642401/lsp/testmodule/interfacerank/interface_rank.go]
    packages=1
2022/06/28 11:27:39 go/packages.Load
    snapshot=1
    package="golang.org/x/tools/internal/lsp/interfacerank"
    files=[/var/folders/9w/4l2_g3kx01x199n37fbmv3s80000gn/T/workdir-host-darwin-10_14/tmp/TestLSP_MultiModule32642401/lsp/testmodule/testmodule/interfacerank/interface_rank.go]

Note that we're querying for testmodule/interfacerank/interface_rank.go, but getting back a package containing an extra 'testmodule': testmodule/testmodule/interfacerank/interface_rank.go. This would explain why it only affects the 'MultiModule' run mode, which creates this synthetic module.

Because the load succeeds, we don't mark these files as unloadable and continue to reload them ad-infinitum.

The bug may be in go/packages, or may be in one of the transformations gopls applies. I haven't figured out where the extra 'testmodule' is coming from.

findleyr · 2022-06-30T02:58:20Z

Ok, I've stared at this for a while, reading the gopls, go/packages, go list, and modindex code. With that said, I haven't made much progress.

This appears to be a go list or go/packages bug, perhaps related to the recent change to package indexing? The first failure was shortly after https://go.dev/cl/413815 landed ("cmd/go: add per-package indexing for modules outside mod cache", though I don't necessarily think that CL is implicated).

A few notes:

the go.mod file starts out in lsp/go.mod but is moved to lsp/testmodule/go.mod, so perhaps that move could cause the extra "testmodule" due to improper invalidation. That seems plausible, but unlikely because the file move happens before we start up the tests, and therefore should be before we invoke the go command for the first time
there are many packages in the module, but only a subset get this bug, which is strange
go/packages doesn't appear to verify that GoFile paths match the file=query, only checking basenames. That would allow this bug: https://cs.opensource.google/go/x/tools/+/master:go/packages/golist.go;l=332;drc=7743d1d949f1006ad12b190d68996acafc84d1d6

@bcmills does this type of corruption ring any bells?

rsc · 2022-06-30T15:05:56Z

I am looking into modindex to understand a performance problem and will look into this behavior too.

bcmills · 2022-06-30T16:27:55Z

I wonder if the per-package index needs to include the corresponding module's go.mod file (contents and location) in the cache key. That could potentially affect the import path and the directory relative to the module root.

gopherbot · 2022-06-30T17:55:54Z

Change https://go.dev/cl/415475 mentions this issue: cmd/go: include module root in package index key

gopherbot · 2022-06-30T17:55:54Z

Change https://go.dev/cl/415474 mentions this issue: cmd/go: add a 'sleep' command for script tests

Due to mtime skew we don't index mutable packages with an mtime younger than 2 seconds. In order to test indexed packages reliably, we want to be able to sleep long enough for the files in the package to be cached. (As an alternative we could instead use os.Chtimes to fake old enough timestamps, but sleeping keeps the tests more realistic.) For #53586. Change-Id: I1873f47c55a72d928451593b8c989f0092a557db Reviewed-on: https://go-review.googlesource.com/c/go/+/415474 Auto-Submit: Bryan Mills <bcmills@google.com> Run-TryBot: Bryan Mills <bcmills@google.com> Reviewed-by: Russ Cox <rsc@golang.org> TryBot-Result: Gopher Robot <gobot@golang.org>

gopherbot · 2022-06-30T18:20:55Z

Change https://go.dev/cl/415514 mentions this issue: cmd/go/internal/modindex: remove spurious field from index_format documentation

findleyr · 2022-06-30T18:58:46Z

Ok, the final piece of the puzzle: the packagestest runner actually does invoke the go command before calling the test function, here:
~~https://cs.opensource.google/go/x/tools/+/master:go/packages/packagestest/modules.go;l=187;drc=d5f48fca5379171ebce583082a3dd683c8f8ad75~~
EDIT: that wouldn't do it, but this would: https://cs.opensource.google/go/x/tools/+/master:go/packages/packagestest/expect.go;l=153;drc=facb0d30e9e8a14e6e9b3f3df1f49b003391d5f4

And then inside the test function, the go.mod is moved: https://cs.opensource.google/go/x/tools/+/master:internal/lsp/tests/tests.go;l=505;drc=ebc084af8ba794babff1d58912b41608629acd72)

So now everything makes sense.

…umentation The 'path' field was removed in an earlier revision to the format. While auditing the format, I also cleaned up a couple of minor typographical issues. For #53586. Change-Id: I4cd1ce9e970023441c11244428ed2971be1d8138 Reviewed-on: https://go-review.googlesource.com/c/go/+/415514 Reviewed-by: Ian Lance Taylor <iant@google.com> Run-TryBot: Bryan Mills <bcmills@google.com> Auto-Submit: Bryan Mills <bcmills@google.com> TryBot-Result: Gopher Robot <gobot@golang.org>

Due to mtime skew we don't index mutable packages with an mtime younger than 2 seconds. In order to test indexed packages reliably, we want to be able to sleep long enough for the files in the package to be cached. (As an alternative we could instead use os.Chtimes to fake old enough timestamps, but sleeping keeps the tests more realistic.) For golang#53586. Change-Id: I1873f47c55a72d928451593b8c989f0092a557db Reviewed-on: https://go-review.googlesource.com/c/go/+/415474 Auto-Submit: Bryan Mills <bcmills@google.com> Run-TryBot: Bryan Mills <bcmills@google.com> Reviewed-by: Russ Cox <rsc@golang.org> TryBot-Result: Gopher Robot <gobot@golang.org>

The package index format includes the directory relative to the module root. The module root for a given directory can change even if the contents of the directory itself do not (by adding or removing a go.mod file in some parent directory). Thus, we need to invalidate the index for a package when its module root location changes. Fixes golang#53586 (I think). Change-Id: I2d9f4de80e16bce75b3106a2bad4a11d8378d037 Reviewed-on: https://go-review.googlesource.com/c/go/+/415475 Reviewed-by: Russ Cox <rsc@golang.org> Auto-Submit: Bryan Mills <bcmills@google.com> Run-TryBot: Bryan Mills <bcmills@google.com> TryBot-Result: Gopher Robot <gobot@golang.org>

…umentation The 'path' field was removed in an earlier revision to the format. While auditing the format, I also cleaned up a couple of minor typographical issues. For golang#53586. Change-Id: I4cd1ce9e970023441c11244428ed2971be1d8138 Reviewed-on: https://go-review.googlesource.com/c/go/+/415514 Reviewed-by: Ian Lance Taylor <iant@google.com> Run-TryBot: Bryan Mills <bcmills@google.com> Auto-Submit: Bryan Mills <bcmills@google.com> TryBot-Result: Gopher Robot <gobot@golang.org>

findleyr added this to the gopls/v0.9.0 milestone Jun 28, 2022

gopherbot added Tools This label describes issues relating to any tools in the x/tools repository. gopls Issues related to the Go language server, gopls. labels Jun 28, 2022

bcmills added GoCommand cmd/go release-blocker labels Jun 30, 2022

bcmills modified the milestones: gopls/v0.9.0, Go1.19 Jun 30, 2022

bcmills self-assigned this Jun 30, 2022

bcmills changed the title ~~x/tools/gopls: "no packages" flake of the internal/lsp package~~ cmd/go: indexed packages not invalidated when location of parent go.mod file changes Jun 30, 2022

gopherbot closed this as completed in 981d594 Jun 30, 2022

bcmills mentioned this issue Jul 7, 2022

build dashboard triage log #52653

Closed

golang locked and limited conversation to collaborators Jun 30, 2023

gopherbot added the FrozenDueToAge label Jun 30, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

cmd/go: indexed packages not invalidated when location of parent go.mod file changes #53586

cmd/go: indexed packages not invalidated when location of parent go.mod file changes #53586

findleyr commented Jun 28, 2022 •

edited

findleyr commented Jun 28, 2022

gopherbot commented Jun 28, 2022

findleyr commented Jun 29, 2022 •

edited

findleyr commented Jun 30, 2022

rsc commented Jun 30, 2022

bcmills commented Jun 30, 2022

gopherbot commented Jun 30, 2022

gopherbot commented Jun 30, 2022

gopherbot commented Jun 30, 2022

findleyr commented Jun 30, 2022 •

edited

cmd/go: indexed packages not invalidated when location of parent go.mod file changes #53586

cmd/go: indexed packages not invalidated when location of parent go.mod file changes #53586

Comments

findleyr commented Jun 28, 2022 • edited

findleyr commented Jun 28, 2022

gopherbot commented Jun 28, 2022

findleyr commented Jun 29, 2022 • edited

findleyr commented Jun 30, 2022

rsc commented Jun 30, 2022

bcmills commented Jun 30, 2022

gopherbot commented Jun 30, 2022

gopherbot commented Jun 30, 2022

gopherbot commented Jun 30, 2022

findleyr commented Jun 30, 2022 • edited

findleyr commented Jun 28, 2022 •

edited

findleyr commented Jun 29, 2022 •

edited

findleyr commented Jun 30, 2022 •

edited