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

#!watchflakes
post <- goos != "netbsd" && (pkg ~ `^golang.org/x/tools/gopls` || (repo == "tools" && pkg == "")) && 
        `detected 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?

About this issue

Original URL
State: open
Created 2 years ago
Reactions: 1
Comments: 126 (40 by maintainers)

Commits related to this issue

internal/gocommand: add instrumentation for hanging go commands When a go command hangs during gopls regression tests, print out additional information about processes and file descriptors. For gola... — committed to golang/tools by findleyr 2 years ago
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 Ch... — committed to golang/tools by findleyr 2 years ago
internal/gocommand: show pid of process We're almost certain that the go process shown by ps is not the one that we're waiting for in runCmdContext, but only by printing the pid can we be sure. Upda... — committed to golang/tools by adonovan 2 years ago
internal/gocommand: add instrumentation for hanging go commands When a go command hangs during gopls regression tests, print out additional information about processes and file descriptors. For gola... — committed to rinchsan/gosimports by findleyr 2 years ago
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 Ch... — committed to rinchsan/gosimports by findleyr 2 years ago
internal/gocommand: show pid of process We're almost certain that the go process shown by ps is not the one that we're waiting for in runCmdContext, but only by printing the pid can we be sure. Upda... — committed to rinchsan/gosimports by adonovan 2 years ago
internal/gocommand: more tweaks to DebugHangingGoCommands As suggested by bcmills, this change increases the time between SIGINT and SIGKILL to 5s (was 1s), and also suppresses the process dump if SI... — committed to golang/tools by adonovan a year ago
internal/gocommand: stop copying stdout as soon as ctx is done If ctx is done, that means (by definition) that the caller is no longer interested in the output of the command. Since 'go list' output ... — committed to golang/tools by bcmills a year ago

Most upvoted comments

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

bcmills on Sep 16, 2022

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.

findleyr on Sep 14, 2022

A simpler explanation is that gopls sent SIGINT, waited for 1s, then sent SIGKILL, and the child (go) exited during the 1s grace period, causing kill(2) to fail with ESRCH (-> ErrProcessDone = “process already finished”). Seems like that’s to be expected if a busy machine causes a delay in responding to SIGINT. Perhaps the debugging logic should treat ErrProcessDone as success, not a reason to debug?

adonovan on Sep 21, 2022