x/tools/gopls: regtest flakes due to hanging go commands #54461

findleyr · 2022-08-15T18:50:27Z

#!watchflakes
post <- goos != "netbsd" && (pkg ~ `^golang.org/x/tools/gopls` || (repo == "tools" && pkg == "")) && 
        (`detected hanging go command` || log ~ `detected hanging go command` || `DETECTED A HANGING GO COMMAND` || log ~ `DETECTED A HANGING GO COMMAND`)

greplogs --dashboard -md -l -e 'runCmdContext' --since=2022-07-14

We recently started waiting for all go command invocations when shutting down gopls regtests. It appears that sometimes we kill the go command and still don't get a result from cmd.Wait(). For example, here:
https://build.golang.org/log/00046e0b005c7660d676a3a415561950048f756a

In that failure, the test runner looks otherwise healthy (other tests ran fast), and yet the goroutine stack clearly shows a go command hanging for 9 minutes here:
https://cs.opensource.google/go/x/tools/+/master:internal/gocommand/invoke.go;l=260;drc=f38573358cbedf46d64c5759ef41b72afcf0c5c0

@bcmills do you happen to have any idea of what might cause this?

The text was updated successfully, but these errors were encountered:

findleyr · 2022-08-15T19:05:19Z

Two observations:

We're not checking the error from Kill. If killing failed, I don't think we can expect Wait to return.
Discussion at https://groups.google.com/g/golang-nuts/c/pUaEjqd5wo8

adonovan · 2022-08-15T19:26:41Z

The only reason the kill system call can fail (at least in this situation) is when the child process has already exited, so failure of kill is unlikely to be the culprit. More likely kill terminated the go process itself, but not the tree of processes rooted at it. If one of them (a test?) retains an open file descriptor to the stdout pipe created by os/exec then the cmd.Run operation will hang indefinitely.

To dig further, we could add logic to run during the failure (on linux) that does ps -e f and ls -l /proc/*/fd/* to show the process tree and their open files.

bcmills · 2022-08-16T15:05:57Z

Please do check the error from Kill — that would at least give a useful data point for diagnostics. (This may be closely related to ~~#53400~~ #50187.)

bcmills · 2022-09-14T14:25:22Z

greplogs -l -e 'panic: test timed out(?:.*\n)*goroutine \d+ \[.*, \d+ minutes\]:\n.*runCmdContext' --since=2022-08-15 --details

(66 matching logs)

findleyr · 2022-09-14T14:43:14Z

Interesting, I was debugging this in https://go.dev/cl/424075. On windows, our call to Process.Kill() is failing with "invalid argument":
https://storage.googleapis.com/go-build-log/e2f60200/windows-386-2008_71ad7007.log

A bit of googling suggests that this is because we can't kill subprocesses on windows.

@bcmills any advice for how to properly kill the go command on windows?

findleyr · 2022-09-14T15:08:28Z

After reading the source a bit more: this is EINVAL, which appears to mean that the Process.wait() has exited and the handle released, so this is a race, although it is surprising that we hit it so reliably.

gopherbot · 2022-09-14T15:17:54Z

Change https://go.dev/cl/424075 mentions this issue: internal/gocommand: add instrumentation for hanging go commands

bcmills · 2022-09-14T16:44:06Z

any advice for how to properly kill the go command on windows?

Can't be done without creating a whole extra process group, unfortunately. (Probably we should add a side-channel — perhaps an open file descriptor or a pidfile? — to request clean shutdown on Windows.)

When a go command hangs during gopls regression tests, print out additional information about processes and file descriptors. For golang/go#54461 Change-Id: I92aa4665e9056d15a274c154fce2783bed79718e Reviewed-on: https://go-review.googlesource.com/c/tools/+/424075 gopls-CI: kokoro <noreply+kokoro@google.com> Reviewed-by: Alan Donovan <adonovan@google.com> Run-TryBot: Robert Findley <rfindley@google.com> TryBot-Result: Gopher Robot <gobot@golang.org>

gopherbot · 2022-09-15T14:47:42Z

Change https://go.dev/cl/431075 mentions this issue: internal/gocommand: tweak debugging for hanging go commands

Add a TODO and wait for a shorter period of time following Kill, per post-submit advice from bcmills on CL 424075. For golang/go#54461 Change-Id: Ia0e388c0119660844dad32629ebca4f122fded12 Reviewed-on: https://go-review.googlesource.com/c/tools/+/431075 TryBot-Result: Gopher Robot <gobot@golang.org> Run-TryBot: Robert Findley <rfindley@google.com> gopls-CI: kokoro <noreply+kokoro@google.com> Reviewed-by: Bryan Mills <bcmills@google.com>

findleyr · 2022-09-16T17:24:36Z

A hit!
https://build.golang.org/log/4eea0e5bfe425fcd097a49fcb92fd015fa88f383

adonovan · 2022-09-16T17:32:38Z

Nice. Well, that test process seems very much alive, falsifying my hypothesis.

findleyr · 2022-09-16T17:35:17Z

13032 12910 (compile)
 9802 13032 go list -modfile=/tmp/workdir/tmp/go.8f5d4cc245da9790bda529e64ae3e7

Looks like the hanging go command is in the middle of a compile. Wish we had the full subprocesss command line -- I'll look into that.

Not sure how to interpret the fstat output.

adonovan · 2022-09-16T17:36:24Z

That's a dead cmd/compile process: there's no command because argv has been destroyed along with the rest of the address space. Perhaps the go list parent simply hasn't called waitpid yet, so the process table entry has to be retained. I suspect the problem is in go list.

findleyr · 2022-09-16T17:38:43Z

Aha, thanks (excuse my ps noobness).

Note that we instrumented this panic in two places: once before Kill() and once after. This is before, so I don't think it falsifies your hypothesis, if I'm understanding correctly.

bcmills · 2022-09-16T18:06:58Z

That one is netbsd, which could plausibly be explained as #50138. (I'd rather we wait for one of these on a platform without a known issue for Wait before we do too much digging.)

findleyr · 2022-09-17T12:18:46Z

greplogs --dashboard -md -l -e 'HANGING GO' --since=2022-09-15

2022-09-17T02:56:51-4d18923-cc1b20e/netbsd-amd64-9_0
2022-09-16T17:59:31-a61f20e-a84f46a/netbsd-amd64-9_0
2022-09-16T16:33:11-a61f20e-8451529/netbsd-386-9_0
2022-09-16T14:49:13-a61f20e-b35b4a3/netbsd-amd64-9_0

Still only netbsd. Posting the greplogs query here for future reference.

bcmills · 2022-09-21T20:04:36Z

Ooh, nice! https://go.dev/issue/55323#issuecomment-1254107802 has a darwin/arm64 hang. 😃

gopherbot · 2024-08-29T21:31:20Z

Found new dashboard test flakes for:

#!watchflakes
post <- goos != "netbsd" && (pkg ~ `^golang.org/x/tools/gopls` || (repo == "tools" && pkg == "")) && 
        (`detected hanging go command` || log ~ `detected hanging go command` || `DETECTED A HANGING GO COMMAND` || log ~ `DETECTED A HANGING GO COMMAND`)

2024-08-29 16:17 x_tools-gotip-windows-amd64-race tools@ce02ccd1 go@ffb3e574 x/tools/gopls/internal/test/integration/codelens.TestUpgradeCodelens_Workspace/Upgrade_transitive_dependencies/default [ABORT] (log)

=== RUN   TestUpgradeCodelens_Workspace/Upgrade_transitive_dependencies/default
panic: detected hanging go command (golang/go#54461); waited 1m0.0027303s
		command:C:\b\s\w\ir\x\w\goroot\bin\go.exe list -m -e -json ...
		pid:960

goroutine 737 [running]:
golang.org/x/tools/internal/gocommand.HandleHangingGoCommand({0xc006b2caa8?, 0xc006b2c934?, 0x141fde4a0?}, 0xc000180d80)
	C:/b/s/w/ir/x/w/targetrepo1838056557/internal/gocommand/invoke.go:462 +0x14d
golang.org/x/tools/internal/gocommand.runCmdContext({0x14181e728, 0x142027c80}, 0xc000180d80)
	C:/b/s/w/ir/x/w/targetrepo1838056557/internal/gocommand/invoke.go:395 +0x6eb
...
golang.org/x/tools/internal/imports.newModuleResolver(0xc00039d7a0, 0xc006fc4300)
	C:/b/s/w/ir/x/w/targetrepo1838056557/internal/imports/mod.go:158 +0x1325
golang.org/x/tools/internal/imports.(*ProcessEnv).GetResolver(0xc00039d7a0)
	C:/b/s/w/ir/x/w/targetrepo1838056557/internal/imports/fix.go:1022 +0x45c
golang.org/x/tools/gopls/internal/cache.(*importsState).refreshProcessEnv(0xc006bd0cd0)
	C:/b/s/w/ir/x/w/targetrepo1838056557/gopls/internal/cache/imports.go:233 +0xf6
golang.org/x/tools/gopls/internal/cache.(*refreshTimer).schedule.func1()
	C:/b/s/w/ir/x/w/targetrepo1838056557/gopls/internal/cache/imports.go:73 +0x75
created by time.goFunc
	C:/b/s/w/ir/x/w/goroot/src/time/sleep.go:215 +0x45

2024-08-29 16:17 x_tools-gotip-windows-amd64-race tools@ce02ccd1 go@ffb3e574 x/tools/gopls/internal/test/integration/completion.TestFuzzFunc/default [ABORT] (log)

=== RUN   TestFuzzFunc/default
panic: detected hanging go command (golang/go#54461); waited 1m0.0026447s
		command:C:\b\s\w\ir\x\w\goroot\bin\go.exe list -mod=readonly -m -f {{.Path}}
	{{.Dir}}
	{{.GoMod}}
	{{.GoVersion}}
	{{range context.ReleaseTags}}{{if eq . "go1.14"}}{{.}}{{end}}{{end}}
	
		pid:10136

...
golang.org/x/tools/internal/imports.newModuleResolver(0xc00055d830, 0xc006a2eba0)
	C:/b/s/w/ir/x/w/targetrepo1838056557/internal/imports/mod.go:123 +0x72c
golang.org/x/tools/internal/imports.(*ProcessEnv).GetResolver(0xc00055d830)
	C:/b/s/w/ir/x/w/targetrepo1838056557/internal/imports/fix.go:1022 +0x45c
golang.org/x/tools/gopls/internal/cache.(*importsState).refreshProcessEnv(0xc006638d20)
	C:/b/s/w/ir/x/w/targetrepo1838056557/gopls/internal/cache/imports.go:233 +0xf6
golang.org/x/tools/gopls/internal/cache.(*refreshTimer).schedule.func1()
	C:/b/s/w/ir/x/w/targetrepo1838056557/gopls/internal/cache/imports.go:73 +0x75
created by time.goFunc
	C:/b/s/w/ir/x/w/goroot/src/time/sleep.go:215 +0x45

2024-08-29 16:17 x_tools-gotip-windows-amd64-race tools@ce02ccd1 go@ffb3e574 x/tools/gopls/internal/test/integration/diagnostics.TestTimeFormatAnalyzer/default [ABORT] (log)

=== RUN   TestTimeFormatAnalyzer/default
panic: detected hanging go command (golang/go#54461); waited 1m0.0034029s
		command:C:\b\s\w\ir\x\w\goroot\bin\go.exe mod tidy -modfile=C:\b\s\w\ir\x\t\gopls-tempmod937247241\go.mod
		pid:7832

goroutine 572 [running]:
golang.org/x/tools/internal/gocommand.HandleHangingGoCommand({0xc006db4ee8?, 0xc007914d74?, 0x142013aa0?}, 0xc0002dac00)
	C:/b/s/w/ir/x/w/targetrepo1838056557/internal/gocommand/invoke.go:462 +0x14d
golang.org/x/tools/internal/gocommand.runCmdContext({0x1418447a8, 0xc00786b590}, 0xc0002dac00)
	C:/b/s/w/ir/x/w/targetrepo1838056557/internal/gocommand/invoke.go:395 +0x6eb
...
golang.org/x/tools/gopls/internal/cache.(*Snapshot).ModTidy.func1({0x1418447e0, 0xc000329d10}, {0x1414836c0, 0xc0002f5680})
	C:/b/s/w/ir/x/w/targetrepo1838056557/gopls/internal/cache/mod_tidy.go:81 +0x65
golang.org/x/tools/internal/memoize.(*Promise).run.func2.1()
	C:/b/s/w/ir/x/w/targetrepo1838056557/internal/memoize/memoize.go:187 +0xda
runtime/trace.WithRegion({0x1418447e0, 0xc000329d10}, {0xc00016d6f8, 0x13}, 0xc0071f5f80)
	C:/b/s/w/ir/x/w/goroot/src/runtime/trace/annotation.go:141 +0x138
golang.org/x/tools/internal/memoize.(*Promise).run.func2()
	C:/b/s/w/ir/x/w/targetrepo1838056557/internal/memoize/memoize.go:180 +0x1d8
created by golang.org/x/tools/internal/memoize.(*Promise).run in goroutine 707
	C:/b/s/w/ir/x/w/targetrepo1838056557/internal/memoize/memoize.go:179 +0x331

x/tools/gopls: regtest flakes due to hanging go commands #54461

x/tools/gopls: regtest flakes due to hanging go commands #54461

Comments

findleyr commented Aug 15, 2022 • edited by cherrymui Loading

findleyr commented Aug 15, 2022

adonovan commented Aug 15, 2022 • edited Loading

bcmills commented Aug 16, 2022 • edited Loading

bcmills commented Sep 14, 2022

findleyr commented Sep 14, 2022

findleyr commented Sep 14, 2022

gopherbot commented Sep 14, 2022

bcmills commented Sep 14, 2022

gopherbot commented Sep 15, 2022

findleyr commented Sep 16, 2022

adonovan commented Sep 16, 2022

findleyr commented Sep 16, 2022

adonovan commented Sep 16, 2022

findleyr commented Sep 16, 2022

bcmills commented Sep 16, 2022

findleyr commented Sep 17, 2022

bcmills commented Sep 21, 2022

gopherbot commented Aug 29, 2024

gopherbot commented Sep 4, 2024

gopherbot commented Sep 5, 2024

gopherbot commented Sep 6, 2024

gopherbot commented Sep 6, 2024

gopherbot commented Sep 16, 2024

gopherbot commented Sep 17, 2024

gopherbot commented Sep 17, 2024

gopherbot commented Sep 18, 2024

gopherbot commented Sep 19, 2024

gopherbot commented Sep 20, 2024

gopherbot commented Sep 27, 2024

gopherbot commented Sep 30, 2024

gopherbot commented Oct 1, 2024

gopherbot commented Oct 1, 2024

gopherbot commented Oct 3, 2024

gopherbot commented Oct 4, 2024

gopherbot commented Oct 4, 2024

gopherbot commented Oct 4, 2024

gopherbot commented Oct 10, 2024

gopherbot commented Oct 22, 2024

gopherbot commented Nov 6, 2024

gopherbot commented Nov 26, 2024

gopherbot commented Dec 3, 2024

gopherbot commented Dec 9, 2024

gopherbot commented Dec 10, 2024

gopherbot commented Dec 10, 2024

gopherbot commented Dec 11, 2024

findleyr commented Aug 15, 2022 •

edited by cherrymui

Loading

adonovan commented Aug 15, 2022 •

edited

Loading

bcmills commented Aug 16, 2022 •

edited

Loading