Background: I maintain a fork/branch of Joker (a Clojure interpreter/clone written in Go) that "autowraps" much of the Go standard library for easy access by Joker code.

A couple of weeks ago, I first noticed that the (small) test suite occasionally hung. Digging further, I posted this to get some feedback:

https://stackoverflow.com/questions/61342000/why-might-exec-command-start-hang-on-darwin

As suggested there, I ran git bisect run on the Go source code to find "the" commit that introduced or triggered the problem. The culprit simply turned on "new" timer code (turning off old code), which was quite suggestive.

Later, I boiled the pertinent Joker code down to a small test program and was able to reproduce that. The first such version pulled in all the Go standard library that my fork of Joker did. I then performed manual bisections of that set and narrowed them down to just the plugin package: when included (despite not being referenced), the sample program would occasionally hang; without it, it wouldn't.

This issue is being tracked (on my end) via jcburley/joker#19. It's Closed due to a workaround being implemented such that plugin isn't included in the list of imported (and wrapped) packages when Joker is built for OS X (Darwin).

A slightly "fuller" version of the sample program, along with instructions on another approach to run it, is here:

https://github.com/jcburley/hangme/blob/master/README.md

cc @odeke-em re MacOS

Hi, the same thing in golangci-lint: can reproduce only on Mac OS (Linux is ok, Windows - didn't test properly), only on go1.14 (1.13 works ok). Also, reproduces not every time: I ran in loop to reproduce.
When reproduced I see in ps two identical processes win my binary, one is the child of another.
And I also import plugin and can't reproduce the problem when comment out this importing.

(dlv) bt                                                                                                                                            
 0  0x00007fff6bcef062 in ???
    at ?:-1
 1  0x00007fff6bdab937 in ???
    at ?:-1
 2  0x00007fff6bbaa786 in ???
    at ?:-1
 3  0x000000000b163395 in ???
    at ?:-1
 4  0x000000000b143acb in ???
    at ?:-1
 5  0x00007fff6bbaa692 in ???
    at ?:-1
 6  0x00000000053c4000 in ???
    at ?:-1
 7  0x0000000004067da0 in runtime.asmcgocall
    at /usr/local/go/src/runtime/asm_amd64.s:655
 8  0x0000000000000000 in ???
    at ?:-1
 9  0x0000000004055a8c in syscall.rawSyscall
    at /usr/local/go/src/runtime/sys_darwin.go:107
10  0x00000000040b1d1f in syscall.forkAndExecInChild
    at /usr/local/go/src/syscall/exec_darwin.go:157
11  0x00000000040b284b in syscall.forkExec
    at /usr/local/go/src/syscall/exec_unix.go:201
12  0x00000000040d5ef0 in syscall.StartProcess
    at /usr/local/go/src/syscall/exec_unix.go:248
13  0x00000000040d5ef0 in os.startProcess
    at /usr/local/go/src/os/exec_posix.go:53
14  0x00000000040d591c in os.StartProcess
    at /usr/local/go/src/os/exec.go:102
15  0x000000000429b5f6 in os/exec.(*Cmd).Start
    at /usr/local/go/src/os/exec/exec.go:422
16  0x0000000004512610 in golang.org/x/tools/internal/gocommand.runCmdContext
    at /Users/denis/go/pkg/mod/golang.org/x/tools@v0.0.0-20200502202811-ed308ab3e770/internal/gocommand/invoke.go:153
17  0x0000000004511d29 in golang.org/x/tools/internal/gocommand.(*Invocation).RunPiped
    at /Users/denis/go/pkg/mod/golang.org/x/tools@v0.0.0-20200502202811-ed308ab3e770/internal/gocommand/invoke.go:147
18  0x000000000451178e in golang.org/x/tools/internal/gocommand.(*Invocation).runRaw

$ go version
go version go1.14.2 darwin/amd64
$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/denis/Library/Caches/go-build"
GOENV="/Users/denis/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/denis/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="/Users/denis/golangci-lint/go.mod"
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/nl/54f5x38s4m53mkzzj92zsj340000gn/T/go-build180675235=/tmp/go-build -gno-record-gcc-switches -fno-common"

I took a quick look at this today and can at the very least confirm that the bug still exists with 1.14.3:

(Here's my very slightly modified code, where all I did was add some more STDOUT output to figure out what's going on.)

As we can see here, I ran it the same way as James and indeed it locked after only 3 attempts. At the point this screenshot was taken, the same program had been hanging for 7 minutes, 35 seconds.

So I looked at Activity Monitor.app to see if I can get some more information:

Here's the text of that stack trace if you can't view the image for some reason:

[...snip...]
Call graph:
    973 Thread_4709590   DispatchQueue_1: com.apple.main-thread  (serial)
      973 runtime.asmcgocall  (in hangme) + 112  [0x405f8c0]
        973 ???  (in hangme)  load address 0x4000000 + 0x1de000  [0x41de000]
          973 dyld_stub_binder  (in libdyld.dylib) + 282  [0x7fff6e279692]
            973 dyld::fastBindLazySymbol(ImageLoader**, unsigned long)  (in dyld) + 86  [0x10656acb]
              973 ImageLoaderMachOCompressed::doBindFastLazySymbol(unsigned int, ImageLoader::LinkContext const&, void (*)(), void (*)())  (in dyld) + 53  [0x10676395]
                973 dyldGlobalLockAcquire()  (in libdyld.dylib) + 16  [0x7fff6e279786]
                  973 _pthread_mutex_firstfit_lock_slow  (in libsystem_pthread.dylib) + 222  [0x7fff6e47a937]
                    973 _pthread_mutex_firstfit_lock_wait  (in libsystem_pthread.dylib) + 83  [0x7fff6e47c917]
                      973 __psynch_mutexwait  (in libsystem_kernel.dylib) + 10  [0x7fff6e3be062]
[...snip...]

That last line caught my eye. Stuck in a mutex wait in the kernel? I went for a dtruss (like strace but for BSD/MacOS) on the pid for that process:

$ sudo dtruss -p 46759
Password:
dtrace: system integrity protection is on, some features will not be available

SYSCALL(args) 		 = return

It's just flat hung on the last line, no progress beyond that point at all.

My theory at this point is that the process isn't returning because one of the executions of ./hangme 0 is being held up by the kernel, which is waiting on a mutex to be released on some resource. This, to me, smells of a bug in MacOS, not necessarily in Go. I'm not sure why it worked with previous versions and not this version, but clearly something that plugin is doing is causing a hang at the kernel level (or at least appears to be) by having some resource tied up.

This is about the depth of my ability to debug at this point (I'm always learning, in fact that's why I'm looking at this issue!). I don't know how much help it'll be, but I certainly hope this aids in tracking things down.

Hi, I'm so glad to find a fellow sufferer from this :)

From that stack trace, and stack traces of my own issues, it looks like the dup2 call is calling into libc, which must be re-bound, which requires dyld, which has a global lock, which was already locked in the parent.

We are also importing plugin via containerd, so I suspect it's related. This is highly reproducible in "release" builds of the product (https://github.com/datadog/datadog-agent) but not in dev builds, and when it reproduces it occurs fairly late in the process startup: we shell out to lots of subprocesses, probably simultaneously with gathering containerd information, and around 5s into that, a subprocess will hang. That suggests that if this is a race condition, it's got a pretty broad failure window. Also, I don't have containerd installed on my system, so it's unlikely that it's actually loading any plugins, but I'll continue to investigate that.

Glad to know someone else might have been saved some time by this report! Hope they fix it someday (though it's not blocking me, and I don't expect it will for some time).

I cannot reproduce this locally, using hangme, with go1.16.5 or go1.16.7, which are the versions we are using in our production builds. There's some other ingredient here, as well. Do you happen to have a recollection of other details of the environment where you saw this fail? OS X version, go version, etc.?

^^ I take that back, right after posting the comment, it failed (go1.16.7).

I've adjusted hangme to run lots of exec's in parallel, and it reproduces much more quickly. I can confirm it does not reproduce with the unused plugin import removed.

I've built a custom Go1.16.7 which panics in plugin.Load and plugin.Plugin#Lookup as well as plugin_lastmoduleinit just to be sure that code wasn't being called. I think that covers everything I could imagine occurring at runtime in this package, and none of it is happening. So, I don't see what could be causing the mere import of plugin to cause this issue.

One difference I can see is that, when importing plugin:

$ otool -L hangme
hangme:
        /usr/lib/libSystem.B.dylib (compatibility version 1.0.0, current version 1292.60.1)

but when not importing plugin:

        /usr/lib/libSystem.B.dylib (compatibility version 0.0.0, current version 0.0.0)

but I don't know what would cause that. I think the #cgo linux LDFLAGS: -ldl in plugin_dlopen.go applies only on linux, so no additional linker flags should be involved to include plugin.

Looking at disassembly of hangme binaries both with and without the import shows that the two cgo functions are included in the binary when plugin is imported, but the linker has discarded all of the go functions in the package.

I tried adding the cgo comment directly in hangme.go, and not importing plugin, but was unable to reproduce. I was also unable to reproduce after removing the cgo comment from plugin_dlopen.go (and stubbing out the calls to it with a panic(..)).

I've narrowed this further, slowing making changes to plugin_dlopen.go. Here's where I'm at:

--- fails.go    2021-12-15 15:56:19.000000000 -0500
+++ works.go    2021-12-15 15:42:11.000000000 -0500
@@ -7,10 +7,6 @@

 package plugin

-/*
- */
-import "C"
-
 import (
        "sync"
 )

or in words, if plugin_dlopen.go has import "C" in it, then there's a good chance that something holds the dyld global lock when the process is fork()'d. If it doesn't have import "C", everything works fine.

What if you have some source file outside of the standard library that does import "C"? I can't see why it would matter whether it is the plugin package that uses cgo or some other package.

For that matter, what if you take your working version, and build with go build -ldflags=-linkmode=external?

I'll try those things. The pattern of

• compatibility version 0.0.0, current version 0.0.0 -> working
• compatibility version 1.0.0, current version 1292.60.1 -> failing

appears to have held up. I'm not sure what that means, though -- any ideas?

The two also seem to be drastically different executables:

dustin.mitchell@bell ~/tmp/hangme [master*] $ dlv exec hangme-succeeds
Type 'help' for list of commands.
(dlv) break main
Command failed: Location "main" ambiguous: runtime.main, main.main…
(dlv) break runtime.main
Breakpoint 1 set at 0x10354d3 for runtime.main() /Users/dustin.mitchell/p/go/src/runtime/proc.go:115
(dlv) c
> runtime.main() /Users/dustin.mitchell/p/go/src/runtime/proc.go:115 (hits goroutine(1):1 total:1) (PC: 0x10354d3)
Warning: debugging optimized function
   110:
   111: // Value to use for signal mask for newly created M's.
   112: var initSigmask sigset
   113:
   114: // The main goroutine.
=> 115: func main() {
   116:         g := getg()
   117:
   118:         // Racectx of m0->g0 is used only as the parent of the main goroutine.
   119:         // It must not be used for anything else.
   120:         g.m.g0.racectx = 0
(dlv) exit
dustin.mitchell@bell ~/tmp/hangme [master*] $ dlv exec hangme-fails
Type 'help' for list of commands.
(dlv) break main
Breakpoint 1 set at 0x4067be0 for main() /Users/dustin.mitchell/p/go/src/runtime/asm_amd64.s:23
(dlv) c
> main() /Users/dustin.mitchell/p/go/src/runtime/asm_amd64.s:23 (hits total:1) (PC: 0x4067be0)
Warning: debugging optimized function
    18:
    19: // main is common startup code for most amd64 systems when using
    20: // external linking. The C startup code will call the symbol "main"
    21: // passing argc and argv in the usual C ABI registers DI and SI.
    22: TEXT main(SB),NOSPLIT,$-8
=>  23:         JMP     runtime·rt0_go(SB)
    24:
    25: // _rt0_amd64_lib is common startup code for most amd64 systems when
    26: // using -buildmode=c-archive or -buildmode=c-shared. The linker will
    27: // arrange to invoke this function as a global constructor (for
    28: // c-archive) or when the shared library is loaded (for c-shared).
(dlv)

Definitions:

• hangme: see the embedded links
• plugin_dlopen: modifications to src/plugin/plugin_dlopen.go
  • "standard xx" = using the go installed via gvm
  • "no import "C"" = entire import "C" and associated comment removed, along with Go code calling those functions
  • "empty import "C"" = import "C" but with the associated comment empty, and all Go code calling those functions removed
• linkmode:
  • external: go build -ldflags=-linkmode=external
  • auto: no go build arguments
• otool -L:
  • "0" means compatibility version 0.0.0, current version 0.0.0
  • "1" means compatibility version 1.0.0, current version 1292.60.1
• result:
  • success = 1000's of forks with no deadlock
  • failure = at least one deadlock observed

From the above chart and reading https://cs.opensource.google/go/go/+/refs/tags/go1.17.5:src/cmd/cgo/doc.go it seems that the otool -L output is reliably distinguishing internal and external linking. We only see the 0.0.0 variant when nothing containing import "C" is imported, and when -linkmode=external isn't passed to go build. I suspect this explains the marked difference in executables in my previous comment.

"Don't call cmd.Start() with external linkage" is not the whole answer, though: the error never occurs with internal linkage, but it does not always occur with external linkage. So what is the additional variable here? From the above table, the rule appears to be

• If plugin is imported, and
• If the plugin package contains an import "C" statement, then
• cmd.Start() hangs intermittently, and
• linking mode is external

Obviously this isn't a great answer! What other variables should I investigate?

I just tried copying the stripped-down plugin module locally and that test was also successful.

I don't know what is happening here. Just a note that in the linker there is special handling of the case in which the plugin case is imported and uses cgo: https://go.dev/src/cmd/link/internal/ld/lib.go?#L551. I don't see any obvious reason why that would cause a hang, though.

Oh, thanks! I was grepping for "plugin" but hadn't found that yet. That explains why this behavior is tied to the plugin package, and not reproducible with a local copy of that package.

Referring back to earlier in this issue, the hang is because the dyld global lock is held when fork() is called, so trying to resolve a libc symbol in the child results in a deadlock.

At this point, I think that's because of something that link is doing when CanUsePlugins() and iscgo, presumably building a binary that interacts differently with dyld at runtime. Do you know of folks familiar with the linker that might have some intuition about that connection?

CC @cherrymui @thanm

(just confirmed this is still an issue with go1.17.5 and go1.18beta1)

Thanks. I can reproduce with Go tip locally as well. I'll look into it.

The difference for if plugin is used is that it pass -Wl,-flat_namespace to the darwin linker https://cs.opensource.google/go/go/+/master:src/cmd/link/internal/ld/lib.go;l=1272 , which is necessary to support plugins.

If I remove the import of plugin package but pass -ldflags="-linkmode=external -extldflags=-Wl,-flat_namespace", I can still reproduce.

It seems it hangs if only the parent uses plugin. I can reproduce if hangme just shells out /usr/bin/true.

It does not hang if only the child uses plugin, but parent does not.

With async preemption disabled it can still hang, albeit with seemingly lower frequency. So #41702 or any workaround related to that probably would not help.

Change https://golang.org/cl/372798 mentions this issue: cmd/link: force eager binding when using plugins on darwin

As mentioned above (thanks @djmitche !) this may be related to the dynamic linker resolving bindings. Forcing early binding resolution (-Wl,-bind_at_load) seems to make it no longer hang. At least I can no longer reproduce. I sent a CL for the workaround.

I'll look further into it to see how exactly this happens and if it is a bug of the dynamic linker.

From dyld source

	// <rdar://problem/8663923> race condition with flat-namespace lazy binding
	if ( this->usesTwoLevelNameSpace() ) {
		// two-level namespace lookup does not require lock because dependents can't be unloaded before this image
	}
	else {
		// acquire dyld global lock
		if ( lock != NULL )
			lock();
	}

So it is indeed that the use of flat namespace makes it acquire the global lock (which could deadlock if we're forking while the lock is held and the child needs to resolve a binding before exec). Resolve bindings ahead of time seems the right workaround to me.

Another possibility is to just resolve the set of symbols that the child may use before exec (e.g. by making dummy syscalls before forking). Probably not worth it.

Awesome, what teamwork! Knowing what's wrong, and that there's a fix in a future Go, means we can work around it for the time being.

@gopherbot please backport this to previous releases. This can cause program that uses plugins to hang on macOS.

Backport issue(s) opened: #50245 (for 1.16), #50246 (for 1.17).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://golang.org/wiki/MinorReleases.

Change https://golang.org/cl/373094 mentions this issue: [release-branch.go1.17] cmd/link: force eager binding when using plugins on darwin

Change https://golang.org/cl/373095 mentions this issue: [release-branch.go1.16] cmd/link: force eager binding when using plugins on darwin