x/tools/internal/lsp/regtest: various flakes due to go.mod contention

[bcmills]

https://build.golang.org/log/fe27a791913be11bc439f9612e1ba92f52673e54

2020/02/20 00:34:56 initial workspace load failed: go [list -f {{context.GOARCH}} {{context.Compiler}} -modfile=/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/tmp/go.042197626.mod -- unsafe]: exit status 1: go: open /var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/tmp/go.042197626.mod: no such file or directory

2020/02/20 00:35:01 diagnose: could not generate diagnostics for go.mod file: err: chdir /var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/tmp/goplstest-ws-lsprpc-132098964: no such file or directory: stderr: 
2020/02/20 00:35:04 diagnose: could not generate diagnostics for go.mod file: err: exit status 1: stderr: go: cannot find main module, but -modfile was set.
	-modfile cannot be used to set the module root directory.

2020/02/20 00:35:07 diagnose: could not generate diagnostics for go.mod file: err: exit status 1: stderr: go: open /var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/tmp/go.115179283.mod: no such file or directory

2020/02/20 00:35:08 serving stream: failed reading header line "EOF"
2020/02/20 00:35:37 : context deadline exceeded
--- FAIL: TestGoToStdlibDefinition (37.17s)
    --- FAIL: TestGoToStdlibDefinition/forwarded (30.41s)
        definition_test.go:69: Definition: context deadline exceeded
panic: Shutdown: context deadline exceeded [recovered]
	panic: Shutdown: context deadline exceeded

goroutine 11620 [running]:
testing.tRunner.func1.1(0x1698620, 0xc00c71a0b0)
	/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/go/src/testing/testing.go:941 +0x3d0
testing.tRunner.func1(0xc00a536360)
	/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/go/src/testing/testing.go:944 +0x3f9
panic(0x1698620, 0xc00c71a0b0)
	/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/go/src/runtime/panic.go:967 +0x15d
golang.org/x/tools/internal/lsp/regtest.(*Runner).RunInMode.func1.1(0xc00a1fb140, 0x189f140, 0xc00a1fad80)
	/private/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/gopath/src/golang.org/x/tools/internal/lsp/regtest/env.go:178 +0x70
runtime.Goexit()
	/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/go/src/runtime/panic.go:615 +0x192
testing.(*common).FailNow(0xc00a536360)
	/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/go/src/testing/testing.go:657 +0x39
testing.(*common).Fatal(0xc00a536360, 0xc000a3bd98, 0x1, 0x1)
	/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/go/src/testing/testing.go:718 +0x78
golang.org/x/tools/internal/lsp/regtest.(*Env).GoToDefinition(0xc00a1fb140, 0x17774e5, 0x7, 0x8, 0x13, 0x100ea48, 0x10, 0x16c56a0, 0x173f301)
	/private/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/gopath/src/golang.org/x/tools/internal/lsp/regtest/env.go:310 +0x130
golang.org/x/tools/internal/lsp/regtest.TestGoToStdlibDefinition.func1(0x189f140, 0xc00a1fad80, 0xc00a536360, 0xc00a1fb140)
	/private/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/gopath/src/golang.org/x/tools/internal/lsp/regtest/definition_test.go:69 +0x8d
golang.org/x/tools/internal/lsp/regtest.(*Runner).RunInMode.func1(0xc00a536360)
	/private/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/gopath/src/golang.org/x/tools/internal/lsp/regtest/env.go:181 +0x2af
testing.tRunner(0xc00a536360, 0xc00a508500)
	/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/go/src/testing/testing.go:992 +0xdc
created by testing.(*T).Run
	/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/go/src/testing/testing.go:1043 +0x357
FAIL	golang.org/x/tools/internal/lsp/regtest	44.585s

CC @stamblerre @jayconrod @matloob

[stamblerre]

@ridersofrohan: Can you take a look at these failures? The error messages at the top seem to be caused by -modfile.

[findleyr]

Thanks, this looks like a flake. Let me investigate first.

[findleyr]

Ok, I think this is a test simply timing out due to an extremely slow initial workspace load (we delete the temp modfiles when the test exits, so I think the -modfile error log is a red herring).

Locally, the entire regtest suite runs in ~3s, but I can produce a similar error message by setting the test timeout to 1s.

As a temporary fix, I'm going to increase the timeout to 60s to see if this still flakes. Longer term, I need to understand why this test runs more than an order of magnitude slower on the builders.

[gopherbot]

Change https://golang.org/cl/220280 mentions this issue: internal/lsp/regtest: increase test timeout to 60s

[bcmills]

Here is a similar failure on freebsd-amd64-race, in TestGoToStdlibDefinition/singleton in
https://build.golang.org/log/a7e57b48b2eb87387651b04e268638d5b1b25f9d

--- FAIL: TestGoToStdlibDefinition (60.55s)
    --- FAIL: TestGoToStdlibDefinition/singleton (60.53s)
        definition_test.go:69: Definition: context deadline exceeded
panic: Shutdown: context deadline exceeded [recovered]
	panic: Shutdown: context deadline exceeded

goroutine 32 [running]:
testing.tRunner.func1.1(0xe31000, 0xc0024ade50)
	/tmp/workdir/go/src/testing/testing.go:941 +0x5d0
testing.tRunner.func1(0xc000224fc0)
	/tmp/workdir/go/src/testing/testing.go:944 +0x600
panic(0xe31000, 0xc0024ade50)
	/tmp/workdir/go/src/runtime/panic.go:973 +0x396
golang.org/x/tools/internal/lsp/regtest.(*Runner).RunInMode.func1.1(0xc00028e2a0, 0x1087780, 0xc000254120)
	/tmp/workdir/gopath/src/golang.org/x/tools/internal/lsp/regtest/env.go:178 +0xc1
runtime.Goexit()
	/tmp/workdir/go/src/runtime/panic.go:634 +0x104
testing.(*common).FailNow(0xc000224fc0)
	/tmp/workdir/go/src/testing/testing.go:657 +0x5b
testing.(*common).Fatal(0xc000224fc0, 0xc0001f9ba0, 0x1, 0x1)
	/tmp/workdir/go/src/testing/testing.go:718 +0x8a
golang.org/x/tools/internal/lsp/regtest.(*Env).GoToDefinition(0xc00028e2a0, 0xf16f3a, 0x7, 0x8, 0x13, 0xc0002283c0, 0xc000254300, 0xc000268000, 0x0)
	/tmp/workdir/gopath/src/golang.org/x/tools/internal/lsp/regtest/env.go:310 +0x1a2
golang.org/x/tools/internal/lsp/regtest.TestGoToStdlibDefinition.func1(0x1087780, 0xc000254120, 0xc000224fc0, 0xc00028e2a0)
	/tmp/workdir/gopath/src/golang.org/x/tools/internal/lsp/regtest/definition_test.go:69 +0x9e
golang.org/x/tools/internal/lsp/regtest.(*Runner).RunInMode.func1(0xc000224fc0)
	/tmp/workdir/gopath/src/golang.org/x/tools/internal/lsp/regtest/env.go:181 +0x3bc
testing.tRunner(0xc000224fc0, 0xc000228230)
	/tmp/workdir/go/src/testing/testing.go:992 +0x1ec
created by testing.(*T).Run
	/tmp/workdir/go/src/testing/testing.go:1043 +0x661
FAIL	golang.org/x/tools/internal/lsp/regtest	61.597s

[bcmills]

And that appears to be after the timeout increase: note that the time has risen to 60s.

I wonder if the underlying problem is a failure to propagate some other error appropriately. (See #36444 and #36605.)

[findleyr]

Hmm, my intuition was that the timeout was not specific to this test, but the fact that it is the same test and that it timed out at 60s suggests that this is a real failure. I haven't yet been able to reproduce, but I will skip this test until it is understood.

[gopherbot]

Change https://golang.org/cl/220360 mentions this issue: internal/lsp/regtest: skip flaky TestGoToStdlibDefinition

[bcmills]

Looks like TestGoToInternalDefinition is flaky too (https://build.golang.org/log/f4005ba97ed110dada6639ae9471c52d744e9bb3):

2020/02/27 06:05:06 initial workspace load failed: err: exit status 1: stderr: go: open /tmp/workdir/tmp/go.goplstest-ws-lsprpc-546835840.254255568.mod: no such file or directory

2020/02/27 06:05:35 diagnose: could not generate diagnostics for go.mod file: err: exit status 1: stderr: 2020/02/27 06:05:35 cannot determine current directory: getwd: no such file or directory

2020/02/27 06:06:01 diagnose: could not generate diagnostics for go.mod file: err: exit status 1: stderr: 2020/02/27 06:06:01 cannot determine current directory: getwd: no such file or directory

--- FAIL: TestGoToInternalDefinition (135.43s)
2020/02/27 06:09:39 : context deadline exceeded
    --- FAIL: TestGoToInternalDefinition/forwarded (77.60s)
        definition_test.go:38: definition: context deadline exceeded
panic: Shutdown: context deadline exceeded [recovered]
	panic: Shutdown: context deadline exceeded

goroutine 9453 [running]:
testing.tRunner.func1.1(0xe3fac0, 0xc002a7a6a0)
	/tmp/workdir/go/src/testing/testing.go:941 +0x5d0
testing.tRunner.func1(0xc00aafbe60)
	/tmp/workdir/go/src/testing/testing.go:944 +0x600
panic(0xe3fac0, 0xc002a7a6a0)
	/tmp/workdir/go/src/runtime/panic.go:973 +0x396
golang.org/x/tools/internal/lsp/regtest.(*Runner).RunInMode.func1.1(0xc00b179140, 0x10990c0, 0xc00a7d9440)
	/tmp/workdir/gopath/src/golang.org/x/tools/internal/lsp/regtest/env.go:180 +0xc1
runtime.Goexit()
	/tmp/workdir/go/src/runtime/panic.go:634 +0x104
testing.(*common).FailNow(0xc00aafbe60)
	/tmp/workdir/go/src/testing/testing.go:657 +0x5b
testing.(*common).Fatal(0xc00aafbe60, 0xc0009e9bc0, 0x1, 0x1)
	/tmp/workdir/go/src/testing/testing.go:718 +0x8a
golang.org/x/tools/internal/lsp/regtest.(*Env).GoToDefinition(0xc00b179140, 0xf26c4b, 0x7, 0x5, 0xd, 0x0, 0xc005b3b0d0, 0xc005b3b300, 0xc00aaf8ff0)
	/tmp/workdir/gopath/src/golang.org/x/tools/internal/lsp/regtest/env.go:323 +0x1a2
golang.org/x/tools/internal/lsp/regtest.TestGoToInternalDefinition.func1(0x10990c0, 0xc00a7d9440, 0xc00aafbe60, 0xc00b179140)
	/tmp/workdir/gopath/src/golang.org/x/tools/internal/lsp/regtest/definition_test.go:38 +0x9e
golang.org/x/tools/internal/lsp/regtest.(*Runner).RunInMode.func1(0xc00aafbe60)
	/tmp/workdir/gopath/src/golang.org/x/tools/internal/lsp/regtest/env.go:183 +0x3bc
testing.tRunner(0xc00aafbe60, 0xc00aaf8eb0)
	/tmp/workdir/go/src/testing/testing.go:992 +0x1ec
created by testing.(*T).Run
	/tmp/workdir/go/src/testing/testing.go:1043 +0x661
FAIL	golang.org/x/tools/internal/lsp/regtest	275.474s

Looks like the same or a similar root cause.

[findleyr]

Root cause is still unknown, but I agree it's probably the same. It's actually good to see this test failing as well. I've been trying to catch this failure in https://golang.org/cl/220362, but have not yet succeeded.

I'm going to remove all my t.Parallel() calls in hopes that this just goes away. It's concerning that we don't understand this, but pragmatically this level of parallelism is unrealistic and I'd prefer not to have to skip all of these tests.

If this reoccur's after the parallelism is removed, I'll skip the tests.

[gopherbot]

Change https://golang.org/cl/221379 mentions this issue: internal/lsp/regtest: remove calls to t.Parallel()

[bcmills]

Possibly the same failure mode in TestDiagnosticErrorInNewFile/forwarded?

2020/02/28 00:40:12 diagnose: could not generate diagnostics for go.mod file: err: exit status 1: stderr: 2020/02/28 00:40:12 cannot determine current directory: getwd: no such file or directory

2020/02/28 00:40:18 diagnose: could not generate diagnostics for go.mod file: err: exit status 1: stderr: 2020/02/28 00:40:18 cannot determine current directory: getwd: no such file or directory

2020/02/28 00:40:25 closed a connection with error: disconnected
2020/02/28 00:40:37 closed a connection with error: disconnected
--- FAIL: TestDiagnosticErrorInNewFile (91.72s)
    --- FAIL: TestDiagnosticErrorInNewFile/forwarded (60.01s)
        diagnostics_test.go:47: waiting on (diagnostic in "broken.go" at (line:2, column:12)):
            err:context deadline exceeded
            diagnostics:
panic: Shutdown: context deadline exceeded [recovered]
	panic: Shutdown: context deadline exceeded

[findleyr]

@bcmills, where was this test failure? Was this on a builder, or did you produce it locally? I ask both because I haven't been able to reproduce locally, and to check if the build had golang.org/cl/221379.

[bcmills]

Sorry, thought I had pasted a link. That one is from https://build.golang.org/log/e78c48b9bfdaee4e6529403cb7d074969d334387.

A lot of these seem to be occurring on the freebsd-amd64-race builder (#36444), which could plausibly be due to some subprocess failing due to an out-of-memory condition.

I wonder if you could reproduce it locally by randomly sending SIGKILL to subprocesses while the test is running...

[gopherbot]

Change https://golang.org/cl/226957 mentions this issue: internal/lsp/regtest: dump gopls logs on test failure

[findleyr]

I am 87%* certain that I have found the root cause for these flakes, as described in https://go-review.googlesource.com/c/tools/+/230464/2#message-8e002f1f2938802ba8f8d0bd45936948d2b884a3

...a rare and hard to reproduce race condition plus broken error propagation on jsonrpc2 shutdown made this extremely difficult to track down. Plus it was temporarily fixed/masked by an unrelated change. Fix incoming, at which point I'll let it soak for a while to make sure there are no additional failures on the builder.

This may also affect internal/lsp/cmd tests. CC @ianthehat

* I guess more accurately I should say: I am 87% certain that I have found a cause for some of these flakes. I am not confident that there aren't multiple causes.

Edit: this is possibly related but unfortunately not the root cause. See below.

[findleyr]

Oh no, as soon as I wrote this I realized that the write synchronization had been removed at the CL I was debugging, so this can't be the cause :(

But I think the part about connection errors not being surfaced is still important, and fixing jsonrpc2 shutdown is likely critical to solving these flakes, if they still exist.

[findleyr]

Using fetchlogs/greplogs, I categorized flakes for the last month into two groups:

• 80-90% appear related to go.mod concurrency, which appears to also manifest outside of regtests (see x/tools/internal/lsp: TryBot failure in upgradedep #39504). The cause of this is now more clear, due to recently added logging:

files=[C:\Users\gopher\AppData\Local\Temp\goplstest-sandbox-regtest-794066405\work\main.go]
2020/06/04 18:13:17 warning: diagnose go.mod: write C:\Users\gopher\AppData\Local\Temp\go.work.571081216.mod: The process cannot access the file because another process has locked a portion of the file.
	directory=C:\Users\gopher\AppData\Local\Temp\goplstest-sandbox-regtest-794066405\work
2020/06/04 18:13:17 go/packages.Load: go [-e -json -compiled=true -test=true -export=false -deps=true -find=false -modfile=C:\Users\gopher\AppData\Local\Temp\go.work.571081216.mod -- github.com/ardanlabs/conf]: exit status 1: go: cannot determine module path for source directory C:\Users\gopher\AppData\Local\Temp\goplstest-sandbox-regtest-794066405\work (outside GOPATH, module path must be specified)

The problem appears to be that we re-use the temp modfile path, and not all actions we perform on it are atomic. @stamblerre is looking into a couple possible fixes: (1) locking, or (2) using a different temp modfile location for each invocation.

• Around 10% of failures do not fall into this category, and seem to be related to TestInconsistentVendoring. I believe that regtest is independently flaky, though I haven't investigated why.

[gopherbot]

Change https://golang.org/cl/237517 mentions this issue: internal/lsp: use a new temporary go.mod for every go list call

[stamblerre]

@findleyr: Now that the load concurrency errors should be gone, I'll try to take a look at the TestInconsistentVendoring flakes (since I wrote the test). Do you have any logs for those?

[findleyr]

I can find some, but those were pretty rare and may have also been related to mod concurrency. In the meantime, while grepping for logs, I discovered the more concerning #39696, which may be related to your fix.

[findleyr]

Here's an example of a TestInconsistentVendoring flake from today:
https://build.golang.org/log/82f7b6a5717c88cb6371de2080d00f7b9848f014

[stamblerre]

I just looked around in the build dashboard, and I agree that #39696 does look more concerning. Am currently trying to reproduce it locally, but also improved the logging in CL 238737, so hopefully that will help.

I also noticed a few more test failures on the dashboard (1, 2, 3), which all include same error message:

lsprpc.go:341: unable to add local env to initialize request: err: exit status 1: stderr: missing $GOPATH

It appears once in a TestInconsistenVendoring failure too, so I wonder if it's related?

[stamblerre]

Ran into another instance of this on CL 239117: https://storage.googleapis.com/go-build-log/206ee872/linux-amd64_efb99276.log.

Edit: The error turned out to be unrelated.

[heschi]

I haven't seen one of these in ages. Close?