Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

runtime: corrupt binary export data seen after signal preemption CL #35326

Closed
mvdan opened this issue Nov 3, 2019 · 87 comments
Closed

runtime: corrupt binary export data seen after signal preemption CL #35326

mvdan opened this issue Nov 3, 2019 · 87 comments

Comments

@mvdan
Copy link
Member

@mvdan mvdan commented Nov 3, 2019

$ go version
go version devel +d2c039fb21 Sun Nov 3 01:44:46 2019 +0000 linux/amd64
$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/mvdan/.cache/go-build"
GOENV="/home/mvdan/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GONOPROXY="brank.as/*"
GONOSUMDB="brank.as/*"
GOOS="linux"
GOPATH="/home/mvdan/go"
GOPRIVATE="brank.as/*"
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/mvdan/tip"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/mvdan/tip/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/mvdan/src/gio/cmd/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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build819987201=/tmp/go-build -gno-record-gcc-switches"

After building Go from master, I sometimes see errors like:

$ go test -race
# encoding/json
vet: /home/mvdan/tip/src/encoding/json/decode.go:13:2: could not import fmt (cannot import "fmt" (unknown bexport format version -1 ("\x80\x16\x13\x00\xc0\x00\x00\x00\x80\x17\x13\x00\xc0\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x06format\x01a\x00\x04esc:\x05esc:\x02\x18$GOROOT/src/fmt/print.go\x05Write\x01b\x01n\x03err\x05Width\x03wid\x02ok\tPrecision\x04prec\x04Flag\x01c\x06Format\x01f\x05State\x06String\bGoString\x01w\x06Writer\x02io")), possibly version skew - reinstall package)
PASS
ok      gioui.org/cmd/gogio     4.559s

Here's another crash from earlier today, with a slightly modified (and freshly built) Go master - you can see the error mentions a different std package:

$ go test
# mime
vet: /home/mvdan/tip/src/mime/encodedword.go:12:2: could not import io (cannot import "io" (unknown bexport format version -1 ("DX\xcdq㦔d_\xbf\x97\xa64h\xf7\x8f\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00d\x01p\x01n\x03err\x05Write\x05Close\x04Seek\x06offset\x06whence\x06Reader\x06Writer\x06Closer\x06Seeker\bReadFrom\x01r\aWriteTo\x01w\x06ReadAt\x03off\aWriteAt\bReadByte")), possibly version skew - reinstall package)
PASS
ok      gioui.org/cmd/gogio     7.199s

@heschik correctly points out that this could be a bad version of vet in play, since the bexport format has been replaced with the iexport. However, I already nuked my $GOBIN, and go test -x seems to be running /home/mvdan/tip/pkg/tool/linux_amd64/vet, which is freshly built.

Usually I'd assume this is an issue with my setup, but I can't find anything wrong with it, and I've only started seeing these errors today.

/cc @mdempsky @griesemer @alandonovan

@mvdan mvdan added this to the Go1.14 milestone Nov 3, 2019
@mvdan

This comment has been minimized.

Copy link
Member Author

@mvdan mvdan commented Nov 3, 2019

I get many errors like it when I attempt to test my Go installation, too - via bash run.bash --no-rebuild.

@mvdan

This comment has been minimized.

Copy link
Member Author

@mvdan mvdan commented Nov 3, 2019

I built 50 commits behind the current master (cc4b824) and bash run.bash --no-rebuild succeeds without a problem. So perhaps there was a regression in the last 50 commits; will keep digging.

@siebenmann

This comment has been minimized.

Copy link

@siebenmann siebenmann commented Nov 4, 2019

I'm seeing this error on all.bash builds at the current git tip, at varying and erratic places through the tests. For me this happens in a completely clean environment (as far as I can arrange it) on Fedora 30 64-bit Linux:

$ mkdir /tmp/gb
$ env -i HOME=/tmp/gb PATH=/usr/bin:/usr/sbin ./all.bash
Building Go cmd/dist using /usr/lib/golang. (go1.12.10 linux/amd64)
Building Go toolchain1 using /usr/lib/golang.
Building Go bootstrap cmd/go (go_bootstrap) using Go toolchain1.
Building Go toolchain2 using go_bootstrap and Go toolchain1.
Building Go toolchain3 using go_bootstrap and Go toolchain2.
Building packages and commands for linux/amd64.

##### Testing packages.
# sync
vet: sync/pool.go:9:2: could not import runtime (cannot import "runtime" (unknown bexport format version -1 ("77;>$history;uma\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00ler.go\x02gc\x1e$GOROOT/src/runtime/cpuprof.go\x02hz\x00\x1eCPUProfile no longer available\x1c$GOROOT/src/runtime/debug.go\x01n\x04ncpu\x06gcount\x1c$GOROOT/src/runtime/error.go\fRuntimeError")), possibly version skew - reinstall package)
[...]

Which parts of the tests and which packages it fails on varies, but it looks like it's always vet failing.

Re-running all.bash sometimes succeeds, but not always. I just had such a rebuild attempt fail with a different error in tests, although some other tests in this run also reported vet failures:

##### Testing packages.
# crypto/subtle.test
fatal error: index out of range

runtime stack:
runtime.throw(0xe30bc2, 0x12)
        /data/code/go-lang/go/src/runtime/panic.go:1045 +0x72
runtime.panicCheck1(0x41fd9f, 0xe30bc2, 0x12)
        /data/code/go-lang/go/src/runtime/panic.go:34 +0xd9
runtime.goPanicIndexU(0x1b9a789ccb, 0x400000)
        /data/code/go-lang/go/src/runtime/panic.go:91 +0x44
runtime.heapBitsForAddr(...)
        /data/code/go-lang/go/src/runtime/mbitmap.go:340
runtime.scanobject(0x6e6962732f727375, 0xc000021270)
        /data/code/go-lang/go/src/runtime/mgcmark.go:1191 +0x39f
runtime.gcDrain(0xc000021270, 0x3)
        /data/code/go-lang/go/src/runtime/mgcmark.go:1028 +0x1fb
runtime.gcBgMarkWorker.func2()
        /data/code/go-lang/go/src/runtime/mgc.go:1926 +0x80
runtime.systemstack(0x0)
        /data/code/go-lang/go/src/runtime/asm_amd64.s:370 +0x66
runtime.mstart()
        /data/code/go-lang/go/src/runtime/proc.go:1069

goroutine 19 [GC worker (idle)]:
runtime.systemstack_switch()
        /data/code/go-lang/go/src/runtime/asm_amd64.s:330 fp=0xc00003c760 sp=0xc00003c758 pc=0x45da10
runtime.gcBgMarkWorker(0xc000020000)
        /data/code/go-lang/go/src/runtime/mgc.go:1913 +0x1be fp=0xc00003c7d8 sp=0xc00003c760 pc=0x41b4ce
runtime.goexit()
        /data/code/go-lang/go/src/runtime/asm_amd64.s:1375 +0x1 fp=0xc00003c7e0 sp=0xc00003c7d8 pc=0x45f9a1
created by runtime.gcBgMarkStartWorkers
        /data/code/go-lang/go/src/runtime/mgc.go:1807 +0x77

goroutine 1 [semacquire]:
sync.runtime_Semacquire(0xc000588488)
        /data/code/go-lang/go/src/runtime/sema.go:56 +0x42
sync.(*WaitGroup).Wait(0xc000588480)
        /data/code/go-lang/go/src/sync/waitgroup.go:130 +0x64
cmd/compile/internal/gc.compileFunctions()
        /data/code/go-lang/go/src/cmd/compile/internal/gc/pgen.go:373 +0x1ce
cmd/compile/internal/gc.Main(0xe4ae98)
        /data/code/go-lang/go/src/cmd/compile/internal/gc/main.go:709 +0x3280
main.main()
        /data/code/go-lang/go/src/cmd/compile/main.go:50 +0xac

goroutine 39 [runnable]:
cmd/compile/internal/ssa.SparseTree.numberBlock(0xc000441200, 0x2, 0x2, 0xc000486c30, 0x1, 0xc00008fd70)
        /data/code/go-lang/go/src/cmd/compile/internal/ssa/sparsetree.go:147 +0x102
cmd/compile/internal/ssa.newSparseTree(0xc0002e0580, 0xc00008fd70, 0x2, 0x2, 0xdee4c0, 0x1, 0xc00042cb10)
        /data/code/go-lang/go/src/cmd/compile/internal/ssa/sparsetree.go:69 +0x18b
cmd/compile/internal/ssa.(*Func).sdom(0xc0002e0580, 0xc00042cb10, 0xd, 0xc00040d100)
        /data/code/go-lang/go/src/cmd/compile/internal/ssa/func.go:652 +0x95
cmd/compile/internal/ssa.cse(0xc0002e0580)
        /data/code/go-lang/go/src/cmd/compile/internal/ssa/cse.go:158 +0xbfa
cmd/compile/internal/ssa.Compile(0xc0002e0580)
        /data/code/go-lang/go/src/cmd/compile/internal/ssa/compile.go:92 +0x9a5
cmd/compile/internal/gc.buildssa(0xc0002e02c0, 0x0, 0x0)
        /data/code/go-lang/go/src/cmd/compile/internal/gc/ssa.go:444 +0xcd8
cmd/compile/internal/gc.compileSSA(0xc0002e02c0, 0x0)
        /data/code/go-lang/go/src/cmd/compile/internal/gc/pgen.go:298 +0x5d
cmd/compile/internal/gc.compileFunctions.func2(0xc0005a39e0, 0xc000588480, 0x0)
        /data/code/go-lang/go/src/cmd/compile/internal/gc/pgen.go:363 +0x49
created by cmd/compile/internal/gc.compileFunctions
        /data/code/go-lang/go/src/cmd/compile/internal/gc/pgen.go:361 +0x128

goroutine 40 [runnable]:
cmd/compile/internal/types.(*Sym).Linksym(0xc0003b24e0, 0xc00001e0c0)
        /data/code/go-lang/go/src/cmd/compile/internal/types/sym.go:79 +0x1d4
cmd/compile/internal/gc.(*state).addr(0xc000010120, 0xc0003b0ff0, 0xc000000800, 0x0)
        /data/code/go-lang/go/src/cmd/compile/internal/gc/ssa.go:4580 +0x275
cmd/compile/internal/gc.(*state).expr(0xc000010120, 0xc0003b0ff0, 0x0)
        /data/code/go-lang/go/src/cmd/compile/internal/gc/ssa.go:2007 +0x143
cmd/compile/internal/gc.(*state).stmt(0xc000010120, 0xc0005c6780)
        /data/code/go-lang/go/src/cmd/compile/internal/gc/ssa.go:1239 +0x234
cmd/compile/internal/gc.(*state).stmtList(0xc000010120, 0xc0005be140)
        /data/code/go-lang/go/src/cmd/compile/internal/gc/ssa.go:1018 +0x58
cmd/compile/internal/gc.(*state).stmt(0xc000010120, 0xc0005c6900)
        /data/code/go-lang/go/src/cmd/compile/internal/gc/ssa.go:1040 +0x15ce
cmd/compile/internal/gc.(*state).stmtList(0xc000010120, 0xc0005be060)
        /data/code/go-lang/go/src/cmd/compile/internal/gc/ssa.go:1018 +0x58
cmd/compile/internal/gc.buildssa(0xc0002e0420, 0x1, 0x0)
        /data/code/go-lang/go/src/cmd/compile/internal/gc/ssa.go:426 +0xc39
cmd/compile/internal/gc.compileSSA(0xc0002e0420, 0x1)
        /data/code/go-lang/go/src/cmd/compile/internal/gc/pgen.go:298 +0x5d
cmd/compile/internal/gc.compileFunctions.func2(0xc0005a39e0, 0xc000588480, 0x1)
        /data/code/go-lang/go/src/cmd/compile/internal/gc/pgen.go:363 +0x49
created by cmd/compile/internal/gc.compileFunctions
        /data/code/go-lang/go/src/cmd/compile/internal/gc/pgen.go:361 +0x128

goroutine 41 [runnable]:
cmd/compile/internal/gc.compileFunctions.func2(0xc0005a39e0, 0xc000588480, 0x2)
        /data/code/go-lang/go/src/cmd/compile/internal/gc/pgen.go:361
created by cmd/compile/internal/gc.compileFunctions
        /data/code/go-lang/go/src/cmd/compile/internal/gc/pgen.go:361 +0x128

goroutine 42 [runnable]:
cmd/compile/internal/gc.compileFunctions.func2(0xc0005a39e0, 0xc000588480, 0x3)
        /data/code/go-lang/go/src/cmd/compile/internal/gc/pgen.go:361
created by cmd/compile/internal/gc.compileFunctions
        /data/code/go-lang/go/src/cmd/compile/internal/gc/pgen.go:361 +0x128
ok      archive/tar     0.031s
ok      archive/zip     0.025s
@mdempsky

This comment has been minimized.

Copy link
Member

@mdempsky mdempsky commented Nov 4, 2019

vet: sync/pool.go:9:2: could not import runtime (cannot import "runtime" (unknown bexport format version -1 ("77;>$history;uma\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00ler.go\x02gc\x1e$GOROOT/src/runtime/cpuprof.go\x02hz\x00\x1eCPUProfile no longer available\x1c$GOROOT/src/runtime/debug.go\x01n\x04ncpu\x06gcount\x1c$GOROOT/src/runtime/error.go\fRuntimeError")), possibly version skew - reinstall package)

The trailing part of that looks like valid iexport data, except the first 32 bytes have been corrupted.

This seems like memory corruption, either from miscompilation or a GC issue.

@mdempsky

This comment has been minimized.

Copy link
Member

@mdempsky mdempsky commented Nov 4, 2019

In all three of the examples, the first 32 bytes of the buffer were corrupted.

@mdempsky

This comment has been minimized.

Copy link
Member

@mdempsky mdempsky commented Nov 4, 2019

BTW, the thing that makes me suspect memory corruption within cmd/compile is that "unknown bexport format" means that the "$$B\n" signature was written out correctly, but then the next 32 byte were garbage.

Also, cmd/compile explicitly flushes its write buffer after writing "$$B\n" and before writing the indexed export data.

Finally, this data isn't specially aligned at all within the file, so it's not like it could be generic file-level corruption.

Not to mention the index out of range error within the runtime during compilation seems bad.

@mdempsky

This comment has been minimized.

Copy link
Member

@mdempsky mdempsky commented Nov 4, 2019

@mvdan @siebenmann Can you two describe your test environments in more detail so maybe we can try to identify more commonalities?

E.g., it looks like you're both using linux/amd64. @siebenmann mentioned Fedora 30; @mvdan what Linux distro and version are you using?

Also, how many cores?

@siebenmann

This comment has been minimized.

Copy link

@siebenmann siebenmann commented Nov 4, 2019

The machine I'm seeing this on is an i7-8700K (not overclocked) with 32 GB of RAM and HyperThreading still enabled, so a 6/12 cores/threads machine. At the moment it has Fedora's kernel 5.3.7-200.fc30.x86_64. I can't seem to reproduce this on a machine running Ubuntu 18.04 (kernel 4.15.0-52-generic) with a Xeon E5-2680 CPU with HyperThreading off (8 cores) and 64 GB of RAM, nor on another Ubuntu 18.04 machine with the same kernel but a Ryzen 7 1800X CPU (again, not overclocked) with 8 cores (it has HT off) and 32 GB of RAM.

@mvdan

This comment has been minimized.

Copy link
Member Author

@mvdan mvdan commented Nov 4, 2019

I am on a Thinkpad with a i5-8350U, HT left on (4 real cores, 8 total), and 16GiB of RAM. I run Arch Linux, with its current 5.3.8 Linux kernel.

Aside from that my Go setup is a pretty standard build from source, using 1.13.4 to bootstrap. I don't have any fancy go env vars other than GOPRIVATE.

@siebenmann

This comment has been minimized.

Copy link

@siebenmann siebenmann commented Nov 4, 2019

I've now reproduced this on another Fedora 30 linux/amd64 machine, also with kernel 5.3.7-200.fc30.x86_64 but this time with a Ryzen 1800X (not overclocked, 8/16 cores) with 32 GB.

I've git bisected this and on both of my Fedora 30 machines, the commit where the failures start is 62e53b7, 'runtime: use signals to preempt Gs for suspendG', which is targeted at #10958 and #24543. I think this makes this issue CC @aclements.

@mdempsky

This comment has been minimized.

Copy link
Member

@mdempsky mdempsky commented Nov 4, 2019

Linux kernel version-specific signal handling behavior sounds fuuuuun.

@mvdan

This comment has been minimized.

Copy link
Member Author

@mvdan mvdan commented Nov 4, 2019

At least it's good that enough people test tip, so that this was caught at the start of the freeze :)

I'm happy to help debug this further, if the runtime maintainers can't reproduce this themselves.

@mdempsky

This comment has been minimized.

Copy link
Member

@mdempsky mdempsky commented Nov 4, 2019

@mvdan Oh yeah, definitely. I'm glad you and @siebenmann both reported the issue and have been able to reproduce it reliably enough to track down a culprit CL and identify some likely commonality between test setups. (I'll check the Linux kernel version I was using later, and also give it a shot on my personal laptop running Fedora 31.)

I'm just a little nervous because this is already the second issue discovered in the runtime preemption feature that landed last week.

@ianlancetaylor ianlancetaylor changed the title cmd/vet: "possiby version skew" errors after building Go from master runtime: corrupt binary export data seen after signal preemption CL Nov 4, 2019
@bpowers

This comment has been minimized.

Copy link
Contributor

@bpowers bpowers commented Nov 12, 2019

I see similar spurious problems, e.g. tonights tip c2edcf4:

##### internal linking of -buildmode=pie
# runtime/pprof [reflect.test]
fatal error: index out of range

runtime stack:
runtime.throw(0xe512d5, 0x12)
	/home/bpowers/go/src/runtime/panic.go:1106 +0x72
runtime.panicCheck1(0x41eeff, 0xe512d5, 0x12)
	/home/bpowers/go/src/runtime/panic.go:34 +0xd9
runtime.goPanicIndexU(0x2e4a9badd8, 0x400000)
	/home/bpowers/go/src/runtime/panic.go:91 +0x44
runtime.heapBitsForAddr(...)
	/home/bpowers/go/src/runtime/mbitmap.go:340
runtime.scanobject(0xb929eeb762d7c042, 0xc000032e90)
	/home/bpowers/go/src/runtime/mgcmark.go:1197 +0x39f
runtime.gcDrain(0xc000032e90, 0x3)
	/home/bpowers/go/src/runtime/mgcmark.go:1034 +0x1fb
runtime.gcBgMarkWorker.func2()
	/home/bpowers/go/src/runtime/mgc.go:1941 +0x80
runtime.systemstack(0x0)
	/home/bpowers/go/src/runtime/asm_amd64.s:370 +0x66
runtime.mstart()
	/home/bpowers/go/src/runtime/proc.go:1069

goroutine 28 [GC worker (idle)]:
runtime.systemstack_switch()
	/home/bpowers/go/src/runtime/asm_amd64.s:330 fp=0xc000484760 sp=0xc000484758 pc=0x460910
runtime.gcBgMarkWorker(0xc000031800)
	/home/bpowers/go/src/runtime/mgc.go:1928 +0x1be fp=0xc0004847d8 sp=0xc000484760 pc=0x41b53e
runtime.goexit()
	/home/bpowers/go/src/runtime/asm_amd64.s:1375 +0x1 fp=0xc0004847e0 sp=0xc0004847d8 pc=0x4628a1
created by runtime.gcBgMarkStartWorkers
	/home/bpowers/go/src/runtime/mgc.go:1822 +0x77

goroutine 1 [syscall]:
syscall.Syscall6(0x9, 0x0, 0x2192, 0x1, 0x1, 0x3, 0x0, 0x7f6981fd3000, 0x1, 0x0)
	/home/bpowers/go/src/syscall/asm_linux_amd64.s:41 +0x5
syscall.mmap(0x0, 0x2192, 0x1, 0x1, 0x3, 0x0, 0xc000358e38, 0x4aeee3, 0xc0004a32c0)
	/home/bpowers/go/src/syscall/zsyscall_linux_amd64.go:1627 +0x73
syscall.(*mmapper).Mmap(0x154ae80, 0x3, 0x0, 0x2192, 0x1, 0x1, 0x0, 0x0, 0x0, 0x0, ...)
	/home/bpowers/go/src/syscall/syscall_unix.go:58 +0xbe
syscall.Mmap(...)
	/home/bpowers/go/src/syscall/syscall_linux.go:985
cmd/compile/internal/gc.mapFile(0xc000494290, 0xdb, 0x20b7, 0x80, 0x200, 0x1b, 0x1c)
	/home/bpowers/go/src/cmd/compile/internal/gc/mapfile_mmap.go:28 +0xaf
cmd/compile/internal/gc.iimport(0xc0004ba050, 0xc00049c170)
	/home/bpowers/go/src/cmd/compile/internal/gc/iimport.go:113 +0x106
cmd/compile/internal/gc.importfile(0xc000359528, 0x0)
	/home/bpowers/go/src/cmd/compile/internal/gc/main.go:1270 +0x8a9
cmd/compile/internal/gc.(*noder).importDecl(0xc000350240, 0xc000064090)
	/home/bpowers/go/src/cmd/compile/internal/gc/noder.go:317 +0x86
cmd/compile/internal/gc.(*noder).decls(0xc000350240, 0xc000012800, 0x42, 0x80, 0x0, 0x0, 0xc000359678)
	/home/bpowers/go/src/cmd/compile/internal/gc/noder.go:289 +0x2d0
cmd/compile/internal/gc.(*noder).node(0xc000350240)
	/home/bpowers/go/src/cmd/compile/internal/gc/noder.go:244 +0xcc
cmd/compile/internal/gc.parseFiles(0xc0000a4600, 0x8, 0x8, 0x2)
	/home/bpowers/go/src/cmd/compile/internal/gc/noder.go:62 +0x35f
cmd/compile/internal/gc.Main(0xe6c650)
	/home/bpowers/go/src/cmd/compile/internal/gc/main.go:543 +0x2702
main.main()
	/home/bpowers/go/src/cmd/compile/main.go:50 +0xac
FAIL	reflect [build failed]

I'm similarly running Fedora with a 5.3.10 kernel and an intel i7-8550U (4 core with hyperthreading disabled). I haven't tried bisecting this yet, but can

@aclements

This comment has been minimized.

Copy link
Member

@aclements aclements commented Nov 12, 2019

Thanks for all of the reports!

Could someone who can reproduce this try setting debugScanConservative to true in runtime/mgc.go and capturing a failure? In a second run, could you both set debugScanConservative and run with GODEBUG=gccheckmark=1?

The two "index out of range" failures are interesting. In both cases they're in scanobject -> heapBitsForAddr. We can tell the argument for heapBitsForAddr from the argument to scanobject. In the first one, it's 0x6e6962732f727375 and in the second it's 0xb929eeb762d7c042. Both are obviously bad addresses that must have come from a gcWork buffer. Since all pointers that go in to a gcWork buffer have to pass findObject, which does the exact same lookup as heapBitsForAddr, they must have been valid when they were inserted and were corrupted while in the gcWork buffer.

@siebenmann

This comment has been minimized.

Copy link

@siebenmann siebenmann commented Nov 12, 2019

Is it useful to do this if I can only reliably reproduce the vet-based failures, not the crashes? And is there something smaller to reproduce problems than running all.bash, which produces several MB of output with these options that I don't know how to usefully reduce? (I can make the full output available if it would be useful.)

@aclements

This comment has been minimized.

Copy link
Member

@aclements aclements commented Nov 12, 2019

Yes, it's useful for the vet-based failures, too. I only need the output from the failed process (basically, after the last "# ..."), which should be substantially less.

@myitcv

This comment has been minimized.

Copy link
Member

@myitcv myitcv commented Nov 12, 2019

I just ran into this via go test -short -count=1 ./... but cannot reproduce. The output was:

vet: cmd/govim/internal/golang_org_x_tools/telemetry/id.go:8:8: could not import crypto/rand (cannot import "crypto/rand" (unknown bexport format version -1 ("ashdefault -o de\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00and.go\x06Reader\x02io\x00\x01b\x01n\x03err\x1f$GOROOT/src/crypto/rand/util.go\x04rand\x04bits\x01p\x03Int\bmath/big\x03max\x05esc:\x02\x1b$GOROOT/src/math/big/int.go\x01x\x03nat\x04esc:\x04v·3$$GOROOT/src/math/bits/bits_tables.go\x1d$GOROOT/src/math/bits/bits.go\alen8tab\tmath/bits\x05Len64\x14$GOROOT/src/io/io.go\x04Read\x03neg\x03abs\x04Sign\bSetInt64\x01z\tSetUint64\x03Set\x04Bits\x04Word\aSetBits\x03Abs\x03Neg\x03Add\x01y\x03Sub\x03Mul\bMulRange\x01a\bBinomial\x01k\x03Quo\x03Rem\x06QuoRem\x01r\x03Div\x03Mod\x06DivMod\x01m\x03Cmp\x06CmpAbs\x05Int64\x06Uint64\aIsInt64\bIsUint64\tSetString\x01s\x04base\x0esetFromScanner\vByteScanner\bSetBytes\x03buf\x05Bytes\x06BitLen\x10TrailingZeroBits\x03Exp\x03GCD\tlehmerGCD\x04Rand\x03rnd\tmath/rand")), possibly version skew - reinstall package)
@myitcv

This comment has been minimized.

Copy link
Member

@myitcv myitcv commented Nov 12, 2019

Sorry, sent too early there. System details as follows:

$ go env
GO111MODULE="on"
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/myitcv/.cache/go-build"
GOENV="/home/myitcv/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/myitcv/gostuff"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/myitcv/gos"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/myitcv/gos/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/myitcv/gostuff/src/github.com/myitcv/govim/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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build072574281=/tmp/go-build -gno-record-gcc-switches"
$ go version
go version devel +99957b6930 Tue Nov 12 05:35:33 2019 +0000 linux/amd64
$ uname -r
5.3.0-19-generic
$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 19.10
Release:        19.10
Codename:       eoan
@mvdan

This comment has been minimized.

Copy link
Member Author

@mvdan mvdan commented Nov 12, 2019

@aclements I'm attaching the two logs you wanted. It's hard to reproduce it when running go vet on a single package, so I had an easier time with a for loop and many Go packages at once. I used the following bits of shell:

# first file
while true; do go clean -testcache -cache; go vet encoding/... |& tee out; grep bexport out && break; done
# second file
while true; do go clean -testcache -cache; GODEBUG=gccheckmark=1 go vet encoding/... |& tee out; grep bexport out && break; done

conservative.txt
conservative-gccheckmark.txt

If these files don't contain enough information, let me know and I can try again.

@mpx

This comment has been minimized.

Copy link
Contributor

@mpx mpx commented Nov 13, 2019

go version devel +43ec1b12f5 Wed Nov 13 01:15:54 2019 +0000 linux/amd64

I have been seeing very repeatable failures building all.bash under Fedora 30 (currently kernel 5.3.8-200.fc30.x86_64). The ... unknown bexport format version -1 ... always occurs in one of the tests.

Builds/tests are successful under GODEBUG=asyncpreemptoff=1.

Here is my debug output in case it's useful:

$ ./all.bash >& all-debugScanConservative.txt
$ GODEBUG=gccheckmark=1 ./all.bash >& all-debugScanConservative-gccheckmark.txt

all-debugScanConservative.txt
all-debugScanConservative-gccheckmark.txt

@zikaeroh

This comment has been minimized.

Copy link

@zikaeroh zikaeroh commented Nov 13, 2019

I just saw this too, while running some benchmarks:

# crypto/ecdsa
vet: ../../../sdk/gotip/src/crypto/ecdsa/ecdsa.go:36:2: could not import encoding/asn1 (cannot import "encoding/asn1" (unknown bexport format version -1 ("e/.antigen/bundl\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00/asn1.go\x00\x03Msg\x05Error\x01e\x0fStructuralError\x04esc:\x17asn1: structure error: \vSyntaxError\x14asn1: syntax error: \x05Bytes\tBitLength\x02At\x01b\tBitString\x01i")), possibly version skew - reinstall package)
# github.com/pmylund/go-cache
vet: ../../../nobackup/gotip_home/gopath/pkg/mod/github.com/pmylund/go-cache@v2.1.0+incompatible/cache.go:5:2: could not import fmt (cannot import "fmt" (unknown bexport format version -1 ("e/.antigen/bundl\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x06format\x01a\x00\x04esc:\x05esc:\x02\x18$GOROOT/src/fmt/print.go\x05Write\x01b\x01n\x03err\x05Width\x03wid\x02ok\tPrecision\x04prec\x04Flag\x01c\x06Format\x01f\x05State\x06String\bGoString\x01w\x06Writer\x02io")), possibly version skew - reinstall package)
?   	github.com/hortbot/hortbot	[no test files]

e/.antigen/bundl is something from my environment variables which has somehow made its way here...

go version devel +49e05d4f Wed Nov 13 20:53:39 2019 +0000 linux/amd64
Linux Jake-X1 5.3.11-arch1-1 #1 SMP PREEMPT Tue, 12 Nov 2019 22:19:48 +0000 x86_64 GNU/Linux
@josharian

This comment has been minimized.

Copy link
Contributor

@josharian josharian commented Nov 19, 2019

@aclements assuming for the moment that this is caused by async pre-emption, is there a way to disable stackguard-based pre-emption? That might make this reproduce more easily.

It seems like it should suffice to comment out this line from func preemptone:

	 gp.stackguard0 = stackPreempt

but I don't know for sure, or know what else that might break. :)

@ianlancetaylor

This comment has been minimized.

Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Nov 22, 2019

Sorry for confusion, I was being sarcastic.

Of course we have to fix it, one way or another.

@ianlancetaylor

This comment has been minimized.

Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Nov 22, 2019

Would somebody like to try this C program on a 5.3 kernel and see whether it reports any memory corruption? It runs without error on my 4.19 kernel.

#include <errno.h>
#include <signal.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <unistd.h>
#include <pthread.h>

static void die(const char* msg, int err) {
  if (err != 0) {
    fprintf(stderr, "%s: %s\n", msg, strerror(err));
  } else {
    fprintf(stderr, "%s\n", msg);
  }
  exit(EXIT_FAILURE);
}

static int sigs;

void handler(int sig __attribute__((unused)),
	     siginfo_t* info __attribute__((unused)),
	     void* context __attribute__((unused))) {
  sigs++;
}

void* thread(void* arg) {
  pthread_t tid;
  int err;

  tid = *(pthread_t*)(arg);
  for (;;) {
    usleep(100);
    err = pthread_kill(tid, SIGWINCH);
    if (err != 0) {
      die("pthread_kill", err);
    }
  }
  return NULL;
}

static char altSigstack[SIGSTKSZ];

/* Looking at the glibc source code it appears that it will use rep
   movsb somewhere above 2048 bytes.  */
static char buf1[2040];
static char buf2[2040];

/* Pretend to clobber memory to avoid compiler optimizations.  */
static void clobber() {
  asm volatile("" : : : "memory");
}

int main() {
  stack_t ss;
  struct sigaction sa;
  pthread_t tid;
  pthread_t ctid;
  int err;
  int i;

  memset(&ss, 0, sizeof ss);
  ss.ss_sp = altSigstack;
  ss.ss_size = sizeof altSigstack;
  if (sigaltstack(&ss, NULL) < 0) {
    die("sigaltstack", errno);
  }

  memset(&sa, 0, sizeof sa);
  sa.sa_sigaction = handler;
  sigfillset(&sa.sa_mask);
  sa.sa_flags = SA_ONSTACK | SA_RESTART;
  if (sigaction(SIGWINCH, &sa, NULL) < 0) {
    die("sigaction", errno);
  }

  tid = pthread_self();
  err = pthread_create(&ctid, NULL, thread, (void*)(&tid));
  if (err != 0) {
    die("pthread_create", err);
  }

  for (i = 0; i < sizeof buf1; i++) {
    buf1[i] = (char)(i);
  }

  for (i = 0; i < 10000000; i++) {
    memset(buf2, 0, sizeof buf2);
    clobber();
    memcpy(buf2, buf1, sizeof buf1);
    clobber();
    if (memcmp(buf1, buf2, sizeof buf1) != 0) {
      printf("memory corruption at iteration %d\n", i);
    }
    clobber();
  }

  printf("received %d signals\n", sigs);
}
@zikaeroh

This comment has been minimized.

Copy link

@zikaeroh zikaeroh commented Nov 22, 2019

I ran the above 50 times in a row on 5.3.12-arch1-1, and saw no corruption:

$ for i in $(seq 50); do echo -n "run $i: "; ./a.out; done
run 1: received 6081 signals
run 2: received 5944 signals
run 3: received 6151 signals
run 4: received 6027 signals
run 5: received 6050 signals
run 6: received 6083 signals
run 7: received 6032 signals
run 8: received 5986 signals
run 9: received 6057 signals
run 10: received 5958 signals
run 11: received 6092 signals
run 12: received 6017 signals
run 13: received 5942 signals
run 14: received 5933 signals
run 15: received 5975 signals
run 16: received 5900 signals
run 17: received 6016 signals
run 18: received 6002 signals
run 19: received 6046 signals
run 20: received 5962 signals
run 21: received 6034 signals
run 22: received 6118 signals
run 23: received 6251 signals
run 24: received 5978 signals
run 25: received 5958 signals
run 26: received 5980 signals
run 27: received 5932 signals
run 28: received 5999 signals
run 29: received 6044 signals
run 30: received 5999 signals
run 31: received 6003 signals
run 32: received 5991 signals
run 33: received 5981 signals
run 34: received 5937 signals
run 35: received 6019 signals
run 36: received 6160 signals
run 37: received 6056 signals
run 38: received 5953 signals
run 39: received 6034 signals
run 40: received 6157 signals
run 41: received 6048 signals
run 42: received 5975 signals
run 43: received 6150 signals
run 44: received 6027 signals
run 45: received 6047 signals
run 46: received 5950 signals
run 47: received 6169 signals
run 48: received 5894 signals
run 49: received 6083 signals
run 50: received 6033 signals
@siebenmann

This comment has been minimized.

Copy link

@siebenmann siebenmann commented Nov 22, 2019

I see no errors on my Fedora 30 machine with kernel 5.3.11, even with a drastically lengthened run time:

received 891483 signals
@ianlancetaylor

This comment has been minimized.

Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Nov 22, 2019

Thanks for trying it!

Pity it didn't fail. It would have been nice to be able to recreate the problem in C. At this point I'm a bit baffled as to what we are doing differently in Go. Well, one possibility is that it may be necessary to make some system calls that cause the kernel to use AVX registers internally, but I'm not sure what those would be.

@mdempsky

This comment has been minimized.

Copy link
Member

@mdempsky mdempsky commented Nov 22, 2019

Doesn't killall -WINCH send process-directed signals (i.e., using kill()), whereas pthread_kill sends thread-directed ones? (I know these behavior somewhat differently on OpenBSD; not sure if they do on Linux too.)

Maybe worth using fork+kill instead of threads to better recreate our current minimized test case?

@mdempsky mdempsky added the OS-Linux label Nov 22, 2019
@ianlancetaylor

This comment has been minimized.

Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Nov 22, 2019

Well, maybe, but we're seeing the problem with Go's runtime package signal preemption which uses thread-directed signals.

@aclements

This comment has been minimized.

Copy link
Member

@aclements aclements commented Nov 24, 2019

I set out to bisect the kernel and discovered that it also depends on the GCC version:

Kernel tag GCC Outcome
v5.3 9 Reproducible
v5.3 8 Not reproducible
v5.2 9 Kernel doesn't build
v5.2 8 Not reproducible

So this may happen in earlier kernel versions but be masked by their incompatibility with GCC 9. My guess is that GCC 9 started using AVX registers for something that GCC 8 didn't?

I'm going to see if a later v5.2.x kernel builds with GCC 9.

@josharian

This comment has been minimized.

Copy link
Contributor

@josharian josharian commented Nov 24, 2019

This is not the first time that the kernel, gcc, and signals have gotten tangled up in a mess: https://news.ycombinator.com/item?id=13313563

@aclements

This comment has been minimized.

Copy link
Member

@aclements aclements commented Nov 24, 2019

I'm finally ready to actually bisect. Setting CONFIG_RETPOLINE to n works around the GCC 9 incompatibility. With this configuration, I've been able to reproduce the failure with v5.2, but NOT with v5.1. I'm now bisecting between the two.

For reference, here's the script I'm using to configure, build, and load the kernel. This is based on the ubuntu-1910-eoan-v20191114 GCE image (grown to 50 GiB to fit the kernel build, sigh).

#!/bin/sh
set -e
# Start with system's 5.3 config
cp /boot/config-5.3.0-1008-gcp .config
# Work around GCC 9 flag incompatibility
sed -r -i 's/^(CONFIG_RETPOLINE)=y/\1=n/' .config
# Remove file systems that are modules
sed -r -i 's/^(CONFIG_.*_FS)=m/\1=n/' .config
# Disable big hardware subsystems we don't need
sed -r -i 's/^(CONFIG_(BT|WLAN|WIRELESS|SOUND|INFINIBAND|USB_SUPPORT|MEDIA_SUPPORT|FIREWIRE|ISDN|IIO|INPUT_(JOYSTICK|TOUCHSCREEN|TABLET|MISC)))=./\1=n/' .config
# Turn off ETHERNET (we use VIRTIO_NET) and things that force it on
sed -r -i 's/^(CONFIG_(ETHERNET|SCSI_CXGB3_ISCSI|SCSI_BNX2_ISCSI|SCSI_BNX2X_FCOE))=./\1=n/' .config
# Clean up the config
make olddefconfig
# Build kernel and install modules
make -j12 && sudo make modules_install
# Load kexec image. Command line from /boot/grub/grub.cfg
sudo kexec -l arch/x86/boot/bzImage --append="root=PARTUUID=2954cd84-339a-4c4a-b80d-c039bd33478c ro scsi_mod.use_blk_mq=Y console=ttyS0" --initrd=/boot/initrd.img-5.3.0-1008-gcp
# Run sudo kexec -e to reboot into loaded kernel (does NOT do a clean shut down)
@aclements

This comment has been minimized.

Copy link
Member

@aclements aclements commented Nov 25, 2019

I've bisected the issue to kernel commit torvalds/linux@d9c9ce3. I haven't dug into this commit yet, but it appears to be a fix for bug that was introduced earlier (or possibly a redo of an earlier commit).

For reference, torvalds/linux@a352a3b in that same commit series introduced another bug first that produced similar failure types, but at a far higher rate (I couldn't even run cmd/go). However, this was fixed later in the series, somewhere between torvalds/linux@e0d3602 and torvalds/linux@1d731e7.

My first bisect log is below. This led to the fail-fast failure.

# bad: [0ecfebd2b52404ae0c54a878c872bb93363ada36] Linux 5.2
# good: [e93c9c99a629c61837d5a7fc2120cd2b6c70dbdd] Linux 5.1
git bisect start 'v5.2' 'v5.1'
# bad: [a2d635decbfa9c1e4ae15cb05b68b2559f7f827c] Merge tag 'drm-next-2019-05-09' of git://anongit.freedesktop.org/drm/drm
git bisect bad a2d635decbfa9c1e4ae15cb05b68b2559f7f827c
# bad: [82efe439599439a5e1e225ce5740e6cfb777a7dd] Merge tag 'devicetree-for-5.2' of git://git.kernel.org/pub/scm/linux/kernel/git/robh/linux
git bisect bad 82efe439599439a5e1e225ce5740e6cfb777a7dd
# bad: [78438ce18f26dbcaa8993bb45d20ffb0cec3bc3e] Merge branch 'stable-fodder' of git://git.kernel.org/pub/scm/linux/kernel/git/viro/vfs
git bisect bad 78438ce18f26dbcaa8993bb45d20ffb0cec3bc3e
# good: [275b103a26e218b3d739e5ab15be6b40303a1428] Merge tag 'edac_for_5.2' of git://git.kernel.org/pub/scm/linux/kernel/git/bp/bp
git bisect good 275b103a26e218b3d739e5ab15be6b40303a1428
# good: [962d5ecca101e65175a8cdb1b91da8e1b8434d96] Merge tag 'regmap-v5.2' of git://git.kernel.org/pub/scm/linux/kernel/git/broonie/regmap
git bisect good 962d5ecca101e65175a8cdb1b91da8e1b8434d96
# good: [9bff9dfc513bd5de72cb59f4bffb72cf0a5aa526] Merge tag 'spi-v5.2' of git://git.kernel.org/pub/scm/linux/kernel/git/broonie/spi
git bisect good 9bff9dfc513bd5de72cb59f4bffb72cf0a5aa526
# good: [573de2a6e844cb230c4483833f29b8344a6a17cc] Merge branch 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/livepatching/livepatching
git bisect good 573de2a6e844cb230c4483833f29b8344a6a17cc
# good: [b62de322579702f07175fc275ecb2c3afae6cd96] hugetlb: make use of ->free_inode()
git bisect good b62de322579702f07175fc275ecb2c3afae6cd96
# bad: [d9c9ce34ed5c892323cbf5b4f9a4c498e036316a] x86/fpu: Fault-in user stack if copy_fpstate_to_sigframe() fails
git bisect bad d9c9ce34ed5c892323cbf5b4f9a4c498e036316a
# good: [577ff465f5a6a5a0866d75a033844810baca20a0] x86/fpu: Only write PKRU if it is different from current
git bisect good 577ff465f5a6a5a0866d75a033844810baca20a0
#
# Below here the failure mode changed to fail almost instantly in cmd/go,
# though the types of failures looked similar.
#
# bad: [e0d3602f933367881bddfff310a744e6e61c284c] x86/fpu: Inline copy_user_to_fpregs_zeroing()
git bisect bad e0d3602f933367881bddfff310a744e6e61c284c
# good: [383c252545edcc708128e2028a2318b05c45ede4] x86/entry: Add TIF_NEED_FPU_LOAD
git bisect good 383c252545edcc708128e2028a2318b05c45ede4
# bad: [a352a3b7b7920212ee4c45a41500c66826318e92] x86/fpu: Prepare copy_fpstate_to_sigframe() for TIF_NEED_FPU_LOAD
git bisect bad a352a3b7b7920212ee4c45a41500c66826318e92
# good: [69277c98f5eef0d9839699b7825923c3985f665f] x86/fpu: Always store the registers in copy_fpstate_to_sigframe()
git bisect good 69277c98f5eef0d9839699b7825923c3985f665f
# first bad commit: [a352a3b7b7920212ee4c45a41500c66826318e92] x86/fpu: Prepare copy_fpstate_to_sigframe() for TIF_NEED_FPU_LOAD

After this I backed up and looked for the original failure. This bisect also happened to reveal that the fast failure had been fixed before the original failure was introduced.

# bad: [d9c9ce34ed5c892323cbf5b4f9a4c498e036316a] x86/fpu: Fault-in user stack if copy_fpstate_to_sigframe() fails
# good: [e0d3602f933367881bddfff310a744e6e61c284c] x86/fpu: Inline copy_user_to_fpregs_zeroing()
git bisect start 'd9c9ce34ed5c892323cbf5b4f9a4c498e036316a' 'e0d3602f933367881bddfff310a744e6e61c284c'
# good: [1d731e731c4cd7cbd3b1aa295f0932e7610da82f] x86/fpu: Add a fastpath to __fpu__restore_sig()
git bisect good 1d731e731c4cd7cbd3b1aa295f0932e7610da82f
# good: [06b251dff78704c7d122bd109384d970a7dbe94d] x86/fpu: Restore regs in copy_fpstate_to_sigframe() in order to use the fastpath
git bisect good 06b251dff78704c7d122bd109384d970a7dbe94d
# good: [a5eff7259790d5314eff10563d6e59d358cce482] x86/pkeys: Add PKRU value to init_fpstate
git bisect good a5eff7259790d5314eff10563d6e59d358cce482
# first bad commit: [d9c9ce34ed5c892323cbf5b4f9a4c498e036316a] x86/fpu: Fault-in user stack if copy_fpstate_to_sigframe() fails
@aclements

This comment has been minimized.

Copy link
Member

@aclements aclements commented Nov 25, 2019

Progress update.

Eagerly faulting in the gsignal stack immediately after allocating it (by just writing zeros to the whole stack) successfully mitigates the issue. This indicates that it's related to the failure path of torvalds/linux@d9c9ce3, which deals with the stack not being mapped for the xsave area. This is a workaround, but not a great one, since other things could cause those stack pages to be faulted out (though this isn't very likely).

I tried modifying the C reproducer to mmap the sigaltstack and MADV_DONTNEED it before every pthread_kill, but it still doesn't reproduce the issue.

Things that haven't changed the behavior:

  • Building the kernel with -mno-avx2
  • Add back set_thread_flag(TIF_NEED_FPU_LOAD) to copy_fpstate_to_sigframe
@ianlancetaylor

This comment has been minimized.

Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Nov 25, 2019

We could use mlock to lock the signal stack into memory on affected systems.

Would be really nice to have a C reproducer, though. If you write 1 to /proc/sys/vm/drop_caches, the Linux kernel is supposed to drop the page cache. That suggests that we could mmap some file into memory and use that memory space for the signal stack. Then after each signal msync the signal stack and set drop_caches. That should force the stack to be paged in for the next signal. Maybe.

@mdempsky

This comment has been minimized.

Copy link
Member

@mdempsky mdempsky commented Nov 25, 2019

What about just mmap'ing new signal stack VMA each iteration of the main loop?

@aclements

This comment has been minimized.

Copy link
Member

@aclements aclements commented Nov 25, 2019

I just got the C reproducer working. I'm working on tidying it up and I'll post it. Both madvising and mmaping the sigaltstack work to clear the pages (and that is necessary). The other missing ingredient was just running lots of the processes simultaneously.

@aclements

This comment has been minimized.

Copy link
Member

@aclements aclements commented Nov 26, 2019

Here's the C reproducer. This fails almost instantly on 5.3.0-1008-gcp, and torvalds/linux@d9c9ce3 (5.1.0-rc3+). It does not fail at the parent of that commit (torvalds/linux@a5eff72).

I'll work on filing this upstream with Linux.

// Build with: gcc -pthread test.c
//
// This demonstrates an issue where AVX state becomes corrupted when a
// signal is delivered where the signal stack pages aren't faulted in.
//
// There appear to be three necessary ingredients, which are marked
// with "!!!" below:
//
// 1. A thread doing AVX operations using YMM registers.
//
// 2. A signal where the kernel must fault in stack pages to write the
//    signal context.
//
// 3. Context switches. Having a single task isn't sufficient.

#include <errno.h>
#include <signal.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <unistd.h>
#include <pthread.h>
#include <sys/mman.h>
#include <sys/prctl.h>
#include <sys/wait.h>

static int sigs;

static stack_t altstack;
static pthread_t tid;

static void die(const char* msg, int err) {
  if (err != 0) {
    fprintf(stderr, "%s: %s\n", msg, strerror(err));
  } else {
    fprintf(stderr, "%s\n", msg);
  }
  exit(EXIT_FAILURE);
}

void handler(int sig __attribute__((unused)),
             siginfo_t* info __attribute__((unused)),
             void* context __attribute__((unused))) {
  sigs++;
}

void* sender(void *arg) {
  int err;

  for (;;) {
    usleep(100);
    err = pthread_kill(tid, SIGWINCH);
    if (err != 0)
      die("pthread_kill", err);
  }
  return NULL;
}

void dump(const char *label, unsigned char *data) {
  printf("%s =", label);
  for (int i = 0; i < 32; i++)
    printf(" %02x", data[i]);
  printf("\n");
}

void doAVX(void) {
  unsigned char input[32];
  unsigned char output[32];

  // Set input to a known pattern.
  for (int i = 0; i < sizeof input; i++)
    input[i] = i;
  // Mix our PID in so we detect cross-process leakage, though this
  // doesn't appear to be what's happening.
  pid_t pid = getpid();
  memcpy(input, &pid, sizeof pid);

  while (1) {
    for (int i = 0; i < 1000; i++) {
      // !!! Do some computation we can check using YMM registers.
      asm volatile(
        "vmovdqu %1, %%ymm0;"
        "vmovdqa %%ymm0, %%ymm1;"
        "vmovdqa %%ymm1, %%ymm2;"
        "vmovdqa %%ymm2, %%ymm3;"
        "vmovdqu %%ymm3, %0;"
        : "=m" (output)
        : "m" (input)
        : "memory", "ymm0", "ymm1", "ymm2", "ymm3");
      // Check that input == output.
      if (memcmp(input, output, sizeof input) != 0) {
        dump("input ", input);
        dump("output", output);
        die("mismatch", 0);
      }
    }

    // !!! Release the pages of the signal stack. This is necessary
    // because the error happens when copy_fpstate_to_sigframe enters
    // the failure path that handles faulting in the stack pages.
    // (mmap with MMAP_FIXED also works.)
    //
    // (We do this here to ensure it doesn't race with the signal
    // itself.)
    if (madvise(altstack.ss_sp, altstack.ss_size, MADV_DONTNEED) != 0)
      die("madvise", errno);
  }
}

void doTest() {
  // Create an alternate signal stack so we can release its pages.
  void *altSigstack = mmap(NULL, SIGSTKSZ, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0);
  if (altSigstack == MAP_FAILED)
    die("mmap failed", errno);
  altstack.ss_sp = altSigstack;
  altstack.ss_size = SIGSTKSZ;
  if (sigaltstack(&altstack, NULL) < 0)
    die("sigaltstack", errno);

  // Install SIGWINCH handler.
  struct sigaction sa = {
    .sa_sigaction = handler,
    .sa_flags = SA_ONSTACK | SA_RESTART,
  };
  sigfillset(&sa.sa_mask);
  if (sigaction(SIGWINCH, &sa, NULL) < 0)
    die("sigaction", errno);

  // Start thread to send SIGWINCH.
  int err;
  pthread_t ctid;
  tid = pthread_self();
  if ((err = pthread_create(&ctid, NULL, sender, NULL)) != 0)
    die("pthread_create sender", err);

  // Run test.
  doAVX();
}

void *exiter(void *arg) {
  sleep(60);
  exit(0);
}

int main() {
  int err;
  pthread_t ctid;

  // !!! We need several processes to cause context switches. Threads
  // probably also work. I don't know if the other tasks also need to
  // be doing AVX operations, but here we do.
  int nproc = sysconf(_SC_NPROCESSORS_ONLN);
  for (int i = 0; i < 2 * nproc; i++) {
    pid_t child = fork();
    if (child < 0) {
      die("fork failed", errno);
    } else if (child == 0) {
      // Exit if the parent dies.
      prctl(PR_SET_PDEATHSIG, SIGKILL, 0, 0, 0);
      doTest();
    }
  }

  // Exit after a while.
  if ((err = pthread_create(&ctid, NULL, exiter, NULL)) != 0)
    die("pthread_create exiter", err);

  // Wait for a failure.
  int status;
  if (wait(&status) < 0)
    die("wait", errno);
  if (status == 0)
    die("child unexpectedly exited with success", 0);
  fprintf(stderr, "child process failed\n");
  exit(1);
}
@dr2chase

This comment has been minimized.

Copy link
Contributor

@dr2chase dr2chase commented Nov 26, 2019

For your nerd-sniping amusement (and not mine), the bug is somewhere in the differences in these two disassembled files. Link Linux with the gcc8 one, all is well, link with the other, it goes bad.

signal.8.dis.txt
signal.9.dis.txt

There's a ridiculous amount of inlining going on, not sure it helps to have the source annotation in the disassembly, but here it is:

signal.8.il.dis.txt
signal.9.il.dis.txt

The source file in question, arch/x86/kernel/fpu/signal.o, is from this commit: torvalds/linux@d9c9ce3

I verified this by building two kernels, one entirely compiled by gcc8 except for arch/x86/kernel/fpu/signal.o, compiled by gcc9. It fails . The other kernel is built entirely by gcc9, except for arch/x86/kernel/fpu/signal.o, built by gcc8. It does not fail.

Enjoy!

@aclements

This comment has been minimized.

Copy link
Member

@aclements aclements commented Nov 26, 2019

For completeness, I have also reproduced at torvalds/linux@b81ff10, which fixed a bug in the kernel code in question (but apparently not this bug), and at v5.4.

@aclements

This comment has been minimized.

Copy link
Member

@aclements aclements commented Nov 26, 2019

I've filed the upstream kernel bug here: https://bugzilla.kernel.org/show_bug.cgi?id=205663

@ianlancetaylor

This comment has been minimized.

Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Nov 26, 2019

@dr2chase One difference I see in the disassembly is that GCC 9 is caching the address of the thread-local variable checked by test_thread_flag across the function, while GCC 8 is reloading it each time. If the retry loop can cause a change between threads, then the call to test_thread_flag(TIF_NEED_FPU_LOAD) will be looking at the wrong thread if the retry occurs.

@dr2chase

This comment has been minimized.

Copy link
Contributor

@dr2chase dr2chase commented Nov 26, 2019

FYI, I reproduced, at Linux tip (5.4 + a little), the dependence of the bug on how arch/x86/kernel/fpu/signal.o is compiled --

  • if that is the only file compiled with gcc9, the rest with gcc8, then the bug appears;
  • if that is the only file compiled with gcc8, the rest with gcc9 then the bug does not appear.

The exact gcc versions are

gcc-8 --version
gcc-8 (Ubuntu 8.3.0-23ubuntu2) 8.3.0

and

gcc-9 --version
gcc-9 (Ubuntu 9.2.1-9ubuntu2) 9.2.1 20191008
@josharian

This comment has been minimized.

Copy link
Contributor

@josharian josharian commented Nov 26, 2019

@ianlancetaylor @dr2chase seems like at this point further diagnosis of the issue should occur over at bugzilla, so that kernel developers will have the benefit of it.

@dr2chase

This comment has been minimized.

Copy link
Contributor

@dr2chase dr2chase commented Nov 26, 2019

Austin said he'd copy my remarks over there (I don't think I've got an account) and this is pretty much the end of it for me. I'm pretty sure we gave them a nice start. Ian's observation has a good smell to it.

@mdempsky

This comment has been minimized.

Copy link
Member

@mdempsky mdempsky commented Nov 26, 2019

Great work @aclements et al identifying the root cause here.

Should we start discussing how Go should respond to this issue?

Is there an easy/reliable way to detect affected kernels? E.g., is kernel version number a reliable test?

@ianlancetaylor suggested mlock'ing the msignal stack into memory; we probably only need to lock the top page or two (not sure exactly how big sigcontext is w/ AVX-512 register files, but 32 512-bit registers by itself is already 2KiB).

As a fallback (e.g., when mlock fails due to ulimit), we could just explicitly fault the pages at allocation time, and maybe again before sending an inter-thread signal?

@ianlancetaylor

This comment has been minimized.

Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Nov 26, 2019

@mdempsky There is some discussion of workarounds over at #35777 (I forget why there are two different issues).

@knweiss

This comment has been minimized.

Copy link

@knweiss knweiss commented Nov 27, 2019

There is a patch from Sebastian Andrzej Siewior now and he asks the reporters to test and verify.

@gopherbot

This comment has been minimized.

Copy link

@gopherbot gopherbot commented Dec 5, 2019

Change https://golang.org/cl/209899 mentions this issue: runtime: mlock top of signal stack on Linux 5.2–5.4.1

@gopherbot gopherbot closed this in 8174f7f Dec 5, 2019
@aclements

This comment has been minimized.

Copy link
Member

@aclements aclements commented Dec 5, 2019

For everyone following along, I've closed up with a summary over on #35777. Thanks for all of the reports and helping to debug!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
You can’t perform that action at this time.