go: runtime: rare stack corruption on Go 1.20 and later
Go version
Go 1.20.x and later
What operating system and processor architecture are you using (go env
)?
Reported on linux/amd64 systems. Reported on both Go 1.20.x and 1.21.x builds.
We have limited access to customer systems.
What did you do?
We have at MinIO been experiencing runtime crashes since the release of Go 1.20
The issues only appear to occur for a very small number of our customers, and supplying them with a Go 1.19.x compiled binary always solves the issue.
The issue appear slightly different each time, but all indicate some sort of corruption. Since none of them had any “smoking gun”, I held off on submitting an issue.
Here are some
samples of customer crashes (click to expand)
May 8 04:11:36 framin107 minio[1082653]: fatal error: unexpected signal during runtime execution
May 8 04:11:36 framin107 minio[1082653]: panic during panic
May 8 04:11:36 framin107 minio[1082653]: [signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x0]
May 8 04:11:36 framin107 minio[1082653]: runtime stack:
May 8 04:11:36 framin107 minio[1082653]: runtime.throw({0x2b40d78?, 0x0?})
May 8 04:11:36 framin107 minio[1082653]: #011runtime/panic.go:1047 +0x5d fp=0xc0102f1ed8 sp=0xc0102f1ea8 pc=0x43933d
May 8 04:11:36 framin107 minio[1082653]: runtime: g 0: unexpected return pc for runtime.sigpanic called from 0x0
… Same hardware:
May 10 10:17:18 framin107 minio[1097631]: fatal error: bulkBarrierPreWrite: unaligned arguments
May 10 10:17:18 framin107 minio[1097631]: unexpected fault address 0x0
May 10 10:17:18 framin107 minio[1097631]: fatal error: fault
May 10 10:17:18 framin107 minio[1097631]: goroutine 50957332 [running]:
May 10 10:17:18 framin107 minio[1097631]: runtime: g 50957332: unexpected return pc for runtime.throw called from 0x0
May 10 10:17:18 framin107 minio[1097631]: stack: frame={sp:0xc01034b1b8, fp:0xc01034b1e8} stack=[0xc01034a000,0xc01034c000)
May 10 03:53:32 framin107 minio[1090219]: fatal error: index out of range
May 10 03:53:32 framin107 minio[1090219]: fatal error: index out of range
May 10 03:53:32 framin107 minio[1090219]: fatal error: index out of range
May 10 03:53:32 framin107 minio[1090219]: fatal: bad g in signal handler
May 10 03:53:33 framin107 systemd[1]: minio.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Second customer:
Nov 27 02:36:00 minio minio[240609]: fatal error: unexpected signal during runtime execution
Nov 27 02:36:00 minio minio[240609]: unexpected fault address 0x0
Nov 27 02:36:00 minio minio[240609]: fatal error: fault
Nov 27 02:36:00 minio minio[240609]: fatal error: unexpected signal during runtime execution
Nov 27 02:36:00 minio minio[240609]: fatal error: bulkBarrierPreWrite: unaligned arguments
Nov 27 02:36:00 minio minio[240609]: runtime: pointer 0xc034ec65b0 to unallocated span span.base()=0xc034ec6000 span.limit=0xc034ec7e40 span.state=0
Nov 27 02:36:00 minio minio[240609]: runtime: found in object at *(0xc03939c580+0x28)
Nov 27 02:36:00 minio minio[240609]: object=0xc03939c580 s.base()=0xc03939c000 s.limit=0xc03939de40 s.spanclass=58 s.elemsize=704 s.state=mSpanInUse
Nov 27 02:36:00 minio minio[240609]: *(object+0) = 0x4baf5a0
Nov 27 02:36:00 minio minio[240609]: *(object+8) = 0xc01ec44a80
Nov 27 02:36:00 minio minio[240609]: *(object+16) = 0x4baf5a0
Nov 27 02:36:00 minio minio[240609]: *(object+24) = 0xc027728000
Nov 27 02:36:00 minio minio[240609]: *(object+32) = 0x732280
Nov 27 02:36:00 minio minio[240609]: *(object+40) = 0xc034ec65b0 <==
Nov 27 02:36:00 minio minio[240609]: *(object+48) = 0xc03e43b7a0
Nov 27 02:36:00 minio minio[240609]: *(object+56) = 0xc022b526c0
Nov 27 02:36:00 minio minio[240609]: *(object+64) = 0x4b9e4f8
Nov 27 02:36:00 minio minio[240609]: *(object+72) = 0xc02f21a2c0
Nov 27 02:36:00 minio minio[240609]: *(object+80) = 0x0
Nov 27 02:36:00 minio minio[240609]: *(object+88) = 0x0
Nov 27 02:36:00 minio minio[240609]: *(object+96) = 0x23eafe0
Nov 27 02:36:00 minio minio[240609]: *(object+104) = 0xc035cb8c14
Nov 27 02:36:00 minio minio[240609]: *(object+112) = 0xc00147c000
Nov 27 02:36:00 minio minio[240609]: *(object+120) = 0xc02f21a340
Nov 27 02:36:00 minio minio[240609]: *(object+128) = 0x4b9df08
Nov 27 02:36:00 minio minio[240609]: *(object+136) = 0x62aa480
Nov 27 02:36:00 minio minio[240609]: *(object+144) = 0x1
Nov 27 02:36:00 minio minio[240609]: *(object+152) = 0x0
Nov 27 02:36:00 minio minio[240609]: *(object+160) = 0xc035c885b8
Nov 27 02:36:00 minio minio[240609]: *(object+168) = 0x4
Nov 27 02:36:00 minio minio[240609]: *(object+176) = 0xc035c885bd
Nov 27 02:36:00 minio minio[240609]: *(object+184) = 0xd
Nov 27 02:36:00 minio minio[240609]: *(object+192) = 0x4baf5a0
Nov 27 02:36:00 minio minio[240609]: *(object+200) = 0xc01ec44a80
Nov 27 02:36:00 minio minio[240609]: *(object+208) = 0x4baf5a0
Nov 27 02:36:00 minio minio[240609]: *(object+216) = 0xc0064520e0
Nov 27 02:36:00 minio minio[240609]: *(object+224) = 0xc030055712
Nov 27 02:36:00 minio minio[240609]: *(object+232) = 0x16
Nov 27 02:36:00 minio minio[240609]: *(object+240) = 0xc035c885b8
Nov 27 02:36:00 minio minio[240609]: *(object+248) = 0x12
Nov 27 02:36:00 minio minio[240609]: *(object+256) = 0x23eafe0
Nov 27 02:36:00 minio minio[240609]: *(object+264) = 0xc035cb8e40
Nov 27 02:36:00 minio minio[240609]: *(object+272) = 0xc00137bb80
Nov 27 02:36:00 minio minio[240609]: *(object+280) = 0xc02f21a480
Nov 27 02:36:00 minio minio[240609]: *(object+288) = 0xc035c88618
Nov 27 02:36:00 minio minio[240609]: *(object+296) = 0x4
Nov 27 02:36:00 minio minio[240609]: *(object+304) = 0xc035c8861d
Nov 27 02:36:00 minio minio[240609]: *(object+312) = 0xd
Nov 27 02:36:00 minio minio[240609]: *(object+320) = 0x4baf5a0
Nov 27 02:36:00 minio minio[240609]: *(object+328) = 0xc01ec44a80
Nov 27 02:36:00 minio minio[240609]: *(object+336) = 0x4baf5a0
Nov 27 02:36:00 minio minio[240609]: *(object+344) = 0xc0064520e0
Nov 27 02:36:00 minio minio[240609]: *(object+352) = 0xc0300557d3
Nov 27 02:36:00 minio minio[240609]: *(object+360) = 0x15
Nov 27 02:36:00 minio minio[240609]: *(object+368) = 0xc035c88618
Nov 27 02:36:00 minio minio[240609]: *(object+376) = 0x12
Nov 27 02:36:00 minio minio[240609]: *(object+384) = 0x23eafe0
Nov 27 02:36:00 minio minio[240609]: *(object+392) = 0xc035cb8f30
Nov 27 02:36:00 minio minio[240609]: *(object+400) = 0xc001e26780
Nov 27 02:36:00 minio minio[240609]: *(object+408) = 0xc02f21a580
Nov 27 02:36:00 minio minio[240609]: *(object+416) = 0x0
Nov 27 02:36:00 minio minio[240609]: *(object+424) = 0x0
Nov 27 02:36:00 minio minio[240609]: *(object+432) = 0xc035ce9320
Nov 27 02:36:00 minio minio[240609]: *(object+440) = 0xc035ce9330
Nov 27 02:36:00 minio minio[240609]: *(object+448) = 0x0
Nov 27 02:36:00 minio minio[240609]: *(object+456) = 0x0
Nov 27 02:36:00 minio minio[240609]: *(object+464) = 0xc035ce93f0
Nov 27 02:36:00 minio minio[240609]: *(object+472) = 0xc035ce9400
Nov 27 02:36:00 minio minio[240609]: *(object+480) = 0x0
Nov 27 02:36:00 minio minio[240609]: *(object+488) = 0x0
Nov 27 02:36:00 minio minio[240609]: *(object+496) = 0xc035ce94c0
Nov 27 02:36:00 minio minio[240609]: *(object+504) = 0xc035ce94d0
Nov 27 02:36:00 minio minio[240609]: *(object+512) = 0x4b9df08
Nov 27 02:36:00 minio minio[240609]: *(object+520) = 0x62aa480
Nov 27 02:36:00 minio minio[240609]: *(object+528) = 0x0
Nov 27 02:36:00 minio minio[240609]: *(object+536) = 0x0
Nov 27 02:36:00 minio minio[240609]: *(object+544) = 0xc035c887f8
Nov 27 02:36:00 minio minio[240609]: *(object+552) = 0x4
Nov 27 02:36:00 minio minio[240609]: *(object+560) = 0xc035c887fd
Nov 27 02:36:00 minio minio[240609]: *(object+568) = 0xd
Nov 27 02:36:00 minio minio[240609]: *(object+576) = 0xc035cb90f0
Nov 27 02:36:00 minio minio[240609]: *(object+584) = 0xa
Nov 27 02:36:00 minio minio[240609]: *(object+592) = 0xc035cb90fb
Nov 27 02:36:00 minio minio[240609]: *(object+600) = 0x3
Nov 27 02:36:00 minio minio[240609]: *(object+608) = 0x4baf5a0
Nov 27 02:36:00 minio minio[240609]: *(object+616) = 0xc01ec44a80
Nov 27 02:36:00 minio minio[240609]: *(object+624) = 0x4baf5a0
Nov 27 02:36:00 minio minio[240609]: *(object+632) = 0xc027728000
Nov 27 02:36:00 minio minio[240609]: *(object+640) = 0x23ae600
Nov 27 02:36:00 minio minio[240609]: *(object+648) = 0x4ba47f0
Nov 27 02:36:00 minio minio[240609]: *(object+656) = 0xc034ecedc0
Nov 27 02:36:00 minio minio[240609]: *(object+664) = 0xc018072b90
Nov 27 02:36:00 minio minio[240609]: *(object+672) = 0x23eafe0
Nov 27 02:36:00 minio minio[240609]: *(object+680) = 0xc035cb9150
Nov 27 02:36:00 minio minio[240609]: *(object+688) = 0xc001599180
Nov 27 02:36:00 minio minio[240609]: *(object+696) = 0xc02f21a800
Nov 27 02:36:00 minio minio[240609]: fatal error: found bad pointer in Go heap (incorrect use of unsafe or cgo?)
Third customer:
Aug 10 12:02:06 minio minio[13162]: fatal error: unexpected signal during runtime execution
Aug 10 12:02:06 minio minio[13162]: unexpected fault address 0x0
Aug 10 12:02:06 minio minio[13162]: fatal error: fault
Aug 10 12:02:06 minio minio[13162]: runtime: pointer 0xc0228c4a20 to unused region of span span.base()=0xc0141cc000 span.limit=0xc014Aug 10 12:02:06 minio minio[13162]: runtime: found in object at *(0xc020089980+0x10)
Aug 10 12:02:06 minio minio[13162]: object=0xc020089980 s.base()=0xc020088000 s.limit=0xc020089fe0 s.spanclass=16 s.elemsize=96 s.staAug 10 12:02:06 minio minio[13162]: *(object+0) = 0x2b3b90b
Aug 10 12:02:06 minio minio[13162]: *(object+8) = 0x4
Aug 10 12:02:06 minio minio[13162]: *(object+16) = 0xc0228c4a20 <==
Aug 10 12:02:06 minio minio[13162]: *(object+24) = 0x8b
Aug 10 12:02:06 minio minio[13162]: *(object+32) = 0x4d3c400
Aug 10 12:02:06 minio minio[13162]: *(object+40) = 0x61953a0
Aug 10 12:02:06 minio minio[13162]: *(object+48) = 0x2309720
Aug 10 12:02:06 minio minio[13162]: *(object+56) = 0xc12d4b44a6b3921a
Aug 10 12:02:06 minio minio[13162]: *(object+64) = 0xafc4c36fd829a
Aug 10 12:02:06 minio minio[13162]: *(object+72) = 0x6301700
Aug 10 12:02:06 minio minio[13162]: *(object+80) = 0x6380620
Aug 10 12:02:06 minio minio[13162]: *(object+88) = 0x5
Aug 10 12:02:06 minio minio[13162]: fatal error: found bad pointer in Go heap (incorrect use of unsafe or cgo?)
It does however seem like the “Thanos” project has supplied what looks to be smoking gun. (issue contains additional traces)
So the crash occurs in a goroutine that compresses a block.
The only really interesting thing that goes on is that calls assembler to compress the block. Looking at the assembly caller it is pretty straightforward. This is the disassembly for the caller:
github.com/klauspost/compress/s2.encodeBlockBetter STEXT size=465 args=0x30 locals=0x40 funcid=0x0 align=0x0
0x0000 00000 (/s2/encode_amd64.go:52) TEXT github.com/klauspost/compress/s2.encodeBlockBetter(SB), ABIInternal, $64-48
0x0000 00000 (/s2/encode_amd64.go:52) CMPQ SP, 16(R14)
0x0004 00004 (/s2/encode_amd64.go:52) PCDATA $0, $-2
0x0004 00004 (/s2/encode_amd64.go:52) JLS 395
0x000a 00010 (/s2/encode_amd64.go:52) PCDATA $0, $-1
0x000a 00010 (/s2/encode_amd64.go:52) PUSHQ BP
0x000b 00011 (/s2/encode_amd64.go:52) MOVQ SP, BP
0x000e 00014 (/s2/encode_amd64.go:52) SUBQ $56, SP
0x0012 00018 (/s2/encode_amd64.go:52) MOVQ AX, github.com/klauspost/compress/s2.dst+72(FP)
0x0017 00023 (/s2/encode_amd64.go:52) MOVQ DI, github.com/klauspost/compress/s2.src+96(FP)
0x001c 00028 (/s2/encode_amd64.go:52) FUNCDATA $0, gclocals·cNGUyZq94N9QFR70tEjj5A==(SB)
0x001c 00028 (/s2/encode_amd64.go:52) FUNCDATA $1, gclocals·J5F+7Qw7O7ve2QcWC7DpeQ==(SB)
0x001c 00028 (/s2/encode_amd64.go:52) FUNCDATA $5, github.com/klauspost/compress/s2.encodeBlockBetter.arginfo1(SB)
0x001c 00028 (/s2/encode_amd64.go:52) FUNCDATA $6, github.com/klauspost/compress/s2.encodeBlockBetter.argliveinfo(SB)
0x001c 00028 (/s2/encode_amd64.go:52) PCDATA $3, $1
0x001c 00028 (/s2/encode_amd64.go:52) NOP
0x0020 00032 (/s2/encode_amd64.go:62) CMPQ SI, $4194304
0x0027 00039 (/s2/encode_amd64.go:62) JGT 337
[...]
0x0151 00337 (/s2/encode_amd64.go:63) MOVQ AX, (SP)
0x0155 00341 (/s2/encode_amd64.go:63) MOVQ BX, 8(SP)
0x015a 00346 (/s2/encode_amd64.go:63) MOVQ CX, 16(SP)
0x015f 00351 (/s2/encode_amd64.go:63) MOVQ DI, 24(SP)
0x0164 00356 (/s2/encode_amd64.go:63) MOVQ SI, 32(SP)
0x0169 00361 (/s2/encode_amd64.go:63) MOVQ R8, 40(SP)
0x016e 00366 (/s2/encode_amd64.go:63) CALL github.com/klauspost/compress/s2.encodeBetterBlockAsm(SB)
0x0173 00371 (/s2/encode_amd64.go:63) XORPS X15, X15
0x0177 00375 (/s2/encode_amd64.go:63) MOVQ (TLS), R14
0x0180 00384 (/s2/encode_amd64.go:63) MOVQ 48(SP), AX
0x0185 00389 (/s2/encode_amd64.go:63) ADDQ $56, SP
0x0189 00393 (/s2/encode_amd64.go:63) POPQ BP
0x018a 00394 (/s2/encode_amd64.go:63) RET
[...]
0x018b 00395 (/s2/encode_amd64.go:52) MOVQ AX, 8(SP)
0x0190 00400 (/s2/encode_amd64.go:52) MOVQ BX, 16(SP)
0x0195 00405 (/s2/encode_amd64.go:52) MOVQ CX, 24(SP)
0x019a 00410 (/s2/encode_amd64.go:52) MOVQ DI, 32(SP)
0x019f 00415 (/s2/encode_amd64.go:52) MOVQ SI, 40(SP)
0x01a4 00420 (/s2/encode_amd64.go:52) MOVQ R8, 48(SP)
0x01a9 00425 (/s2/encode_amd64.go:52) CALL runtime.morestack_noctxt(SB)
0x01ae 00430 (/s2/encode_amd64.go:52) MOVQ 8(SP), AX
0x01b3 00435 (/s2/encode_amd64.go:52) MOVQ 16(SP), BX
0x01b8 00440 (/s2/encode_amd64.go:52) MOVQ 24(SP), CX
0x01bd 00445 (/s2/encode_amd64.go:52) MOVQ 32(SP), DI
0x01c2 00450 (/s2/encode_amd64.go:52) MOVQ 40(SP), SI
0x01c7 00455 (/s2/encode_amd64.go:52) MOVQ 48(SP), R8
0x01cc 00460 (/s2/encode_amd64.go:52) PCDATA $0, $-1
0x01cc 00460 (/s2/encode_amd64.go:52) JMP 0
This is the assembly function called signature:
// func encodeBetterBlockAsm(dst []byte, src []byte) int
// Requires: BMI, SSE2
TEXT ·encodeBetterBlockAsm(SB), $589848-56
… and the function definition:
//go:noescape
func encodeBetterBlockAsm(dst []byte, src []byte) int
The reason I included the stack size check is that it uses quite a bit of stack, so there is a chance that it is called.
The stack is used for a dynamic lookup table. I am fairly sure there are no writes outside the stack, and I also am pretty confident there are no writes outside the provided slices (this would likely also give different errors).
I do not use the BP
register - so it is not clobbered, and only SSE2 registers are used - so no VZEROUPPER
weirdness. The stack is managed by avo, so less likely there is a bug with that.
So my questions are:
A) Am I doing something obviously wrong? B) What would be a typical reason for this error to show up? C) This seems releated to GC, so is there a window where the goroutine could be preempted in an unsafe state? D) Are there any Go 1.20 changes that seem likely to be triggering this?
Keep in mind that this doesn’t appear to happen on too many machines. Talos reported that it seem to happen more often if a lot of memory is allocated.
I will of course assist with any information that may be needed - but I feel at this point I need some pointers from people deeper understanding of the runtime to get much further.
Also note we have tested CPU+RAM on some of these customer systems extensively since that seemed like a possibility at first. Also note that crashes can be completely unrelated - but the coincidence seems to big.
What did you expect to see?
No crash
What did you see instead?
Rare, random runtime crashes
Edit: Assembly is now linux compiled.
About this issue
- Original URL
- State: open
- Created 6 months ago
- Comments: 30 (22 by maintainers)
GODEBUG="asyncpreemptoff=1"
resulted in multiple panics of:Switching to next flag
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.GODEBUG=gcshrinkstackoff=1
hasn’t had any panics in 20hI’ll switch to
gccheckmark=1
to confirm it has no effect (as-in, still get panics)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. usinggo tool objdump
), it will have those instructions.@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 https://github.com/golang/go/issues/58212#issuecomment-1412216775?
@mauri870, I followed the steps by @klauspost in https://github.com/golang/go/issues/64781#issuecomment-1866590541 I used
go version go1.21.5 linux/amd64
to build this time.After couple hours got a panic though:
Perhaps as @mknyszek suggested, we can add some debug prints. This way I can also validate I’m building properly with the patch applied.
Okay, I misread the comment https://github.com/golang/go/issues/64781#issuecomment-1864956541 – it is gccheckmark, not gcshrinkstackoff… Then try if that patch makes any difference. Thanks.
Here’s a quick demo https://github.com/egonelbre/compress/commit/c7df670870dc509127572281d79075a7faac8f13. Instrumenting around buffers and pools is also a good idea.
@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.