runtime: hang in all.bash runtime test

[rsc]

At 43ed65f (Mar 13 2016), running all.bash. The only change in my client is in os/user/user_test.go which is clearly not involved.

/cc @dvyukov @aclements

panic: test timed out after 3m0s

goroutine 21722 [running]:
panic(0x1c27e0, 0xc820484040)
    /Users/rsc/go/src/runtime/panic.go:500 +0x18e fp=0xc82003ff50 sp=0xc82003fec8
testing.startAlarm.func1()
    /Users/rsc/go/src/testing/testing.go:724 +0x10f fp=0xc82003ffb0 sp=0xc82003ff50
runtime.goexit()
    /Users/rsc/go/src/runtime/asm_amd64.s:2006 +0x1 fp=0xc82003ffb8 sp=0xc82003ffb0
created by time.goFunc
    /Users/rsc/go/src/time/sleep.go:129 +0x3a

goroutine 1 [chan receive, 2 minutes]:
runtime.gopark(0x26bed0, 0xc82025e778, 0x22ff46, 0xc, 0xc820256a17, 0x3)
    /Users/rsc/go/src/runtime/proc.go:262 +0x131 fp=0xc82003cc08 sp=0xc82003cbe0
runtime.goparkunlock(0xc82025e778, 0x22ff46, 0xc, 0x17, 0x3)
    /Users/rsc/go/src/runtime/proc.go:268 +0x54 fp=0xc82003cc40 sp=0xc82003cc08
runtime.chanrecv(0x190d40, 0xc82025e720, 0xc82003ce08, 0xc820237c01, 0x6783c)
    /Users/rsc/go/src/runtime/chan.go:474 +0x2ac fp=0xc82003ccc0 sp=0xc82003cc40
runtime.chanrecv1(0x190d40, 0xc82025e720, 0xc82003ce08)
    /Users/rsc/go/src/runtime/chan.go:357 +0x2b fp=0xc82003ccf0 sp=0xc82003ccc0
testing.RunTests(0x26b8c8, 0x34d460, 0xb0, 0xb0, 0x5b)
    /Users/rsc/go/src/testing/testing.go:582 +0x362 fp=0xc82003ce30 sp=0xc82003ccf0
testing.(*M).Run(0xc82003cf08, 0xc8200180b8)
    /Users/rsc/go/src/testing/testing.go:515 +0x79 fp=0xc82003ceb0 sp=0xc82003ce30
runtime_test.TestMain(0xc82003cf08)
    /Users/rsc/go/src/runtime/crash_test.go:24 +0x25 fp=0xc82003cef8 sp=0xc82003ceb0
main.main()
    runtime/_test/_testmain.go:956 +0xb4 fp=0xc82003cf60 sp=0xc82003cef8
runtime.main()
    /Users/rsc/go/src/runtime/proc.go:188 +0x20a fp=0xc82003cfb0 sp=0xc82003cf60
runtime.goexit()
    /Users/rsc/go/src/runtime/asm_amd64.s:2006 +0x1 fp=0xc82003cfb8 sp=0xc82003cfb0

goroutine 17 [syscall, 2 minutes, locked to thread]:
runtime.goexit()
    /Users/rsc/go/src/runtime/asm_amd64.s:2006 +0x1 fp=0xc820040fb8 sp=0xc820040fb0

goroutine 2 [force gc (idle), 2 minutes]:
runtime.gopark(0x26bed0, 0x350870, 0x2328b1, 0xf, 0x100000000000014, 0x1)
    /Users/rsc/go/src/runtime/proc.go:262 +0x131 fp=0xc82002c758 sp=0xc82002c730
runtime.goparkunlock(0x350870, 0x2328b1, 0xf, 0xc820000114, 0x1)
    /Users/rsc/go/src/runtime/proc.go:268 +0x54 fp=0xc82002c790 sp=0xc82002c758
runtime.forcegchelper()
    /Users/rsc/go/src/runtime/proc.go:229 +0x9f fp=0xc82002c7c0 sp=0xc82002c790
runtime.goexit()
    /Users/rsc/go/src/runtime/asm_amd64.s:2006 +0x1 fp=0xc82002c7c8 sp=0xc82002c7c0
created by runtime.init.4
    /Users/rsc/go/src/runtime/proc.go:218 +0x2b

goroutine 3 [GC sweep wait]:
runtime.gopark(0x26bed0, 0x350aa0, 0x230a06, 0xd, 0x4d914, 0x1)
    /Users/rsc/go/src/runtime/proc.go:262 +0x131 fp=0xc82002cf48 sp=0xc82002cf20
runtime.goparkunlock(0x350aa0, 0x230a06, 0xd, 0x14, 0x1)
    /Users/rsc/go/src/runtime/proc.go:268 +0x54 fp=0xc82002cf80 sp=0xc82002cf48
runtime.bgsweep(0xc82005c000)
    /Users/rsc/go/src/runtime/mgcsweep.go:79 +0x125 fp=0xc82002cfb8 sp=0xc82002cf80
runtime.goexit()
    /Users/rsc/go/src/runtime/asm_amd64.s:2006 +0x1 fp=0xc82002cfc0 sp=0xc82002cfb8
created by runtime.gcenable
    /Users/rsc/go/src/runtime/mgc.go:191 +0x53

goroutine 4 [finalizer wait]:
runtime.gopark(0x26bed0, 0x36be30, 0x231a6a, 0xe, 0xc820001314, 0x1)
    /Users/rsc/go/src/runtime/proc.go:262 +0x131 fp=0xc82002d710 sp=0xc82002d6e8
runtime.goparkunlock(0x36be30, 0x231a6a, 0xe, 0x2000000014, 0x1)
    /Users/rsc/go/src/runtime/proc.go:268 +0x54 fp=0xc82002d748 sp=0xc82002d710
runtime.runfinq()
    /Users/rsc/go/src/runtime/mfinal.go:158 +0xa5 fp=0xc82002d7c0 sp=0xc82002d748
runtime.goexit()
    /Users/rsc/go/src/runtime/asm_amd64.s:2006 +0x1 fp=0xc82002d7c8 sp=0xc82002d7c0
created by runtime.createfing
    /Users/rsc/go/src/runtime/mfinal.go:139 +0x66

goroutine 5 [timer goroutine (idle)]:
runtime.gopark(0x26bed0, 0x350ba0, 0x23a0db, 0x16, 0x26d314, 0x1)
    /Users/rsc/go/src/runtime/proc.go:262 +0x131 fp=0xc82002df10 sp=0xc82002dee8
runtime.goparkunlock(0x350ba0, 0x23a0db, 0x16, 0x14, 0x1)
    /Users/rsc/go/src/runtime/proc.go:268 +0x54 fp=0xc82002df48 sp=0xc82002df10
runtime.timerproc()
    /Users/rsc/go/src/runtime/time.go:202 +0x302 fp=0xc82002dfc0 sp=0xc82002df48
runtime.goexit()
    /Users/rsc/go/src/runtime/asm_amd64.s:2006 +0x1 fp=0xc82002dfc8 sp=0xc82002dfc0
created by runtime.addtimerLocked
    /Users/rsc/go/src/runtime/time.go:116 +0x115

goroutine 22288 [syscall, 2 minutes]:
syscall.Syscall6(0x7, 0xc218, 0xc82003dce4, 0x0, 0xc820256bd0, 0x0, 0x0, 0x1d0120, 0xc800000000, 0xc8204a5100)
    /Users/rsc/go/src/syscall/asm_darwin_amd64.s:41 +0x5 fp=0xc82003dc38 sp=0xc82003dc30
syscall.wait4(0xc218, 0xc82003dce4, 0x0, 0xc820256bd0, 0x90, 0x2162c0, 0x1)
    /Users/rsc/go/src/syscall/zsyscall_darwin_amd64.go:34 +0x78 fp=0xc82003dca8 sp=0xc82003dc38
syscall.Wait4(0xc218, 0xc82003dd2c, 0x0, 0xc820256bd0, 0x26ba78, 0xc8202468c0, 0xc820264520)
    /Users/rsc/go/src/syscall/syscall_bsd.go:129 +0x47 fp=0xc82003dcf0 sp=0xc82003dca8
os.(*Process).wait(0xc8202647a0, 0xc82024e380, 0xc820250150, 0xc820264540)
    /Users/rsc/go/src/os/exec_unix.go:22 +0xf4 fp=0xc82003dd70 sp=0xc82003dcf0
os.(*Process).Wait(0xc8202647a0, 0xc82003ddd0, 0x0, 0x0)
    /Users/rsc/go/src/os/doc.go:49 +0x21 fp=0xc82003dd98 sp=0xc82003dd70
os/exec.(*Cmd).Wait(0xc8202468c0, 0x0, 0x0)
    /Users/rsc/go/src/os/exec/exec.go:396 +0x58 fp=0xc82003de20 sp=0xc82003dd98
os/exec.(*Cmd).Run(0xc8202468c0, 0xc82024e380, 0xc82025d400)
    /Users/rsc/go/src/os/exec/exec.go:262 +0x3e fp=0xc82003de40 sp=0xc82003de20
os/exec.(*Cmd).CombinedOutput(0xc8202468c0, 0xc8202468c0, 0xc8204feed8, 0x1, 0x1, 0xc8202468c0)
    /Users/rsc/go/src/os/exec/exec.go:453 +0x174 fp=0xc82003de80 sp=0xc82003de40
runtime_test.runTestProg(0xc820256ab0, 0x22f573, 0xb, 0x23ac6d, 0x17, 0xc8204fef90, 0x28929)
    /Users/rsc/go/src/runtime/crash_test.go:68 +0xf9 fp=0xc82003def0 sp=0xc82003de80
runtime_test.TestCgoExternalThreadSignal(0xc820256ab0)
    /Users/rsc/go/src/runtime/crash_cgo_test.go:109 +0x5a fp=0xc82003df80 sp=0xc82003def0
testing.tRunner(0xc820256ab0, 0x34d688)
    /Users/rsc/go/src/testing/testing.go:473 +0x7e fp=0xc82003dfa0 sp=0xc82003df80
runtime.goexit()
    /Users/rsc/go/src/runtime/asm_amd64.s:2006 +0x1 fp=0xc82003dfa8 sp=0xc82003dfa0
created by testing.RunTests
    /Users/rsc/go/src/testing/testing.go:581 +0x31c

goroutine 5319 [GC worker (idle)]:
runtime.gopark(0xc8204a5118, 0xc820214fa0, 0x233443, 0x10, 0xc820452214, 0x0)
    /Users/rsc/go/src/runtime/proc.go:262 +0x131 fp=0xc820214f48 sp=0xc820214f20
runtime.gcBgMarkWorker(0xc820025500)
    /Users/rsc/go/src/runtime/mgc.go:1397 +0xc1 fp=0xc820214fb8 sp=0xc820214f48
runtime.goexit()
    /Users/rsc/go/src/runtime/asm_amd64.s:2006 +0x1 fp=0xc820214fc0 sp=0xc820214fb8
created by runtime.gcBgMarkStartWorkers
    /Users/rsc/go/src/runtime/mgc.go:1324 +0x8a

goroutine 195 [GC worker (idle)]:
runtime.gopark(0xc8204a4000, 0xc8200ce7a0, 0x233443, 0x10, 0xc8200ce714, 0x0)
    /Users/rsc/go/src/runtime/proc.go:262 +0x131 fp=0xc8200ce748 sp=0xc8200ce720
runtime.gcBgMarkWorker(0xc82001c000)
    /Users/rsc/go/src/runtime/mgc.go:1397 +0xc1 fp=0xc8200ce7b8 sp=0xc8200ce748
runtime.goexit()
    /Users/rsc/go/src/runtime/asm_amd64.s:2006 +0x1 fp=0xc8200ce7c0 sp=0xc8200ce7b8
created by runtime.gcBgMarkStartWorkers
    /Users/rsc/go/src/runtime/mgc.go:1324 +0x8a

goroutine 5579 [GC worker (idle)]:
runtime.gopark(0xc820484038, 0xc8204fcfa0, 0x233443, 0x10, 0xc820473314, 0x0)
    /Users/rsc/go/src/runtime/proc.go:262 +0x131 fp=0xc8204fcf48 sp=0xc8204fcf20
runtime.gcBgMarkWorker(0xc820024000)
    /Users/rsc/go/src/runtime/mgc.go:1397 +0xc1 fp=0xc8204fcfb8 sp=0xc8204fcf48
runtime.goexit()
    /Users/rsc/go/src/runtime/asm_amd64.s:2006 +0x1 fp=0xc8204fcfc0 sp=0xc8204fcfb8
created by runtime.gcBgMarkStartWorkers
    /Users/rsc/go/src/runtime/mgc.go:1324 +0x8a

goroutine 5545 [GC worker (idle)]:
runtime.gopark(0xc820010360, 0xc8200cefa0, 0x233443, 0x10, 0xc82041c614, 0x0)
    /Users/rsc/go/src/runtime/proc.go:262 +0x131 fp=0xc8200cef48 sp=0xc8200cef20
runtime.gcBgMarkWorker(0xc820020000)
    /Users/rsc/go/src/runtime/mgc.go:1397 +0xc1 fp=0xc8200cefb8 sp=0xc8200cef48
runtime.goexit()
    /Users/rsc/go/src/runtime/asm_amd64.s:2006 +0x1 fp=0xc8200cefc0 sp=0xc8200cefb8
created by runtime.gcBgMarkStartWorkers
    /Users/rsc/go/src/runtime/mgc.go:1324 +0x8a

goroutine 5586 [GC worker (idle)]:
runtime.gopark(0xc8204b24a8, 0xc8200c87a0, 0x233443, 0x10, 0xc8201d7a14, 0x0)
    /Users/rsc/go/src/runtime/proc.go:262 +0x131 fp=0xc8200c8748 sp=0xc8200c8720
runtime.gcBgMarkWorker(0xc820021500)
    /Users/rsc/go/src/runtime/mgc.go:1397 +0xc1 fp=0xc8200c87b8 sp=0xc8200c8748
runtime.goexit()
    /Users/rsc/go/src/runtime/asm_amd64.s:2006 +0x1 fp=0xc8200c87c0 sp=0xc8200c87b8
created by runtime.gcBgMarkStartWorkers
    /Users/rsc/go/src/runtime/mgc.go:1324 +0x8a

goroutine 168 [GC worker (idle)]:
runtime.gopark(0xc820482018, 0xc8200cb7a0, 0x233443, 0x10, 0xc8200cb714, 0x0)
    /Users/rsc/go/src/runtime/proc.go:262 +0x131 fp=0xc8200cb748 sp=0xc8200cb720
runtime.gcBgMarkWorker(0xc82001d500)
    /Users/rsc/go/src/runtime/mgc.go:1397 +0xc1 fp=0xc8200cb7b8 sp=0xc8200cb748
runtime.goexit()
    /Users/rsc/go/src/runtime/asm_amd64.s:2006 +0x1 fp=0xc8200cb7c0 sp=0xc8200cb7b8
created by runtime.gcBgMarkStartWorkers
    /Users/rsc/go/src/runtime/mgc.go:1324 +0x8a

goroutine 5587 [GC worker (idle)]:
runtime.gopark(0xc820276008, 0xc8200cdfa0, 0x233443, 0x10, 0xc8201d6914, 0x0)
    /Users/rsc/go/src/runtime/proc.go:262 +0x131 fp=0xc8200cdf48 sp=0xc8200cdf20
runtime.gcBgMarkWorker(0xc820022a00)
    /Users/rsc/go/src/runtime/mgc.go:1397 +0xc1 fp=0xc8200cdfb8 sp=0xc8200cdf48
runtime.goexit()
    /Users/rsc/go/src/runtime/asm_amd64.s:2006 +0x1 fp=0xc8200cdfc0 sp=0xc8200cdfb8
created by runtime.gcBgMarkStartWorkers
    /Users/rsc/go/src/runtime/mgc.go:1324 +0x8a

goroutine 5544 [GC worker (idle)]:
runtime.gopark(0xc8204b0010, 0xc8200c8fa0, 0x233443, 0x10, 0xc82046f114, 0x0)
    /Users/rsc/go/src/runtime/proc.go:262 +0x131 fp=0xc8200c8f48 sp=0xc8200c8f20
runtime.gcBgMarkWorker(0xc82001ea00)
    /Users/rsc/go/src/runtime/mgc.go:1397 +0xc1 fp=0xc8200c8fb8 sp=0xc8200c8f48
runtime.goexit()
    /Users/rsc/go/src/runtime/asm_amd64.s:2006 +0x1 fp=0xc8200c8fc0 sp=0xc8200c8fb8
created by runtime.gcBgMarkStartWorkers
    /Users/rsc/go/src/runtime/mgc.go:1324 +0x8a

goroutine 22289 [syscall, 2 minutes]:
syscall.Syscall(0x3, 0x4, 0xc82023d000, 0x200, 0x0, 0x0, 0x0)
    /Users/rsc/go/src/syscall/asm_darwin_amd64.s:16 +0x5 fp=0xc8204fecc0 sp=0xc8204fecb8
syscall.read(0x4, 0xc82023d000, 0x200, 0x200, 0xc82023d000, 0xc82025d400, 0x11ffed8e3)
    /Users/rsc/go/src/syscall/zsyscall_darwin_amd64.go:972 +0x48 fp=0xc8204fed08 sp=0xc8204fecc0
syscall.Read(0x4, 0xc82023d000, 0x200, 0x200, 0x0, 0xc820033000, 0xc8202a0f00)
    /Users/rsc/go/src/syscall/syscall_unix.go:161 +0x3f fp=0xc8204fed48 sp=0xc8204fed08
os.(*File).read(0xc820250138, 0xc82023d000, 0x200, 0x200, 0xc8f21, 0x190800, 0x200)
    /Users/rsc/go/src/os/file_unix.go:228 +0x68 fp=0xc8204fed88 sp=0xc8204fed48
os.(*File).Read(0xc820250138, 0xc82023d000, 0x200, 0x200, 0x22fc46, 0xc, 0x0)
    /Users/rsc/go/src/os/file.go:95 +0x4c fp=0xc8204fede8 sp=0xc8204fed88
bytes.(*Buffer).ReadFrom(0xc82024e380, 0x1684000, 0xc820250138, 0xc8204feea8, 0xc82024e301, 0xc820264460)
    /Users/rsc/go/src/bytes/buffer.go:176 +0x150 fp=0xc8204fee50 sp=0xc8204fede8
io.copyBuffer(0x7446b8, 0xc82024e380, 0x1684000, 0xc820250138, 0x0, 0x0, 0x0, 0x22f573, 0xb, 0x23ac6d)
    /Users/rsc/go/src/io/io.go:374 +0x317 fp=0xc8204feed0 sp=0xc8204fee50
io.Copy(0x7446b8, 0xc82024e380, 0x1684000, 0xc820250138, 0xc8204fef90, 0xc8204fefa0, 0x4e120)
    /Users/rsc/go/src/io/io.go:350 +0x5a fp=0xc8204fef28 sp=0xc8204feed0
os/exec.(*Cmd).writerDescriptor.func1(0xc81fd86010, 0x66b3e)
    /Users/rsc/go/src/os/exec/exec.go:236 +0x56 fp=0xc8204fef80 sp=0xc8204fef28
os/exec.(*Cmd).Start.func1(0xc8202468c0, 0xc820264520)
    /Users/rsc/go/src/os/exec/exec.go:344 +0x20 fp=0xc8204fefb0 sp=0xc8204fef80
runtime.goexit()
    /Users/rsc/go/src/runtime/asm_amd64.s:2006 +0x1 fp=0xc8204fefb8 sp=0xc8204fefb0
created by os/exec.(*Cmd).Start
    /Users/rsc/go/src/os/exec/exec.go:345 +0x50f
FAIL    runtime 180.051s

[bradfitz]

I just got another one of these on a trybot run:
https://storage.googleapis.com/go-build-log/5121af01/darwin-amd64-10_10_1dc794a3.log

[quentinmit]

@dvyukov @aclements Have either of you had a chance to look at this yet?

[aclements]

I spent all day trying to reproduce this on the darwin-amd64-10_10 gomote with no success.

[gopherbot]

CL https://golang.org/cl/24110 mentions this issue.

[aclements]

Unfortunately, we haven't had any TestCgoExternalThreadSignal failures since 2016-06-01T00:09:32-04acd62/darwin-amd64-10_10, which was before @ianlancetaylor's CL to get stack traces of child processes. (In fact, the only runtime test timeouts since June 2nd have been on Plan 9.)

There was one interesting failure around that time that looks related to signals, though it wasn't this specific test: 2016-06-01T00:09:32-04acd62/linux-ppc64le-buildlet. @ianlancetaylor, it looks like goroutine 207880 got preempted at the beginning of sigpanic and never came back. Do you think that could be related?