x/tools/gopls/internal/regtest/diagnostics: TestOrphanedFiles failures

[gopherbot]

#!watchflakes
default <- pkg == "golang.org/x/tools/gopls/internal/regtest/diagnostics" && test == "TestOrphanedFiles"

Issue created automatically to collect these failures.

Example (log):

#### Start Gopls Test Logs for "TestOrphanedFiles/default"
[Trace - 03:07:45.066 AM] Sending request 'initialize - (1)'.
Params: {"processId":0,"rootUri":"","capabilities":{"workspace":{"workspaceEdit":{"resourceOperations":["rename"]},"didChangeConfiguration":{},"didChangeWatchedFiles":{"dynamicRegistration":true},"configuration":true},"textDocument":{"completion":{"completionItem":{"snippetSupport":true,"tagSupport":{"valueSet":[1]}}},"documentSymbol":{"hierarchicalDocumentSymbolSupport":true},"codeAction":{"codeActionLiteralSupport":{"codeActionKind":{"valueSet":null}}},"publishDiagnostics":{},"semanticTokens":{"requests":{"range":null,"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":{"completionBudget":"10s","diagnosticsDelay":"10ms","env":{"GO111MODULE":"","GOMODCACHE":"","GOPACKAGESDRIVER":"off","GOPATH":"/tmp/buildlet/tmp/gopls-regtest-3950782489/TestOrphanedFiles/default/gopath","GOPROXY":"file:///tmp/buildlet/tmp/gopls-regtest-3950782489/TestOrphanedFiles/default/proxy","GOSUMDB":"off"},"verboseWorkDoneProgress":true},"trace":"messages","workspaceFolders":[{"uri":"file:///tmp/buildlet/tmp/gopls-regtest-3950782489/TestOrphanedFiles/default/work","name":"work"}]}


[Trace - 03:07:45.068 AM] Received response 'initialize - (1)' in 1ms.
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,"selectionRangeProvider":true,"executeCommandProvider":{"commands":["gopls.add_dependency","gopls.add_import","gopls.apply_fix","gopls.check_upgrades","gopls.edit_go_directive","gopls.fetch_vulncheck_result","gopls.gc_details","gopls.generate","gopls.go_get_package","gopls.list_imports","gopls.list_known_packages","gopls.mem_stats","gopls.regenerate_cgo","gopls.remove_dependency","gopls.reset_go_mod_diagnostics","gopls.run_go_work_command","gopls.run_govulncheck","gopls.run_tests","gopls.start_debugging","gopls.start_profile","gopls.stop_profile","gopls.test","gopls.tidy","gopls.toggle_gc_details","gopls.update_go_sum","gopls.upgrade_dependency","gopls.vendor","gopls.workspace_stats"]},"callHierarchyProvider":true,"semanticTokensProvider":{"legend":{"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"]},"range":true,"full":true},"inlayHintProvider":{},"workspace":{"workspaceFolders":{"supported":true,"changeNotifications":"workspace/didChangeWorkspaceFolders"}}},"serverInfo":{"name":"gopls","version":"{\"GoVersion\":\"devel e201ff2b98981807c4d57ed15d42d308817e138a\",\"Path\":\"\",\"Main\":{\"Path\":\"\",\"Version\":\"\",\"Sum\":\"\",\"Replace\":null},\"Deps\":null,\"Settings\":null,\"Version\":\"master\"}"}}


[Trace - 03:07:45.068 AM] Sending notification 'initialized'.
...


[Trace - 03:07:46.460 AM] Received notification '$/progress'.
Params: {"token":"695885170452308191","value":{"kind":"end","message":"Done."}}


#### End Gopls Test Logs for "TestOrphanedFiles/default"
--- FAIL: TestOrphanedFiles (1.49s)
    --- FAIL: TestOrphanedFiles/default (1.49s)
        diagnostics_test.go:1340: got 6 Load log messages after change to orphaned file, want 5

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "golang.org/x/tools/gopls/internal/regtest/diagnostics" && test == "TestOrphanedFiles"

2023-07-20 20:41 darwin-amd64-11_0 tools@3e82a5b1 go@e201ff2b x/tools/gopls/internal/regtest/diagnostics.TestOrphanedFiles (log)

#### Start Gopls Test Logs for "TestOrphanedFiles/default"
[Trace - 03:07:45.066 AM] Sending request 'initialize - (1)'.
Params: {"processId":0,"rootUri":"","capabilities":{"workspace":{"workspaceEdit":{"resourceOperations":["rename"]},"didChangeConfiguration":{},"didChangeWatchedFiles":{"dynamicRegistration":true},"configuration":true},"textDocument":{"completion":{"completionItem":{"snippetSupport":true,"tagSupport":{"valueSet":[1]}}},"documentSymbol":{"hierarchicalDocumentSymbolSupport":true},"codeAction":{"codeActionLiteralSupport":{"codeActionKind":{"valueSet":null}}},"publishDiagnostics":{},"semanticTokens":{"requests":{"range":null,"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":{"completionBudget":"10s","diagnosticsDelay":"10ms","env":{"GO111MODULE":"","GOMODCACHE":"","GOPACKAGESDRIVER":"off","GOPATH":"/tmp/buildlet/tmp/gopls-regtest-3950782489/TestOrphanedFiles/default/gopath","GOPROXY":"file:///tmp/buildlet/tmp/gopls-regtest-3950782489/TestOrphanedFiles/default/proxy","GOSUMDB":"off"},"verboseWorkDoneProgress":true},"trace":"messages","workspaceFolders":[{"uri":"file:///tmp/buildlet/tmp/gopls-regtest-3950782489/TestOrphanedFiles/default/work","name":"work"}]}


[Trace - 03:07:45.068 AM] Received response 'initialize - (1)' in 1ms.
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,"selectionRangeProvider":true,"executeCommandProvider":{"commands":["gopls.add_dependency","gopls.add_import","gopls.apply_fix","gopls.check_upgrades","gopls.edit_go_directive","gopls.fetch_vulncheck_result","gopls.gc_details","gopls.generate","gopls.go_get_package","gopls.list_imports","gopls.list_known_packages","gopls.mem_stats","gopls.regenerate_cgo","gopls.remove_dependency","gopls.reset_go_mod_diagnostics","gopls.run_go_work_command","gopls.run_govulncheck","gopls.run_tests","gopls.start_debugging","gopls.start_profile","gopls.stop_profile","gopls.test","gopls.tidy","gopls.toggle_gc_details","gopls.update_go_sum","gopls.upgrade_dependency","gopls.vendor","gopls.workspace_stats"]},"callHierarchyProvider":true,"semanticTokensProvider":{"legend":{"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"]},"range":true,"full":true},"inlayHintProvider":{},"workspace":{"workspaceFolders":{"supported":true,"changeNotifications":"workspace/didChangeWorkspaceFolders"}}},"serverInfo":{"name":"gopls","version":"{\"GoVersion\":\"devel e201ff2b98981807c4d57ed15d42d308817e138a\",\"Path\":\"\",\"Main\":{\"Path\":\"\",\"Version\":\"\",\"Sum\":\"\",\"Replace\":null},\"Deps\":null,\"Settings\":null,\"Version\":\"master\"}"}}


[Trace - 03:07:45.068 AM] Sending notification 'initialized'.
...


[Trace - 03:07:46.460 AM] Received notification '$/progress'.
Params: {"token":"695885170452308191","value":{"kind":"end","message":"Done."}}


#### End Gopls Test Logs for "TestOrphanedFiles/default"
--- FAIL: TestOrphanedFiles (1.49s)
    --- FAIL: TestOrphanedFiles/default (1.49s)
        diagnostics_test.go:1340: got 6 Load log messages after change to orphaned file, want 5

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "golang.org/x/tools/gopls/internal/regtest/diagnostics" && test == "TestOrphanedFiles"

2023-07-24 17:08 darwin-amd64-11_0 tools@67ba5997 go@bd3a1f24 x/tools/gopls/internal/regtest/diagnostics.TestOrphanedFiles (log)

#### Start Gopls Test Logs for "TestOrphanedFiles/default"
[Trace - 13:49:39.589 PM] Sending request 'initialize - (1)'.
Params: {"processId":0,"rootUri":"","capabilities":{"workspace":{"workspaceEdit":{"resourceOperations":["rename"]},"didChangeConfiguration":{},"didChangeWatchedFiles":{"dynamicRegistration":true},"configuration":true},"textDocument":{"completion":{"completionItem":{"snippetSupport":true,"tagSupport":{"valueSet":[1]}}},"documentSymbol":{"hierarchicalDocumentSymbolSupport":true},"codeAction":{"codeActionLiteralSupport":{"codeActionKind":{"valueSet":null}}},"publishDiagnostics":{},"semanticTokens":{"requests":{"range":null,"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":{"completionBudget":"10s","diagnosticsDelay":"10ms","env":{"GO111MODULE":"","GOMODCACHE":"","GOPACKAGESDRIVER":"off","GOPATH":"/tmp/buildlet/tmp/gopls-regtest-2430794313/TestOrphanedFiles/default/gopath","GOPROXY":"file:///tmp/buildlet/tmp/gopls-regtest-2430794313/TestOrphanedFiles/default/proxy","GOSUMDB":"off"},"verboseWorkDoneProgress":true},"trace":"messages","workspaceFolders":[{"uri":"file:///tmp/buildlet/tmp/gopls-regtest-2430794313/TestOrphanedFiles/default/work","name":"work"}]}


[Trace - 13:49:39.589 PM] 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,"selectionRangeProvider":true,"executeCommandProvider":{"commands":["gopls.add_dependency","gopls.add_import","gopls.apply_fix","gopls.check_upgrades","gopls.edit_go_directive","gopls.fetch_vulncheck_result","gopls.gc_details","gopls.generate","gopls.go_get_package","gopls.list_imports","gopls.list_known_packages","gopls.mem_stats","gopls.regenerate_cgo","gopls.remove_dependency","gopls.reset_go_mod_diagnostics","gopls.run_go_work_command","gopls.run_govulncheck","gopls.run_tests","gopls.start_debugging","gopls.start_profile","gopls.stop_profile","gopls.test","gopls.tidy","gopls.toggle_gc_details","gopls.update_go_sum","gopls.upgrade_dependency","gopls.vendor","gopls.workspace_stats"]},"callHierarchyProvider":true,"semanticTokensProvider":{"legend":{"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"]},"range":true,"full":true},"inlayHintProvider":{},"workspace":{"workspaceFolders":{"supported":true,"changeNotifications":"workspace/didChangeWorkspaceFolders"}}},"serverInfo":{"name":"gopls","version":"{\"GoVersion\":\"go1.20.6\",\"Path\":\"\",\"Main\":{\"Path\":\"\",\"Version\":\"\",\"Sum\":\"\",\"Replace\":null},\"Deps\":null,\"Settings\":null,\"Version\":\"master\"}"}}


[Trace - 13:49:39.590 PM] Sending notification 'initialized'.
...


[Trace - 13:49:41.172 PM] Received notification '$/progress'.
Params: {"token":"638357575133869889","value":{"kind":"end","message":"Done."}}


#### End Gopls Test Logs for "TestOrphanedFiles/default"
--- FAIL: TestOrphanedFiles (1.69s)
    --- FAIL: TestOrphanedFiles/default (1.69s)
        diagnostics_test.go:1340: got 6 Load log messages after change to orphaned file, want 5

— watchflakes

[adonovan]

It seems like there be a nondeterministic log ordering problem here: the sequence of events is:

...
logMessage(Load) x 5
publishDiagnostics
loadMessage(Load)
didChange(a.go)
publishDiagnostics
...

The first publishDiagnostics event causes the test to read the logs and count 5 "Load" events, then the sixth shows up late, but still before the didChange. Then the second publishDiagnostics causes the test to read the log again and count 6.

Are the publishDiagnostics events asynchronous to the Load logMessage events?

[findleyr]

@adonovan I think we discovered only very recently that log messages in general are not synchronous. I forgot.

I wonder if fixing that would fix this test? If that's it, funny that it bit us so soon after we recognized the long-standing bug.

[gopherbot]

Change https://go.dev/cl/513097 mentions this issue: gopls: fix tests that depend on log sequencing

[adonovan]

funny that it bit us so soon after we recognized the long-standing bug.

Indeed. I spent 10 minutes today looking for the statement of the form go something.Log(foo) preceded by a TODO comment warning about happens-before, and yet could not find the damn thing.