runtime,syscall: SIGABRT failures in syscall.StartProcess on darwin-arm64-12 starting 2022-09-03

[bcmills]

#!watchflakes
post <- `^SIGABRT: abort` && `goroutine \d+ \[running\]:\n(.+\n\t.+\n)*syscall\.StartProcess`

greplogs -l -e '^SIGABRT: abort(?:.*\n)*goroutine \d+ \[running\]:\n(?:.+\n\t.+\n)*syscall\.StartProcess' --since=2022-01-01
2022-09-06T22:23:43-c83e1b6/darwin-arm64-12
2022-09-03T06:26:16-9fc09d2/darwin-arm64-12

SIGABRT: abort
PC=0x1b13f8db8 m=9 sigcode=0

goroutine 0 [idle]:
syscall.rawSyscall(0x16?, 0x2?, 0x1?, 0x0?)
	/tmp/buildlet/go/src/runtime/sys_darwin.go:77 +0x64 fp=0x140010f58f0 sp=0x140010f5860 pc=0x102943b94
syscall.forkAndExecInChild(0x140000bba40, {0x14000074e40, 0x4, 0x4?}, {0x140004da400, 0x3e, 0x0?}, 0x0, 0x0, 0x140010f5b50, ...)
	/tmp/buildlet/go/src/syscall/exec_libc2.go:81 +0xcc fp=0x140010f59a0 sp=0x140010f58f0 pc=0x102953c3c
syscall.forkExec({0x14000298140?, 0x1036ca648?}, {0x1400032af60, 0x3, 0x3}, 0x14000298140?)
	/tmp/buildlet/go/src/syscall/exec_unix.go:209 +0x280 fp=0x140010f5ab0 sp=0x140010f59a0 pc=0x102954810
syscall.StartProcess(...)
	/tmp/buildlet/go/src/syscall/exec_unix.go:255
os.startProcess({0x14000298140, 0x44}, {0x1400032af60, 0x3, 0x3}, 0x140010f5d70)
	/tmp/buildlet/go/src/os/exec_posix.go:54 +0x25c fp=0x140010f5ba0 sp=0x140010f5ab0 pc=0x10298585c
os.StartProcess({0x14000298140, 0x44}, {0x1400032af60, 0x3, 0x3}, 0x1028e95e8?)
	/tmp/buildlet/go/src/os/exec.go:109 +0x50 fp=0x140010f5bf0 sp=0x140010f5ba0 pc=0x102985360
os/exec.(*Cmd).Start(0x140003686e0)
	/tmp/buildlet/go/src/os/exec/exec.go:524 +0x460 fp=0x140010f5dc0 sp=0x140010f5bf0 pc=0x102a2c5a0
os/exec.(*Cmd).Run(0x14000298140?)
	/tmp/buildlet/go/src/os/exec/exec.go:434 +0x20 fp=0x140010f5de0 sp=0x140010f5dc0 pc=0x102a2c100
cmd/go_test.(*testgoData).doRun(0x1400021e000, {0x14000074d80?, 0x2, 0x2})
	/tmp/buildlet/go/src/cmd/go/go_test.go:476 +0x268 fp=0x140010f5e70 sp=0x140010f5de0 pc=0x102e2a968
cmd/go_test.(*testgoData).run(0x1400021e000, {0x14000074d80, 0x2, 0x2})
	/tmp/buildlet/go/src/cmd/go/go_test.go:492 +0x50 fp=0x140010f5f00 sp=0x140010f5e70 pc=0x102e2ac80
cmd/go_test.TestGenerateUsesBuildContext(0x14000003d40?)
	/tmp/buildlet/go/src/cmd/go/go_test.go:1934 +0x1e8 fp=0x140010f5f60 sp=0x140010f5f00 pc=0x102e35908
testing.tRunner(0x1400021c000, 0x1030525a0)
	/tmp/buildlet/go/src/testing/testing.go:1479 +0x10c fp=0x140010f5fb0 sp=0x140010f5f60 pc=0x1029f267c
testing.(*T).Run.func1()
	/tmp/buildlet/go/src/testing/testing.go:1526 +0x2c fp=0x140010f5fd0 sp=0x140010f5fb0 pc=0x1029f33ac
runtime.goexit()
	/tmp/buildlet/go/src/runtime/asm_arm64.s:1172 +0x4 fp=0x140010f5fd0 sp=0x140010f5fd0 pc=0x1029471b4
created by testing.(*T).Run
	/tmp/buildlet/go/src/testing/testing.go:1526 +0x300

goroutine 8 [running]:
runtime.systemstack_switch()
	/tmp/buildlet/go/src/runtime/asm_arm64.s:200 +0x8 fp=0x140010f5830 sp=0x140010f5820 pc=0x102944b28
runtime.libcCall(0x140010f5888?, 0x102929ea4?)
	/tmp/buildlet/go/src/runtime/sys_libc.go:49 +0x5c fp=0x140010f5860 sp=0x140010f5830 pc=0x10293235c
syscall.rawSyscall(0x16?, 0x2?, 0x1?, 0x0?)
	/tmp/buildlet/go/src/runtime/sys_darwin.go:77 +0x64 fp=0x140010f58f0 sp=0x140010f5860 pc=0x102943b94
syscall.forkAndExecInChild(0x140000bba40, {0x14000074e40, 0x4, 0x4?}, {0x140004da400, 0x3e, 0x0?}, 0x0, 0x0, 0x140010f5b50, ...)
	/tmp/buildlet/go/src/syscall/exec_libc2.go:81 +0xcc fp=0x140010f59a0 sp=0x140010f58f0 pc=0x102953c3c
syscall.forkExec({0x14000298140?, 0x1036ca648?}, {0x1400032af60, 0x3, 0x3}, 0x14000298140?)
	/tmp/buildlet/go/src/syscall/exec_unix.go:209 +0x280 fp=0x140010f5ab0 sp=0x140010f59a0 pc=0x102954810
syscall.StartProcess(...)
	/tmp/buildlet/go/src/syscall/exec_unix.go:255
os.startProcess({0x14000298140, 0x44}, {0x1400032af60, 0x3, 0x3}, 0x140010f5d70)
	/tmp/buildlet/go/src/os/exec_posix.go:54 +0x25c fp=0x140010f5ba0 sp=0x140010f5ab0 pc=0x10298585c
os.StartProcess({0x14000298140, 0x44}, {0x1400032af60, 0x3, 0x3}, 0x1028e95e8?)
	/tmp/buildlet/go/src/os/exec.go:109 +0x50 fp=0x140010f5bf0 sp=0x140010f5ba0 pc=0x102985360
os/exec.(*Cmd).Start(0x140003686e0)
	/tmp/buildlet/go/src/os/exec/exec.go:524 +0x460 fp=0x140010f5dc0 sp=0x140010f5bf0 pc=0x102a2c5a0
os/exec.(*Cmd).Run(0x14000298140?)
	/tmp/buildlet/go/src/os/exec/exec.go:434 +0x20 fp=0x140010f5de0 sp=0x140010f5dc0 pc=0x102a2c100
cmd/go_test.(*testgoData).doRun(0x1400021e000, {0x14000074d80?, 0x2, 0x2})
	/tmp/buildlet/go/src/cmd/go/go_test.go:476 +0x268 fp=0x140010f5e70 sp=0x140010f5de0 pc=0x102e2a968
cmd/go_test.(*testgoData).run(0x1400021e000, {0x14000074d80, 0x2, 0x2})
	/tmp/buildlet/go/src/cmd/go/go_test.go:492 +0x50 fp=0x140010f5f00 sp=0x140010f5e70 pc=0x102e2ac80
cmd/go_test.TestGenerateUsesBuildContext(0x14000003d40?)
	/tmp/buildlet/go/src/cmd/go/go_test.go:1934 +0x1e8 fp=0x140010f5f60 sp=0x140010f5f00 pc=0x102e35908
testing.tRunner(0x1400021c000, 0x1030525a0)
	/tmp/buildlet/go/src/testing/testing.go:1479 +0x10c fp=0x140010f5fb0 sp=0x140010f5f60 pc=0x1029f267c
testing.(*T).Run.func1()
	/tmp/buildlet/go/src/testing/testing.go:1526 +0x2c fp=0x140010f5fd0 sp=0x140010f5fb0 pc=0x1029f33ac
runtime.goexit()
	/tmp/buildlet/go/src/runtime/asm_arm64.s:1172 +0x4 fp=0x140010f5fd0 sp=0x140010f5fd0 pc=0x1029471b4
created by testing.(*T).Run
	/tmp/buildlet/go/src/testing/testing.go:1526 +0x300

attn @golang/runtime, @golang/darwin

[bcmills]

Marking as release-blocker because this failure mode is new during the Go 1.20 cycle and darwin/arm64 is a first class port.

[cherrymui]

There is an issue about fork/exec on macOS #53863 , which looks like a kernel issue. I wonder if this has any connection with that.

[bcmills]

I wonder if this has any connection with that.

That is plausible, but I think it would be a little surprising given the timing..? That issue affects back to at least Go 1.18.1, but the two failures in the logs are both recent and (so far) only on the main branch.

[gopherbot]

Found new matching dashboard test flakes for:

#!watchflakes
post <- `^SIGABRT: abort` && `goroutine \d+ \[running\]:\n(.+\n\t.+\n)*syscall\.StartProcess`

2022-09-03 06:26 darwin-arm64-12 go@9fc09d2f cmd/go.TestMentionGOPATHInFirstGOPATHEntry (log)

go test proxy running at GOPROXY=http://127.0.0.1:54789/mod
SIGABRT: abort
PC=0x1c41a0db8 m=14 sigcode=0

goroutine 11 [running]:
runtime.systemstack_switch()
	/tmp/buildlet/go/src/runtime/asm_arm64.s:200 +0x8 fp=0x14000067780 sp=0x14000067770 pc=0x100224988
runtime.libcCall(0x140000677d8?, 0x100209d34?)
	/tmp/buildlet/go/src/runtime/sys_libc.go:49 +0x5c fp=0x140000677b0 sp=0x14000067780 pc=0x1002121dc
syscall.rawSyscall(0x16?, 0x2?, 0x1?, 0x0?)
...
r28     0x140000b8820
r29     0x17035ac40
lr      0x1c41d5ee0
sp      0x17035ac20
pc      0x1c41a0db8
fault   0x1c41a0db8
--- FAIL: TestMentionGOPATHInFirstGOPATHEntry (0.03s)
    go_test.go:1286: running testgo [install foo/quxx]
    go_test.go:1286: testgo failed as expected: exit status 2
    go_test.go:1288: go install foo/quxx expected error: .*testdata/a/src/foo/quxx (from $GOPATH)

2022-09-06 22:23 darwin-arm64-12 go@c83e1b6d cmd/go.TestGenerateUsesBuildContext (log)

go test proxy running at GOPROXY=http://127.0.0.1:59105/mod
SIGABRT: abort
PC=0x1b13f8db8 m=9 sigcode=0

goroutine 8 [running]:
runtime.systemstack_switch()
	/tmp/buildlet/go/src/runtime/asm_arm64.s:200 +0x8 fp=0x140010f5830 sp=0x140010f5820 pc=0x102944b28
runtime.libcCall(0x140010f5888?, 0x102929ea4?)
	/tmp/buildlet/go/src/runtime/sys_libc.go:49 +0x5c fp=0x140010f5860 sp=0x140010f5830 pc=0x10293235c
syscall.rawSyscall(0x16?, 0x2?, 0x1?, 0x0?)
...
sp      0x16d97ec20
pc      0x1b13f8db8
fault   0x1b13f8db8
--- FAIL: TestGenerateUsesBuildContext (0.08s)
    go_test.go:1929: running testgo [generate gen]
    go_test.go:1929: standard output:
    go_test.go:1929: linux amd64

    go_test.go:1934: running testgo [generate gen]
    go_test.go:1934: go [generate gen] failed unexpectedly in /tmp/buildlet/go/src/cmd/go: exit status 2

— watchflakes