cmd/go: test timeouts without useful debugging output on darwin builders #38768

bcmills · 2020-04-30T14:58:48Z

There are numerous occasional test timeouts on the darwin-amd64-race builder in the logs.

I note that the windows-amd64-race builder sets GO_TEST_TIMEOUT_SCALE=2:
https://github.com/golang/build/blob/916311cec4e1738aae572fe49767cebdc0351144/dashboard/builders.go#L2067

I suspect that we may need to do the same for the darwin-amd64-race builder to reduce flakiness.

CC @andybons

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

bcmills · 2020-08-24T20:41:26Z

This seems to be one of the larger sources of dashboard flakes at the moment (CC @golang/osp-team).

2020-08-24T19:20:59-bb99874/darwin-amd64-race
2020-08-22T12:35:47-8acbe4c/darwin-amd64-race
2020-08-20T15:21:34-822dca4/darwin-amd64-race
2020-08-16T14:23:50-d303630/darwin-amd64-race
2020-06-03T22:07:42-429d2c5/darwin-amd64-race
2020-05-09T23:17:17-c9442dc/darwin-amd64-race
2020-05-07T23:22:45-78aa4af/darwin-amd64-race
2020-05-02T20:20:16-2d323f9/darwin-amd64-race
2020-05-01T15:02:30-e3b0e3d/darwin-amd64-race

bcmills · 2021-02-19T14:45:22Z

Looks like it's not just the darwin-amd64-race builder. We might need to rework the timeout logic in the cmd/go tests to get more useful information.

gopherbot · 2021-03-15T21:05:49Z

Change https://golang.org/cl/302052 mentions this issue: cmd/go: bail out from script tests earlier when a timeout occurs

bcmills · 2021-03-16T16:49:11Z

CL 302052 “fixes” this issue in the sense that the timeouts will probably continue to occur, but should produce more useful debugging output when that happens. If it is successful in that regard, we can file a separate issue for whatever failure mode that uncovers.

bcmills · 2021-03-17T13:54:30Z

Still not useful, but we're narrowing in on it, I think.
Looks like we also need to add useful timeouts for (*testgoData).run:

goroutine 117 [syscall, 5 minutes]:
syscall.syscall6(0x10d7940, 0x3e89, 0xc0006a7ad8, 0x0, 0xc000c881b0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/go/src/runtime/sys_darwin.go:41 +0x2e
syscall.wait4(0x3e89, 0xc0006a7ad8, 0x0, 0xc000c881b0, 0xc000c881b0, 0xc0006a7af8, 0x1050558)
	/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/go/src/syscall/zsyscall_darwin_amd64.go:43 +0xa5
syscall.Wait4(0x3e89, 0xc0006a7b40, 0x0, 0xc000c881b0, 0x105026a, 0xc000666170, 0xc0005ae240)
	/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/go/src/syscall/syscall_bsd.go:145 +0x66
os.(*Process).wait(0xc0001900f0, 0xc0007e41e0, 0xc0007e4210, 0xc0007e4160)
	/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/go/src/os/exec_unix.go:44 +0x159
os.(*Process).Wait(...)
	/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/go/src/os/exec.go:129
os/exec.(*Cmd).Wait(0xc0007e4160, 0x0, 0x0)
	/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/go/src/os/exec/exec.go:507 +0x105
os/exec.(*Cmd).Run(0xc0007e4160, 0x81, 0xc0006680c0)
	/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/go/src/os/exec/exec.go:341 +0x8a
cmd/go_test.(*testgoData).doRun(0xc00050e0b0, 0xc0006680c0, 0x4, 0x4, 0x40, 0xc0006680c0)
	/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/go/src/cmd/go/go_test.go:411 +0x518
cmd/go_test.(*testgoData).run(0xc00050e0b0, 0xc0006680c0, 0x4, 0x4)
	/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/go/src/cmd/go/go_test.go:427 +0xa6
cmd/go_test.TestCacheCoverage(0xc0004fe480)
	/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/go/src/cmd/go/go_test.go:2318 +0x3c5
testing.tRunner(0xc0004fe480, 0x1b01cd0)
	/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/go/src/testing/testing.go:1236 +0x22e
created by testing.(*T).Run
	/var/folders/kh/5zzynz152r94t18yzstnrwx80000gn/T/workdir-host-darwin-10_15/go/src/testing/testing.go:1281 +0x78c

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

gopherbot · 2021-03-19T16:08:22Z

Change https://golang.org/cl/303330 mentions this issue: testing: allow parallel-subtest goroutines to exit when the subtest is complete

…s complete Fixes #45127 Updates #38768 Change-Id: I7f41901d5bcc07741ac9f5f2a24d2b07ef633cb1 Reviewed-on: https://go-review.googlesource.com/c/go/+/303330 Trust: Bryan C. Mills <bcmills@google.com> Run-TryBot: Bryan C. Mills <bcmills@google.com> TryBot-Result: Go Bot <gobot@golang.org> Reviewed-by: Ian Lance Taylor <iant@golang.org>

bcmills · 2021-03-25T04:07:43Z

https://build.golang.org/log/ebdf7a853ae4dba70c0d76c53f5885501cd54668 has what seems to be a fairly useful trace; it seems to indicate that os.Interrupt is not succeeding in terminating a go subprocess.

gopherbot · 2021-04-09T02:02:24Z

Change https://golang.org/cl/308809 mentions this issue: cmd/go: in TestScript, set GOTRACEBACK and use SIGQUIT to terminate hung subprocesses

…ung subprocesses This should produce more useful outputs if a cmd/go invocation hangs during a test. (In some cases the outputs will be very verbose, but verbose is still better than uninformative.) For #36460 For #38768 Change-Id: Ibaf2d0fbf7387dfab1aad8981140ecb11901fc4b Reviewed-on: https://go-review.googlesource.com/c/go/+/308809 Trust: Bryan C. Mills <bcmills@google.com> Run-TryBot: Bryan C. Mills <bcmills@google.com> Reviewed-by: Jay Conrod <jayconrod@google.com>

ianlancetaylor · 2021-04-27T00:59:27Z

Are we going to do anything else here for 1.17? Thanks.

bcmills · 2021-04-27T01:10:25Z

I'm planning to investigate this further during the freeze. I've managed to pare down the failure output enough that most of what remains is goroutines stuck in os/exec and syscall, and I suspect that it boils down to a platform bug of some sort (and/or a bug in the os package on macOS).

Thor-Bjorgvinsson · 2021-05-17T16:33:54Z

Could this halting command issue on mac be related? #38824

Integralist · 2021-07-07T12:51:30Z

I've been seeing similar with .Run() when using GitHub's Actions CI. I've only been able to replicate once on my local macOS but it's very regular to see it timeout on macOS in the CI environment.

bcmills · 2022-06-01T12:45:52Z

It's been a year since the last of these timeouts. I'm calling this “probably fixed”, either by an intervening runtime change or by an intervening update to the race detector.

greplogs -l -e '(?ms)\Adarwin-(?:amd64|arm64)-race.*panic: test timed out' --since=2021-04-27
2021-05-26T22:43:54-1d5298d/darwin-amd64-race

bcmills added OS-Darwin Builders NeedsInvestigation labels Apr 30, 2020

gopherbot added this to the Unreleased milestone Apr 30, 2020

andybons self-assigned this Apr 30, 2020

andybons removed their assignment Aug 4, 2020

bcmills changed the title ~~x/build: darwin-amd64-race may need a GO_TEST_TIMEOUT_SCALE~~ cmd/go: test timeouts on darwin builders Feb 19, 2021

bcmills removed the Builders label Feb 19, 2021

bcmills modified the milestones: Unreleased, Backlog Feb 19, 2021

bcmills added the Testing label Feb 19, 2021

bcmills changed the title ~~cmd/go: test timeouts on darwin builders~~ cmd/go: test timeouts without useful debugging output on darwin builders Feb 19, 2021

bcmills modified the milestones: Backlog, Go1.17 Feb 19, 2021

gopherbot closed this as completed in 72d98df Mar 16, 2021

bcmills self-assigned this Mar 16, 2021

bcmills reopened this Mar 17, 2021

bcmills added the okay-after-beta1 label Apr 27, 2021

bcmills mentioned this issue Apr 30, 2021

cmd/compile: apparent deadlocks on builders #45885

Closed

Integralist mentioned this issue Jul 7, 2021

Improve GitHub Actions intermittent test timeouts fastly/cli#336

Merged

bcmills removed the okay-after-beta1 label Jul 15, 2021

bcmills modified the milestones: Go1.17, Backlog Jul 15, 2021

bcmills closed this as completed Jun 1, 2022

rsc unassigned bcmills Jun 23, 2022

golang locked and limited conversation to collaborators Jun 23, 2023

gopherbot added the FrozenDueToAge label Jun 23, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

cmd/go: test timeouts without useful debugging output on darwin builders #38768

cmd/go: test timeouts without useful debugging output on darwin builders #38768

bcmills commented Apr 30, 2020

bcmills commented Aug 24, 2020

bcmills commented Feb 19, 2021

gopherbot commented Mar 15, 2021

bcmills commented Mar 16, 2021

bcmills commented Mar 17, 2021

gopherbot commented Mar 19, 2021

bcmills commented Mar 25, 2021

gopherbot commented Apr 9, 2021

ianlancetaylor commented Apr 27, 2021

bcmills commented Apr 27, 2021

Thor-Bjorgvinsson commented May 17, 2021

Integralist commented Jul 7, 2021

bcmills commented Jun 1, 2022

cmd/go: test timeouts without useful debugging output on darwin builders #38768

cmd/go: test timeouts without useful debugging output on darwin builders #38768

Comments

bcmills commented Apr 30, 2020

bcmills commented Aug 24, 2020

bcmills commented Feb 19, 2021

gopherbot commented Mar 15, 2021

bcmills commented Mar 16, 2021

bcmills commented Mar 17, 2021

gopherbot commented Mar 19, 2021

bcmills commented Mar 25, 2021

gopherbot commented Apr 9, 2021

ianlancetaylor commented Apr 27, 2021

bcmills commented Apr 27, 2021

Thor-Bjorgvinsson commented May 17, 2021

Integralist commented Jul 7, 2021

bcmills commented Jun 1, 2022