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

Jump to bottom

x/tools/gopls: optimize metadata invalidation #36165

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

x/tools/gopls: optimize metadata invalidation #36165

bmhatfield opened this issue Dec 16, 2019 · 21 comments
Labels
FrozenDueToAge gopls Issues related to the Go language server, gopls. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Tools This label describes issues relating to any tools in the x/tools repository.
Milestone
gopls/v0.3.0

Comments

@bmhatfield
Copy link

bmhatfield commented Dec 16, 2019 •
edited

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 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 Dec 16, 2019
@gopherbot
Copy link

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
Copy link
Author

bmhatfield commented Dec 16, 2019 •
edited

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
Copy link
Author

bmhatfield commented Dec 16, 2019 •
edited

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

@heschi
Copy link
Contributor

heschi 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
Copy link
Author

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
Copy link

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
Copy link
Contributor

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
Copy link

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
Copy link
Contributor

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

@muirdm
Copy link

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
Copy link
Contributor

stamblerre commented Dec 23, 2019 •
edited

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
Copy link
Contributor

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
@stamblerre stamblerre added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jan 16, 2020
@muirdm
Copy link

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
Copy link
Contributor

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
Copy link
Member

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
Copy link

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

@stamblerre
Copy link
Contributor

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
Copy link

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

@stamblerre
Copy link
Contributor

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.

@magandrez
Copy link

magandrez commented Dec 28, 2020 •
edited

Not sure if this is the right place, please direct me to the right solution/place where to raise my issue.

I am able to reproduce this error in all the services I write in go, but only for the external packages (i.e. dependencies external to the service itself).

  • I run Emacs. GNU Emacs 27.1 (build 1, x86_64-pc-linux-gnu, GTK+ Version 3.24.23, cairo version 1.16.0) of 2020-11-08, modified by Debian.
$ go version
go version go1.15.6 linux/amd64
  • Gopls build in $GOPATH mode.
  • Below, the lsp-log I get:
Command "gopls" is present on the path.
Command "gopls" is present on the path.
Found the following clients for /home/manuel/workbench/go/src/github.com/<EDITED>: (server-id gopls, priority 0)
The following clients were selected based on priority: (server-id gopls, priority 0)
2020/12/28 14:03:57 Build info
----------
version master, built in $GOPATH mode

Go info
-------
go version go1.15.6 linux/amd64



2020/12/28 14:03:57 go env for /home/manuel
(root /home/manuel)
(valid build configuration = false)
(build flags: [])
GOPROXY=https://proxy.golang.org,direct
GOSUMDB=sum.golang.org
GOPATH=/home/manuel/workbench/go
GOPRIVATE=
GOROOT=/usr/lib/go-1.15
GO111MODULE=
GOCACHE=/home/manuel/.cache/go-build
GONOPROXY=
GOMODCACHE=/home/manuel/workbench/go/pkg/mod
GONOSUMDB=
GOINSECURE=
GOFLAGS=
GOMOD=


2020/12/28 14:03:57 go/packages.Load
	snapshot=0
	directory=/home/manuel
	query=[./ builtin]
	packages=2

2020/12/28 14:03:57 go/packages.Load
	snapshot=0
	directory=/home/manuel
	query=[./]
	packages=1

2020/12/28 14:03:57 go/packages.Load
	snapshot=1
	directory=/home/manuel
	query=[./]
	packages=1

2020/12/28 14:03:57 go/packages.Load
	snapshot=1
	directory=/home/manuel
	query=[file=/home/manuel/workbench/go/src/github.com/EDITED]
	packages=1

2020/12/28 14:03:57 go/packages.Load
	snapshot=1
	package_path="github.com/EDITED"
	files=[/home/manuel/workbench/go/src/github.com/EDITED /home/manuel/workbench/go/src/github.com/EDITED /home/manuel/workbench/go/src/github.com/EDITED /home/manuel/workbench/go/src/github.com/EDITED]

2020/12/28 14:03:57 go/packages.Load
	snapshot=1
	package_path="github.com/EDITED"
	files=[/home/manuel/workbench/go/src/github.com/EDITED /home/manuel/workbench/go/src/github.com/EDITED /home/manuel/workbench/go/src/github.com/EDITED /home/manuel/workbench/go/src/github.com/EDITED]

2020/12/28 14:03:57 go/packages.Load
	snapshot=1
	directory=/home/manuel
	query=[file=/home/manuel/workbench/go/src/github.com/EDITED]
	packages=1

2020/12/28 14:03:57 no dep handle: no metadata for contrib.go.opencensus.io/exporter/stackdriver/propagation
	package="contrib.go.opencensus.io/exporter/stackdriver/propagation"

2020/12/28 14:03:57 no dep handle: no metadata for contrib.go.opencensus.io/exporter/stackdriver
	package="contrib.go.opencensus.io/exporter/stackdriver"

2020/12/28 14:03:57 no dep handle: no metadata for go.opencensus.io/trace
	package="go.opencensus.io/trace"

2020/12/28 14:03:57 no dep handle: no metadata for go.opencensus.io/plugin/ochttp
	package="go.opencensus.io/plugin/ochttp"

2020/12/28 14:03:57 no dep handle: no metadata for go.opencensus.io/trace/propagation
	package="go.opencensus.io/trace/propagation"

2020/12/28 14:03:57 no dep handle: no metadata for github.com/swaggo/http-swagger
	package="github.com/swaggo/http-swagger"

2020/12/28 14:03:57 no dep handle: no metadata for github.com/alecthomas/template
	package="github.com/alecthomas/template"

2020/12/28 14:03:57 no dep handle: no metadata for github.com/alecthomas/template
	package="github.com/alecthomas/template"

2020/12/28 14:03:57 no dep handle: no metadata for github.com/swaggo/http-swagger
	package="github.com/swaggo/http-swagger"

2020/12/28 14:03:57 no dep handle: no metadata for github.com/stripe/stripe-go/v72/checkout/session
	package="github.com/stripe/stripe-go/v72/checkout/session"

2020/12/28 14:03:57 no dep handle: no metadata for github.com/stripe/stripe-go/v72/customer
	package="github.com/stripe/stripe-go/v72/customer"

2020/12/28 14:03:57 no dep handle: no metadata for github.com/stripe/stripe-go/v72/price
	package="github.com/stripe/stripe-go/v72/price"

2020/12/28 14:03:57 no dep handle: no metadata for github.com/stripe/stripe-go/v72/webhook
	package="github.com/stripe/stripe-go/v72/webhook"

2020/12/28 14:03:57 no dep handle: no metadata for contrib.go.opencensus.io/exporter/stackdriver/propagation
	package="contrib.go.opencensus.io/exporter/stackdriver/propagation"

2020/12/28 14:03:57 no dep handle: no metadata for github.com/stripe/stripe-go/v72/taxrate
	package="github.com/stripe/stripe-go/v72/taxrate"

2020/12/28 14:03:57 no dep handle: no metadata for github.com/stripe/stripe-go/v72
	package="github.com/stripe/stripe-go/v72"

2020/12/28 14:03:57 no dep handle: no metadata for go.opencensus.io/plugin/ochttp
	package="go.opencensus.io/plugin/ochttp"

2020/12/28 14:04:27 background imports cache refresh starting

2020/12/28 14:04:27 background refresh finished after 31.727533ms

As a result, I don't have autocompletion for the packages without metadata and the editor highlights those as errors (including the related imports).

@stamblerre
Copy link
Contributor

@magandrez: Please open a new issue at https://github.com/golang/go/issues/new. It also looks like you may be using an old gopls version, so please download the latest by running GO111MODULE=on go get golang.org/x/tools/gopls.

@magandrez magandrez mentioned this issue Dec 29, 2020
Closed
@golang golang locked and limited conversation to collaborators Dec 28, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge gopls Issues related to the Go language server, gopls. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Tools This label describes issues relating to any tools in the x/tools repository.
Projects
None yet
Milestone
gopls/v0.3.0
Development

No branches or pull requests
8 participants
@magandrez @bmhatfield @myitcv @stamblerre @gopherbot @muirdm @heschi @zikaeroh