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

[findleyr]

#!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

2022-08-15T17:42:12-987de34-1f833e4/darwin-amd64-12_0
2022-08-14T00:06:23-35f806b-59865f1/netbsd-amd64-9_0
2022-08-12T20:40:05-bebd890-2f6783c/netbsd-386-9_0
2022-08-12T18:15:28-bebd890-b6f87b0/netbsd-amd64-9_0
2022-08-12T12:39:26-88d981e-f67c766/netbsd-amd64-9_0
2022-08-12T00:04:29-c4ec74a-a5cd894/netbsd-386-9_0
2022-08-11T19:05:54-c4ec74a-62654df/netbsd-amd64-9_0
2022-08-11T17:53:50-37a81b6-a526ec1/netbsd-amd64-9_0
2022-08-11T16:19:14-37a81b6-2340d37/netbsd-amd64-9_0
2022-08-11T12:53:59-b2156b5-3c200d6/netbsd-386-9_0
2022-08-10T22:22:48-b2156b5-6b80b62/netbsd-amd64-9_0
2022-08-10T17:41:25-0ad49fd-f19f6c7/netbsd-amd64-9_0
2022-08-10T15:08:24-3950865-c81dfdd/netbsd-amd64-9_0
2022-08-10T02:14:09-6fa767d-5531838/plan9-386-0intro
2022-08-09T14:33:24-92d58ea-0981d9f/openbsd-386-70
2022-08-09T14:12:01-92d58ea-662a729/netbsd-amd64-9_0
2022-08-09T13:39:27-92d58ea-9e8020b/netbsd-386-9_0
2022-08-09T11:28:56-92d58ea-0f8dffd/netbsd-amd64-9_0
2022-08-08T18:10:56-fff6d6d-4bcc138/netbsd-amd64-9_0
2022-08-08T15:33:45-06d96ee-0581d69/netbsd-amd64-9_0
2022-08-08T15:07:46-06d96ee-cd54ef1/netbsd-amd64-9_0
2022-08-08T14:12:21-06d96ee-e761556/netbsd-amd64-9_0
2022-08-08T06:16:59-06d96ee-0f6ee42/darwin-amd64-11_0
2022-08-08T06:16:59-06d96ee-0f6ee42/netbsd-386-9_0
2022-08-06T15:20:00-06d96ee-0c4db1e/plan9-386-0intro
2022-08-05T19:51:08-06d96ee-4fb7e22/plan9-386-0intro
2022-08-04T20:05:03-81c7dc4-39728f4/netbsd-386-9_0
2022-08-04T20:05:03-81c7dc4-39728f4/netbsd-amd64-9_0
2022-08-04T20:04:16-3519aa2-39728f4/netbsd-386-9_0
2022-08-04T19:57:25-763f65c-39728f4/netbsd-386-9_0
2022-08-04T18:51:46-99fd76f-39728f4/openbsd-386-70
2022-08-04T17:05:18-3e0a503-fb1bfd4/netbsd-amd64-9_0
2022-08-04T15:50:11-3e0a503-fcdd099/netbsd-386-9_0
2022-08-04T15:50:11-3e0a503-44ff9bf/netbsd-amd64-9_0
2022-08-04T15:31:49-87f47bb-44ff9bf/plan9-386-0intro
2022-08-04T14:58:59-87f47bb-4345620/netbsd-386-9_0
2022-08-04T10:32:51-3e0a503-a10afb1/linux-386-buster
2022-08-03T21:02:27-8b9a1fb-f28fa95/plan9-386-0intro
2022-08-03T21:02:27-8b9a1fb-4345620/netbsd-386-9_0
2022-08-03T18:07:40-d08f5dc-fcdd099/netbsd-386-9_0
2022-08-03T13:50:38-ddb90ec-c6a2dad/dragonfly-amd64-622
2022-08-03T13:50:38-ddb90ec-c6a2dad/plan9-386-0intro
2022-08-03T12:09:24-ddb90ec-29b9a32/plan9-386-0intro
2022-08-02T18:52:36-0d04f65-29b9a32/plan9-386-0intro
2022-08-02T18:19:01-d025cce-be59153/netbsd-amd64-9_0
2022-08-02T18:16:22-10cb435-d723df7/netbsd-amd64-9_0
2022-08-02T18:07:14-4d0b383-d723df7/netbsd-386-9_0
2022-08-02T18:07:14-4d0b383-d723df7/netbsd-amd64-9_0
2022-08-02T17:23:42-4d0b383-1b7e71e/darwin-amd64-nocgo
2022-08-02T16:05:48-4d0b383-f2a9f3e/netbsd-amd64-9_0
2022-07-29T20:19:23-9580c84-9240558/windows-arm64-11
2022-07-28T20:06:00-8ea5687-d9242f7/darwin-amd64-nocgo
2022-07-27T15:04:58-39a4e36-4248146/freebsd-386-13_0
2022-07-26T18:43:08-6c8a6c4-d9242f7/aix-ppc64
2022-07-25T20:44:49-2a6393f-24dc27a/darwin-amd64-10_14
2022-07-25T18:11:01-4375b29-795a88d/plan9-386-0intro
2022-07-25T14:16:17-178fdf9-64f2829/plan9-386-0intro
2022-07-22T20:12:19-7b605f4-c5da4fb/plan9-386-0intro
2022-07-21T20:11:06-ec1f924-c4a6d30/plan9-386-0intro
2022-07-15T15:11:26-22d1494-2aa473c/windows-386-2008-newcc
2022-07-15T14:27:36-1a4e02f-4651ebf/windows-arm64-10
2022-07-15T14:20:24-db8f89b-4651ebf/windows-arm64-10
2022-07-14T21:03:14-db8f89b-783ff7d/windows-arm64-11
2022-07-14T21:01:58-db8f89b-aa80228/darwin-arm64-11
2022-07-14T19:05:09-db8f89b-a906d3d/windows-arm64-10
2022-07-14T15:54:36-db8f89b-266c70c/windows-arm64-10
2022-07-14T01:47:39-db8f89b-558785a/windows-arm64-11

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?

[findleyr]

Two observations:

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

[adonovan]

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]

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]

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

2022-09-13T12:58:04-ec74389-dad2966/netbsd-386-9_0
2022-09-13T12:38:14-ec74389-c7a0b15/netbsd-amd64-9_0
2022-09-13T12:37:11-ec74389-f4a587b/netbsd-amd64-9_0
2022-09-11T21:08:46-e71c338-00ece11/netbsd-amd64-9_0
2022-09-09T18:42:57-0eebaab-b244b89/netbsd-386-9_0
2022-09-09T15:36:26-eeaf4eb-600db8a/netbsd-386-9_0
2022-09-09T15:10:10-4754f75-9a5574a/netbsd-amd64-9_0
2022-09-08T15:55:44-a630751-cd8aa40/netbsd-amd64-9_0
2022-09-08T14:33:45-a630751-e5ed221/netbsd-386-9_0
2022-09-08T13:27:43-a630751-51fdfeb/darwin-arm64-11
2022-09-07T16:37:07-dd1bab2-3e75859/darwin-arm64-12
2022-09-07T14:47:36-c1dd25e-d81ed4d/netbsd-386-9_0
2022-09-07T14:47:36-c1dd25e-d81ed4d/netbsd-amd64-9_0
2022-09-07T14:33:56-c1dd25e-0752f4a/netbsd-386-9_0
2022-09-07T00:49:41-83d7619-8fd2073/netbsd-amd64-9_0
2022-09-06T22:14:56-83d7619-c82304b/netbsd-386-9_0
2022-09-06T17:36:47-83d7619-e0e0c8f/netbsd-amd64-9_0
2022-09-06T16:17:26-83d7619-4a4127b/netbsd-amd64-9_0
2022-09-06T16:04:07-83d7619-60ef4b2/netbsd-386-9_0
2022-09-06T12:35:13-d815cba-8a32354/netbsd-amd64-9_0
2022-09-03T06:26:16-d815cba-9fc09d2/netbsd-386-9_0
2022-09-02T18:51:37-be9eab1-5b1fbfb/netbsd-amd64-9_0
2022-09-02T18:17:25-5ba8541-0cf996a/netbsd-amd64-9_0
2022-09-02T15:27:18-eb8352e-321a220/netbsd-386-9_0
2022-09-02T05:05:13-33c1ddd-8e35910/darwin-arm64-12
2022-09-02T05:05:13-33c1ddd-8e35910/netbsd-amd64-9_0
2022-09-02T00:06:00-40cfaff-0592ce5/netbsd-amd64-9_0
2022-09-01T23:18:06-40cfaff-1280ae7/netbsd-amd64-9_0
2022-09-01T22:37:04-40cfaff-aa5ff29/netbsd-386-9_0
2022-09-01T18:08:05-f16be35-ef84141/netbsd-386-9_0
2022-09-01T15:27:30-6c10975-86e9e0e/netbsd-386-9_0
2022-09-01T03:24:42-49ab44d-91ef076/netbsd-amd64-9_0
2022-09-01T00:42:27-550e1f5-64b260d/netbsd-386-9_0
2022-08-31T23:52:00-550e1f5-ca634fa/netbsd-amd64-9_0
2022-08-31T22:22:43-550e1f5-e4b624e/netbsd-amd64-9_0
2022-08-31T22:10:52-550e1f5-33a7e5a/netbsd-386-9_0
2022-08-31T21:08:24-4ccc73c-ce77a46/netbsd-386-9_0
2022-08-31T21:08:24-4ccc73c-889d326/netbsd-amd64-9_0
2022-08-31T16:26:07-41c3a9b-d2d5929/netbsd-386-9_0
2022-08-31T01:16:54-248c34b-ee0e40a/netbsd-amd64-9_0
2022-08-30T21:30:15-248c34b-bd56cb9/netbsd-amd64-9_0
2022-08-30T00:49:19-248c34b-629ae1c/netbsd-amd64-9_0
2022-08-28T16:04:49-717a671-846c378/netbsd-386-9_0
2022-08-26T19:15:02-717a671-897ad2f/netbsd-amd64-9_0
2022-08-26T18:28:14-717a671-bf812b3/netbsd-386-9_0
2022-08-26T17:48:20-7f23307-296c40d/netbsd-amd64-9_0
2022-08-26T15:36:36-7c5e035-951d2c6/netbsd-386-9_0
2022-08-25T19:17:14-d35bb19-f64f12f/netbsd-386-9_0
2022-08-25T17:31:33-db6a62c-83b5fe6/netbsd-386-9_0
2022-08-25T14:56:18-db6a62c-e4be2ac/netbsd-amd64-9_0
2022-08-25T04:00:07-db6a62c-8c8429f/netbsd-386-9_0
2022-08-25T04:00:07-db6a62c-8c8429f/netbsd-amd64-9_0
2022-08-24T21:20:11-db6a62c-e4bed41/netbsd-amd64-9_0
2022-08-24T17:56:56-587a153-cfae70c/netbsd-386-9_0
2022-08-24T15:37:38-587a153-d5aa088/netbsd-amd64-9_0
2022-08-24T14:31:08-c837a30-f983a93/netbsd-amd64-9_0
2022-08-24T12:12:12-587a153-b5a9459/netbsd-amd64-9_0
2022-08-23T20:32:50-587a153-fc0d423/netbsd-386-9_0
2022-08-19T16:55:03-e55fb40-7dad1d2/netbsd-386-9_0
2022-08-19T16:17:50-e55fb40-5729419/netbsd-386-9_0
2022-08-19T15:53:47-e55fb40-f324355/netbsd-amd64-9_0
2022-08-19T03:09:05-e55fb40-a409356/netbsd-386-9_0
2022-08-15T20:41:00-938e162-de0f4d1/netbsd-amd64-9_0
2022-08-15T20:02:31-938e162-7b45edb/netbsd-amd64-9_0
2022-08-15T19:17:20-8c83056-7b45edb/netbsd-amd64-9_0
2022-08-15T17:42:12-987de34-1f833e4/darwin-amd64-12_0

(66 matching logs)

[findleyr]

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]

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]

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