x/tools/gopls/internal/regtest/diagnostics: TestEditGoDirective/experimental failure with deadline exceeded #51930
Comments
gopherbot
added
Tools
|
I think I know what is causing these failures, approximately. The example in the test has two diagnostics with quick fixes:
In the test, we call "apply quick fixes" which applies quick-fixes in rapid succession. However, we asynchronously reload the workspace when notified of the first on-disk change, and so may theoretically call packages.Load while the Go command is in the middle of the second edit. I guess this because the failing tests have the log message "no module declaration for file:///tmp/workdir/tmp/gopls-regtest-1306654604/TestEditGoDirectiveWorkspace/experimental/work/go.mod", which doesn't occur in the logs of successful test runs. However, I still don't understand the following:
Both of these indicate a bug in gopls, but at least there is some rational explanation for the failure. Investigation continues. |
|
Change https://go.dev/cl/399625 mentions this issue: |
|
Aha, ok I've got it.
I've "fixed" the latter by including mtime in our file identity. We'll see if that makes the errors go away: on certain platforms (e.g. WSL) I recall that mtime is particularly coarse. |
|
Note: another "fix" is to only apply a single quick-fix. I'd prefer if we didn't have to make that accomodation: the regtest framework should be able to handle multiple quick-fixes being applied in succession. Let's see if the flakes go to zero after the CL above. |
When polling for on-disk file changes, we must detect changes even if there is no change in the file since the last polling. The reason for this is that there could have been intermediate changes to the file that affected our calculations, and those calculations must be invalidated. For golang/go#51930 Change-Id: I92f5c34f982970d8386fddfaa22b82ba471e22e7 Reviewed-on: https://go-review.googlesource.com/c/tools/+/399625 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
added
Testing
@bcmills it looks like you added an 'omit' flag to your local copy of greplogs. Care to upstream? :) |
Just waiting on review from @aclements. 🙂 |
findleyr
added
Testing
|
No failures since the CL above. I'm declaring victory 🎉 |
https://storage.googleapis.com/go-build-log/b95d332c/windows-386-2008_1bfb115d.log
Observed during trybot run for https://go-review.googlesource.com/c/tools/+/395694.
This log message when running
gopls.edit_go_directivecommand is suspicious:Potential file corruption or windows file mishandling? (windows)
full gopls test logs
``` #### Start Gopls Test Logs for "TestEditGoDirective/experimental" [Trace - 21:46:57.134 PM] Sending request 'initialize - (1)'. Params: {"processId":0,"clientInfo":{"name":"fakeclient","version":"v1.0.0"},"rootUri":"","capabilities":{"workspace":{"didChangeConfiguration":{},"didChangeWatchedFiles":{"dynamicRegistration":true},"executeCommand":{},"semanticTokens":{},"codeLens":{},"inlineValue":{},"inlayHint":{},"configuration":true},"textDocument":{"synchronization":{},"completion":{"completionItem":{"snippetSupport":true,"tagSupport":{"valueSet":[1]},"resolveSupport":{"properties":null},"insertTextModeSupport":{"valueSet":null}},"completionItemKind":{},"completionList":{}},"hover":{},"signatureHelp":{"signatureInformation":{"parameterInformation":{}}},"declaration":{},"definition":{},"typeDefinition":{},"implementation":{},"references":{},"documentHighlight":{},"documentSymbol":{"symbolKind":{},"tagSupport":{"valueSet":null}},"codeAction":{"codeActionLiteralSupport":{"codeActionKind":{"valueSet":null}},"resolveSupport":{"properties":null}},"codeLens":{},"documentLink":{},"colorProvider":{},"formatting":{},"rangeFormatting":{},"onTypeFormatting":{},"rename":{},"foldingRange":{},"selectionRange":{},"publishDiagnostics":{"tagSupport":{"valueSet":null}},"callHierarchy":{},"semanticTokens":{"requests":{"full":true},"tokenTypes":["namespace","type","class","enum","interface","struct","typeParameter","parameter","variable","property","enumMember","event","function","method","macro","keyword","modifier","comment","string","number","regexp","operator"],"tokenModifiers":null,"formats":null},"linkedEditingRange":{},"moniker":{},"typeHierarchy":{},"inlineValue":{},"inlayHint":{"resolveSupport":{"properties":null}}},"window":{"workDoneProgress":true,"showMessage":{"messageActionItem":{}},"showDocument":{"support":false}},"general":{"staleRequestSupport":{"cancel":false,"retryOnContentModified":null},"regularExpressions":{"engine":""},"markdown":{"parser":""}}},"initializationOptions":{"completionBudget":"10s","diagnosticsDelay":"10ms","env":{"GO111MODULE":"","GOMODCACHE":"","GOPACKAGESDRIVER":"off","GOPATH":"C:\\Users\\gopher\\AppData\\Local\\Temp\\gopls-regtest-628564068\\TestEditGoDirective\\experimental\\gopath","GOPROXY":"file:///C:/Users/gopher/AppData/Local/Temp/gopls-regtest-628564068/TestEditGoDirective/experimental/proxy","GOSUMDB":"off"},"expandWorkspaceToModule":true,"verboseWorkDoneProgress":true},"trace":"messages","workspaceFolders":[{"uri":"file:///C:/Users/gopher/AppData/Local/Temp/gopls-regtest-628564068/TestEditGoDirective/experimental/work","name":"work"}]}[Trace - 21:46:57.134 PM] Received response 'initialize - (1)' in 0ms.
Result: {"capabilities":{"textDocumentSync":{"openClose":true,"change":2,"save":{}},"completionProvider":{"triggerCharacters":["."],"completionItem":{}},"hoverProvider":true,"signatureHelpProvider":{"triggerCharacters":["(",","]},"definitionProvider":true,"typeDefinitionProvider":true,"implementationProvider":true,"referencesProvider":true,"documentHighlightProvider":true,"documentSymbolProvider":true,"codeActionProvider":true,"codeLensProvider":{},"documentLinkProvider":{},"workspaceSymbolProvider":true,"documentFormattingProvider":true,"documentOnTypeFormattingProvider":{"firstTriggerCharacter":""},"renameProvider":true,"foldingRangeProvider":true,"executeCommandProvider":{"commands":["gopls.add_dependency","gopls.add_import","gopls.apply_fix","gopls.check_upgrades","gopls.edit_go_directive","gopls.gc_details","gopls.generate","gopls.generate_gopls_mod","gopls.go_get_package","gopls.list_imports","gopls.list_known_packages","gopls.regenerate_cgo","gopls.remove_dependency","gopls.run_tests","gopls.run_vulncheck_exp","gopls.start_debugging","gopls.test","gopls.tidy","gopls.toggle_gc_details","gopls.update_go_sum","gopls.upgrade_dependency","gopls.vendor"]},"callHierarchyProvider":true,"workspace":{"workspaceFolders":{"supported":true,"changeNotifications":"workspace/didChangeWorkspaceFolders"}}},"serverInfo":{"name":"gopls","version":"{"GoVersion":"devel b95d332","Path":"","Main":{"Path":"","Version":"","Sum":"","Replace":null},"Deps":null,"Settings":null,"Version":"master"}"}}
[Trace - 21:46:57.135 PM] Sending notification 'initialized'.
Params: {}
[Trace - 21:46:57.135 PM] Received request 'window/workDoneProgress/create - (1)'.
Params: {"token":"1439228946174806623"}
[Trace - 21:46:57.135 PM] Sending response 'window/workDoneProgress/create - (1)' in 0ms.
Result:
[Trace - 21:46:57.135 PM] Received notification '$/progress'.
Params: {"token":"1439228946174806623","value":{"kind":"begin","title":"diagnosing initial workspace load","message":"Calculating diagnostics for initial workspace load..."}}
[Trace - 21:46:57.135 PM] Received request 'window/workDoneProgress/create - (2)'.
Params: {"token":"4995735335659635616"}
[Trace - 21:46:57.135 PM] Sending response 'window/workDoneProgress/create - (2)' in 0ms.
Result:
[Trace - 21:46:57.135 PM] Received notification '$/progress'.
Params: {"token":"4995735335659635616","value":{"kind":"begin","title":"Setting up workspace","message":"Loading packages..."}}
[Trace - 21:46:57.136 PM] Received request 'workspace/configuration - (3)'.
Params: {"items":[{"scopeUri":"file:///C:/Users/gopher/AppData/Local/Temp/gopls-regtest-628564068/TestEditGoDirective/experimental/work","section":"gopls"}]}
[Trace - 21:46:57.136 PM] Sending response 'workspace/configuration - (3)' in 0ms.
Result: [{"completionBudget":"10s","diagnosticsDelay":"10ms","env":{"GO111MODULE":"","GOMODCACHE":"","GOPACKAGESDRIVER":"off","GOPATH":"C:\Users\gopher\AppData\Local\Temp\gopls-regtest-628564068\TestEditGoDirective\experimental\gopath","GOPROXY":"file:///C:/Users/gopher/AppData/Local/Temp/gopls-regtest-628564068/TestEditGoDirective/experimental/proxy","GOSUMDB":"off"},"expandWorkspaceToModule":true,"verboseWorkDoneProgress":true}]
[Trace - 21:46:57.283 PM] Received request 'window/workDoneProgress/create - (4)'.
Params: {"token":"2477080916348470461"}
[Trace - 21:46:57.283 PM] Sending response 'window/workDoneProgress/create - (4)' in 0ms.
Result:
[Trace - 21:46:57.283 PM] Received notification '$/progress'.
Params: {"token":"2477080916348470461","value":{"kind":"begin","title":"Load","message":"Loading query=[builtin mod.com/...]"}}
[Trace - 21:46:57.356 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2022/03/24 21:46:57 go env for C:\Users\gopher\AppData\Local\Temp\gopls-regtest-628564068\TestEditGoDirective\experimental\work\n(root C:\Users\gopher\AppData\Local\Temp\gopls-regtest-628564068\TestEditGoDirective\experimental\work)\n(go version go version devel b95d332 windows/386)\n(valid build configuration = true)\n(build flags: [])\nGOFLAGS=\nGOINSECURE=\nGOWORK=\nGONOSUMDB=\nGO111MODULE=\nGOCACHE=C:\Users\gopher\AppData\Local\go-build\nGOMOD=C:\Users\gopher\AppData\Local\Temp\gopls-regtest-628564068\TestEditGoDirective\experimental\work\go.mod\nGOSUMDB=off\nGOPATH=C:\Users\gopher\AppData\Local\Temp\gopls-regtest-628564068\TestEditGoDirective\experimental\gopath\nGOROOT=C:\workdir\go\nGONOPROXY=\nGOPROXY=file:///C:/Users/gopher/AppData/Local/Temp/gopls-regtest-628564068/TestEditGoDirective/experimental/proxy\nGOPRIVATE=\nGOMODCACHE=\n\n"}
[Trace - 21:46:57.772 PM] Received notification '$/progress'.
Params: {"token":"2477080916348470461","value":{"kind":"end","message":"Done."}}
[Trace - 21:46:57.773 PM] Received notification '$/progress'.
Params: {"token":"4995735335659635616","value":{"kind":"end","message":"Finished loading packages."}}
[Trace - 21:46:57.776 PM] Received request 'client/registerCapability - (5)'.
Params: {"registrations":[{"id":"workspace/didChangeWatchedFiles-0","method":"workspace/didChangeWatchedFiles","registerOptions":{"watchers":[{"globPattern":"**/*.{go,mod,sum,work}","kind":7}]}}]}
[Trace - 21:46:57.776 PM] Sending response 'client/registerCapability - (5)' in 0ms.
Result:
[Trace - 21:46:57.777 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2022/03/24 21:46:57 go/packages.Load\n\tsnapshot=0\n\tdirectory=C:\Users\gopher\AppData\Local\Temp\gopls-workspace-mod1975635461\n\tquery=[builtin mod.com/...]\n\tpackages=2\n"}
[Trace - 21:46:57.810 PM] Received notification 'textDocument/publishDiagnostics'.
Params: {"uri":"file:///C:/Users/gopher/AppData/Local/Temp/gopls-regtest-628564068/TestEditGoDirective/experimental/work/main.go","diagnostics":[{"range":{"start":{"line":2,"character":7},"end":{"line":2,"character":12}},"severity":1,"code":"UnsupportedFeature","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UnsupportedFeature"},"source":"compiler","message":"type parameters require go1.18 or later"},{"range":{"start":{"line":2,"character":9},"end":{"line":2,"character":12}},"severity":1,"code":"UndeclaredName","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UndeclaredName"},"source":"compiler","message":"undeclared name: any (requires version go1.18 or later)"}]}
[Trace - 21:46:57.811 PM] Received notification '$/progress'.
Params: {"token":"1439228946174806623","value":{"kind":"end","message":"Done."}}
[Trace - 21:46:57.813 PM] Sending request 'textDocument/codeAction - (2)'.
Params: {"textDocument":{"uri":"file:///C:/Users/gopher/AppData/Local/Temp/gopls-regtest-628564068/TestEditGoDirective/experimental/work/main.go"},"range":{"start":{"line":0,"character":0},"end":{"line":0,"character":0}},"context":{"diagnostics":[{"range":{"start":{"line":2,"character":7},"end":{"line":2,"character":12}},"severity":1,"code":"UnsupportedFeature","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UnsupportedFeature"},"source":"compiler","message":"type parameters require go1.18 or later"},{"range":{"start":{"line":2,"character":9},"end":{"line":2,"character":12}},"severity":1,"code":"UndeclaredName","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UndeclaredName"},"source":"compiler","message":"undeclared name: any (requires version go1.18 or later)"}],"only":["source.fixAll","quickfix"]}}
[Trace - 21:46:57.815 PM] Received response 'textDocument/codeAction - (2)' in 1ms.
Result: [{"title":"go mod edit -go=1.18","kind":"quickfix","diagnostics":[{"range":{"start":{"line":2,"character":7},"end":{"line":2,"character":12}},"severity":1,"code":"UnsupportedFeature","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UnsupportedFeature"},"source":"compiler","message":"type parameters require go1.18 or later"}],"edit":{},"command":{"title":"go mod edit -go=1.18","command":"gopls.edit_go_directive","arguments":[{"URI":"file:///C:/Users/gopher/AppData/Local/Temp/gopls-regtest-628564068/TestEditGoDirective/experimental/work/main.go","Version":"1.18"}]}},{"title":"go mod edit -go=1.18","kind":"quickfix","diagnostics":[{"range":{"start":{"line":2,"character":9},"end":{"line":2,"character":12}},"severity":1,"code":"UndeclaredName","codeDescription":{"href":"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal?utm_source=gopls#UndeclaredName"},"source":"compiler","message":"undeclared name: any (requires version go1.18 or later)"}],"edit":{},"command":{"title":"go mod edit -go=1.18","command":"gopls.edit_go_directive","arguments":[{"URI":"file:///C:/Users/gopher/AppData/Local/Temp/gopls-regtest-628564068/TestEditGoDirective/experimental/work/main.go","Version":"1.18"}]}}]
[Trace - 21:46:57.815 PM] Sending request 'workspace/executeCommand - (3)'.
Params: {"command":"gopls.edit_go_directive","arguments":[{"URI":"file:///C:/Users/gopher/AppData/Local/Temp/gopls-regtest-628564068/TestEditGoDirective/experimental/work/main.go","Version":"1.18"}]}
[Trace - 21:46:57.855 PM] Received response 'workspace/executeCommand - (3)' in 40ms.
Result: null
[Trace - 21:46:57.857 PM] Sending notification 'workspace/didChangeWatchedFiles'.
Params: {"changes":[{"uri":"file:///C:/Users/gopher/AppData/Local/Temp/gopls-regtest-628564068/TestEditGoDirective/experimental/work/go.mod","type":2}]}
[Trace - 21:46:57.857 PM] Received request 'window/workDoneProgress/create - (6)'.
Params: {"token":"8741248032194605601"}
[Trace - 21:46:57.858 PM] Sending response 'window/workDoneProgress/create - (6)' in 0ms.
Result:
[Trace - 21:46:57.858 PM] Received notification '$/progress'.
Params: {"token":"8741248032194605601","value":{"kind":"begin","title":"diagnosing files changed on disk","message":"Calculating file diagnostics..."}}
[Trace - 21:46:57.863 PM] Sending request 'workspace/executeCommand - (4)'.
Params: {"command":"gopls.edit_go_directive","arguments":[{"URI":"file:///C:/Users/gopher/AppData/Local/Temp/gopls-regtest-628564068/TestEditGoDirective/experimental/work/main.go","Version":"1.18"}]}
[Trace - 21:46:57.910 PM] Received notification 'window/logMessage'.
Params: {"type":1,"message":"2022/03/24 21:46:57 building workspace mod file: no module declaration for file:///C:/Users/gopher/AppData/Local/Temp/gopls-regtest-628564068/TestEditGoDirective/experimental/work/go.mod\n"}
[Trace - 21:46:57.911 PM] Received response 'workspace/executeCommand - (4)' in 47ms.
Result: null
[Trace - 21:46:57.922 PM] Received request 'window/workDoneProgress/create - (7)'.
Params: {"token":"7174218026911131881"}
[Trace - 21:46:57.923 PM] Sending response 'window/workDoneProgress/create - (7)' in 0ms.
Result:
[Trace - 21:46:57.923 PM] Received notification '$/progress'.
Params: {"token":"7174218026911131881","value":{"kind":"begin","title":"Error loading workspace","message":"no module path for file:///C:/Users/gopher/AppData/Local/Temp/gopls-regtest-628564068/TestEditGoDirective/experimental/work/go.mod"}}
[Trace - 21:46:57.924 PM] Received notification 'window/logMessage'.
Params: {"type":1,"message":"2022/03/24 21:46:57 errors loading workspace: no module path for file:///C:/Users/gopher/AppData/Local/Temp/gopls-regtest-628564068/TestEditGoDirective/experimental/work/go.mod\n\tsnapshot=1\n\tdirectory=file:///C:/Users/gopher/AppData/Local/Temp/gopls-regtest-628564068/TestEditGoDirective/experimental/work\n"}
[Trace - 21:46:57.924 PM] Received notification 'textDocument/publishDiagnostics'.
Params: {"uri":"file:///C:/Users/gopher/AppData/Local/Temp/gopls-regtest-628564068/TestEditGoDirective/experimental/work/go.mod","diagnostics":[{"range":{"start":{"line":0,"character":0},"end":{"line":0,"character":0}},"severity":1,"source":"go list","message":"no module path for file:///C:/Users/gopher/AppData/Local/Temp/gopls-regtest-628564068/TestEditGoDirective/experimental/work/go.mod"}]}
[Trace - 21:46:57.924 PM] Received notification '$/progress'.
Params: {"token":"8741248032194605601","value":{"kind":"end","message":"Done."}}
[Trace - 21:47:27.852 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2022/03/24 21:47:27 background imports cache refresh starting\n"}
[Trace - 21:47:27.969 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2022/03/24 21:47:27 background refresh finished after 151.3671ms\n"}
The text was updated successfully, but these errors were encountered: