Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

x/tools/gopls: optimize metadata invalidation #36165

Closed
bmhatfield opened this issue Dec 16, 2019 · 19 comments
Closed

x/tools/gopls: optimize metadata invalidation #36165

bmhatfield opened this issue Dec 16, 2019 · 19 comments

Comments

@bmhatfield
Copy link

@bmhatfield bmhatfield commented Dec 16, 2019

What version of Go are you using (go version)?

go 1.13.4 (latest available in Homebrew)

Does this issue reproduce with the latest release?

Currently using gopls from HEAD: 49a3e744

What operating system and processor architecture are you using (go env)?

OSX

What did you do?

Normal course of editing source code

What did you expect to see?

Completions and imports of valid go packages continue to work during a development session in VSCode

What did you see instead?

Certain imports stop working partway through an edit session. Restarting the gopls server temporarily resolves the issue.

So far I have only observed this issue with code generated by protoc-gen-go, which I did update this morning; however, I must emphasize that the code is valid Go and does initially work with gopls.

After an undetermined amount of time, the import lines (in all files that import it) become highlighted red for (seemingly at random) one of my generated proto files. Note that the generated file is not changing in any way during this time.

In the logs, the file that has suddenly stopped working from gopls' perspective has numerous log messages all saying the same thing: "no dep handle: no metadata for <import path>".

I then need to restart gopls to continue working.

EDIT: removed accidental copy/pasta text

EDIT2: We do not use dep as a dependency manager; this is exclusively managed by go modules.

@gopherbot gopherbot added this to the Unreleased milestone Dec 16, 2019
@gopherbot

This comment has been minimized.

Copy link

@gopherbot gopherbot commented Dec 16, 2019

Thank you for filing a gopls issue! Please take a look at the Troubleshooting guide, and make sure that you have provided all of the relevant information here.

@bmhatfield

This comment has been minimized.

Copy link
Author

@bmhatfield bmhatfield commented Dec 16, 2019

I believe I observe this issue most frequently when I attempt to reference a previously unreferenced type from the imported package for the first time during a code editing session.

Once that newly-referenced type is in the code, restarting gopls allows it to re-recognize the import as valid again, and it's happy to work with the code once more.

@bmhatfield

This comment has been minimized.

Copy link
Author

@bmhatfield bmhatfield commented Dec 16, 2019

I was able to eliminate protoc-gen-go as related to this issue:

2019/12/16 16:29:59 no dep handle: no metadata for github.com/digits/go-services/services/external-apis/dashboard/models/input
	package = github.com/digits/go-services/services/external-apis/dashboard/models/input
[Error - 4:29:59 PM] 2019/12/16 16:29:59 no dep handle: no metadata for github.com/digits/go-services/services/external-apis/dashboard/models/input
	package = github.com/digits/go-services/services/external-apis/dashboard/models/input
[Error - 4:30:00 PM] Request textDocument/definition failed.
  Message: no object for ident NewThread
  Code: 0
@heschik

This comment has been minimized.

Copy link
Contributor

@heschik heschik commented Dec 17, 2019

I'd probably need more logs, if not a reproducer, to make headway on this. What you're saying is consistent with gopls losing track of the low-level information ("metadata") about a package and then never trying to reload it. The first question is why it forgot about it. If you can show the logs from that point I'd be very interested to take a look.

It would be surprising if simply using a symbol from that package triggered the error. More likely is adding or removing an import of it, though of course that will happen automatically.

@stamblerre stamblerre modified the milestones: Unreleased, gopls v1.0 Dec 17, 2019
@bmhatfield

This comment has been minimized.

Copy link
Author

@bmhatfield bmhatfield commented Dec 17, 2019

Thanks for the note. Sorry for not providing enough debug information - I have yet to notice a consistent set of steps for reproducing this. I also can't reproduce it consistently enough to bisect which commit may have introduced the problem.

There's been a bunch of changes to gopls over the past 7 hours. I will update to current HEAD in the morning, and if the issue keeps happening, I'll turn on rpc.trace in gopls to get better logs.

@muirdm

This comment has been minimized.

Copy link

@muirdm muirdm commented Dec 19, 2019

I've looked at the metadata issues a bit recently. Packages can get stuck with no metadata because metadata doesn't get fetched very often. It is basically only fetched when a package is first opened and when an import is added to a file in the package (or when a dependent package's metadata gets reloaded). So if a package's metadata is cleared for whatever reason, the package will be broken until one of the above happens to trigger metadata refetch.

I've made a couple changes recently so we are more selective about invalidating metadata for the above reason. There are still some cases that probably trigger lost metadata:

  • changes to go.mode (if file watching is enabled)
  • creating the first test file in an existing package (just confirmed this does mess up metadata for the non-test package)

It is also possible metadata gets lost due to an unlucky context cancelation. For example, we clear a package's metadata as a new import is added, but then the request is canceled before go/packages has reloaded the metadata (so we are stuck with no metadata).

I played around with allowing metadata to be refreshed on-demand when we discover metadata is missing. The challenge is we don't know what to give to go/packages.Load() without the metadata. I tried adding a separate map to track each package's directory so we could reload the package's entire directory if we lose its metadata, but it didn't fix my issue at the time so I abandoned it.

@zikaeroh

This comment has been minimized.

Copy link

@zikaeroh zikaeroh commented Dec 21, 2019

I just experienced this. I did add a new package, then used it in a few other libraries, then added tests for that new package. No go.mod changes.

I have a giant log file (some 7 MB uncompressed) that's the entire editor session from start to finish, though I'm not sure how useful it'd be. You can see "mo metadata for" logs and "no package for import" showing up at the end.

logs.tar.gz

@muirdm

This comment has been minimized.

Copy link

@muirdm muirdm commented Dec 21, 2019

The metadata issue after adding a test file is easily reproducible for me:

  1. create foo.go
package foo
import "fmt"
func _() {
fmt.Println()
}
  1. create foo_test.go
package foo
  1. Observe brokenness in foo.go.
@stamblerre

This comment has been minimized.

Copy link
Contributor

@stamblerre stamblerre commented Dec 23, 2019

I'm actually not able to reproduce that behavior. Is this with modules or in GOPATH mode?

@muirdm

This comment has been minimized.

Copy link

@muirdm muirdm commented Dec 23, 2019

My steps were in module mode. Below is the rpc trace. foo.go becomes broken as we get the could not import fmt (no package for import fmt) diagnostic.

2019/12/23 12:03:18 debug server listening on port 58367
[Trace - 12:03:18.194 PM] Sending request 'initialize - (19527)'.
Params: {"processId":69135,"rootPath":"/Users/muir/scratch/foo","rootUri":"file:///Users/muir/scratch/foo","capabilities":{"workspace":{"workspaceEdit":{"documentChanges":true,"resourceOperations":["create","rename","delete"]},"applyEdit":true,"symbol":{"symbolKind":{"valueSet":[1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26]}},"executeCommand":{"dynamicRegistration":false},"didChangeWatchedFiles":{"dynamicRegistration":true},"workspaceFolders":true,"configuration":true},"textDocument":{"declaration":{"linkSupport":true},"definition":{"linkSupport":true},"implementation":{"linkSupport":true},"typeDefinition":{"linkSupport":true},"synchronization":{"willSave":true,"didSave":true,"willSaveWaitUntil":true},"documentSymbol":{"symbolKind":{"valueSet":[1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26]},"hierarchicalDocumentSymbolSupport":true},"formatting":{"dynamicRegistration":true},"rangeFormatting":{"dynamicRegistration":true},"rename":{"dynamicRegistration":true},"semanticHighlightingCapabilities":{"semanticHighlighting":null},"codeAction":{"dynamicRegistration":true,"codeActionLiteralSupport":{"codeActionKind":{"valueSet":["","quickfix","refactor","refactor.extract","refactor.inline","refactor.rewrite","source","source.organizeImports"]}}},"completion":{"completionItem":{"snippetSupport":true,"documentationFormat":["markdown"]},"contextSupport":true},"signatureHelp":{"signatureInformation":{"parameterInformation":{"labelOffsetSupport":true}}},"documentLink":{"dynamicRegistration":true},"hover":{"contentFormat":["markdown","plaintext"]},"foldingRange":{"dynamicRegistration":true,"rangeLimit":null,"lineFoldingOnly":false}}},"initializationOptions":null}


[Trace - 12:03:18.194 PM] Received response 'initialize - (19527)' in 0ms.
Result: {"capabilities":{"textDocumentSync":{"openClose":true,"change":2,"save":{}},"completionProvider":{"triggerCharacters":["."]},"hoverProvider":true,"signatureHelpProvider":{"triggerCharacters":["(",","]},"definitionProvider":true,"typeDefinitionProvider":true,"implementationProvider":true,"referencesProvider":true,"documentHighlightProvider":true,"documentSymbolProvider":true,"codeActionProvider":{"codeActionKinds":["quickfix","source.organizeImports"]},"codeLensProvider":{},"documentLinkProvider":{},"documentFormattingProvider":true,"documentOnTypeFormattingProvider":{"firstTriggerCharacter":""},"renameProvider":true,"foldingRangeProvider":true,"executeCommandProvider":{"commands":["tidy"]},"workspace":{"workspaceFolders":{"supported":true,"changeNotifications":"workspace/didChangeWorkspaceFolders"}}},"serverInfo":{"name":""}}


[Trace - 12:03:18.199 PM] Sending notification 'initialized'.
Params: {}


[Trace - 12:03:18.200 PM] Sending notification 'textDocument/didOpen'.
Params: {"textDocument":{"uri":"file:///Users/muir/scratch/foo/foo/foo.go","languageId":"go","version":0,"text":""}}


[Trace - 12:03:18.202 PM] Sending request 'textDocument/documentHighlight - (19528)'.
Params: {"textDocument":{"uri":"file:///Users/muir/scratch/foo/foo/foo.go"},"position":{"line":0,"character":0}}


[Trace - 12:03:18.329 PM] Received request 'workspace/configuration - (1)'.
Params: {"items":[{"scopeUri":"file:///Users/muir/scratch/foo","section":"gopls"},{"scopeUri":"file:///Users/muir/scratch/foo","section":"gopls-foo"}]}


[Trace - 12:03:18.329 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2019/12/23 12:03:18 Build info\n----------\ngolang.org/x/tools/gopls master\n    golang.org/x/tools/gopls@(devel)\n    github.com/BurntSushi/toml@v0.3.1 h1:WXkYYl6Yr3qBf1K79EBnL4mak0OimBfB0XUf9Vl28OQ=\n    github.com/sergi/go-diff@v1.0.0 h1:Kpca3qRNrduNnOQeazBd0ysaKrUJiIuISHxogkT9RPQ=\n    golang.org/x/mod@v0.1.1-0.20191105210325-c90efee705ee h1:WG0RUwxtNT4qqaXX3DPA8zHFNm/D9xaBpxzHt1WcA/E=\n    golang.org/x/sync@v0.0.0-20190423024810-112230192c58 h1:8gQV6CLnAEikrhgkHFbMAEhagSSnXWGV915qUMm9mrU=\n    golang.org/x/tools@v0.0.0-20191017151554-a3bc800455d5 =\u003e ../\n    golang.org/x/xerrors@v0.0.0-20191011141410-1b5146add898 h1:/atklqdjdhuosWIl6AIbOeHJjicWYPqR9bpxqxYG2pA=\n    honnef.co/go/tools@v0.0.1-2019.2.3 h1:3JgtbtFHMiCmsznwGVTUWbgGov+pVqnlf1dEJTNAXeM=\n\nGo info\n-------\ngo version go1.13.3 darwin/amd64\n\nGO111MODULE=\"\"\nGOARCH=\"amd64\"\nGOBIN=\"\"\nGOCACHE=\"/Users/muir/Library/Caches/go-build\"\nGOENV=\"/Users/muir/Library/Application Support/go/env\"\nGOEXE=\"\"\nGOFLAGS=\"\"\nGOHOSTARCH=\"amd64\"\nGOHOSTOS=\"darwin\"\nGONOPROXY=\"\"\nGONOSUMDB=\"\"\nGOOS=\"darwin\"\nGOPATH=\"/Users/muir/projects/<project>/go\"\nGOPRIVATE=\"\"\nGOPROXY=\"https://proxy.golang.org,direct\"\nGOROOT=\"/usr/local/go\"\nGOSUMDB=\"sum.golang.org\"\nGOTMPDIR=\"\"\nGOTOOLDIR=\"/usr/local/go/pkg/tool/darwin_amd64\"\nGCCGO=\"gccgo\"\nAR=\"ar\"\nCC=\"clang\"\nCXX=\"clang++\"\nCGO_ENABLED=\"1\"\nGOMOD=\"/Users/muir/scratch/foo/go.mod\"\nCGO_CFLAGS=\"-g -O2\"\nCGO_CPPFLAGS=\"\"\nCGO_CXXFLAGS=\"-g -O2\"\nCGO_FFLAGS=\"-g -O2\"\nCGO_LDFLAGS=\"-g -O2\"\nPKG_CONFIG=\"pkg-config\"\nGOGCCFLAGS=\"-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/_q/1xpb0k992ll803xsldpx0qyr0000gn/T/go-build540774488=/tmp/go-build -gno-record-gcc-switches -fno-common\"\n"}


[Trace - 12:03:18.333 PM] Sending response 'workspace/configuration - (1)' took 3ms.
Result: [{"env":{},"buildFlags":[],"hoverKind":"SynopsisDocumentation","usePlaceholders":true,"experimentalDisabledAnalyses":["ST1000"],"watchFileChanges":false,"verboseOutput":false,"staticcheck":true,"completionDocumentation":false,"completeUnimported":false},null]


[Trace - 12:03:18.333 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2019/12/23 12:03:18 using the -modfile flag is disabled\n\tdirectory = /Users/muir/scratch/foo"}


[Trace - 12:03:18.471 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2019/12/23 12:03:18 go/packages.Load\n\tquery = ./...\n\tpackages = 4"}


[Error - 12:03:18.496 PM] Received #19528 stat /Users/muir/scratch/foo/foo/foo.go: no such file or directory


[Trace - 12:03:18.510 PM] Received notification 'window/logMessage'.
Params: {"type":1,"message":"2019/12/23 12:03:18 : stat /Users/muir/scratch/foo/foo/foo.go: no such file or directory"}


[Trace - 12:03:22.925 PM] Sending notification 'textDocument/didChange'.
Params: {"textDocument":{"uri":"file:///Users/muir/scratch/foo/foo/foo.go","version":1},"contentChanges":[{"range":{"start":{"line":0,"character":0},"end":{"line":0,"character":0}},"rangeLength":0,"text":"package foo\nimport \"fmt\"\nfunc _() {\nfmt.Println()\n}"}]}


[Trace - 12:03:22.926 PM] Received notification 'window/logMessage'.
Params: {"type":1,"message":"2019/12/23 12:03:22 : stat /Users/muir/scratch/foo/foo/foo.go: no such file or directory"}


[Trace - 12:03:22.928 PM] Sending notification 'textDocument/didChange'.
Params: {"textDocument":{"uri":"file:///Users/muir/scratch/foo/foo/foo.go","version":2},"contentChanges":[{"range":{"start":{"line":0,"character":0},"end":{"line":4,"character":1}},"rangeLength":51,"text":"package foo\nimport \"fmt\"\nfunc _() {\nfmt.Println()\n}"}]}


[Trace - 12:03:22.928 PM] Received notification 'window/logMessage'.
Params: {"type":1,"message":"2019/12/23 12:03:22 : stat /Users/muir/scratch/foo/foo/foo.go: no such file or directory"}


[Trace - 12:03:22.930 PM] Sending notification 'textDocument/didChange'.
Params: {"textDocument":{"uri":"file:///Users/muir/scratch/foo/foo/foo.go","version":3},"contentChanges":[{"range":{"start":{"line":4,"character":0},"end":{"line":4,"character":1}},"rangeLength":1,"text":"}"}]}


[Trace - 12:03:22.930 PM] Received notification 'window/logMessage'.
Params: {"type":1,"message":"2019/12/23 12:03:22 : stat /Users/muir/scratch/foo/foo/foo.go: no such file or directory"}


[Trace - 12:03:23.139 PM] Sending request 'textDocument/documentHighlight - (19529)'.
Params: {"textDocument":{"uri":"file:///Users/muir/scratch/foo/foo/foo.go"},"position":{"line":4,"character":1}}


[Error - 12:03:23.139 PM] Received #19529 stat /Users/muir/scratch/foo/foo/foo.go: no such file or directory


[Trace - 12:03:23.767 PM] Sending notification 'textDocument/didChange'.
Params: {"textDocument":{"uri":"file:///Users/muir/scratch/foo/foo/foo.go","version":4},"contentChanges":[{"range":{"start":{"line":4,"character":1},"end":{"line":4,"character":1}},"rangeLength":0,"text":"\n"}]}


[Trace - 12:03:23.767 PM] Received notification 'window/logMessage'.
Params: {"type":1,"message":"2019/12/23 12:03:23 : stat /Users/muir/scratch/foo/foo/foo.go: no such file or directory"}


[Trace - 12:03:23.769 PM] Sending request 'textDocument/formatting - (19530)'.
Params: {"textDocument":{"uri":"file:///Users/muir/scratch/foo/foo/foo.go"},"options":{"tabSize":2,"insertSpaces":false}}


[Error - 12:03:23.769 PM] Received #19530 stat /Users/muir/scratch/foo/foo/foo.go: no such file or directory


[Trace - 12:03:23.783 PM] Sending notification 'textDocument/didSave'.
Params: {"textDocument":{"uri":"file:///Users/muir/scratch/foo/foo/foo.go","version":4},"text":null}


[Trace - 12:03:28.027 PM] Sending notification 'textDocument/didOpen'.
Params: {"textDocument":{"uri":"file:///Users/muir/scratch/foo/foo/foo_test.go","languageId":"go","version":0,"text":""}}


[Trace - 12:03:28.039 PM] Sending request 'textDocument/documentHighlight - (19531)'.
Params: {"textDocument":{"uri":"file:///Users/muir/scratch/foo/foo/foo_test.go"},"position":{"line":0,"character":0}}


[Trace - 12:03:28.167 PM] Received response 'textDocument/documentHighlight - (19531)' in 127ms.
Result: []


[Trace - 12:03:28.167 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2019/12/23 12:03:28 go/packages.Load\n\tquery = file=/Users/muir/scratch/foo/foo/foo_test.go\n\tpackages = 0"}


[Trace - 12:03:28.167 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2019/12/23 12:03:28 go/packages.Load\n\tquery = file=/Users/muir/scratch/foo/foo/foo_test.go\n\tpackages = 0"}


[Trace - 12:03:28.167 PM] Received notification 'window/logMessage'.
Params: {"type":1,"message":"2019/12/23 12:03:28 diagnoseFile: could not generate diagnostics: no packages found for query file=/Users/muir/scratch/foo/foo/foo_test.go"}


[Trace - 12:03:28.167 PM] Received notification 'window/logMessage'.
Params: {"type":1,"message":"2019/12/23 12:03:28 no highlight: getting file for Highlight: no packages found for query file=/Users/muir/scratch/foo/foo/foo_test.go\n\tURI = file:///Users/muir/scratch/foo/foo/foo_test.go"}


[Trace - 12:03:30.998 PM] Sending notification 'textDocument/didChange'.
Params: {"textDocument":{"uri":"file:///Users/muir/scratch/foo/foo/foo_test.go","version":1},"contentChanges":[{"range":{"start":{"line":0,"character":0},"end":{"line":0,"character":0}},"rangeLength":0,"text":"package foo"}]}


[Trace - 12:03:31.007 PM] Sending notification 'textDocument/didChange'.
Params: {"textDocument":{"uri":"file:///Users/muir/scratch/foo/foo/foo_test.go","version":2},"contentChanges":[{"range":{"start":{"line":0,"character":0},"end":{"line":0,"character":11}},"rangeLength":11,"text":"package foo"}]}


[Trace - 12:03:31.010 PM] Sending notification 'textDocument/didChange'.
Params: {"textDocument":{"uri":"file:///Users/muir/scratch/foo/foo/foo_test.go","version":3},"contentChanges":[{"range":{"start":{"line":0,"character":10},"end":{"line":0,"character":11}},"rangeLength":1,"text":"o"}]}


[Trace - 12:03:31.011 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2019/12/23 12:03:31 go/packages.Load\n\tquery = file=/Users/muir/scratch/foo/foo/foo_test.go\n\tpackages = 0"}


[Trace - 12:03:31.011 PM] Received notification 'window/logMessage'.
Params: {"type":1,"message":"2019/12/23 12:03:31 diagnoseFile: could not generate diagnostics: go [list -f {{context.GOARCH}} {{context.Compiler}} -- unsafe]: signal: killed: "}


[Trace - 12:03:31.011 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2019/12/23 12:03:31 go/packages.Load\n\tquery = file=/Users/muir/scratch/foo/foo/foo_test.go\n\tpackages = 0"}


[Trace - 12:03:31.011 PM] Received notification 'window/logMessage'.
Params: {"type":1,"message":"2019/12/23 12:03:31 diagnoseFile: could not generate diagnostics: couldn't exec 'go [list -f {{context.GOARCH}} {{context.Compiler}} -- unsafe]': context canceled *errors.errorString"}


[Trace - 12:03:31.127 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2019/12/23 12:03:31 go/packages.Load\n\tquery = file=/Users/muir/scratch/foo/foo/foo_test.go\n\tpackages = 1"}


[Trace - 12:03:31.127 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2019/12/23 12:03:31 go/packages.Load\n\tpackage = foo/foo\n\tfiles = [/Users/muir/scratch/foo/foo/foo.go /Users/muir/scratch/foo/foo/foo_test.go]"}


[Trace - 12:03:31.128 PM] Received notification 'textDocument/publishDiagnostics'.
Params: {"uri":"file:///Users/muir/scratch/foo/foo/foo.go","version":4,"diagnostics":[{"range":{"start":{"line":1,"character":7},"end":{"line":1,"character":12}},"severity":1,"source":"compiler","message":"could not import fmt (no package for import fmt)"}]}


[Trace - 12:03:31.128 PM] Received notification 'textDocument/publishDiagnostics'.
Params: {"uri":"file:///Users/muir/scratch/foo/foo/foo_test.go","version":3,"diagnostics":[]}


[Trace - 12:03:31.214 PM] Sending request 'textDocument/documentHighlight - (19532)'.
Params: {"textDocument":{"uri":"file:///Users/muir/scratch/foo/foo/foo_test.go"},"position":{"line":0,"character":11}}


[Trace - 12:03:31.214 PM] Received response 'textDocument/documentHighlight - (19532)' in 0ms.
Result: [{"range":{"start":{"line":0,"character":8},"end":{"line":1,"character":0}},"kind":1}]


[Trace - 12:03:31.972 PM] Sending notification 'textDocument/didChange'.
Params: {"textDocument":{"uri":"file:///Users/muir/scratch/foo/foo/foo_test.go","version":4},"contentChanges":[{"range":{"start":{"line":0,"character":11},"end":{"line":0,"character":11}},"rangeLength":0,"text":"\n"}]}


[Trace - 12:03:31.973 PM] Received notification 'textDocument/publishDiagnostics'.
Params: {"uri":"file:///Users/muir/scratch/foo/foo/foo.go","version":4,"diagnostics":[{"range":{"start":{"line":1,"character":7},"end":{"line":1,"character":12}},"severity":1,"source":"compiler","message":"could not import fmt (no package for import fmt)"}]}


[Trace - 12:03:31.974 PM] Sending request 'textDocument/formatting - (19533)'.
Params: {"textDocument":{"uri":"file:///Users/muir/scratch/foo/foo/foo_test.go"},"options":{"tabSize":2,"insertSpaces":false}}


[Trace - 12:03:31.974 PM] Received response 'textDocument/formatting - (19533)' in 0ms.
Result: []


[Trace - 12:03:31.980 PM] Sending request 'textDocument/codeAction - (19534)'.
Params: {"textDocument":{"uri":"file:///Users/muir/scratch/foo/foo/foo_test.go"},"range":{"start":{"line":0,"character":11},"end":{"line":0,"character":11}},"context":{"diagnostics":[]}}


[Trace - 12:03:31.993 PM] Received response 'textDocument/codeAction - (19534)' in 12ms.
Result: {}


[Trace - 12:03:32.005 PM] Sending notification 'textDocument/didSave'.
Params: {"textDocument":{"uri":"file:///Users/muir/scratch/foo/foo/foo_test.go","version":4},"text":null}
@stamblerre

This comment has been minimized.

Copy link
Contributor

@stamblerre stamblerre commented Dec 23, 2019

Can you share this log with verbose output enabled? I think this must be related to foo_test.go being created as an overlay file because I don't see this behavior with VS Code (when you create a file in VS Code, it saves it on disk).

@stamblerre stamblerre modified the milestones: gopls v1.0, gopls/v0.3.0 Jan 15, 2020
@stamblerre stamblerre changed the title x/tools/gopls: "no dep handle: no metadata for ..." x/tools/gopls: random metadata invalidation Jan 16, 2020
@stamblerre

This comment has been minimized.

Copy link
Contributor

@stamblerre stamblerre commented Jan 16, 2020

I thought that this was fixed, but I seem to have just run into this again at master (7042ee6). I keep seeing it in golang.org/x/tools/internal/lsp/source/source_test.go, and specifically the golang.org/x/tools/internal/lsp/cache import gets invalidated for some reason, and then never comes back. It is a test-variant dependency, so that seems relevant, as well as the fact that golang.org/x/tools/internal/lsp/cache is also a workspace package in my workspace.

@stamblerre stamblerre changed the title x/tools/gopls: random metadata invalidation x/tools/gopls: unexpected metadata invalidation Jan 16, 2020
@muirdm

This comment has been minimized.

Copy link

@muirdm muirdm commented Jan 16, 2020

I was seeing something like that before. Does it happen when you change an import in a file in the cache package? You can "fix" it by forcing a metadata refresh in source by changing an import.

The details are fuzzy, but I think the issue was that reloading cache's metadata cleared out the source_test package's "cache" dependency metadata, but the only thing that fills that metadata in is loading the source package's metadata (i.e. reloading cache's metadata doesn't fill source_test's "cache" dependency metadata back in).

Maybe when reloading a package's metadata we also need to trigger reloading metadata of any xtest dependents?

@stamblerre

This comment has been minimized.

Copy link
Contributor

@stamblerre stamblerre commented Jan 16, 2020

Yes, it definitely seems like something a missing reverse dependency link with x_tests. Another thing I just noticed is that, specifically in source_test.go, removing an import and then organizing imports does not clear out the diagnostics (and results in an error of no metadata for source_test).

@myitcv

This comment has been minimized.

Copy link
Member

@myitcv myitcv commented Jan 16, 2020

Once we land an upgrade to the latest x/tools and gopls in govim (govim/govim#675) I will be adding a few tests around xtest packages.

@gopherbot

This comment has been minimized.

Copy link

@gopherbot gopherbot commented Jan 16, 2020

Change https://golang.org/cl/215117 mentions this issue: internal/lsp/cache: invalidate metadata for x_tests and test variants

@stamblerre

This comment has been minimized.

Copy link
Contributor

@stamblerre stamblerre commented Jan 17, 2020

Re-opening to make sure that we optimize the metadata invalidation as discussed on the above CL.

@stamblerre stamblerre reopened this Jan 17, 2020
@stamblerre stamblerre changed the title x/tools/gopls: unexpected metadata invalidation x/tools/gopls: optimize metadata invalidation Jan 17, 2020
@gopherbot

This comment has been minimized.

Copy link

@gopherbot gopherbot commented Jan 23, 2020

Change https://golang.org/cl/215901 mentions this issue: internal/lsp: invalidate metadata for all reverse transitive deps

@stamblerre

This comment has been minimized.

Copy link
Contributor

@stamblerre stamblerre commented Jan 23, 2020

Since I accidentally combined two CLs and put the changes I had wanted to make into https://golang.org/cl/215902/, I'll put a description of what I had intended to do here. The intention is evident in https://golang.org/cl/215901.

Previous changes tried to reduce the amount of metadata invalidated for
reverse transitive dependencies, but our metadata handling model
fundamentally does not support this behavior. We weren't noticing the
effects of this behavior because, in practice, we will always eagerly
re-load metadata for workspace packages. However, if this were not the
case, we would end up with metadata that had holes in the dependencies.

@stamblerre stamblerre closed this Jan 23, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
7 participants
You can’t perform that action at this time.