cc @golang/runtime

Hi @klauspost, others will likely have more useful comments, but two initial questions that spring to mind — are you able to gather exact kernel versions for different machines where this is observed, and is there an opportunity to try some triage debug settings (for example, along the lines of those outlined in #58212 (comment))?

hi go Team,

thanks for looking into this, I've able to reproduce it (rarely), here is what kernel used right now:

/ $ uname -r
5.4.0-1113-aws-fips
/ $ cat /etc/os-release
NAME="Alpine Linux"
ID=alpine
VERSION_ID=3.15.11
PRETTY_NAME="Alpine Linux v3.15"
HOME_URL="https://alpinelinux.org/"
BUG_REPORT_URL="https://bugs.alpinelinux.org/"
/ $ cat /proc/version
Linux version 5.4.0-1113-aws-fips (buildd@lcy02-amd64-015) (gcc version 9.4.0 (Ubuntu 9.4.0-1ubuntu1~20.04.2)) #123+fips1-Ubuntu SMP Thu Oct 19 16:21:22 UTC 2023

Customer 1: kernelVersion: 4.14.111-1.el7.centos.x86_64 - centos/7.6.1810
Customer 3: kernelVersion: 4.18.0-425.13.1.el8_7.x86_64 rhel/8.7
Don't have the information for the final customer.

CGO disabled for build FWIW.

Updated disassembly. Was accidentally Windows compiled. Now shows Linux.

Kernel: 5.15.0-1051-aws #56~20.04.1-Ubuntu SMP Tue Nov 28 15:43:31 UTC 2023 x86_64 GNU/Linux
Go: go1.21.3

Two things where I might make mistakes at:

One thing I did encounter was that races aren't instrumented in assembly; so if you have a data-race that may cause some pain. Annotate your assembly (or anything that might call assembly in stdlib) with runtime.RaceReadRange or runtime.RaceWriteRange. Alternatively, replace the code with equivalent Go code.

The other is that assembly code might write outside of it's bounds -- in which case, write exhaustive tests across some range of data sizes / offsets, with memory protected byte slices.

@egonelbre As I wrote, I am pretty sure this isn't a buffer write issue. I have fuzz tests in place that already checks out-of-buffer writes - allocating a bigger buffer, writing random data there - and then truncates the capacity in the buffer given to compression as destination. And after the compression checking if the data after the buffer has been touched.

Since it (to me at least) appears to be a stack issue, I don't think there are races going on, since of course stacks are never shared. I do run all tests through the race detector as part of CI tests. However instrumenting sounds like a good idea anyway - do you have any doc/examples? Google doesn't really turn up anything useful.

Here's a quick demo https://github.com/egonelbre/compress/commit/c7df670870dc509127572281d79075a7faac8f13. Instrumenting around buffers and pools is also a good idea.

I added GODEBUG="gccheckmark=1,gcshrinkstackoff=1,asyncpreemptoff=1" and we have not had a panic in >24h. We used to see at least a couple per hour.

@dctrwatson, that's great, thanks for trying that! What do you think about trying those one at a time, maybe in the reverse order they are listed in #58212 (comment)?

GODEBUG="asyncpreemptoff=1" resulted in multiple panics of:

fatal error: workbuf is empty
fatal: bad g in signal handler

Switching to next flag

So looking at the generated assembly one things that sticks out is that SP and BP is kept as-is, even though compiled functions generate:

		PUSHQ	BP
		MOVQ	SP, BP
		SUBQ	$56, SP
...
		ADDQ	$56, SP
		POPQ	BP
		RET

Since I don't know anything about the GC preemption it is hard for me to see if this is a problem with my code or the runtime.

So looking at the generated assembly one things that sticks out is that SP and BP is kept as-is

What generated assembly, in which function? Thanks.

@cherrymui The avo generated assembly - example - meaning the assembly being called and presumably pre-empted.

Oh, that is fine. The Go assembler itself will insert prologue and epilogue to adjust SP and BP, as long as the frame size (589848 in TEXT ·encodeBetterBlockAsm(SB), $589848-56) is declared correctly. These instructions don't need to (and should not) be written out in assembly source code. If you look at the generated binary (e.g. using go tool objdump), it will have those instructions.

Then unfortunately that isn't where the problem lies.

GODEBUG=gcshrinkstackoff=1 hasn't had any panics in 20h

I'll switch to gccheckmark=1 to confirm it has no effect (as-in, still get panics)

Well that was fast... got one already with GODEBUG=gccheckmark=1

unexpected fault address 0x0
fatal error: fault

Interesting finding!

I see that copystack says https://go.googlesource.com/go/+/adec22b9f7c9d9cfb95ff6af1c63ec489d6e9bb8/src/runtime/stack.go#853

Caller must have changed gp status to Gcopystack.

But I see here that we are not changing the status to Gcopystack https://go.googlesource.com/go/+/adec22b9f7c9d9cfb95ff6af1c63ec489d6e9bb8/src/runtime/stack.go#1214

Can it be the case? If it is not in _Gcopystack the concurrent gc might try to scan the stack while we are doing the copy?

cc @cherrymui

@mauri870 Thanks for catching that. I agree that it seems inconsistent with the comment. But I don't obviously see what is wrong. The G (and its stack) is either owned by the scan bit, or it is the running G itself. So other goroutines shouldn't be doing anything with its stack. Also, #64781 (comment) seems to suggest that stack shrinking isn't the cause. That said, if you'd like, you can try if this patch makes any difference.

diff --git a/src/runtime/stack.go b/src/runtime/stack.go
index 61cd0a0fdd..6d4c6ea485 100644
--- a/src/runtime/stack.go
+++ b/src/runtime/stack.go
@@ -1161,6 +1161,7 @@ func shrinkstack(gp *g) {
 	if gp.stack.lo == 0 {
 		throw("missing stack in shrinkstack")
 	}
+	var selfShrink bool
 	if s := readgstatus(gp); s&_Gscan == 0 {
 		// We don't own the stack via _Gscan. We could still
 		// own it if this is our own user G and we're on the
@@ -1169,6 +1170,7 @@ func shrinkstack(gp *g) {
 			// We don't own the stack.
 			throw("bad status in shrinkstack")
 		}
+		selfShrink = true
 	}
 	if !isShrinkStackSafe(gp) {
 		throw("shrinkstack at bad time")
@@ -1211,7 +1213,13 @@ func shrinkstack(gp *g) {
 		print("shrinking stack ", oldsize, "->", newsize, "\n")
 	}
 
+	if selfShrink {
+		casgstatus(gp, _Grunning, _Gcopystack)
+	}
 	copystack(gp, newsize)
+	if selfShrink {
+		casgstatus(gp, _Gcopystack, _Grunning)
+	}
 }
 
 // freeStackSpans frees unused stack spans at the end of GC.

From what I understood, setting GODEBUG=gcshrinkstackoff=1 did fix the issue, so taking this short path where we don't call copystack seemed to prevent the stack corruption.

This paired with the comment that we should be changing the status to _Gcopystack raised some eyebrows.

Plus this comment in the other usage of copystack:

// The concurrent GC will not scan the stack while we are doing the copy since
// the gp is in a Gcopystack status.

Okay, I misread the comment #64781 (comment) -- it is gccheckmark, not gcshrinkstackoff... Then try if that patch makes any difference. Thanks.

@dctrwatson If you are able to, can you compile your binary with a custom Go toolchain with cherrymui's patch and then run the program without any GODEBUG env set to see if that fixes the issue? Thanks

@dctrwatson As far as I can tell the workflow would be:

1. Locate go installation folder (for example via whereis go)
2. Go to ../src/runtime/stack.go and apply the patch.
3. Recompile the crashing application.
4. Deploy application.

AFAICT it shouldn't be necessary to recompile the go compiler, but someone can correct me if I am wrong.

You're right that there is no need to recompile the Go compiler. You can also find your Go installation by running go env GOROOT.

I'm still not sure what could go wrong. For the concurrent GC to scan its stack, it needs to preempt the goroutine. But if we're copying the stack, we cannot be preempted until the copying is done.

I don't know if it is relevant. At least 2/3 (and probably also the third) of our customers that have dual-CPU systems - it may however not statistically significant, since probably about 40% of our customers use that.

It seems to be somewhat specific for certain machines to be "vulnerable" to this. If it was something that would happen on all installs, I'd say it would happen a lot more than what we are observing.

If you're OK with log spew in the name of debugging, it might also be worthwhile to set stackDebug = 1 in src/runtime/stack.go. We may also want to patch in a few lines that prints the top frames of the stack in the stack shrinking case, before the shrink happens.

If this is some stack-shrink-at-a-bad-time bug then we should at least be able to identify which stack shrink messed things up. And if we can get exactly when that stack shrink happened (i.e. what the stack looked like at the time of the shrink), then that might give us a smoking gun.

For this patch #64781 (comment), go1.19 https://github.com/golang/go/blob/release-branch.go1.19/src/runtime/stack.go#L1160 doesn't have such patch, and it's same as go1.20 https://github.com/golang/go/blob/release-branch.go1.20/src/runtime/stack.go#L1162.

For this error, fatal error: found bad pointer in Go heap (incorrect use of unsafe or cgo?), it looks like one pointer in heap refers to illegal pointer, which error comes from https://github.com/golang/go/blob/release-branch.go1.20/src/runtime/mbitmap.go#L288.

This error happens at 1.19 #56552, 1.14 #37968 too.

In this issue's case,

The issues only appear to occur for a very small number of our customers

It seems to be somewhat specific for certain machines to be "vulnerable" to this. If it was something that would happen on all installs, I'd say it would happen a lot more than what we are observing.

and https://go.dev/doc/go1.20

The most important effect of the default change is that when Go is installed on a system without a C compiler, it will now use pure Go builds for packages in the standard library that use cgo, instead of using pre-distributed package archives (which have been removed, as noted above) or attempting to use cgo and failing.

Is it possible customers using different systems with/without C compilers leading this error ^?

@mauri870, I followed the steps by @klauspost in #64781 (comment)
I used go version go1.21.5 linux/amd64 to build this time.

After couple hours got a panic though:

unexpected fault address 0x0
fatal error: fault
fatal: bad g in signal handler

Perhaps as @mknyszek suggested, we can add some debug prints. This way I can also validate I'm building properly with the patch applied.

@klauspost @dctrwatson hey, do you guys have some minimal code structure sample to setup in a local env to reproduce this error?

@klauspost @dctrwatson hey, do you guys have some minimal code structure sample to setup in a local env to reproduce this error?

This is with Thanos v0.32.5 running the receiver component in router mode. So unfortunately, I cannot provide one, sorry.

@smiletrl As I wrote it seems to only trigger on certain setups. Unfortunately these are all production setups running on customer hardware to which we don't have access.

We are also seeing this corruption issue on our production, building with go 1.20.11, using Klauspost v1.17.3 on Debian 10 running kernel 5.10.0-25-amd64 on dual CPU Intel Xeon Gold 6348/6230R.

@klauspost This ended up back in the compiler/runtime triage queue, do you have any updates from your end on trying it out with debug settings enabled?

@mknyszek We also see the issue being worked around with the GODEBUG=gcshrinkstackoff=1. We've seem the issue at one or two more customers. I will see if I can find more common things. Since all have been on production systems we have not been able to provide a custom compile with the proposed path.

It was shortly looking like "Intel SDE" could reproduce the issue, but it turned out that it was probably just emulation quirks. So I still don't have a reliable reproducer.

It does match quite well with the code using quite a bit of stack. Probably more than most other code out there.

Hi all, I want to add one more case to the issue with some additional details if it helps for the debugging.
In our case we are also running Thanos (v0.33) on K8s on GCP AMD instances.
We were seeing restarts (fatal errors) every couple of hours only in the region where we have the highest traffic.
The restarts disappeared completely when we set the GODEBUG=gcshrinkstackoff=1 environment variable.

Here are the last log lines in 3 different occasions of fatal errors (without GODEBUG):

Pod 1:

fatal error: workbuf is empty
fatal: bad g in signal handler

Pod 2:

runtime: pointer 0xc00a685fd0 to unallocated span span.base()=0xc00265a000 span.limit=0xc00265bf80 span.state=0
runtime: found in object at *(0xc00228eb40+0x88)
object=0xc00228eb40 s.base()=0xc00228e000 s.limit=0xc00228ff80 s.spanclass=38 s.elemsize=288 s.state=mSpanInUse
 *(object+0) = 0x0
 *(object+8) = 0x0
 *(object+16) = 0x0
 *(object+24) = 0x0
 *(object+32) = 0x0
 *(object+40) = 0x0
 *(object+48) = 0x0
 *(object+56) = 0xffffffffffffffff
 *(object+64) = 0x0
 *(object+72) = 0x0
 *(object+80) = 0x0
 *(object+88) = 0xc00a685fa8
 *(object+96) = 0x44529c
 *(object+104) = 0xc000a36b60
 *(object+112) = 0x0
 *(object+120) = 0x0
 *(object+128) = 0x0
 *(object+136) = 0xc00a685fd0 <==
 *(object+144) = 0x0
 *(object+152) = 0x4891a5
 *(object+160) = 0xc00a685fe0
 *(object+168) = 0x0
 *(object+176) = 0x6
 *(object+184) = 0x1b02e04
 *(object+192) = 0xc0018b7520
 *(object+200) = 0x0
 *(object+208) = 0x1000000000000
 *(object+216) = 0x6500000000
 *(object+224) = 0x0
 *(object+232) = 0x0
 *(object+240) = 0x0
 *(object+248) = 0x0
 *(object+256) = 0x0
 *(object+264) = 0x0
 *(object+272) = 0x0
 *(object+280) = 0x0
fatal error: found bad pointer in Go heap (incorrect use of unsafe or cgo?)

Pod 3:

runtime: pointer 0xc000557180 to unallocated span span.base()=0xc000556000 span.limit=0xc000558000 span.state=0
runtime: found in object at *(0xc00122dd10+0x10)
object=0xc00122dd10 s.base()=0xc00122c000 s.limit=0xc00122dfe0 s.spanclass=10 s.elemsize=48 s.state=mSpanInUse
 *(object+0) = 0x0
 *(object+8) = 0x0
 *(object+16) = 0xc000557180 <==
 *(object+24) = 0x1b
 *(object+32) = 0x1b
 *(object+40) = 0xc0032657d0
fatal error: found bad pointer in Go heap (incorrect use of unsafe or cgo?)
fatal: bad g in signal handler

I hope this helps.

@karsov , thanks! Are you able to share the stack tracebacks as well? You can strip out the symbols, paths, and arguments, though if you could keep the runtime functions that's probably helpful. I mostly want to see the goroutines and the sp/fp printed on each frame.

That's the strange part (at least for me).
There are absolutely no stack traces, nor other log lines with timestamps close to the errors I already shared.

Oh, hmm. I guess I would expect there to be no stack trace for the "fatal: bad g in signal handler" ones. I would have expected a traceback from pod 2, though.

The fact that two of them are printing "fatal: bad g in signal handler" is really strange. We don't manipulate workbufs or scan stacks from signal handlers. This suggests we somehow 1) crashed for one reason and then 2) somehow set g to nil, which would immediately cause a signal and print that message. I don't see how we get from 1 to 2.

Hi all, I want to add one more case to the issue with some additional details if it helps for the debugging. In our case we are also running Thanos (v0.33) on K8s on GCP AMD instances. We were seeing restarts (fatal errors) every couple of hours only in the region where we have the highest traffic. The restarts disappeared completely when we set the GODEBUG=gcshrinkstackoff=1 environment variable.

Here are the last log lines in 3 different occasions of fatal errors (without GODEBUG):

Pod 1:

fatal error: workbuf is empty
fatal: bad g in signal handler

Pod 2:

runtime: pointer 0xc00a685fd0 to unallocated span span.base()=0xc00265a000 span.limit=0xc00265bf80 span.state=0
runtime: found in object at *(0xc00228eb40+0x88)
object=0xc00228eb40 s.base()=0xc00228e000 s.limit=0xc00228ff80 s.spanclass=38 s.elemsize=288 s.state=mSpanInUse
 *(object+0) = 0x0
 *(object+8) = 0x0
 *(object+16) = 0x0
 *(object+24) = 0x0
 *(object+32) = 0x0
 *(object+40) = 0x0
 *(object+48) = 0x0
 *(object+56) = 0xffffffffffffffff
 *(object+64) = 0x0
 *(object+72) = 0x0
 *(object+80) = 0x0
 *(object+88) = 0xc00a685fa8
 *(object+96) = 0x44529c
 *(object+104) = 0xc000a36b60
 *(object+112) = 0x0
 *(object+120) = 0x0
 *(object+128) = 0x0
 *(object+136) = 0xc00a685fd0 <==
 *(object+144) = 0x0
 *(object+152) = 0x4891a5
 *(object+160) = 0xc00a685fe0
 *(object+168) = 0x0
 *(object+176) = 0x6
 *(object+184) = 0x1b02e04
 *(object+192) = 0xc0018b7520
 *(object+200) = 0x0
 *(object+208) = 0x1000000000000
 *(object+216) = 0x6500000000
 *(object+224) = 0x0
 *(object+232) = 0x0
 *(object+240) = 0x0
 *(object+248) = 0x0
 *(object+256) = 0x0
 *(object+264) = 0x0
 *(object+272) = 0x0
 *(object+280) = 0x0
fatal error: found bad pointer in Go heap (incorrect use of unsafe or cgo?)

Pod 3:

runtime: pointer 0xc000557180 to unallocated span span.base()=0xc000556000 span.limit=0xc000558000 span.state=0
runtime: found in object at *(0xc00122dd10+0x10)
object=0xc00122dd10 s.base()=0xc00122c000 s.limit=0xc00122dfe0 s.spanclass=10 s.elemsize=48 s.state=mSpanInUse
 *(object+0) = 0x0
 *(object+8) = 0x0
 *(object+16) = 0xc000557180 <==
 *(object+24) = 0x1b
 *(object+32) = 0x1b
 *(object+40) = 0xc0032657d0
fatal error: found bad pointer in Go heap (incorrect use of unsafe or cgo?)
fatal: bad g in signal handler

I hope this helps.

@karsov We also encountered the same error, can you tell me how to set GODEBUG=gcshrinkstackoff=1 environment variable in k8s deployment? thx

If someone has the possibility to test the latest release without the GODEBUG switch.

v1.17.7 contains an OOB write fix. It isn't on the stack however, so I am unsure if it resolves this issue. We have been unable to confirm either way internally.