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: quickfix_new_files (govim) test flaky #36661

Closed
myitcv opened this issue Jan 20, 2020 · 18 comments
Closed

x/tools/gopls: quickfix_new_files (govim) test flaky #36661

myitcv opened this issue Jan 20, 2020 · 18 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.
Milestone

Comments

@myitcv
Copy link
Member

myitcv commented Jan 20, 2020

What version of Go are you using (go version)?

$ go version
go version devel +8e0be05ec7 Sun Jan 19 14:04:09 2020 +0000 linux/amd64
$ go list -m golang.org/x/tools
golang.org/x/tools v0.0.0-20200117220505-0cba7a3a9ee9 => github.com/myitcvforks/tools v0.0.0-20200119092928-0fd5434cd1ba
$ go list -m golang.org/x/tools/gopls
golang.org/x/tools/gopls v0.1.8-0.20200117220505-0cba7a3a9ee9 => github.com/myitcvforks/tools/gopls v0.0.0-20200119092928-0fd5434cd1ba

Note that per govim/govim@c7a6cc3, github.com/myitcvforks/tools/gopls@v0.0.0-20200119092928-0fd5434cd1ba is 0cba7a3 with a partial revert of CL214586 on top (the result of which can be seen in https://go-review.googlesource.com/c/tools/+/215239)

The issue described below also exists when tested against 0cba7a3.

Does this issue reproduce with the latest release?

Yes.

What operating system and processor architecture are you using (go env)?

go env Output
$ go env
GO111MODULE="on"
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/myitcv/.cache/go-build"
GOENV="/home/myitcv/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/myitcv/gostuff"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/myitcv/gos"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/myitcv/gos/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/myitcv/gostuff/src/github.com/myitcv/govim/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build026758154=/tmp/go-build -gno-record-gcc-switches"

What did you do?

We have just added a new govim test that seeks to verify diagnostics are as expected for new files that do not, initially, exist on disk.

The scenario involves creating a package p with a simple function DoIt. p is imported by a main package. p also has a test file that exercises DoIt, and an external test file that does the same.

Initially all call sites for DoIt incorrectly pass an integer argument, meaning we should have error diagnostics for all call sites. Then we correct the definition of DoIt to take an integer argument at which point all diagnostics should disappear.

The test can be seen here:

https://github.com/govim/govim/blob/cmd_govim_testscript_new_files_quickfix/cmd/govim/testdata/scenario_default/quickfix_new_files.txt

What did you expect to see?

  1. Error diagnostics for main.go, p/p_test.go, and p/x_test.go once the files have been created.
  2. And then no diagnostics once we fix the definition of DoIt.

What did you see instead?

  1. No error diagnostics
  2. Because we don't get the right error diagnostic state, the test stops so we can't verify this check

Marking as v0.3.0 because this is a fairly fundamental test case.


cc @stamblerre

FYI @leitzler

@myitcv myitcv added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. gopls Issues related to the Go language server, gopls. labels Jan 20, 2020
@myitcv myitcv added this to the gopls/v0.3.0 milestone Jan 20, 2020
@gopherbot gopherbot added the Tools This label describes issues relating to any tools in the x/tools repository. label Jan 20, 2020
@stamblerre
Copy link
Contributor

I tried reproducing this, but I wasn't able to get a failing test. Is this test expected to fail or will the logs just show the incorrect output?

@stamblerre stamblerre added WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Jan 22, 2020
@myitcv
Copy link
Member Author

myitcv commented Jan 22, 2020

The test is not merged yet, but you can do:

git fetch origin pull/699/head && git checkout FETCH_HEAD

and then remove the skip from cmd/govim/testdata/scenario_default/quickfix_new_files.txt

Full repro steps using dockexec:

cd $(mktemp -d)
git clone https://github.com/govim/govim
cd govim
git fetch origin pull/699/head && git checkout FETCH_HEAD
sed -i '/skip/d' cmd/govim/testdata/scenario_default/quickfix_new_files.txt
go test -exec="dockexec govim/govim:go1.14beta1_vim_v8.2.0025_v1 -t -e VIM_FLAVOR=vim -e GOVIM_ERRLOGMATCH_WAIT=5s" -count=1 -v -run "TestScripts/scenario_default/quickfix_new_files" ./cmd/govim

gives

=== CONT  TestScripts/scenario_default/quickfix_new_files
    TestScripts/scenario_default/quickfix_new_files: testscript.go:348: 
        WORK=$WORK
        PATH=/vim/bin:/go/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
        HOME=$WORK/.home
        TMPDIR=$WORK/_tmp
        devnull=/dev/null
        :=:
        exe=
        GOPATH=$WORK/.home/gopath
        CCACHE_DISABLE=1
        GOARCH=amd64
        GOOS=linux
        GOROOT=/go
        GOCACHE=/gocache
        GOPROXY=http://127.0.0.1:34861/mod
        goversion=1.14
        GOVIM_ERRLOGMATCH_WAIT=5s
        GOVIM_DETECT_USER_BUSY=false
        GONOSUMDB=*
        PLUGIN_PATH=/start
        GOVIMTEST_SOCKET=127.0.0.1:37849
        GOVIMTESTDRIVER_SOCKET=127.0.0.1:42901
        
        # Test that we get diagnostics for new files that don't exist on disk.
        #
        # The scenario involves creating a package p with a simple function DoIt. p is
        # imported by a main package. p also has a test file that exercises DoIt, and
        # an external test file that does the same.
        #
        # Initially all call sites for DoIt incorrectly pass an integer argument,
        # meaning we should have error diagnostics for all call sites. Then we correct
        # the definition of DoIt to take an integer argument at which point all
        # diagnostics should disappear.
        # Create all the new files (0.109s)
        > vim ex 'e p/p.go'
        > vim ex 'r p/p.go.orig | 0d_'
        > vim ex 'noau w! check'
        > cmp check p/p.go.orig
        > vim ex 'sp main.go'
        > vim ex 'r main.go.orig | 0d_'
        > vim ex 'noau w! check'
        > cmp check main.go.orig
        > vim ex 'sp p/p_test.go'
        > vim ex 'r p/p_test.go.orig | 0d_'
        > vim ex 'noau w! check'
        > cmp check p/p_test.go.orig
        > vim ex 'sp p/x_test.go'
        > vim ex 'r p/x_test.go.orig | 0d_'
        > vim ex 'noau w! check'
        > cmp check p/x_test.go.orig
        # Expect the errors (4.942s)
        > vimexprwait errors.golden getqflist()
        [stderr]
        -[]
        +[
        +  {
        +    "bufnr": 1,
        +    "col": 9,
        +    "lnum": 6,
        +    "module": "",
        +    "nr": 0,
        +    "pattern": "",
        +    "text": "cannot convert 5 (untyped int constant) to string",
        +    "type": "",
        +    "valid": 1,
        +    "vcol": 0
        +  },
        +  {
        +    "bufnr": 2,
        +    "col": 7,
        +    "lnum": 6,
        +    "module": "",
        +    "nr": 0,
        +    "pattern": "",
        +    "text": "cannot convert 5 (untyped int constant) to string",
        +    "type": "",
        +    "valid": 1,
        +    "vcol": 0
        +  },
        +  {
        +    "bufnr": 3,
        +    "col": 9,
        +    "lnum": 9,
        +    "module": "",
        +    "nr": 0,
        +    "pattern": "",
        +    "text": "cannot convert 5 (untyped int constant) to string",
        +    "type": "",
        +    "valid": 1,
        +    "vcol": 0
        +  }
        +]
        [exit status 1]
        FAIL: testdata/scenario_default/quickfix_new_files.txt:32: unexpected command failure
        
--- FAIL: TestScripts (5.32s)
    --- FAIL: TestScripts/scenario_default (0.04s)
        --- FAIL: TestScripts/scenario_default/quickfix_new_files (5.31s)
FAIL

@stamblerre stamblerre added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. and removed WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. labels Jan 22, 2020
@stamblerre
Copy link
Contributor

Thanks for the repro! I'll look into it ASAP.

@myitcv
Copy link
Member Author

myitcv commented Jan 22, 2020

The test is now merged so repro steps are:

cd $(mktemp -d)
git clone https://github.com/govim/govim
cd govim
git checkout 1eb9311cf6155f0aceb9f9bb93dce20e406ec205
sed -i '/skip/d' cmd/govim/testdata/scenario_default/quickfix_new_files.txt
go test -exec="dockexec govim/govim:go1.14beta1_vim_v8.2.0025_v1 -t -e VIM_FLAVOR=vim -e GOVIM_ERRLOGMATCH_WAIT=5s" -count=1 -v -run "TestScripts/scenario_default/quickfix_new_files" ./cmd/govim

@heschi
Copy link
Contributor

heschi commented Jan 23, 2020

The problem here is that the initial workspace load finds nothing, and AFAIK we currently have no mechanism for adding packages to the workspace set, so they don't ever end up getting diagnosed in the background.

@myitcv
Copy link
Member Author

myitcv commented Jan 23, 2020

FWIW this will be a common situation for Vim (and other non-VSCode) developers where the editor has an in-memory buffer that can exist without the file needing to exist on disk.

@gopherbot
Copy link

Change https://golang.org/cl/216141 mentions this issue: internal/lsp: track orphaned files when a file is created

@myitcv
Copy link
Member Author

myitcv commented Jan 25, 2020

Re-opening because we're seeing some flakey behaviour here. About 20% of the time in govim tests we're not getting back the expected diagnostics.

We are seeing these failures again 8fe064f

The test mentioned above is failing with the following diff:

[stderr]
 [
   {
     "bufname": "main.go",
-    "col": 8,
-    "lnum": 3,
+    "col": 9,
+    "lnum": 6,
     "module": "",
     "nr": 0,
     "pattern": "",
-    "text": "could not import mod.com/p (no package for import mod.com/p)",
+    "text": "cannot convert 5 (untyped int constant) to string",
     "type": "",
     "valid": 1,
     "vcol": 0
   },
   {
     "bufname": "p/p_test.go",
     "col": 7,
     "lnum": 6,
     "module": "",
     "nr": 0,
     "pattern": "",
     "text": "cannot convert 5 (untyped int constant) to string",
     "type": "",
     "valid": 1,
     "vcol": 0
   },
   {
     "bufname": "p/x_test.go",
     "col": 9,
     "lnum": 10,
     "module": "",
     "nr": 0,
     "pattern": "",
     "text": "cannot convert 5 (untyped int constant) to string",
     "type": "",
     "valid": 1,
     "vcol": 0
   }
 ]

The gopls log file for this test run was: gopls.log

@myitcv myitcv reopened this Jan 25, 2020
@stamblerre
Copy link
Contributor

@myitcv: Is there a way to run these tests with the "verboseOutput" setting on? I'd need to see what the output of the packages.Load was to understand this error.

@myitcv
Copy link
Member Author

myitcv commented Jan 26, 2020

Does the following give you what you need?

gopls.log

@stamblerre
Copy link
Contributor

stamblerre commented Jan 26, 2020

Thanks, yes, these are helpful. Is there a go.mod file for these files or are they meant to be an ad-hoc package? I ask because of this log statement, where it seems the files are being loaded ad-hoc:

[Trace - 01:30:08.040 AM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2020/01/26 01:30:08 go/packages.Load\n\tpackage = command-line-arguments\n\tfiles = [/artefacts/govim/cmd/govim/scenario_default/script-quickfix_new_files/p/p_test.go /artefacts/govim/cmd/govim/scenario_default/script-quickfix_new_files/p/x_test.go /artefacts/govim/cmd/govim/scenario_default/script-quickfix_new_files/p/p.go]"}

Also, worth noting are these go list errors:

[Trace - 01:30:07.842 AM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2020/01/26 01:30:07 14.002514ms for GOROOT=/go GOPATH=/artefacts/govim/cmd/govim/scenario_default/script-quickfix_new_files/.home/gopath GO111MODULE= PWD=/artefacts/govim/cmd/govim/scenario_default/script-quickfix_new_files go \"list\" \"-e\" \"-json\" \"-compiled=true\" \"-test=true\" \"-export=false\" \"-deps=true\" \"-find=false\" \"--\" \"/artefacts/govim/cmd/govim/scenario_default/script-quickfix_new_files/p\", stderr: \u003c\u003c\u003e\u003e stdout: \u003c\u003c{\n\t\"ImportPath\": \"mod.com/p\",\n\t\"Match\": [\n\t\t\"/artefacts/govim/cmd/govim/scenario_default/script-quickfix_new_files/p\"\n\t],\n\t\"Incomplete\": true,\n\t\"Error\": {\n\t\t\"ImportStack\": [\n\t\t\t\"mod.com/p\"\n\t\t],\n\t\t\"Pos\": \"\",\n\t\t\"Err\": \"unknown import path \\\"mod.com/p\\\": cannot find module providing package mod.com/p\"\n\t}\n}\n\u003e\u003e\n"}


[Trace - 01:30:07.852 AM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2020/01/26 01:30:07 10.519903ms for GOROOT=/go GOPATH=/artefacts/govim/cmd/govim/scenario_default/script-quickfix_new_files/.home/gopath GO111MODULE= PWD=/artefacts/govim/cmd/govim/scenario_default/script-quickfix_new_files go \"list\" \"-e\" \"-json\" \"-compiled=true\" \"-test=true\" \"-export=false\" \"-deps=true\" \"-find=false\" \"--\" \"/artefacts/govim/cmd/govim/scenario_default/script-quickfix_new_files/p/x_test.go\", stderr: \u003c\u003cstat /artefacts/govim/cmd/govim/scenario_default/script-quickfix_new_files/p/x_test.go: no such file or directory\n\u003e\u003e stdout: \u003c\u003c\u003e\u003e\n"}

Do they appear in passing logs? I'll investigate this further when I get a chance to reproduce this locally.

@myitcv
Copy link
Member Author

myitcv commented Jan 27, 2020

Yes, there is a go.mod in this instance too:

https://github.com/govim/govim/blob/013f992e25f23cbc4a778d1eb472e719d276de32/cmd/govim/testdata/scenario_default/quickfix_new_files.txt#L49-L51

Here is a log from a passing test: pass.log

Those go list errors do not appear when it passes, no.

But just to point out, that a go list that looks only at disk files will fail, because this entire test is about the files not existing on disk. So only an overlay is required in this instance for the list of mod.com/p to succeed.

@stamblerre
Copy link
Contributor

Jotting down some notes as I investigate this:

The passing case manages to get all 3 packages for the mod.com/p:

[Trace - 09:14:26.683 AM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2020/01/27 09:14:26 go/packages.Load\n\tsnapshot = 12\n\tquery = [file=/tmp/blah/govim/cmd/govim/scenario_default/script-quickfix_new_files/main.go file=/tmp/blah/govim/cmd/govim/scenario_default/script-quickfix_new_files/p/x_test.go file=/tmp/blah/govim/cmd/govim/scenario_default/script-quickfix_new_files/p/p_test.go file=/tmp/blah/govim/cmd/govim/scenario_default/script-quickfix_new_files/p/p.go]\n\tpackages = 3"}

Whereas the failing case only loads 2:

[Trace - 01:30:08.041 AM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2020/01/26 01:30:08 go/packages.Load\n\tsnapshot = 12\n\tquery = [file=/artefacts/govim/cmd/govim/scenario_default/script-quickfix_new_files/p/p_test.go file=/artefacts/govim/cmd/govim/scenario_default/script-quickfix_new_files/p/p.go file=/artefacts/govim/cmd/govim/scenario_default/script-quickfix_new_files/main.go file=/artefacts/govim/cmd/govim/scenario_default/script-quickfix_new_files/p/x_test.go]\n\tpackages = 2"}

This looks like a case of go/packages overlay flakiness.

@stamblerre stamblerre changed the title x/tools/gopls: diagnostics not received for new files x/tools/gopls: flaky packages.Load results for new files Jan 27, 2020
@stamblerre
Copy link
Contributor

After our CLs today, neither @heschik nor I were able to reproduce this locally, and we didn't see it happen in our CI. If it's still happening in your CI, could you share the logs (for both pass and fail) with "verboseOutput" enabled please?

@stamblerre stamblerre removed the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jan 28, 2020
@stamblerre stamblerre added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Jan 28, 2020
@stamblerre stamblerre changed the title x/tools/gopls: flaky packages.Load results for new files x/tools/gopls: quickfix_new_files (govim) test flaky Jan 28, 2020
@myitcv
Copy link
Member Author

myitcv commented Jan 28, 2020

and we didn't see it happen in our CI

The test is currently skipped so you won't see it fail in your CI:

https://github.com/govim/govim/blob/60a1430268fb2fe39e9b1e9beab2fd7a778bd1c6/cmd/govim/testdata/scenario_default/quickfix_new_files.txt#L12

could you share the logs (for both pass and fail) with "verboseOutput" enabled please?

Pass: gopls.log

Fail: gopls.log

Note that to try our this CL I'm using the following replaces:

$ go list -m golang.org/x/tools/gopls golang.org/x/tools
golang.org/x/tools/gopls v0.1.8-0.20200128002243-345141a36859 => github.com/myitcvforks/tools/gopls v0.0.0-20200128020335-57eb47a4c669
golang.org/x/tools v0.0.0-20200128002243-345141a36859 => github.com/myitcvforks/tools v0.0.0-20200128020335-57eb47a4c669

@stamblerre stamblerre removed the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Jan 28, 2020
@stamblerre
Copy link
Contributor

stamblerre commented Jan 28, 2020

Thanks for the update. It's a similar situation as before, but now we're at least getting closer to the correct number of packages.

Passing gets 4 packages for this query (as expected):

[Trace - 05:36:04.296 AM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2020/01/28 05:36:04 go/packages.Load\n\tsnapshot = 12\n\tquery = [file=/tmp/blah/govim/cmd/govim/scenario_default/script-quickfix_new_files/main.go file=/tmp/blah/govim/cmd/govim/scenario_default/script-quickfix_new_files/p/p.go file=/tmp/blah/govim/cmd/govim/scenario_default/script-quickfix_new_files/p/p_test.go file=/tmp/blah/govim/cmd/govim/scenario_default/script-quickfix_new_files/p/x_test.go]\n\tpackages = 4"}

Whereas failing only gets 3:

[Trace - 05:35:17.037 AM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2020/01/28 05:35:17 go/packages.Load\n\tsnapshot = 12\n\tquery = [file=/tmp/blah/govim/cmd/govim/scenario_default/script-quickfix_new_files/main.go file=/tmp/blah/govim/cmd/govim/scenario_default/script-quickfix_new_files/p/p.go file=/tmp/blah/govim/cmd/govim/scenario_default/script-quickfix_new_files/p/p_test.go file=/tmp/blah/govim/cmd/govim/scenario_default/script-quickfix_new_files/p/x_test.go]\n\tpackages = 3"}

The missing package is always main.

@gopherbot
Copy link

Change https://golang.org/cl/216717 mentions this issue: go/packages: fix flaky failure creating non-test package from overlay

gopherbot pushed a commit to golang/tools that referenced this issue Jan 28, 2020
The core of processGolistOverlay was a map iteration, which is
nondeterministic. When creating both a non-test and test package, we
would sometimes encounter the test file before the non-test file. In
that case, for reasons I didn't bother tracking down, we would never
create the non-test package.

Rather than doing complicated bookkeeping to fix the problem, simply
process non-test before test, and make the loop deterministic to save
all of our sanity.

Updates golang/go#36661.

Change-Id: I1f76869fa52794ac8ae96e22ad06a2b1e1861995
Reviewed-on: https://go-review.googlesource.com/c/tools/+/216717
Reviewed-by: Rebecca Stambler <rstambler@golang.org>
Run-TryBot: Heschi Kreinick <heschi@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
@stamblerre
Copy link
Contributor

I believe that the above CL should've resolved this as well. Closing.

@golang golang locked and limited conversation to collaborators Jan 28, 2021
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.
Projects
None yet
Development

No branches or pull requests

4 participants