runtime: macOS-only segfault on 1.14+ with "split stack overflow" #39079
Comments
ALTree
added
the
NeedsInvestigation
|
It'll be hard to debug this if it's essentially linking in a big blob of non-Go code. But maybe looking at the stack-traces can give some hint. |
|
Looking at those failures, the first thing that jumps out at me is that the |
|
Oh some other aspects I should mention is that So far the best I can surmise is that this is crashing when GC is happening. The call to I'm currently trying to capture a crash in lldb, but it's not being too too successful. I've tried capturing a few core dumps but they're not proving too useful. The core dumps show all threads blocked in You mention there's print-debugging that can be added, do you mean in the runtime? If so are there logs/etc I could try to add to help debug this? |
That makes sense to me. I imagine that given that the file you have above doesn't do much in the Go world that the goroutine calling into cgo has no reason to be preempted, which is where the failures are popping up (
I think I take that back. I was going to suggest putting It still may be worth putting in Does the JIT'd code make use of TLS at all (or the Rust code, even)? The value being clobbered is accessible via an offset from a pointer in a TLS slot. Given that the offset is the same for Go 1.13, I'd be surprised if this is the case, but it is an idea. Given that this is involves the scheduler, one other thing to try is |
|
RE: that last idea about TLS, @cherrymui just informed me that we use a fixed offset for the TLS on Darwin, so that's unlikely to have changed either. |
|
Also the This is assuming that my hypothesis is true that the value in |
|
To make sure I understand, do you mean adding
The JIT'd code doesn't use TLS, but the Rust code does. We use the equivalent of
Interesting! Setting that environment variable though I still see a crash.
|
Ah, I meant the runtime. I'm currently running it in a loop, so I don't mind doing the instrumentation. I'll see if I find anything by printing info.
Yeah OK, then it's probably not that. You mentioned earlier that the JIT'd code needs to run to reproduce the issue, right?
Got it. Well, it doesn't discount the changes around it aren't involved (directly or indirectly), but definitely means that the asynchronous preemption itself isn't an issue here. |
|
A small amount of JIT code is executed inside of Also, to confirm, are you able to reproduce the crash on your end? I still feel bad about not being able to minimize a giant wad of foreign code, but if you can't even reproduce that's even worse! |
|
I can indeed reproduce! Sometimes it fails with a plain-old segfault, sometimes with an illegal instruction failure, and sometimes with one of the "stack split" failures you mentioned in the original post. |
|
Just fyi, this seems to be happening on 1.14.4 as well. At least, in the wasmtime-go repository. I haven't tested this specific repro. |
ianlancetaylor
changed the title
|
This is almost certainly some kind of memory corruption, perhaps due to a race condition. I haven't seen anybody else reporting similar errors. Given the information we have so far, I would not guess that this is a bug in Go. |
This was spelled wrong. Try |
|
Oh thanks for the tip @aclements! Using that env var ( package main
// #include <assert.h>
// #include <signal.h>
// #include <sys/mman.h>
//
// #define ALT_STACK_SIZE (16 * 4096)
//
// void my_run() {
// void *stack = mmap(NULL, ALT_STACK_SIZE, PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_ANON, -1, 0);
// assert(stack != MAP_FAILED);
//
// stack_t new_stack;
// new_stack.ss_sp = stack;
// new_stack.ss_flags = 0;
// new_stack.ss_size = ALT_STACK_SIZE;
// int r = sigaltstack(&new_stack, NULL);
// assert(r == 0);
// }
import "C"
import "runtime"
func main() {
C.my_run()
runtime.GC()
}This program will segfault like original one when run as: $ go build -o binary
$ while true; do ./binary || break; doneThis one can take quite some time to reproduce, so I typically run that in a few windows to get it to fail quicker. I've also seen that mixing in code like seen in preempt.go can cause it to more reliably reproduce. It does seems related to async scheduling in any case. Some example crash logs I've seen are here. So at least on macOS this seems related to switching the sigaltstack. We do this in wasmtime currently because we execute our SIGSEGV handler on the sigaltstack, but we require the stack to be big enough to run the handler. Currently that stack size is set to 64kb, and it looks like the default Go one is 8kb, so the check to see if a previous sigaltstack is big enough fails and we allocate a new one. Is it expected that allocating a bigger sigaltstack causes issues here? Is this something that foreign code isn't allowed to do? |
|
@alexcrichton Oops, very sorry about the wrong environment variable there. Glad that it narrowed down the issue, though (and thanks for narrowing down the reproducer even further!). |
|
/cc @ianlancetaylor @bcmills , our signal experts. Thanks for narrowing it down to such a small repro! Go allocates a 32 KiB signal stack, but that of course suggests that a 64 KiB signal stack should be fine. I could see there potentially being a problem if the |
|
@mknyszek oh no worries! I'm just glad I was able to reduce it to a much more bite-sized chunk. @aclements after running a few million times I wasn't able to reproduce without the call to |
|
What version of macOS was this observed on? |
|
Oh oops sorry should have mentioned that in the original report as well. I'm on version 10.15.5 (19F101) |
|
That said, this example in #39079 (comment) does not look safe in general to me. If there is already an alternate signal stack in place, then something somewhere (in this case, presumably the Go runtime) allocated that signal stack, and may expect to use So I would expect that a program that does this sort of runtime.LockOSThread()
s := C.replaceAltStack()
defer func() {
C.restoreAltStack(s)
runtime.UnlockOSThread()
}()
…So, another question: does the bug still reproduce if you execute |
|
As predicted adding I also understand how modifying the sigaltstack in general is not exactly the safest thing to do, but it seems like "hygienic" usage of sigaltstack would be to grow it if necessary and otherwise not modify it. That's what wasmtime is trying to do (grow it to fit its needs), and it's expected that if anything else configured it then it would take care of deallocating it on its own or would otherwise. Basically at this point I don't understand why this would be invalid. The specific case wasmtime needs is to grow the sigaltstack to meet its needs. Is this incompatible with the Go runtime? If so, why? Comments like this seem to indicate that it's intended to be handled? |
|
The runtime is supposed to do the right thing if a C thread changes the alternate signal stack. As @alexcrichton says, Clearly it isn't working, though. The stack trace suggests that at least sometimes the stack guard is not being updated to correctly match the alternate signal stack installed by the C code. I didn't audit all the code, but it looks like the failure is the first function called that checks the stack guard. Does it look like the code in |
|
Change https://golang.org/cl/238020 mentions this issue: |
|
@alexcrichton does CL https://golang.org/cl/238020 help? Thanks. |
|
@cherrymui thanks for the cc! Locally that appears to fix the issue for me, yes. Using that toolchain against the entire https://github.com/bytecodealliance/wasmtime-go repository's test (which originally segfaulted and currently segfault on 1.14.4 periodically) the issue also appears fixed. I no longer get segfaults there either. |
|
@alexcrichton thanks for confirming! |
|
FYI, This CL failed on mips64le with https://build.golang.org/log/cd5213f231841de332cad8fced10d6cbf6ca5ac9 |
|
@mengzhuo It doesn't seem related to that CL. It could be a flake. It seems a separate issue to me. |
|
Any chance this gets backported to 1.14? It's a crash. @cherrymui |
|
@gopherbot please consider this for backport in 1.14. The issue can cause runtime crashes on MacOS, and there doesn't seem to be any reasonable workaround. |
|
Backport issue(s) opened: #41991 (for 1.14). 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/262557 mentions this issue: |
…Stack When a signal is received, the runtime probes whether an alternate signal stack is set, if so, adjust gsignal's stack to point to the alternate signal stack. This is done in adjustSignalStack, which calls sigaltstack "syscall", which is a libc call on darwin through asmcgocall. asmcgocall decides whether to do stack switch based on whether we're running on g0 stack, gsignal stack, or regular g stack. If g is not set to gsignal, asmcgocall may make wrong decision. Set g first. adjustSignalStack is recursively nosplit, so it is okay that temporarily gsignal.stack doesn't match the stack we're running on. Updates #39079. Fixes #41991. Change-Id: I59b2c5dc08c3c951f1098fff038bf2e06d7ca055 Reviewed-on: https://go-review.googlesource.com/c/go/+/238020 Run-TryBot: Cherry Zhang <[email protected]> TryBot-Result: Gobot Gobot <[email protected]> Reviewed-by: Ian Lance Taylor <[email protected]> (cherry picked from commit d286e61) Reviewed-on: https://go-review.googlesource.com/c/go/+/262557 Trust: Cherry Zhang <[email protected]> TryBot-Result: Go Bot <[email protected]> Reviewed-by: Austin Clements <[email protected]>
The fix for golang/go#39079 has been backported to 1.14 as of version 1.14.11 so the macOS warning can be clarified and the build matrix can be updated.
The fix for golang/go#39079 has been backported to 1.14 as of version 1.14.11 so the macOS warning can be clarified and the build matrix can be updated.
|
Not sure if anyone else is experiencing this, but we are still seing a Go1.14+ only, MacOS-only deadlock and high CPU usage caused by |
|
@albertvaka Since this was about a segfault, which is fixed, please open a new issue about a deadlock you're seeing, so it can be tracked separately. In the description please also include a reference to this issue. Thanks. |
What version of Go are you using (
go version)?Does this issue reproduce with the latest release?
Yes
What operating system and processor architecture are you using (
go env)?go envOutputWhat did you do?
I created a local
main.golike so:Next I downloaded the latest wasmtime release and extracted it locally:
$ curl -L https://github.com/bytecodealliance/wasmtime/releases/download/dev/wasmtime-dev-x86_64-macos-c-api.tar.xz | tar xJf - --strip-components=1Next I compiled the local module:
Finally I ran the binary in an infinite loop:
What did you expect to see?
No segfault. Or more specifically for this to basically run infinitely producing no output.
What did you see instead?
Instead I see sporadic crashes. Some I've seen are:
fatal error: runtime: split stack overflowruntime: newstack sp=0x5791928 stack=[0xc000050000, 0xc000050800] morebuf={pc:0x4015580 sp:0xc000050690 lr:0x0} sched={pc:0x4053df2 sp:0x5791930 lr:0x0 ctxt:0x0} runtime: gp=0xc000000180, goid=1, gp->status=0x2 runtime: split stack overflow: 0x5791928 < 0xc000050000 fatal error: runtime: split stack overflowruntime stack:
runtime.throw(0x4966544, 0x1d)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/panic.go:1116 +0x72
runtime.newstack()
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/stack.go:1002 +0x83e
runtime.morestack()
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/asm_amd64.s:449 +0x8f
goroutine 1 [running]:
runtime.asmcgocall(0x4056290, 0x5791990)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/asm_amd64.s:640 +0x42 fp=0x5791938 sp=0x5791930 pc=0x4053df2
runtime.libcCall(0x10, 0x5791900, 0x0)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/sys_darwin.go:46 +0x6c fp=0x5791968 sp=0x5791938 pc=0x404471c
runtime.sighandler(0x4b37d00, 0x5791ee0, 0x5791f48, 0x4b37d00)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/signal_unix.go:583 +0x143 fp=0x57919e8 sp=0x5791968 pc=0x403cf03
runtime.sigtrampgo(0x10, 0x5791ee0, 0x5791f48)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/signal_unix.go:453 +0x1dc fp=0x5791a60 sp=0x57919e8 pc=0x403caac
runtime: unexpected return pc for runtime.sigtramp called from 0x5791ee0
stack: frame={sp:0x5791a60, fp:0x5791a70} stack=[0xc000050000,0xc000050800)
runtime.sigtramp(0x5791f48, 0x5791f48, 0xeaa614b3296df86d, 0x0, 0x4973920, 0x0, 0x5791ab0, 0x7fff6f847613, 0x7ffeefbff5e0, 0x0, ...)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/sys_darwin_amd64.s:229 +0x33 fp=0x5791a70 sp=0x5791a60 pc=0x4056343
fatal error: unexpected signal during runtime executionfatal error: runtime: stack split at bad timeruntime: newstack at runtime.goPanicIndex+0xa9 sp=0x5791960 stack=[0xc000050000, 0xc000050800] morebuf={pc:0x403d560 sp:0x5791968 lr:0x0} sched={pc:0x40283b9 sp:0x5791960 lr:0x0 ctxt:0x0} os/signal.signal_ignored(...) /usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/sigqueue.go:265 runtime.sighandler(0xc000000180, 0x5791ee0, 0x5791f48, 0xc000000180) /usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/signal_unix.go:588 +0x7a0 fp=0x57919e8 sp=0x5791968 pc=0x403d560 runtime.sigtrampgo(0x10, 0x5791ee0, 0x5791f48) /usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/signal_unix.go:453 +0x1dc fp=0x5791a60 sp=0x57919e8 pc=0x403caac runtime: unexpected return pc for runtime.sigtramp called from 0x5791ee0 stack: frame={sp:0x5791a60, fp:0x5791a70} stack=[0xc000050000,0xc000050800)runtime.sigtramp(0x5791f48, 0x5791f48, 0x7e0fb3c827040376, 0x0, 0x4973920, 0x0, 0x5791ab0, 0x7fff6f847613, 0xc000050640, 0x0, ...)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/sys_darwin_amd64.s:229 +0x33 fp=0x5791a70 sp=0x5791a60 pc=0x4056343
fatal error: runtime: stack split at bad time
runtime stack:
runtime.throw(0x4966d45, 0x20)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/panic.go:1116 +0x72 fp=0x7ffeefbff760 sp=0x7ffeefbff730 pc=0x402a5a2
runtime.newstack()
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/stack.go:951 +0xb42 fp=0x7ffeefbff8f0 sp=0x7ffeefbff760 pc=0x4041352
runtime.morestack()
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/asm_amd64.s:449 +0x8f fp=0x7ffeefbff8f8 sp=0x7ffeefbff8f0 pc=0x405271f
goroutine 1 [syscall]:
os/signal.signal_ignored(...)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/sigqueue.go:265
runtime.sighandler(0xc000000180, 0x5791ee0, 0x5791f48, 0xc000000180)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/signal_unix.go:588 +0x7a0 fp=0x57919e8 sp=0x5791968 pc=0x403d560
runtime.sigtrampgo(0x10, 0x5791ee0, 0x5791f48)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/signal_unix.go:453 +0x1dc fp=0x5791a60 sp=0x57919e8 pc=0x403caac
runtime: unexpected return pc for runtime.sigtramp called from 0x5791ee0
stack: frame={sp:0x5791a60, fp:0x5791a70} stack=[0xc000050000,0xc000050800)
runtime.sigtramp(0x5791f48, 0x5791f48, 0x7e0fb3c827040376, 0x0, 0x4973920, 0x0, 0x5791ab0, 0x7fff6f847613, 0xc000050640, 0x0, ...)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/sys_darwin_amd64.s:229 +0x33 fp=0x5791a70 sp=0x5791a60 pc=0x4056343
goroutine 2 [force gc (idle)]:
runtime.gopark(0x4968c50, 0x4b37870, 0x1411, 0x1)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/proc.go:304 +0xe0 fp=0xc000050fb0 sp=0xc000050f90 pc=0x402cff0
runtime.goparkunlock(...)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/proc.go:310
runtime.forcegchelper()
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/proc.go:253 +0xb7 fp=0xc000050fe0 sp=0xc000050fb0 pc=0x402cea7
runtime.goexit()
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000050fe8 sp=0xc000050fe0 pc=0x40546b1
created by runtime.init.6
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/proc.go:242 +0x35
goroutine 3 [GC sweep wait]:
runtime.gopark(0x4968c50, 0x4b379a0, 0x140c, 0x1)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/proc.go:304 +0xe0 fp=0xc0000517a8 sp=0xc000051788 pc=0x402cff0
runtime.goparkunlock(...)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/proc.go:310
runtime.bgsweep(0xc000076000)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/mgcsweep.go:70 +0x9c fp=0xc0000517d8 sp=0xc0000517a8 pc=0x401c09c
runtime.goexit()
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000517e0 sp=0xc0000517d8 pc=0x40546b1
created by runtime.gcenable
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/mgc.go:214 +0x5c
goroutine 4 [GC scavenge wait]:
runtime.gopark(0x4968c50, 0x4b37960, 0x140d, 0x1)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/proc.go:304 +0xe0 fp=0xc000051f78 sp=0xc000051f58 pc=0x402cff0
runtime.goparkunlock(...)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/proc.go:310
runtime.bgscavenge(0xc000076000)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/mgcscavenge.go:237 +0xd0 fp=0xc000051fd8 sp=0xc000051f78 pc=0x401a690
runtime.goexit()
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000051fe0 sp=0xc000051fd8 pc=0x40546b1
created by runtime.gcenable
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/mgc.go:215 +0x7e
goroutine 18 [GC worker (idle)]:
runtime.gopark(0x4968ae8, 0xc0000140b0, 0x1418, 0x0)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/proc.go:304 +0xe0 fp=0xc00004c760 sp=0xc00004c740 pc=0x402cff0
runtime.gcBgMarkWorker(0xc000024000)
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/mgc.go:1873 +0xff fp=0xc00004c7d8 sp=0xc00004c760 pc=0x40156bf
runtime.goexit()
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc00004c7e0 sp=0xc00004c7d8 pc=0x40546b1
created by runtime.gcBgMarkStartWorkers
/usr/local/Cellar/go/1.14.2_1/libexec/src/runtime/mgc.go:1821 +0x77
This was originally reported upstream in bytecodealliance/wasmtime-go#10, and we've been trying to narrow it down. With some investigation we found out that Go 1.13 runs this code successfully. We've also got the same code running succesfully on other platforms.
I realize though that this isn't the best bug report, unfortunately. The native library, wasmtime, is a pretty large project and is a giant wad of compiled Rust code. I've tried replacing it with a trivial C implementation to remove the dependency, but then the crash goes away. It seems that the bug here is related to something that the native binary is doing. I'm pretty certain that the fault does not lie in the native binary (e.g. no segfault or out of bounds writes or anything like that), but as with all native code I can't really entirely rule it out. I'm opening this because at this point we've at least narrowed it down to a regression between Go versions, and I'm hoping that folks more knowledgeable with changes could help out?
Is there a way we could help to reduce this further to a bite-sized test case? Or would it be helpful to perhaps bisect the Go release to try to find a revision which caused the segfault to appear here? I'm happy to help out in reducing this further!
The text was updated successfully, but these errors were encountered: