runtime: binary hangs on Catalina

[gadelkareem]

What version of Go are you using (go version)?

$ go version
go version go1.14 darwin/amd64

Does this issue reproduce with the latest release?

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/gadelkareem/Library/Caches/go-build"
GOENV="/Users/gadelkareem/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/gadelkareem/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/7p/qc_c3wz575z8wkh83vcwsdnh0000gn/T/go-build052322901=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

running https://gobyexample.com/hello-world

go run hellworld.go

What did you expect to see?

some output

What did you see instead?

it hangs without any output until I manually kill syspolicyd then it works normally. This started happening after upgrading to Catalina 10.15.3

[randall77]

Might be a dup of #37741 . But that's an awfully small program, so I'm not sure it is possible .

Does it happen all the time, or only some times?

When it hangs, does it run at 100% cpu? Can you send it a SIGABRT when it hangs and paste the output here? Is it the actual output program that hangs, or is it the go tool, the compiler, or the linker?

after upgrading to Catalina 10.15.3

So it did not happen with 10.15.2?

[gadelkareem]

Might be a dup of #37741 . But that's an awfully small program, so I'm not sure it is possible .

Does it happen all the time, or only some times?

It happens after several builds for few hours. Not sure of the exact time frame but I have the feeling it is a bit random.

When it hangs, does it run at 100% cpu? Can you send it a SIGABRT when it hangs and paste the output here? Is it the actual output program that hangs, or is it the go tool, the compiler, or the linker?

Last I checked the syspolicyd was on 99.5% when I killed it. The go run has no output.

after upgrading to Catalina 10.15.3

So it did not happen with 10.15.2?

I meant after upgrading to Catalina in general, just wanted to put the exact version. It never happened before Catalina.

[randall77]

It would help if you could show us a bit more about exactly what you did. I'm getting confused between your original report, which involves helloworld.go, and syspolicyd, which I know nothing about.

Can you point me to the source code of syspolicyd?

Next time you get a hang, run top -o cpu and copy/paste the first few lines into this bug.
Then run kill -ABRT ### where ### is the process ID in the leftmost column of that top command, for the command that is using 100% cpu. Your original command should then spew out a bunch of stack traces. Paste that output here.

If you feel up to it, you can try patching in https://go-review.googlesource.com/c/go/+/223240 into the runtime and testing again.

[gadelkareem]

syspolicyd is an OSX daemon https://knight.sc/reverse%20engineering/2019/02/20/syspolicyd-internals.html

The hellloworld.go is just an example of any golang code that does not work. Of course I was working on different code before I reached this bug. But as the binary hangs, any other code would also stop working.

I will get you some more info next time it hangs.

[randall77]

So then what does syspolicyd have to do with this bug? It's not written in Go as far as I can tell.
You said you killed it and things got better. Any idea why that is? Why did you choose syspolicyd to kill?

[gadelkareem]

So then what does syspolicyd have to do with this bug? It's not written in Go as far as I can tell.

True, but other apps are running without a problem. Only Golang compiler produces broken binaries when syspolicyd hangs.

You said you killed it and things got better. Any idea why that is? Why did you choose syspolicyd to kill?

Because it was on 99% CPU and I tried other services and nothing happened. I am almost sure it is a macos bug since I saw the syspolicyd is causing problems already elsewhere, but it needs to be reported here anyways.

[randall77]

So let me see if I understand.

• You wrote a Go program, compiled it, and ran it.
• While it was running, it seemed to hang.
• When you looked at top (?) , syspolicyd was at 100% cpu.
• When you killed syspolicyd, the Go program recovered.

Did you see the Go program at 100% cpu also? If not, then #37741 is probably not relevant.

I don't know what syspolicyd does, so I don't know what might be different between Go binaries and other binaries that would make this happen.

[gadelkareem]

So let me see if I understand.

• You wrote a Go program, compiled it, and ran it.
• While it was running, it seemed to hang.
• When you looked at top (?) , syspolicyd was at 100% cpu.
• When you killed syspolicyd, the Go program recovered.

Yes exactly correct.

Did you see the Go program at 100% cpu also? If not, then #37741 is probably not relevant.

No only the syspolicyd was 100%

I don't know what syspolicyd does, so I don't know what might be different between Go binaries and other binaries that would make this happen.

I don't know either so feel free to close it if you think it is invalid.

[randall77]

I think it would still be interesting to figure this out. I just don't know how to do it.

[gadelkareem]

Here is the debug info since it happed again

> top -o cpu
Processes: 518 total, 3 running, 1 stuck, 514 sleeping, 2712 threads                                                          11:22:11
Load Avg: 3.82, 3.80, 3.27  CPU usage: 5.96% user, 12.51% sys, 81.52% idle  SharedLibs: 264M resident, 68M data, 27M linkedit.
MemRegions: 238474 total, 5310M resident, 106M private, 3931M shared. PhysMem: 16G used (2643M wired), 110M unused.
VM: 3776G vsize, 1883M framework vsize, 54507324(0) swapins, 56999964(0) swapouts.
Networks: packets: 99141658/66G in, 125107826/88G out. Disks: 20173543/422G read, 24450890/485G written.

PID    COMMAND      %CPU TIME     #TH   #WQ  #PORT MEM    PURG  CMPRS PGRP  PPID  STATE    BOOSTS             %CPU_ME %CPU_OTHRS UID
84187  syspolicyd   99.8 19:04.01 5/1   3/1  145   36M    128K  19M   84187 1     running  *0[1]              0.00000 0.00000    0
304    WindowServer 9.5  08:14:54 11    4    3793- 1873M  40M   148M  304   1     sleeping *0[1]              0.55491 0.00626    88
15061  com.docker.h 8.9  41:42:06 19    0    43    6580M  0B    374M  15047 15055 sleeping *0[1]              0.00000 0.00000    501

> kill -ABRT 5947
SIGABRT: abort
PC=0x7fff66ea458c m=0 sigcode=0

goroutine 0 [idle]:
syscall.syscall6(0x10b0ba0, 0x174b, 0xc000abbc3c, 0x0, 0xc0000a6000, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/runtime/sys_darwin.go:74 +0x2e fp=0xc000abbb88 sp=0xc000abbb60 pc=0x10535ce
syscall.wait4(0x174b, 0xc000abbc3c, 0x0, 0xc0000a6000, 0x90, 0x1621040, 0x1)
	/usr/local/go/src/syscall/zsyscall_darwin_amd64.go:44 +0x87 fp=0xc000abbc00 sp=0xc000abbb88 pc=0x10aca57
syscall.Wait4(0x174b, 0xc000abbc8c, 0x0, 0xc0000a6000, 0x3, 0x3, 0xc000abbcc8)
	/usr/local/go/src/syscall/syscall_bsd.go:129 +0x51 fp=0xc000abbc50 sp=0xc000abbc00 pc=0x10a9581
os.(*Process).wait(0xc0003a4ae0, 0x1680d80, 0x1680d88, 0x1680d78)
	/usr/local/go/src/os/exec_unix.go:38 +0x7b fp=0xc000abbcc0 sp=0xc000abbc50 pc=0x10ccf4b
os.(*Process).Wait(...)
	/usr/local/go/src/os/exec.go:125
os/exec.(*Cmd).Wait(0xc0001c7340, 0x0, 0x0)
	/usr/local/go/src/os/exec/exec.go:502 +0x60 fp=0xc000abbd38 sp=0xc000abbcc0 pc=0x110a9d0
os/exec.(*Cmd).Run(0xc0001c7340, 0x167ff00, 0xc0006add80)
	/usr/local/go/src/os/exec/exec.go:340 +0x5c fp=0xc000abbd60 sp=0xc000abbd38 pc=0x1109e6c
cmd/go/internal/base.RunStdin(0xc0006add80, 0x1, 0x1)
	/usr/local/go/src/cmd/go/internal/base/base.go:167 +0x120 fp=0xc000abbdb8 sp=0xc000abbd60 pc=0x119e4a0
cmd/go/internal/run.buildRunProgram(0xc00014b5e0, 0xc0005e4280, 0xc000422000, 0xc000abbf58)
	/usr/local/go/src/cmd/go/internal/run/run.go:157 +0x229 fp=0xc000abbe70 sp=0xc000abbdb8 pc=0x1511fc9
cmd/go/internal/work.(*Builder).Do.func2(0xc0005e4280)
	/usr/local/go/src/cmd/go/internal/work/exec.go:118 +0x358 fp=0xc000abbf10 sp=0xc000abbe70 pc=0x147e068
cmd/go/internal/work.(*Builder).Do.func3(0xc0000cb2a0, 0xc00014b5e0, 0xc00059af20)
	/usr/local/go/src/cmd/go/internal/work/exec.go:178 +0x76 fp=0xc000abbfc8 sp=0xc000abbf10 pc=0x147e196
runtime.goexit()
	/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000abbfd0 sp=0xc000abbfc8 pc=0x10647d1
created by cmd/go/internal/work.(*Builder).Do
	/usr/local/go/src/cmd/go/internal/work/exec.go:165 +0x38a

goroutine 87 [syscall]:
syscall.syscall6(0x10b0ba0, 0x174b, 0xc000abbc3c, 0x0, 0xc0000a6000, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/runtime/sys_darwin.go:74 +0x2e fp=0xc000abbb88 sp=0xc000abbb60 pc=0x10535ce
syscall.wait4(0x174b, 0xc000abbc3c, 0x0, 0xc0000a6000, 0x90, 0x1621040, 0x1)
	/usr/local/go/src/syscall/zsyscall_darwin_amd64.go:44 +0x87 fp=0xc000abbc00 sp=0xc000abbb88 pc=0x10aca57
syscall.Wait4(0x174b, 0xc000abbc8c, 0x0, 0xc0000a6000, 0x3, 0x3, 0xc000abbcc8)
	/usr/local/go/src/syscall/syscall_bsd.go:129 +0x51 fp=0xc000abbc50 sp=0xc000abbc00 pc=0x10a9581
os.(*Process).wait(0xc0003a4ae0, 0x1680d80, 0x1680d88, 0x1680d78)
	/usr/local/go/src/os/exec_unix.go:38 +0x7b fp=0xc000abbcc0 sp=0xc000abbc50 pc=0x10ccf4b
os.(*Process).Wait(...)
	/usr/local/go/src/os/exec.go:125
os/exec.(*Cmd).Wait(0xc0001c7340, 0x0, 0x0)
	/usr/local/go/src/os/exec/exec.go:502 +0x60 fp=0xc000abbd38 sp=0xc000abbcc0 pc=0x110a9d0
os/exec.(*Cmd).Run(0xc0001c7340, 0x167ff00, 0xc0006add80)
	/usr/local/go/src/os/exec/exec.go:340 +0x5c fp=0xc000abbd60 sp=0xc000abbd38 pc=0x1109e6c
cmd/go/internal/base.RunStdin(0xc0006add80, 0x1, 0x1)
	/usr/local/go/src/cmd/go/internal/base/base.go:167 +0x120 fp=0xc000abbdb8 sp=0xc000abbd60 pc=0x119e4a0
cmd/go/internal/run.buildRunProgram(0xc00014b5e0, 0xc0005e4280, 0xc000422000, 0xc000abbf58)
	/usr/local/go/src/cmd/go/internal/run/run.go:157 +0x229 fp=0xc000abbe70 sp=0xc000abbdb8 pc=0x1511fc9
cmd/go/internal/work.(*Builder).Do.func2(0xc0005e4280)
	/usr/local/go/src/cmd/go/internal/work/exec.go:118 +0x358 fp=0xc000abbf10 sp=0xc000abbe70 pc=0x147e068
cmd/go/internal/work.(*Builder).Do.func3(0xc0000cb2a0, 0xc00014b5e0, 0xc00059af20)
	/usr/local/go/src/cmd/go/internal/work/exec.go:178 +0x76 fp=0xc000abbfc8 sp=0xc000abbf10 pc=0x147e196
runtime.goexit()
	/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000abbfd0 sp=0xc000abbfc8 pc=0x10647d1
created by cmd/go/internal/work.(*Builder).Do
	/usr/local/go/src/cmd/go/internal/work/exec.go:165 +0x38a

goroutine 1 [semacquire]:
sync.runtime_Semacquire(0xc0000cb2a8)
	/usr/local/go/src/runtime/sema.go:56 +0x42
sync.(*WaitGroup).Wait(0xc0000cb2a0)
	/usr/local/go/src/sync/waitgroup.go:130 +0x64
cmd/go/internal/work.(*Builder).Do(0xc00014b5e0, 0xc0005e4280)
	/usr/local/go/src/cmd/go/internal/work/exec.go:187 +0x3ae
cmd/go/internal/run.runRun(0x1ac0a80, 0xc0001121a0, 0x1, 0x1)
	/usr/local/go/src/cmd/go/internal/run/run.go:143 +0x538
main.main()
	/usr/local/go/src/cmd/go/main.go:189 +0x569

goroutine 86 [select]:
cmd/go/internal/work.(*Builder).Do.func3(0xc0000cb2a0, 0xc00014b5e0, 0xc00059af20)
	/usr/local/go/src/cmd/go/internal/work/exec.go:168 +0xed
created by cmd/go/internal/work.(*Builder).Do
	/usr/local/go/src/cmd/go/internal/work/exec.go:165 +0x38a

goroutine 88 [select]:
cmd/go/internal/work.(*Builder).Do.func3(0xc0000cb2a0, 0xc00014b5e0, 0xc00059af20)
	/usr/local/go/src/cmd/go/internal/work/exec.go:168 +0xed
created by cmd/go/internal/work.(*Builder).Do
	/usr/local/go/src/cmd/go/internal/work/exec.go:165 +0x38a

goroutine 89 [select]:
cmd/go/internal/work.(*Builder).Do.func3(0xc0000cb2a0, 0xc00014b5e0, 0xc00059af20)
	/usr/local/go/src/cmd/go/internal/work/exec.go:168 +0xed
created by cmd/go/internal/work.(*Builder).Do
	/usr/local/go/src/cmd/go/internal/work/exec.go:165 +0x38a

goroutine 90 [select]:
cmd/go/internal/work.(*Builder).Do.func3(0xc0000cb2a0, 0xc00014b5e0, 0xc00059af20)
	/usr/local/go/src/cmd/go/internal/work/exec.go:168 +0xed
created by cmd/go/internal/work.(*Builder).Do
	/usr/local/go/src/cmd/go/internal/work/exec.go:165 +0x38a

goroutine 91 [select]:
cmd/go/internal/work.(*Builder).Do.func3(0xc0000cb2a0, 0xc00014b5e0, 0xc00059af20)
	/usr/local/go/src/cmd/go/internal/work/exec.go:168 +0xed
created by cmd/go/internal/work.(*Builder).Do
	/usr/local/go/src/cmd/go/internal/work/exec.go:165 +0x38a

goroutine 92 [select]:
cmd/go/internal/work.(*Builder).Do.func3(0xc0000cb2a0, 0xc00014b5e0, 0xc00059af20)
	/usr/local/go/src/cmd/go/internal/work/exec.go:168 +0xed
created by cmd/go/internal/work.(*Builder).Do
	/usr/local/go/src/cmd/go/internal/work/exec.go:165 +0x38a

goroutine 93 [select]:
cmd/go/internal/work.(*Builder).Do.func3(0xc0000cb2a0, 0xc00014b5e0, 0xc00059af20)
	/usr/local/go/src/cmd/go/internal/work/exec.go:168 +0xed
created by cmd/go/internal/work.(*Builder).Do
	/usr/local/go/src/cmd/go/internal/work/exec.go:165 +0x38a

goroutine 32 [chan receive]:
cmd/go/internal/base.processSignals.func1(0xc0002c67e0)
	/usr/local/go/src/cmd/go/internal/base/signal.go:21 +0x34
created by cmd/go/internal/base.processSignals
	/usr/local/go/src/cmd/go/internal/base/signal.go:20 +0x93

goroutine 133 [syscall]:
os/signal.signal_recv(0x0)
	/usr/local/go/src/runtime/sigqueue.go:144 +0x96
os/signal.loop()
	/usr/local/go/src/os/signal/signal_unix.go:23 +0x22
created by os/signal.Notify.func1
	/usr/local/go/src/os/signal/signal.go:127 +0x44

rax    0x2000190
rbx    0xc000abbb88
rcx    0x7ffeefbff638
rdx    0x0
rdi    0x174b
rsi    0xc000abbc3c
rbp    0x7ffeefbff650
rsp    0x7ffeefbff638
r8     0x0
r9     0x0
r10    0xc0000a6000
r11    0x246
r12    0x0
r13    0x40
r14    0x6
r15    0x100
rip    0x7fff66ea458c
rflags 0x246
cs     0x7
fs     0x0
gs     0x0

[randall77]

Those stack traces are from the go command.
It looks like the go binary is just waiting for the forked user process (your program) to finish.

You killed 5947, which isn't one of the programs listed in your top output.
Is your program listed somewhere? Can you get a stack trace of that?
(It might help to go build and then run your binary separately - it's easier to distinguish the build tools from your actual program.)

[gadelkareem]

Yes I think I ran go run main.go but the PID is for the correct command it is just not appearing in top