CC @thanm @mknyszek

Does this reproduce with Go 1.18?

It's hard to tell what's going on here. The second panic is from a signal handler presumably invoked to crash the program, and is caused by the signal handler apparently not being set up right (or something is corrupted). It would be nice to know what's going on in goroutine 1 and setting GOTRACEBACK=crash (or calling runtime/debug.SetTraceback("crash")) might be enough to reveal that.

At first glance, I'm really not sure. More example crashes and more detail via GOTRACEBACK=crash would help. A core dump would be really useful too if you're willing to share, but there may be PII issues.

The only signal handler we have in our code is on this line in the traceback, where it's blocking on waiting for a signal. It's possible there is another signal handler being installed by a third party package, but I can't see it in any of the tracebacks provided.

I will enable GOTRACEBACK=crash

But that said, doesn't the fact that we're getting to this state indicate a corruption (somehow) of the Go runtime?

More information from one of our users:

hey, I have a confusing bug to report. running a hermit-managed command, I see a deadlock in the hermit process when attempting its syscall.Exec operation. attaching a debugger, the goroutine running exec seems to be stuck waiting on pre-empting signals [src]. I'm using go1.17.7 (managed by Hermit) and hermit itself is v0.18.3.

I mean signal handler in the Unix sense of a bunch of code that gets injected onto an OS thread when a signal gets delivered, not something that handles incoming signals in a Go application. I do mean to say that data in the runtime is corrupted. The signal handler runs on the signal stack which I believe "looks" like a g0 stack to most checks.

The exec note is interesting. #52086 might be related (also darwin/amd64). What macOS version are you running on? This may be some bad interaction between Go and new macOS versions, or even a bug in the OS. It certainly wouldn't be the first time.

The note about exec also made me recall #41702. Not sure if that's related exactly, but it may be worth trying to run your application with GODEBUG=asyncpreemptoff=1 which will disable preemption signals. Whether that hangs or not it will help narrow the problem space a bit.

Probing our GitHub issues further, does hermit use the plugin package? (See #38824, which we in theory fixed in the last release, and backported to 1.17.)

Will GODEBUG=asyncpreemptoff=1 take effect if I set it from within the executable itself, or only from outside?

Probing further, does hermit use the plugin package? (See #38824, which we in theory fixed in the last release, and backported to 1.17.)

No, not Hermit itself (though I can't exclude some imported package I guess).

FWIW I think I have also seen this behaviour on darwin/arm64 as well.

Will GODEBUG=asyncpreemptoff=1 take effect if I set it from within the executable itself, or only from outside?

It's used at runtime initialization, so it needs to be set from the outside. We have a few outstanding issues about making GODEBUG settable from inside the program, but there hasn't been any movement on them.

No, not Hermit itself (though I can't exclude some imported package I guess).

Got it. Apparently #38824 could happen even if plugin was just imported and not used. (i.e. import ( _ "plugin" )). Could you check if plugin is transitively imported at any point? I think go mod why plugin is what you want but I'm not 100% sure how that interacts with standard library packages.

FWIW I think I have also seen this behaviour on darwin/arm64 as well.

Good to know. That correlates more strongly with this being either an OS bug, or a bad interaction with new OS versions, or an old bug on our end that really wasn't truly fixed. It could be something new, but I'm not sure we've made any major changes to how macOS syscalls work, or how we call exec on macOS (other than to fix bugs).

🐚 ~/Projects/hermit $ go mod why -m plugin
# plugin
(main module does not need module plugin)

Also FWIW (and my recollection is a bit hazy at this point), but I think I only started seeing this after upgrading from Go 1.16 to Go 1.17

I also tried nm hermit | grep plugin just in case, which returned nothing.

Further anecdata for the Darwin-specific hypothesis: we use hermit in every single CI job running on linux/amd64 , across 100's of repo's and I've never seen or heard of a report of it wedging there.

I was able to dump a stack trace from a wedged Hermit process with GOTRACEBACK=crash set using CTRL-\. The output is in a Github gist: [omitted]

Edit: Sorry, the wrong process's stack was dumped.

@bwester Thanks. What that stack dump shows is an instance of #23019. That is, a known problem when waiting for a child process that has started a grandchild process that is holding standard output/standard error open.

Hmmm, are you sure it's the same issue? We are not waiting for child processes (in our Go code at least), we're calling syscall.Exec() directly.

That's on the main path only though, we do have some other calls to exec.Command() elsewhere. Let me take a look.

Actually I don't see any hermit paths in that traceback (unlike in the initial dump), so perhaps that was somehow from the sub-process that Hermit was executing.

Confirmed that this is a stack trace from a wrapping Go executable (mockery), apologies. We'll try to get one from Hermit itself.

Sorry for the earlier mistake in posting the wrong output. Full stack trace info from the correct process is here: deadlock-hermit-0.18.3-go-db7183ccf9.txt.

This time, I was able to reproduce using a locally-built Go toolchain from commit db7183c (tip as of 2022-04-08) to build Hermit at v0.18.3 (through an internal wrapper). Interestingly, I was only able to reproduce when compiling Hermit with CGO_ENABLED=0.

I was able to use git bisect to determine when this deadlock was introduce to the Go toolchain. I was able to reproduce the deadlock at commit 05739d6 (first released in go1.14.11 and go1.15.4) but not before. That commit, "runtime: wait for preemption signals before syscall.Exec" is exactly what I see in my stack trace (linked above): the process is waiting for pending preemption signals to be received, but apparently they never come.

Thanks for tracking that down.

Why is your code calling syscall.Exec rather than using the os/exec package to start a child process? I mean, obviously syscall.Exec is supposed to work, but it's rarely used.

In delve, when looking at a wedged program, what is the value of runtime.pendingPreemptSignals?

Why is your code calling syscall.Exec

This deadlock was discovered in Hermit, which is a virtual environment for tools. It is invoked as a symlinked shim and execs the real command's binary. exec is used to keep Hermit itself out of the process tree.

Though it was discovered in Hermit, I got the behavior to reproduce in a minimal program. Its source code is here: exec-deadlock.go. The one signal handler seems to be needed. To reproduce, compile it with CGO_ENABLED=0 and run the resulting binary in a loop. On my 2018 MacBook Pro (macOS 11.6.5), it should produce a deadlock within 100,000 iterations.

I also have a core dump (produced by dlv) from an execution of this program that has locked up. I can't post it as a gist—it's 2.3 GiB—but I can answer questions about it. A stack trace from this core is here: exec-deadlock.stack.

In delve, when looking at a wedged program, what is the value of runtime.pendingPreemptSignals?

From the core image:

(dlv) print runtime.pendingPreemptSignals
1

Also, setting GODEBUG=asyncpreemptoff=1 makes the deadlock non-reproducible for me in my minimal program.

Thanks for the simpler recreator.

Some notes on a deadlocked instance:

pendingPreemptSignals is 1.

signalPending is 1 for one M, specifically m0. I think this M may be parked in stoplockedm.

The program is creating a new M. The new M has been added to the allm list, but newm1 is blocked trying to acquire execLock, so the new thread has not yet been created.

The sysmon thread has called retake which has decided to preempt a thread. The preemptM function is blocked trying to acquire execLock. It is possible that retake is trying to preempt the thread due to the deadlock, though. That is, this may be an effect rather than a cause.

OK, I see one possible problem. The goroutine started by ensureSigM blocks many signals including the preemption signal. If something wants to preempt it, nothing may ever decrement pendingPreemptSignals. I'll test a fix.

OK, sending a fix. Thanks.

Change https://go.dev/cl/400315 mentions this issue: runtime: don't block preemption signal in new M's or ensureSigM

@gopherbot Please open backport issues

This bug can cause rare cases of deadlock on macOS in programs that use syscall.Exec. The fix is simple.

Backport issue(s) opened: #52374 (for 1.17), #52375 (for 1.18).

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

@ianlancetaylor Nice catch! I left a comment on your CL. Paraphrasing that comment here for visibility:

Basically, I'm wondering if this is a more general problem.

For instance, should Go programs still be able to work if every thread had sigPreempt blocked? Ultimately asynchronous preemption is an optimization. Maybe there's no other way to implement the pendingPreemptSignals functionality, so enabling sigPreempt on all Go threads is fundamentally necessary. But I figured I'd ask.

The pendingPreemptSignals count is horrible and I would certainly prefer a different approach. But I haven't been able to think of one. As noted in #41702 it's working around a macOS bug.

Change https://go.dev/cl/400317 mentions this issue: [release-branch.go1.17] runtime: don't block preemption signal in new M's or ensureSigM

Change https://go.dev/cl/400318 mentions this issue: [release-branch.go1.18] runtime: don't block preemption signal in new M's or ensureSigM

Thanks @ianlancetaylor, much appreciated.

And thanks to @bwester for digging in and coming up with a reproducible test case.