os/exec: test deadlock #5123

dvyukov · 2013-03-25T17:11:12Z

parent: 16408:2be8c885acc8 tip
 net: band-aid for windows network poller

$ go test os/exec
deadlocks with the following stacks
looks like a real deadlock between tls.Conn.Read and Close


SIGABRT: abort
PC=0x423cb1

runtime.futex()
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/sys_linux_amd64.s:266 +0x21
runtime.futexsleep(0x7e68d8, 0x0, 0xffffffffffffffff)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/os_linux.c:58 +0x59
runtime.notesleep(0x7e68d8)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/lock_futex.c:125 +0x69
sysmon()
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/proc.c:1995 +0x196
runtime.mstart()
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/proc.c:485 +0xd2
crosscall_amd64()
    /usr/local/google/home/dvyukov/src/go4/src/pkg/crypto/dsa/dsa.go:0 +0xc

goroutine 1 [chan receive]:
runtime.park(0x40acf0, 0xc2000cbef0, 0x7e280a)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/proc.c:1167 +0x64
runtime.chanrecv(0x5c5920, 0xc2000cbea0, 0x7ffff7f67ce0, 0x0, 0x0, ...)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/chan.c:366 +0x566
runtime.chanrecv1()
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/chan.c:458 +0x38
testing.RunTests(0x6d4810, 0x7e0d20, 0xc, 0xc, 0x0, ...)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/testing/testing.go:427 +0x88e
testing.Main(0x6d4810, 0x7e0d20, 0xc, 0xc, 0x7e5240, ...)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/testing/testing.go:358 +0x8a
main.main()
    os/exec/_test/_testmain.go:65 +0x9a
runtime.main()
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/proc.c:182 +0x92
runtime.goexit()
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/proc.c:1214

goroutine 2 [syscall]:
runtime.goexit()
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/proc.c:1214

goroutine 3 [syscall]:
runtime.entersyscallblock()
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/proc.c:1324 +0x16e
runtime.MHeap_Scavenger()
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/mheap.c:435 +0xee
runtime.goexit()
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/proc.c:1214
created by runtime.main
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/proc.c:165

goroutine 18 [semacquire]:
runtime.park(0x40acf0, 0x7f4720, 0x7db990)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/proc.c:1167 +0x64
semacquireimpl(0xc2000c5298, 0x1)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/zsema_linux_amd64.c:113 +0x116
sync.runtime_Semacquire(0xc2000c5298)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/zsema_linux_amd64.c:165 +0x2e
sync.(*Mutex).Lock(0xc2000c5294)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/sync/mutex.go:66 +0xbb
crypto/tls.(*Conn).Close(0xc2000c5280, 0x0, 0x0)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/crypto/tls/conn.go:816 +0x4e
net/http/httptest.(*Server).CloseClientConnections(0xc2001c45a0)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/net/http/httptest/server.go:184 +0xa6
net/http/httptest.(*Server).Close(0xc2001c45a0)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/net/http/httptest/server.go:169 +0x4f
os/exec.TestExtraFiles(0xc2000fa1b0)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/os/exec/exec_test.go:268 +0xe52
testing.tRunner(0xc2000fa1b0, 0x7e0dc8)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/testing/testing.go:346 +0x8a
runtime.goexit()
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/proc.c:1214
created by testing.RunTests
    /usr/local/google/home/dvyukov/src/go4/src/pkg/testing/testing.go:426 +0x86b

goroutine 16 [finalizer wait]:
runtime.park(0x0, 0x0, 0x7e306a)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/proc.c:1167 +0x64
runfinq()
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/mgc0.c:2068 +0x6d
runtime.goexit()
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/proc.c:1214
created by runtime.gc
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/mgc0.c:1772

goroutine 21 [IO wait]:
runtime.park(0x40acf0, 0x7ffff7e46c88, 0x7e138f)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/proc.c:1167 +0x64
netpollblock(0x7ffff7e46c80, 0x72)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/znetpoll_linux_amd64.c:255 +0x9f
net.runtime_pollWait(0x7ffff7e46c80, 0x72, 0x0)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/znetpoll_linux_amd64.c:118 +0x82
net.(*pollDesc).WaitRead(0xc2000fa500, 0xb, 0xc2000cf120)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/net/fd_poll_runtime.go:75 +0x31
net.(*netFD).Read(0xc2000fa480, 0xc20008ac00, 0x400, 0x400, 0x0, ...)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/net/fd_unix.go:192 +0x2b3
net.(*conn).Read(0xc200000ae0, 0xc20008ac00, 0x400, 0x400, 0x7fff00000002, ...)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/net/net.go:123 +0xc3
crypto/tls.(*block).readFromUntil(0xc2001ef3c0, 0xc2001ef3f0, 0xc200000ae0, 0x5,
0xc200000ae0, ...)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/crypto/tls/conn.go:401 +0xbd
crypto/tls.(*Conn).readRecord(0xc2000c5280, 0x16, 0x0, 0x4c78c3)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/crypto/tls/conn.go:481 +0xfa
crypto/tls.(*Conn).readHandshake(0xc2000c5280, 0x16, 0xc200000b74, 0x4, 0x0, ...)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/crypto/tls/conn.go:683 +0xac
crypto/tls.(*serverHandshakeState).doFullHandshake(0xc2001f4000, 0xc2001f4000, 0x0)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/crypto/tls/handshake_server.go:325 +0x78a
crypto/tls.(*Conn).serverHandshake(0xc2000c5280, 0x0, 0x0)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/crypto/tls/handshake_server.go:65 +0x21c
crypto/tls.(*Conn).Handshake(0xc2000c5280, 0x0, 0x0)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/crypto/tls/conn.go:844 +0xec
net/http.(*conn).serve(0xc2000fa510)
    /usr/local/google/home/dvyukov/src/go4/src/pkg/net/http/server.go:912 +0x1c8
runtime.goexit()
    /usr/local/google/home/dvyukov/src/go4/src/pkg/runtime/proc.c:1214
created by net/http.(*Server).Serve
    /usr/local/google/home/dvyukov/src/go4/src/pkg/net/http/server.go:1439 +0x266

bradfitz · 2013-03-25T17:23:57Z

Comment 1:

Wonder why I've never hit this.
Mailed https://golang.org/cl/7693053

Owner changed to @bradfitz.

Status changed to Started.

bradfitz · 2013-03-25T20:50:28Z

Comment 2:

Owner changed to ---.

Status changed to Accepted.

bradfitz · 2013-03-25T21:07:55Z

Comment 3:

Yeah, my patch didn't seem to help.

dvyukov · 2013-03-26T07:09:52Z

Comment 4:

Is it test only bug?
How would a real program prevent such hang? Set a deadline? Perhaps we need to do the
same. How does one set deadline for server tls conn handshake?

bradfitz · 2013-03-26T15:26:59Z

Comment 5:

You can net.Dial{Opt,Timeout} with a deadline, then use
http://golang.org/pkg/crypto/tls/#Server to handshake.

davecheney · 2013-06-01T10:06:06Z

Comment 6:

@dmitry i cannot reproduce this at tip, what hardware/os are you using ? Can you still
reproduce the issue ?
% hg id 
1f7fdf4ad92d+ tip
#!/bin/bash
set -e
go test -c
PKG=$(basename $(pwd))
while true ; do 
        export GOMAXPROCS=$[ 1 + $[ RANDOM % 128 ]]
        ./$PKG.test $@ 2>&1
done

dvyukov · 2013-06-01T13:28:20Z

Comment 7:

I am pretty sure the bug is still there.
I was using linux/amd64 on HP z620 (32 HW threads).
I was running 10 or 20 tests at the same time, I think it may be important because the
contention forces OS to preempt threads.

davecheney · 2013-06-01T13:29:21Z

Comment 8:

ok, that is a lot more hardware than I have available to me.

rsc · 2013-07-30T16:46:50Z

Comment 9:

Labels changed: added priority-later, go1.2maybe, removed priority-triage.

rsc · 2013-09-10T23:11:23Z

Comment 10:

Labels changed: added testing.

rsc · 2013-10-02T00:31:16Z

Comment 11:

Labels changed: added go1.3, removed go1.2maybe.

rsc · 2013-12-04T01:30:05Z

Comment 12:

Labels changed: added release-go1.3.

rsc · 2013-12-04T01:30:26Z

Comment 13:

Labels changed: removed go1.3.

rsc · 2013-12-04T01:48:38Z

Comment 14:

Labels changed: added repo-main.

rsc · 2014-04-03T18:57:09Z

Comment 15:

Status changed to TimedOut.

dvyukov added timedout Testing An issue that has been verified to require only test changes, not just a test failure. labels Apr 3, 2014

rsc added this to the Go1.3 milestone Apr 14, 2015

rsc removed the release-go1.3 label Apr 14, 2015

golang locked and limited conversation to collaborators Jun 24, 2016

gopherbot added the FrozenDueToAge label Jun 24, 2016

This issue was closed.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

os/exec: test deadlock #5123

os/exec: test deadlock #5123

dvyukov commented Mar 25, 2013

bradfitz commented Mar 25, 2013

bradfitz commented Mar 25, 2013

bradfitz commented Mar 25, 2013

dvyukov commented Mar 26, 2013

bradfitz commented Mar 26, 2013

davecheney commented Jun 1, 2013

dvyukov commented Jun 1, 2013

davecheney commented Jun 1, 2013

rsc commented Jul 30, 2013

rsc commented Sep 10, 2013

rsc commented Oct 2, 2013

rsc commented Dec 4, 2013

rsc commented Dec 4, 2013

rsc commented Dec 4, 2013

rsc commented Apr 3, 2014

os/exec: test deadlock #5123

os/exec: test deadlock #5123

Comments

dvyukov commented Mar 25, 2013

bradfitz commented Mar 25, 2013

bradfitz commented Mar 25, 2013

bradfitz commented Mar 25, 2013

dvyukov commented Mar 26, 2013

bradfitz commented Mar 26, 2013

davecheney commented Jun 1, 2013

dvyukov commented Jun 1, 2013

davecheney commented Jun 1, 2013

rsc commented Jul 30, 2013

rsc commented Sep 10, 2013

rsc commented Oct 2, 2013

rsc commented Dec 4, 2013

rsc commented Dec 4, 2013

rsc commented Dec 4, 2013

rsc commented Apr 3, 2014