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.

Sign up for GitHub

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/internal/regtest/misc: TestRunVulncheckExpStd failures #56795

Closed
gopherbot opened this issue Nov 17, 2022 · 7 comments
Closed

x/tools/gopls/internal/regtest/misc: TestRunVulncheckExpStd failures #56795

gopherbot opened this issue Nov 17, 2022 · 7 comments
Assignees
@hyangah
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.11.0

Comments

@gopherbot
Copy link
Contributor 

#!watchflakes
post <- pkg == "golang.org/x/tools/gopls/internal/regtest/misc" && test == "TestRunVulncheckExpStd"

Issue created automatically to collect these failures.

Example (log):

serve.go:438: debug server listening at http://localhost:65449
serve.go:438: debug server listening at http://localhost:65448
#### Start Gopls Test Logs for "TestRunVulncheckExpStd/default"
[Trace - 06:14:38.286 AM] Sending request 'initialize - (1)'.
Params: {"processId":0,"clientInfo":{"name":"fakeclient","version":"v1.0.0"},"rootUri":"","capabilities":{"workspace":{"workspaceEdit":{"resourceOperations":["rename"]},"didChangeConfiguration":{},"didChangeWatchedFiles":{"dynamicRegistration":true},"configuration":true},"textDocument":{"completion":{"completionItem":{"snippetSupport":true,"commitCharactersSupport":false,"documentationFormat":null,"deprecatedSupport":false,"preselectSupport":false,"tagSupport":{"valueSet":[1]},"insertReplaceSupport":false,"resolveSupport":{"properties":null},"insertTextModeSupport":{"valueSet":null},"labelDetailsSupport":false}},"hover":{},"documentSymbol":{},"codeAction":{"codeActionLiteralSupport":{"codeActionKind":{"valueSet":null}}},"rename":{},"foldingRange":{},"publishDiagnostics":{},"semanticTokens":{"requests":{"range":false,"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":["declaration","definition","readonly","static","deprecated","abstract","async","modification","documentation","defaultLibrary"],"formats":null}},"window":{"workDoneProgress":true}},"initializationOptions":{"codelenses":{"run_vulncheck_exp":true},"completionBudget":"10s","diagnosticsDelay":"10ms","env":{"GO111MODULE":"","GOMODCACHE":"","GOPACKAGESDRIVER":"off","GOPATH":"/tmp/workdir/tmp/gopls-regtest-155280668/TestRunVulncheckExpStd/default/gopath","GOPROXY":"file:///tmp/workdir/tmp/gopls-regtest-155280668/TestRunVulncheckExpStd/default/proxy","GOSUMDB":"off","GOVULNDB":"file:///tmp/workdir/tmp/vulndb-test343225896","_GOPLS_TEST_BINARY_RUN_AS_GOPLS":"true","_GOPLS_TEST_VULNCHECK_GOVERSION":"go1.18"},"verboseWorkDoneProgress":true},"trace":"messages","workspaceFolders":[{"uri":"file:///tmp/workdir/tmp/gopls-regtest-155280668/TestRunVulncheckExpStd/default/work","name":"work"}]}


[Trace - 06:14:38.287 AM] Received response 'initialize - (1)' 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":true,"codeLensProvider":{},"documentLinkProvider":{},"workspaceSymbolProvider":true,"documentFormattingProvider":true,"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.reset_go_mod_diagnostics","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,"inlayHintProvider":{},"workspace":{"workspaceFolders":{"supported":true,"changeNotifications":"workspace/didChangeWorkspaceFolders"},"fileOperations":{}}},"serverInfo":{"name":"gopls","version":"{\"GoVersion\":\"devel c3d444d09852981daa6ed9e0ba65d90c89a7d917\",\"Path\":\"\",\"Main\":{\"Path\":\"\",\"Version\":\"\",\"Sum\":\"\",\"Replace\":null},\"Deps\":null,\"Settings\":null,\"Version\":\"master\"}"}}

...
--- FAIL: TestRunVulncheckExpStd (531.64s)
    --- FAIL: TestRunVulncheckExpStd/default (531.64s)
        vuln_test.go:175: waiting on:
            Unmet: completed work "govulncheck" at least 1 time(s)
            Unmet: received ShowMessage

            err:context deadline exceeded

            state:
            #### log messages (see RPC logs for full text):
...
            #### diagnostics:
            	go.mod (version 1):

            #### outstanding work:
            	govulncheck: 0.00
            #### completed work:
            	Load: 1
            	Setting up workspace: 1
            	diagnosing initial workspace load: 1
            	diagnosing opened files: 1

— watchflakes
@gopherbot gopherbot added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Nov 17, 2022
@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 Nov 17, 2022
@gopherbot gopherbot added this to the Unreleased milestone Nov 17, 2022
@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/tools/gopls/internal/regtest/misc" && test == "TestRunVulncheckExpStd"
2022-11-09 17:16 netbsd-386-9_0 tools@502c6347 go@c3d444d0 x/tools/gopls/internal/regtest/misc.TestRunVulncheckExpStd (log) 
serve.go:438: debug server listening at http://localhost:65449
serve.go:438: debug server listening at http://localhost:65448
#### Start Gopls Test Logs for "TestRunVulncheckExpStd/default"
[Trace - 06:14:38.286 AM] Sending request 'initialize - (1)'.
Params: {"processId":0,"clientInfo":{"name":"fakeclient","version":"v1.0.0"},"rootUri":"","capabilities":{"workspace":{"workspaceEdit":{"resourceOperations":["rename"]},"didChangeConfiguration":{},"didChangeWatchedFiles":{"dynamicRegistration":true},"configuration":true},"textDocument":{"completion":{"completionItem":{"snippetSupport":true,"commitCharactersSupport":false,"documentationFormat":null,"deprecatedSupport":false,"preselectSupport":false,"tagSupport":{"valueSet":[1]},"insertReplaceSupport":false,"resolveSupport":{"properties":null},"insertTextModeSupport":{"valueSet":null},"labelDetailsSupport":false}},"hover":{},"documentSymbol":{},"codeAction":{"codeActionLiteralSupport":{"codeActionKind":{"valueSet":null}}},"rename":{},"foldingRange":{},"publishDiagnostics":{},"semanticTokens":{"requests":{"range":false,"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":["declaration","definition","readonly","static","deprecated","abstract","async","modification","documentation","defaultLibrary"],"formats":null}},"window":{"workDoneProgress":true}},"initializationOptions":{"codelenses":{"run_vulncheck_exp":true},"completionBudget":"10s","diagnosticsDelay":"10ms","env":{"GO111MODULE":"","GOMODCACHE":"","GOPACKAGESDRIVER":"off","GOPATH":"/tmp/workdir/tmp/gopls-regtest-155280668/TestRunVulncheckExpStd/default/gopath","GOPROXY":"file:///tmp/workdir/tmp/gopls-regtest-155280668/TestRunVulncheckExpStd/default/proxy","GOSUMDB":"off","GOVULNDB":"file:///tmp/workdir/tmp/vulndb-test343225896","_GOPLS_TEST_BINARY_RUN_AS_GOPLS":"true","_GOPLS_TEST_VULNCHECK_GOVERSION":"go1.18"},"verboseWorkDoneProgress":true},"trace":"messages","workspaceFolders":[{"uri":"file:///tmp/workdir/tmp/gopls-regtest-155280668/TestRunVulncheckExpStd/default/work","name":"work"}]}


[Trace - 06:14:38.287 AM] Received response 'initialize - (1)' 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":true,"codeLensProvider":{},"documentLinkProvider":{},"workspaceSymbolProvider":true,"documentFormattingProvider":true,"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.reset_go_mod_diagnostics","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,"inlayHintProvider":{},"workspace":{"workspaceFolders":{"supported":true,"changeNotifications":"workspace/didChangeWorkspaceFolders"},"fileOperations":{}}},"serverInfo":{"name":"gopls","version":"{\"GoVersion\":\"devel c3d444d09852981daa6ed9e0ba65d90c89a7d917\",\"Path\":\"\",\"Main\":{\"Path\":\"\",\"Version\":\"\",\"Sum\":\"\",\"Replace\":null},\"Deps\":null,\"Settings\":null,\"Version\":\"master\"}"}}

...
--- FAIL: TestRunVulncheckExpStd (531.64s)
    --- FAIL: TestRunVulncheckExpStd/default (531.64s)
        vuln_test.go:175: waiting on:
            Unmet: completed work "govulncheck" at least 1 time(s)
            Unmet: received ShowMessage

            err:context deadline exceeded

            state:
            #### log messages (see RPC logs for full text):
...
            #### diagnostics:
            	go.mod (version 1):

            #### outstanding work:
            	govulncheck: 0.00
            #### completed work:
            	Load: 1
            	Setting up workspace: 1
            	diagnosing initial workspace load: 1
            	diagnosing opened files: 1

— watchflakes

@findleyr
Copy link
Member

@hyangah @suzmue it looks like vulncheck didn't even run? Is it possible that the vulncheck process hung?

@findleyr
Copy link
Member

(and can we set a timeout for vulncheck, so that we get a more meaningful failure here?)

@bcmills
Copy link
Contributor

bcmills commented Nov 17, 2022

netbsd-386-9_0 is affected by #56180, so if vulncheck uses a subprocess that's a likely culprit.

@findleyr
Copy link
Member

Looks like vulncheck only invokes a subprocess if we don't supply a Go version (but we do).
https://github.com/golang/vuln/blob/fac3670c993ce0893ff43c1599a591c1e6445ccf/internal/goversion.go#L19

It could have hung the call go go/packages.Load (which we run ad-hoc before calling vulncheck.

I don't think we should investigate much before that netbsd bug is resolved, but it does seem like we could use more logging around the vulncheck invokation. @hyangah a good way to achieve that could be via intermediate progress updates while the command is running.

@gopherbot
Copy link
Contributor Author

Change https://go.dev/cl/452055 mentions this issue: gopls/internal/vulncheck: log progress

gopherbot pushed a commit to golang/tools that referenced this issue Nov 18, 2022
@hyangah
gopls/internal/vulncheck: log progress
c099dff 
Log before/after package loading and govulncheck.Source calls.
All stderr output of `gopls vulncheck` command is forwarded to the
client as LSP progress reports and visible to users.

go/packages.Load can be traced further if GOPACKAGESDEBUG env var
is set. Instrumentation in govulncheck.Source is still under
discussion in upstream.

For golang/go#56795

Change-Id: I8244930494aed17b319887bf96c2523f3215fa50
Reviewed-on: https://go-review.googlesource.com/c/tools/+/452055
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Suzy Mueller <suzmue@golang.org>
gopls-CI: kokoro <noreply+kokoro@google.com>
@hyangah hyangah modified the milestones: Unreleased, gopls/later Nov 18, 2022
@hyangah hyangah self-assigned this Nov 18, 2022
@hyangah
Copy link
Contributor

hyangah commented Dec 8, 2022

The test is renamed. Let's see if watchflakes find more info with new test names.

@hyangah hyangah closed this as completed Dec 8, 2022
@hyangah hyangah moved this to Done in Test Flakes Dec 8, 2022
@findleyr findleyr modified the milestones: gopls/later, gopls/v0.11.0 Dec 8, 2022
@golang golang locked and limited conversation to collaborators Dec 8, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@hyangah hyangah

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
Test Flakes
Archived in project
Milestone
gopls/v0.11.0
Development

No branches or pull requests
4 participants
@hyangah @bcmills @gopherbot @findleyr