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/internal/regtest/diagnostics: TestIssue37978 failures due to unmet location of "http.MethodGet" on netbsd #53040

Closed
bcmills opened this issue May 23, 2022 · 8 comments
Labels
FrozenDueToAge gopls Issues related to the Go language server, gopls. Tools This label describes issues relating to any tools in the x/tools repository. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Milestone

Comments

@bcmills
Copy link
Contributor

bcmills commented May 23, 2022

--- FAIL: TestIssue37978 (567.81s)
    --- FAIL: TestIssue37978/experimental (565.12s)
        diagnostics_test.go:173: waiting on:
            Unmet: c/c.go: diagnostic at {line:2, column:10} (location of "http.MethodGet")
            
            err:context deadline exceeded
            
            state:
            #### log messages (see RPC logs for full text):
            	Info: "2022/05/19 21:23:56 go env for /tmp/workdir/tmp/go...
            	Info: "2022/05/19 21:23:56 go/packages.Load\n\tsnapshot=0...
            	Info: "2022/05/19 21:23:57 discovered missing identifiers...
            	Info: "2022/05/19 21:23:58 go/packages.Load\n\tsnapshot=1...
            	Info: "2022/05/19 21:23:58 go/packages.Load\n\tsnapshot=1...
            
            #### diagnostics:
            	c/c.go (version 1):
            		(0, 0): expected ';', found 'EOF'
            
            #### outstanding work:
            #### completed work:
            	Load: 2
            	Setting up workspace: 1
            	diagnosing initial workspace load: 1
            	diagnosing opened files: 1
            	diagnosing changed files: 1
        runner.go:324: closing editor: Shutdown: context deadline exceeded

greplogs -l -e 'FAIL: TestIssue37978 .*(\n[ ]+.*)*\(location of "http.MethodGet"\)' --since=2022-02-01
2022-05-19T21:15:04-904e24e-34507e8/netbsd-amd64-9_0
2022-05-17T03:26:28-814e0d7-41b9d8c/netbsd-386-9_0

Given the small number of occurrences so far, it's not clear to me whether this issue is specific to NetBSD.

(CC @findleyr @suzmue)

@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 May 23, 2022
@gopherbot gopherbot added this to the Unreleased milestone May 23, 2022
@hyangah
Copy link
Contributor

hyangah commented May 26, 2022

Let's skip the test for now.
We still need to investigate the root cause, but this is low priority.

@bcmills
Copy link
Contributor Author

bcmills commented May 27, 2022

Sounds reasonable. Do we want to go ahead and add a skip, or leave it running to see whether the failure mode is specific to NetBSD?

@findleyr
Copy link
Contributor

Let's just skip on GOOS=netbsd.

@hyangah
Copy link
Contributor

hyangah commented May 27, 2022

Reading the logs (thanks bcmills@ - I couldn't find these logs using fetchlogs/greplogs myself - such a rare failure) ...

What this test does is basically

  • open an empty file
  • write a file content package c\n\nconst a = http.MethodGet\n (not on disk)
  • wait for diagnostics

But, in this trace 2022-05-19T21:15:04-904e24e-34507e8/netbsd-amd64-9_0

we see two diagnostics work started ("Calculating file diagnostics...").
The first publishDiagnostics was computed based on the old content.
The second diagnostics work didn't seem to produce any new diagnostics - not sure if that's debounced, or another bug prevented gopls from computing data from the new contents.

[Trace - 21:23:57.938 PM] Sending notification 'textDocument/didOpen'.
Params: {"textDocument":{"uri":"file:///tmp/workdir/tmp/gopls-regtest-4122224179/TestIssue37978/experimental/work/c/c.go","languageId":"go","version":1,"text":""}}


[Trace - 21:23:57.939 PM] Received request 'window/workDoneProgress/create - (6)'.
Params: {"token":"5570714739468966812"}


[Trace - 21:23:57.939 PM] Sending response 'window/workDoneProgress/create - (6)' in 0ms.
Result: 


[Trace - 21:23:57.940 PM] Sending notification 'textDocument/didChange'.
Params: {"textDocument":{"version":2,"uri":"file:///tmp/workdir/tmp/gopls-regtest-4122224179/TestIssue37978/experimental/work/c/c.go"},"contentChanges":[{"range":{"start":{"line":0,"character":0},"end":{"line":0,"character":0}},"text":"package c\n\nconst a = http.MethodGet\n"}]}


[Trace - 21:23:57.952 PM] Received notification '$/progress'.
Params: {"token":"5570714739468966812","value":{"kind":"begin","title":"diagnosing opened files","message":"Calculating file diagnostics..."}}


[Trace - 21:23:58.003 PM] Received request 'window/workDoneProgress/create - (7)'.
Params: {"token":"3778061770029050113"}


[Trace - 21:23:58.003 PM] Sending response 'window/workDoneProgress/create - (7)' in 0ms.
Result: 


[Trace - 21:23:58.003 PM] Received notification '$/progress'.
Params: {"token":"3778061770029050113","value":{"kind":"begin","title":"Load","message":"Loading query=[file=/tmp/workdir/tmp/gopls-regtest-4122224179/TestIssue37978/experimental/work/c/c.go]"}}


[Trace - 21:23:58.061 PM] Received notification '$/progress'.
Params: {"token":"3778061770029050113","value":{"kind":"end","message":"Done."}}


[Trace - 21:23:58.063 PM] Received notification 'textDocument/publishDiagnostics'.
Params: {"uri":"file:///tmp/workdir/tmp/gopls-regtest-4122224179/TestIssue37978/experimental/work/c/c.go","version":1,"diagnostics":[{"range":{"start":{"line":0,"character":0},"end":{"line":0,"character":0}},"severity":1,"source":"syntax","message":"expected ';', found 'EOF'"}]}


[Trace - 21:23:58.063 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2022/05/19 21:23:58 go/packages.Load\n\tsnapshot=1\n\tdirectory=/tmp/workdir/tmp/gopls-workspace-mod1242501193\n\tquery=[file=/tmp/workdir/tmp/gopls-regtest-4122224179/TestIssue37978/experimental/work/c/c.go]\n\tpackages=1\n"}


[Trace - 21:23:58.064 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2022/05/19 21:23:58 go/packages.Load\n\tsnapshot=1\n\tpackage=\"mod.com/c\"\n\tfiles=[/tmp/workdir/tmp/gopls-regtest-4122224179/TestIssue37978/experimental/work/c/c.go]\n"}


[Trace - 21:23:58.064 PM] Received request 'window/workDoneProgress/create - (8)'.
Params: {"token":"273669266008440571"}


[Trace - 21:23:58.065 PM] Sending response 'window/workDoneProgress/create - (8)' in 0ms.
Result: 


[Trace - 21:23:58.065 PM] Received notification '$/progress'.
Params: {"token":"273669266008440571","value":{"kind":"begin","title":"diagnosing changed files","message":"Calculating file diagnostics..."}}


[Trace - 21:23:58.079 PM] Received notification '$/progress'.
Params: {"token":"5570714739468966812","value":{"kind":"end","message":"Done."}}

The second failure trace shows the same. Smells like a real issue.

@findleyr
Copy link
Contributor

Since this involves going from unparseable header to parseable header, it may have actually been resolved by https://go.dev/cl/407501. (0, 0): expected ';', found 'EOF': this may be from go list. Due to timing perhaps we still thought the workspace was broken. Now we'd correctly invalidate metadata.

But actually, in one of those build results I see a goroutine running go list:
https://build.golang.org/log/f3c7835b8a11ac4b236e31c7e57c7b3339acaf9c

What's that doing? Is the go command hanging?

(sorry for the brain dump, need to move on and wanted to capture my brief investigation)

@hyangah
Copy link
Contributor

hyangah commented May 27, 2022

@findleyr There are two test failures in the log. I think the goroutines in the dump were in the middle of loading packages for the second test. "TestCutAndPaste/experimental".

[Trace - 21:33:45.749 PM] Received notification '$/progress'.
Params: {"token":"942516886148531175","value":{"kind":"begin","title":"Load","message":"Loading query=[builtin mod.com/...]"}}

The real failure is the previous test "TestIssue37978/experimental" which failed eventually with err:context deadline exceeded.

Then, this "TestCutAndPaste/experimental" started which brought down by the test's timeout (panic: test timed out after 10m0s)

@bcmills
Copy link
Contributor Author

bcmills commented May 27, 2022

Given @hyangah's analysis, CL 407501 seems to fit the bill for a fix. Shall we close this issue until/unless we see another one of these failures?

@bcmills bcmills added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label May 27, 2022
@findleyr
Copy link
Contributor

Closing and waiting to see if this reoccurs SGTM.

I'm not entirely convinced by my argument: I notice now from the logs that the diagnostic has source "syntax", not "go list". Still, I think we wouldn't have invalidated metadata before, and now we would, so it seems plausible that there was a race that has been fixed.

@golang golang locked and limited conversation to collaborators May 27, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge gopls Issues related to the Go language server, gopls. Tools This label describes issues relating to any tools in the x/tools repository. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Development

No branches or pull requests

4 participants