x/tools/gopls/internal/regtest/diagnostics: TestIssue37978 failures due to unmet location of "http.MethodGet" on netbsd

[bcmills]

--- 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)

[hyangah]

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

[bcmills]

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]

Let's just skip on GOOS=netbsd.

[hyangah]

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]

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]

@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]

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?

[findleyr]

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.