os/exec, syscall, runtime: hung system call starting process on OS X 10.8

I just noticed an OS X 10.8 builder hung.

The root cause was the builder was stuck in a system call trying to start a child process.

Look at goroutine 511, which is what's blocking the other one:

```
goroutine 511 [syscall, 387 minutes]:
syscall.Syscall(0x3, 0x8, 0x42166db50, 0x8, 0x0, 0x0, 0x0)
    /home/bradfitz/go/src/syscall/asm_darwin_amd64.s:16 +0x5
syscall.readlen(0x8, 0x42166db50, 0x8, 0x2, 0x421796000, 0x18)
    /home/bradfitz/go/src/syscall/zsyscall_darwin_amd64.go:1393 +0x56
syscall.forkExec(0x420838010, 0xd, 0x420838000, 0x1, 0x1, 0x42166dce0, 0x1ffffffffffffff, 0x2ff875, 0x42179a680)
    /home/bradfitz/go/src/syscall/exec_unix.go:202 +0x33e
syscall.StartProcess(0x420838010, 0xd, 0x420838000, 0x1, 0x1, 0x42166dce0, 0x2, 0x4, 0x5c620, 0x4204e04c0)
    /home/bradfitz/go/src/syscall/exec_unix.go:240 +0x64
os.startProcess(0x420838010, 0xd, 0x420838000, 0x1, 0x1, 0x42166de88, 0x42171a000, 0x17, 0x17)
    /home/bradfitz/go/src/os/exec_posix.go:45 +0x1a3
os.StartProcess(0x420838010, 0xd, 0x420838000, 0x1, 0x1, 0x42166de88, 0x0, 0x0, 0x42166de28)
    /home/bradfitz/go/src/os/exec.go:94 +0x64
os/exec.(*Cmd).Start(0x4204dc420, 0x420838001, 0x4205421e0)
    /home/bradfitz/go/src/os/exec/exec.go:358 +0x3ce
os/exec.(*Cmd).Run(0x4204dc420, 0x4205421e0, 0x0)
    /home/bradfitz/go/src/os/exec/exec.go:276 +0x2b
golang.org/x/build/pargzip.(*writeChunk).compress(0x42054a000, 0x0, 0x0)
    /home/bradfitz/src/golang.org/x/build/pargzip/pargzip.go:81 +0x1c5
created by golang.org/x/build/pargzip.(*Writer).startChunk
    /home/bradfitz/src/golang.org/x/build/pargzip/pargzip.go:141 +0x16b
```

Where `asm_darwin_amd64.s:16` is in the call to `runtime·entersyscall`:

```
//                                                                                                                             
// System call support for AMD64, Darwin                                                                                       
//                                                                                                                             

// Trap # in AX, args in DI SI DX, return in AX DX                                                                             

// func Syscall(trap, a1, a2, a3 uintptr) (r1, r2 uintptr, err Errno);                                                         
TEXT    ·Syscall(SB),NOSPLIT,$0-56
        CALL    runtime·entersyscall(SB)  // <==================== LINE 16                                                                           
        MOVQ    a1+8(FP), DI
        MOVQ    a2+16(FP), SI
        MOVQ    a3+24(FP), DX
        MOVQ    $0, R10
        MOVQ    $0, R8
        MOVQ    $0, R9
        MOVQ    trap+0(FP), AX  // syscall entry                                                                               
        ADDQ    $0x2000000, AX
        SYSCALL
        JCC     ok
        MOVQ    $-1, r1+32(FP)
        MOVQ    $0, r2+40(FP)
        MOVQ    AX, err+48(FP)
        CALL    runtime·exitsyscall(SB)
        RET
ok:
        MOVQ    AX, r1+32(FP)
        MOVQ    DX, r2+40(FP)
        MOVQ    $0, err+48(FP)
        CALL    runtime·exitsyscall(SB)
        RET
```

And the system call it's doing is from:

``` go
        // Read child error status from pipe.                                                                                  
        Close(p[1])
        n, err = readlen(p[0], (*byte)(unsafe.Pointer(&err1)), int(unsafe.Sizeof(err1)))
        Close(p[0])
```

Which is:

``` go
func readlen(fd int, p *byte, np int) (n int, err error) {
        r0, _, e1 := Syscall(SYS_READ, uintptr(fd), uintptr(unsafe.Pointer(p)), uintptr(np))
        n = int(r0)
        if e1 != 0 {
                err = errnoErr(e1)
        }
        return
}       
```

Full SIGQUIT output:

```
kmr0000gn/T/workdir/go/src
2016/09/08 09:34:01 [0x420539600] Run = ok, after 1m14.526362819s
2016/09/08 09:34:01 Removing go/doc/gopher
2016/09/08 09:34:01 Removing go/pkg/bootstrap
^\SIGQUIT: quit
PC=0x65c6b m=0

goroutine 0 [idle]:
runtime.mach_semaphore_wait(0x207, 0x580000000e, 0x0, 0x0, 0x16ae97, 0x456100, 0x7fff5fbff9e8, 0x5c4b3, 0xffffffffffffffff, 0x0, ...)
    /home/bradfitz/go/src/runtime/sys_darwin_amd64.s:418 +0xb
runtime.semasleep1(0xffffffffffffffff, 0x0)
    /home/bradfitz/go/src/runtime/os_darwin.go:435 +0x4b
runtime.semasleep.func1()
    /home/bradfitz/go/src/runtime/os_darwin.go:451 +0x33
runtime.systemstack(0x7fff5fbffa10)
    /home/bradfitz/go/src/runtime/asm_amd64.s:314 +0xab
runtime.semasleep(0xffffffffffffffff, 0x0)
    /home/bradfitz/go/src/runtime/os_darwin.go:452 +0x44
runtime.notesleep(0x456830)
    /home/bradfitz/go/src/runtime/lock_sema.go:166 +0x81
runtime.stopm()
    /home/bradfitz/go/src/runtime/proc.go:1594 +0xad
runtime.findrunnable(0x4204e4000, 0x0)
    /home/bradfitz/go/src/runtime/proc.go:2021 +0x296
runtime.schedule()
    /home/bradfitz/go/src/runtime/proc.go:2120 +0x14c
runtime.goexit0(0x42091fa00)
    /home/bradfitz/go/src/runtime/proc.go:2257 +0x18c
runtime.mcall(0x7fff5fbffbf0)
    /home/bradfitz/go/src/runtime/asm_amd64.s:240 +0x5b

goroutine 1 [chan receive, 379 minutes]:
golang.org/x/build/revdial.(*Listener).Accept(0x42053d880, 0x311d68, 0x420548080, 0x439b80, 0x4204e2090)
    /home/bradfitz/src/golang.org/x/build/revdial/revdial.go:451 +0x5e
net/http.(*Server).Serve(0x4205e4a00, 0x4392c0, 0x42053d880, 0x0, 0x0)
    /home/bradfitz/go/src/net/http/server.go:2273 +0x1ce
main.dialCoordinator(0x2fe30d, 0x3)
    /home/bradfitz/src/golang.org/x/build/cmd/buildlet/reverse.go:140 +0xd7f
main.main()
    /home/bradfitz/src/golang.org/x/build/cmd/buildlet/buildlet.go:175 +0x63b

goroutine 35 [select, 387 minutes]:
golang.org/x/build/pargzip.(*Writer).startChunk(0x42175af50, 0x420672000, 0x100000, 0x100000)
    /home/bradfitz/src/golang.org/x/build/pargzip/pargzip.go:142 +0x23e
golang.org/x/build/pargzip.newChunkWriter.Write(0x42175af50, 0x420672000, 0x100000, 0x0, 0x3, 0x13, 0x4216c0000)
    /home/bradfitz/src/golang.org/x/build/pargzip/pargzip.go:214 +0xa0
bufio.(*Writer).flush(0x42053c900, 0x4216c0000, 0x1a00)
    /home/bradfitz/go/src/bufio/bufio.go:563 +0x75
bufio.(*Writer).Write(0x42053c900, 0x4216c0000, 0x6cde, 0x8000, 0x6cde, 0x0, 0x0)
    /home/bradfitz/go/src/bufio/bufio.go:599 +0xd2
golang.org/x/build/pargzip.(*Writer).Write(0x42175af50, 0x4216c0000, 0x6cde, 0x8000, 0x6cde, 0x0, 0x0)
    /home/bradfitz/src/golang.org/x/build/pargzip/pargzip.go:172 +0x56
archive/tar.(*Writer).Write(0x421764000, 0x4216c0000, 0x6cde, 0x8000, 0x6cde, 0x0, 0x0)
    /home/bradfitz/go/src/archive/tar/writer.go:372 +0x83
io.copyBuffer(0x434600, 0x421764000, 0x4355c0, 0x4204f2350, 0x4216c0000, 0x8000, 0x8000, 0xe99e, 0x42092f5f0, 0x42092f600)
    /home/bradfitz/go/src/io/io.go:392 +0x260
io.Copy(0x434600, 0x421764000, 0x4355c0, 0x4204f2350, 0x0, 0x0, 0x0)
    /home/bradfitz/go/src/io/io.go:360 +0x68
main.handleGetTGZ.func1(0x4205ec420, 0x55, 0x43ae20, 0x4217972b0, 0x0, 0x0, 0x0, 0x0)
    /home/bradfitz/src/golang.org/x/build/cmd/buildlet/buildlet.go:433 +0x342
path/filepath.walk(0x4205ec420, 0x55, 0x43ae20, 0x4217972b0, 0x4205e0cc0, 0x0, 0x0)
    /home/bradfitz/go/src/path/filepath/path.go:351 +0x81
path/filepath.walk(0x420880dc0, 0x4d, 0x43ae20, 0x421797110, 0x4205e0cc0, 0x0, 0x0)
    /home/bradfitz/go/src/path/filepath/path.go:376 +0x344
path/filepath.walk(0x420880c80, 0x48, 0x43ae20, 0x421796a90, 0x4205e0cc0, 0x0, 0x0)
    /home/bradfitz/go/src/path/filepath/path.go:376 +0x344
path/filepath.walk(0x4204e0940, 0x3f, 0x43ae20, 0x4205fe410, 0x4205e0cc0, 0x0, 0x0)
    /home/bradfitz/go/src/path/filepath/path.go:376 +0x344
path/filepath.walk(0x42053c840, 0x3b, 0x43ae20, 0x42171d6c0, 0x4205e0cc0, 0x0, 0x20)
    /home/bradfitz/go/src/path/filepath/path.go:376 +0x344
path/filepath.Walk(0x42053c840, 0x3b, 0x4205e0cc0, 0x42053c840, 0x3b)
    /home/bradfitz/go/src/path/filepath/path.go:398 +0x14c
main.handleGetTGZ(0x439540, 0x42171d5f0, 0x420598b40)
    /home/bradfitz/src/golang.org/x/build/cmd/buildlet/buildlet.go:438 +0x3e5
net/http.HandlerFunc.ServeHTTP(0x311b50, 0x439540, 0x42171d5f0, 0x420598b40)
    /home/bradfitz/go/src/net/http/server.go:1726 +0x44
main.requirePasswordHandler.ServeHTTP(0x436440, 0x311b50, 0x0, 0x0, 0x439540, 0x42171d5f0, 0x420598b40)
    /home/bradfitz/src/golang.org/x/build/cmd/buildlet/buildlet.go:1126 +0xe0
main.(*requirePasswordHandler).ServeHTTP(0x4204de980, 0x439540, 0x42171d5f0, 0x420598b40)
    <autogenerated>:25 +0x8b
net/http.(*ServeMux).ServeHTTP(0x455740, 0x439540, 0x42171d5f0, 0x420598b40)
    /home/bradfitz/go/src/net/http/server.go:2022 +0x7f
net/http.serverHandler.ServeHTTP(0x4205e4a00, 0x439540, 0x42171d5f0, 0x420598b40)
    /home/bradfitz/go/src/net/http/server.go:2202 +0x7d
net/http.(*conn).serve(0x4205e4400, 0x439ac0, 0x42053c340)
    /home/bradfitz/go/src/net/http/server.go:1579 +0x4b7
created by net/http.(*Server).Serve
    /home/bradfitz/go/src/net/http/server.go:2293 +0x44d

goroutine 37 [chan receive, 387 minutes]:
golang.org/x/build/pargzip.(*Writer).writeCompressedChunk(0x42175af50, 0x42054a000, 0x0, 0x0)
    /home/bradfitz/src/golang.org/x/build/pargzip/pargzip.go:160 +0x97
golang.org/x/build/pargzip.(*Writer).init.func1(0x42175af50)
    /home/bradfitz/src/golang.org/x/build/pargzip/pargzip.go:126 +0xaf
created by golang.org/x/build/pargzip.(*Writer).init
    /home/bradfitz/src/golang.org/x/build/pargzip/pargzip.go:131 +0x109

goroutine 16 [IO wait]:
net.runtime_pollWait(0x84206d2dd0, 0x72, 0x3)
    /home/bradfitz/go/src/runtime/netpoll.go:160 +0x59
net.(*pollDesc).wait(0x420516220, 0x72, 0x436f00, 0x4205240b0)
    /home/bradfitz/go/src/net/fd_poll_runtime.go:75 +0x38
net.(*pollDesc).waitRead(0x420516220, 0x420670000, 0x2000)
    /home/bradfitz/go/src/net/fd_poll_runtime.go:80 +0x34
net.(*netFD).Read(0x4205161c0, 0x420670000, 0x2000, 0x2000, 0x0, 0x436f00, 0x4205240b0)
    /home/bradfitz/go/src/net/fd_unix.go:243 +0x181
net.(*conn).Read(0x4204f2000, 0x420670000, 0x2000, 0x2000, 0x0, 0x0, 0x0)
    /home/bradfitz/go/src/net/net.go:173 +0x70
crypto/tls.(*block).readFromUntil(0x4208ffb90, 0x842053d368, 0x4204f2000, 0x5, 0x4204f2000, 0x0)
    /home/bradfitz/go/src/crypto/tls/conn.go:472 +0x91
crypto/tls.(*Conn).readRecord(0x4208fc000, 0x312317, 0x4208fc100, 0x420524020)
    /home/bradfitz/go/src/crypto/tls/conn.go:574 +0xc4
crypto/tls.(*Conn).Read(0x4208fc000, 0x420871000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /home/bradfitz/go/src/crypto/tls/conn.go:1109 +0x116
bufio.(*Reader).fill(0x42091cde0)
    /home/bradfitz/go/src/bufio/bufio.go:97 +0x10b
bufio.(*Reader).Read(0x42091cde0, 0x420839fe0, 0x7, 0x7, 0x70, 0x42175a000, 0x42054a750)
    /home/bradfitz/go/src/bufio/bufio.go:209 +0x1bc
io.ReadAtLeast(0x434640, 0x42091cde0, 0x420839fe0, 0x7, 0x7, 0x7, 0x0, 0x42054a730, 0x4204de180)
    /home/bradfitz/go/src/io/io.go:307 +0xa4
io.ReadFull(0x434640, 0x42091cde0, 0x420839fe0, 0x7, 0x7, 0x0, 0x0, 0x0)
    /home/bradfitz/go/src/io/io.go:325 +0x58
golang.org/x/build/revdial.readFrames(0x42091cde0, 0x434b80, 0x42053d880, 0x16ae3f, 0x420540200)
    /home/bradfitz/src/golang.org/x/build/revdial/revdial.go:373 +0xb4
golang.org/x/build/revdial.NewListener.func1(0x420839fb0, 0x42053d880)
    /home/bradfitz/src/golang.org/x/build/revdial/revdial.go:417 +0x5c
created by golang.org/x/build/revdial.NewListener
    /home/bradfitz/src/golang.org/x/build/revdial/revdial.go:431 +0x119

goroutine 511 [syscall, 387 minutes]:
syscall.Syscall(0x3, 0x8, 0x42166db50, 0x8, 0x0, 0x0, 0x0)
    /home/bradfitz/go/src/syscall/asm_darwin_amd64.s:16 +0x5
syscall.readlen(0x8, 0x42166db50, 0x8, 0x2, 0x421796000, 0x18)
    /home/bradfitz/go/src/syscall/zsyscall_darwin_amd64.go:1393 +0x56
syscall.forkExec(0x420838010, 0xd, 0x420838000, 0x1, 0x1, 0x42166dce0, 0x1ffffffffffffff, 0x2ff875, 0x42179a680)
    /home/bradfitz/go/src/syscall/exec_unix.go:202 +0x33e
syscall.StartProcess(0x420838010, 0xd, 0x420838000, 0x1, 0x1, 0x42166dce0, 0x2, 0x4, 0x5c620, 0x4204e04c0)
    /home/bradfitz/go/src/syscall/exec_unix.go:240 +0x64
os.startProcess(0x420838010, 0xd, 0x420838000, 0x1, 0x1, 0x42166de88, 0x42171a000, 0x17, 0x17)
    /home/bradfitz/go/src/os/exec_posix.go:45 +0x1a3
os.StartProcess(0x420838010, 0xd, 0x420838000, 0x1, 0x1, 0x42166de88, 0x0, 0x0, 0x42166de28)
    /home/bradfitz/go/src/os/exec.go:94 +0x64
os/exec.(*Cmd).Start(0x4204dc420, 0x420838001, 0x4205421e0)
    /home/bradfitz/go/src/os/exec/exec.go:358 +0x3ce
os/exec.(*Cmd).Run(0x4204dc420, 0x4205421e0, 0x0)
    /home/bradfitz/go/src/os/exec/exec.go:276 +0x2b
golang.org/x/build/pargzip.(*writeChunk).compress(0x42054a000, 0x0, 0x0)
    /home/bradfitz/src/golang.org/x/build/pargzip/pargzip.go:81 +0x1c5
created by golang.org/x/build/pargzip.(*Writer).startChunk
    /home/bradfitz/src/golang.org/x/build/pargzip/pargzip.go:141 +0x16b

goroutine 535 [semacquire]:
sync.runtime_notifyListWait(0x42053c6d0, 0x8d9)
    /home/bradfitz/go/src/runtime/sema.go:267 +0x121
sync.(*Cond).Wait(0x42053c6c0)
    /home/bradfitz/go/src/sync/cond.go:57 +0x80
golang.org/x/build/revdial.(*conn).Read(0x42054a730, 0x42095f000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /home/bradfitz/src/golang.org/x/build/revdial/revdial.go:296 +0xe5
net/http.(*connReader).Read(0x4204de120, 0x42095f000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /home/bradfitz/go/src/net/http/server.go:586 +0x144
bufio.(*Reader).fill(0x420522240)
    /home/bradfitz/go/src/bufio/bufio.go:97 +0x10b
bufio.(*Reader).ReadSlice(0x420522240, 0x42050ba0a, 0x84a6b, 0x4208fc1b0, 0x4205ae810, 0xac, 0x8000)
    /home/bradfitz/go/src/bufio/bufio.go:330 +0xb5
bufio.(*Reader).ReadLine(0x420522240, 0x4217620f0, 0xf0, 0xf0, 0x2f5040, 0x4208fc310, 0x1ee7b2)
    /home/bradfitz/go/src/bufio/bufio.go:359 +0x37
net/textproto.(*Reader).readLineSlice(0x4208fe7b0, 0x42050baa8, 0x42050baa8, 0x1e518, 0xf0, 0x2f5040)
    /home/bradfitz/go/src/net/textproto/reader.go:55 +0x5e
net/textproto.(*Reader).ReadLine(0x4208fe7b0, 0x4217620f0, 0x1000, 0x8f, 0x0)
    /home/bradfitz/go/src/net/textproto/reader.go:36 +0x2f
net/http.readRequest(0x420522240, 0x0, 0x4217620f0, 0x0, 0x0)
    /home/bradfitz/go/src/net/http/request.go:793 +0xa5
net/http.(*conn).readRequest(0x420548080, 0x439ac0, 0x42053c780, 0x0, 0x0, 0x0)
    /home/bradfitz/go/src/net/http/server.go:765 +0x10d
net/http.(*conn).serve(0x420548080, 0x439ac0, 0x42053c780)
    /home/bradfitz/go/src/net/http/server.go:1532 +0x3d3
created by net/http.(*Server).Serve
    /home/bradfitz/go/src/net/http/server.go:2293 +0x44d

rax    0xe
rbx    0x456720
rcx    0x7fff5fbff988
rdx    0x7fff5fbffa10
rdi    0x207
rsi    0xd3
rbp    0x7fff5fbff9c0
rsp    0x7fff5fbff988
r8     0x42091fa00
r9     0x3
r10    0x0
r11    0x246
r12    0x0
r13    0x42091fa00
r14    0x4b140
r15    0x377130
rip    0x65c6b
rflags 0x246
cs     0x7
fs     0x0
gs     0x0
```

/cc @ianlancetaylor @aclements @cherrymui @josharian 


Provide feedback

Saved searches

Use saved searches to filter your results more quickly

os/exec, syscall, runtime: hung system call starting process on OS X 10.8 #17033

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

os/exec, syscall, runtime: hung system call starting process on OS X 10.8 #17033

Description

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions