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

[gopherbot]

Found new dashboard test flakes for:

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

2022-09-29 22:58 darwin-arm64-12 go@1d655661 cmd/go.TestMentionGOPATHInFirstGOPATHEntry (log)

go test proxy running at GOPROXY=http://127.0.0.1:56698/mod SIGABRT: abort PC=0x19fc84db8 m=9 sigcode=0 goroutine 67 [running]: runtime.systemstack_switch() /tmp/buildlet/go/src/runtime/asm_arm64.s:200 +0x8 fp=0x140003c57d0 sp=0x140003c57c0 pc=0x1043d1598 runtime.libcCall(0x140003c5828?, 0x1043b64f4?) /tmp/buildlet/go/src/runtime/sys_libc.go:49 +0x5c fp=0x140003c5800 sp=0x140003c57d0 pc=0x1043be91c syscall.rawSyscall(0x10?, 0x2?, 0x1?, 0x0?) ... r28 0x140008021a0 r29 0x16bef2c40 lr 0x19fcb9ee0 sp 0x16bef2c20 pc 0x19fc84db8 fault 0x19fc84db8 --- FAIL: TestMentionGOPATHInFirstGOPATHEntry (0.02s) go_test.go:1292: running testgo [install foo/quxx] go_test.go:1292: testgo failed as expected: exit status 2 go_test.go:1294: go install foo/quxx expected error: .*testdata/a/src/foo/quxx (from $GOPATH)

— watchflakes

[gopherbot]

Timed out in state WaitingForInfo. Closing.

(I am just a bot, though. Please speak up if this is a mistake or you have the requested information.)

[aclements]

Reopening because this is still happening. I'm not sure if we have enough extra data to do anything about it yet.

[mknyszek]

Is this still happening? watchflakes hasn't updated this issue.

[mknyszek]

watchflakes hasn't updated this issue since October 4th. Closing for now.