go: runtime: memory corruption crashes with os/exec on Linux kernel 4.4

TEXT runtime·walltime(SB),NOSPLIT,$16
	// Be careful. We're calling a function with gcc calling convention here.
	// We're guaranteed 128 bytes on entry, and we've taken 16, and the
	// call uses another 8.
	// That leaves 104 for the gettime code to use. Hope that's enough!

0000000000000030 <__vdso_clock_gettime>:
  30:	55                   	push   %rbp
  31:	48 89 e5             	mov    %rsp,%rbp
  34:	48 81 ec 20 10 00 00 	sub    $0x1020,%rsp
  3b:	48 83 0c 24 00       	orq    $0x0,(%rsp)
  40:	48 81 c4 20 10 00 00 	add    $0x1020,%rsp

GCC is doing a 4K stack probe here. Two things could happen: a segfault if that page is unmapped, or nothing in the general case, since it’s just an OR 0. But since it’s not an atomic/locked op, if it races another thread, it could corrupt data.

So yeah, 104 bytes is not enough. Whether the kernel should be doing stack probes in vdso is another question entirely… but this explains why only Go with its tight split stacks breaks. And why this whole mess is so nondeterministic and the crashes random and hard to reproduce and require multiple threads.

Turns out my second time debugging an issue in the go runtime wound up being a bug in Go->C interop again. Whee.

Edit: just confirmed that hexediting those probes from 0x1020 to 0x20 bytes on one of the crash-inducing kernels cures the crashes.

Turns out my repro is related to the compiler and compiler flags used to compile the kernel.

• linux-4.13.9-gentoo + gcc (Gentoo Hardened 5.4.0-r3 p1.3, pie-0.6.5) 5.4.0 + CONFIG_OPTIMIZE_INLINING=n - no crash
• linux-4.13.9-gentoo + gcc (Gentoo Hardened 6.4.0 p1.0) 6.4.0 + CONFIG_OPTIMIZE_INLINING=n - crash
• linux-4.13.9-gentoo + gcc (Gentoo Hardened 6.4.0 p1.0) 6.4.0 + CONFIG_OPTIMIZE_INLINING=y - no crash

Will now try to narrow down which change introduced by flipping CONFIG_OPTIMIZE_INLINING causes the issue.

Of course the issue can be fixed in the kernel (and that might even make sense). But right now it’s Go making the undocumented assumptions. So there are two options here (not mutually exclusive):

1. Fix Go so it stops assuming vDSO stack usage limits
2. Convince the kernel guys to change the vDSO spec to guarantee a maximum stack usage, which may include disabling stack probing and/or inlining everything

Doing 2 and not 1 of course means accepting that Go code will potentially break on certain kernels before the change.

That is already an impressive job of fault isolation.

@marcan: Awesome debugging. Thanks!

The 10ns slowdown is unfortunate, but if that’s what we have to do, that’s what we have to do. I made some suggestions on Ian’s CL that may speed things up, but we’ll see.

I emailed the x86 vDSO maintainer (cc: x86, linux-kernel, kernel-hardening) to see what their take on all this is (but I still think Go should fix this, e.g. somehow allocate more stack space or disable vDSO usage on current kernels if the overhead of cgo/stack munging is greater than just using a syscall).

Edit: thread

Note that I came here through node_exporter crashing, and it doesn’t use os/exec. I think that reproducer just so happens to be good at triggering this issue by coincidence, even though it has nothing to do with exec directly.

Also keep in mind that CONFIG_OPTIMIZE_INLINING is somewhat coincidental too; for some reason flipping that flag off (which is supposed to force inline more functions) is making GCC not inline the vread_tsc function. That function isn’t marked inline, so it’s perfectly within its right to do so. But there’s no guarantee that under some other combination of GCC version and flags it won’t happen too. Basically, any GCC with -fstack-check enabled by default can trigger this bug if the vDSO function makes any function calls at all as compiled, which could happen for any reason since the source code does indeed make function calls. You’re depending on everything getting inlined to not crash, even though the kernel source makes no attempt to guarantee that.

@marcan Thanks very much for the detailed analysis.

That is an odd result, though, because as far as I can tell it doesn’t have anything to do with forking. I think you’ve found a code path that could cause a random crash in approximately any amd64 GNU/Linux Go program at approximately any time, if running on a kernel compiled with CONFIG_OPTIMIZE_INLINING turned off (fortunately that is not the default). We clearly need to fix that, somehow. But now I’m confused as to why it happens with this particular reproducer.

Upgrading to go1.8.3 did not resolve the issue, and we’ve narrowed it down to being related to os/exec.

A coworker reminded me of the FreeBSD os/exec memory corruption bug—#15658—and indeed, the first reproducer there (from May 11, 2016) leads to crashes on a Linux 4.4 system.

$ uname -a
Linux redacted 4.4.0-78-generic #99-Ubuntu SMP Thu Apr 27 15:29:09 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

Here are the beginnings of the three crashes I’ve seen with the May 11, 2016 reproducer so far (from spending around 100–250 process-hours of execution):

Starting a bunch of goroutines...
unexpected fault address 0x0
fatal error: fault
[signal SIGSEGV: segmentation violation code=0x80 addr=0x0 pc=0x461df2]

goroutine 189069 [running]:
runtime.throw(0x4cd41c, 0x5)
	/usr/local/go/src/runtime/panic.go:596 +0x95 fp=0xc420067a18 sp=0xc4200679f8
runtime.sigpanic()
	/usr/local/go/src/runtime/signal_unix.go:297 +0x28c fp=0xc420067a68 sp=0xc420067a18
syscall.ByteSliceFromString(0x6962732f7273752f, 0x657572742f6e, 0xc4202ce130, 0xc4202ce070, 0x9, 0xc4202ce110, 0xa)
	/usr/local/go/src/syscall/syscall.go:51 +0x32 fp=0xc420067ac8 sp=0xc420067a68
syscall.BytePtrFromString(0x6962732f7273752f, 0x657572742f6e, 0x2, 0xc4202ce130, 0x2)
	/usr/local/go/src/syscall/syscall.go:71 +0x39 fp=0xc420067b10 sp=0xc420067ac8
syscall.SlicePtrFromStrings(0xc4202ce000, 0x1, 0x1, 0x0, 0x0, 0x7f2bde7d3113, 0x7f2bde7d3140, 0x1e)
	/usr/local/go/src/syscall/exec_unix.go:87 +0x97 fp=0xc420067b80 sp=0xc420067b10
syscall.forkExec(0xc4202ce070, 0x9, 0xc4202ce000, 0x1, 0x1, 0xc420067d90, 0x0, 0x0, 0x0)
	/usr/local/go/src/syscall/exec_unix.go:154 +0x10d fp=0xc420067ca8 sp=0xc420067b80
syscall.StartProcess(0xc4202ce070, 0x9, 0xc4202ce000, 0x1, 0x1, 0xc420067d90, 0x2, 0x4, 0x0, 0xc420067d60)
	/usr/local/go/src/syscall/exec_unix.go:240 +0x64 fp=0xc420067d00 sp=0xc420067ca8
os.startProcess(0xc4202ce070, 0x9, 0xc4202ce000, 0x1, 0x1, 0xc420067f38, 0xc4203f84e0, 0x1a, 0x1a)
	/usr/local/go/src/os/exec_posix.go:45 +0x1a3 fp=0xc420067de8 sp=0xc420067d00
os.StartProcess(0xc4202ce070, 0x9, 0xc4202ce000, 0x1, 0x1, 0xc420067f38, 0x0, 0x0, 0xc4202ce070)
	/usr/local/go/src/os/exec.go:94 +0x64 fp=0xc420067e40 sp=0xc420067de8
os/exec.(*Cmd).Start(0xc4203e0000, 0x4, 0x0)
	/usr/local/go/src/os/exec/exec.go:359 +0x3d2 fp=0xc420067f90 sp=0xc420067e40
main.run(0xc420092060)
	/tmp/15658.go:11 +0x68 fp=0xc420067fd8 sp=0xc420067f90
runtime.goexit()
	/usr/local/go/src/runtime/asm_amd64.s:2197 +0x1 fp=0xc420067fe0 sp=0xc420067fd8
created by main.main
	/tmp/15658.go:35 +0x141

goroutine 1 [runnable]:
main.main()
	/tmp/15658.go:34 +0x11f

[...]

Starting a bunch of goroutines...
fatal error: forEachP: P did not run fn
acquirep: p->m=842353238016(37) p->status=1
fatal error: acquirep: invalid p state
acquirep: p->m=0(0) p->status=3
fatal error: acquirep: invalid p state

runtime stack:
runtime.throw(0x4d09a1, 0x1a)
	/usr/local/go/src/runtime/panic.go:596 +0x95
runtime.forEachP(0x4d4460)
	/usr/local/go/src/runtime/proc.go:1276 +0x2df
runtime.gcMarkDone.func1()
	/usr/local/go/src/runtime/mgc.go:1153 +0x2d
runtime.systemstack(0xc420436d40)
	/usr/local/go/src/runtime/asm_amd64.s:327 +0x79
runtime.mstart()
	/usr/local/go/src/runtime/proc.go:1132

goroutine 400850 [running]:
runtime.systemstack_switch()
	/usr/local/go/src/runtime/asm_amd64.s:281 fp=0xc42012ef30 sp=0xc42012ef28
runtime.gcMarkDone()
	/usr/local/go/src/runtime/mgc.go:1154 +0xe9 fp=0xc42012ef50 sp=0xc42012ef30
runtime.gcBgMarkWorker(0xc42001b300)
	/usr/local/go/src/runtime/mgc.go:1581 +0x303 fp=0xc42012efd8 sp=0xc42012ef50
runtime.goexit()
	/usr/local/go/src/runtime/asm_amd64.s:2197 +0x1 fp=0xc42012efe0 sp=0xc42012efd8
created by runtime.gcBgMarkStartWorkers
	/usr/local/go/src/runtime/mgc.go:1412 +0x98

goroutine 1 [chan receive]:
main.main()
	/tmp/15658.go:34 +0x11f

[...]

Starting a bunch of goroutines...
fatal error: workbuf is not empty

runtime stack:
runtime.throw(0x4cfa21, 0x14)
	/usr/local/go/src/runtime/panic.go:596 +0x95 fp=0xc420195df0 sp=0xc420195dd0
runtime.(*workbuf).checkempty(0x7f9ead2609c0)
	/usr/local/go/src/runtime/mgcwork.go:320 +0x4e fp=0xc420195e10 sp=0xc420195df0
runtime.getempty(0xc420023828)
	/usr/local/go/src/runtime/mgcwork.go:332 +0x96 fp=0xc420195e48 sp=0xc420195e10
runtime.(*gcWork).init(0xc420022528)
	/usr/local/go/src/runtime/mgcwork.go:90 +0x22 fp=0xc420195e60 sp=0xc420195e48
runtime.(*gcWork).tryGet(0xc420022528, 0x27)
	/usr/local/go/src/runtime/mgcwork.go:156 +0xdb fp=0xc420195e88 sp=0xc420195e60
runtime.gcDrain(0xc420022528, 0x2)
	/usr/local/go/src/runtime/mgcmark.go:1075 +0x2eb fp=0xc420195ec0 sp=0xc420195e88
runtime.gchelper()
	/usr/local/go/src/runtime/mgc.go:1912 +0x110 fp=0xc420195ef0 sp=0xc420195ec0
runtime.stopm()
	/usr/local/go/src/runtime/proc.go:1653 +0xdd fp=0xc420195f18 sp=0xc420195ef0
runtime.gcstopm()
	/usr/local/go/src/runtime/proc.go:1854 +0xb7 fp=0xc420195f40 sp=0xc420195f18
runtime.schedule()
	/usr/local/go/src/runtime/proc.go:2186 +0x110 fp=0xc420195f80 sp=0xc420195f40
runtime.park_m(0xc4202ec000)
	/usr/local/go/src/runtime/proc.go:2285 +0xab fp=0xc420195fb8 sp=0xc420195f80
runtime.mcall(0x0)
	/usr/local/go/src/runtime/asm_amd64.s:269 +0x5b fp=0xc420195fc8 sp=0xc420195fb8

goroutine 1 [chan receive]:
runtime.gopark(0x4d45a8, 0xc4200940b8, 0x4ce3a3, 0xc, 0x17, 0x3)
	/usr/local/go/src/runtime/proc.go:271 +0x13a fp=0xc420064e00 sp=0xc420064dd0
runtime.goparkunlock(0xc4200940b8, 0x4ce3a3, 0xc, 0x44b417, 0x3)
	/usr/local/go/src/runtime/proc.go:277 +0x5e fp=0xc420064e40 sp=0xc420064e00
runtime.chanrecv(0x4ab280, 0xc420094060, 0x0, 0xc420064f01, 0x49a6f1)
	/usr/local/go/src/runtime/chan.go:513 +0x371 fp=0xc420064ee0 sp=0xc420064e40
runtime.chanrecv1(0x4ab280, 0xc420094060, 0x0)
	/usr/local/go/src/runtime/chan.go:395 +0x35 fp=0xc420064f18 sp=0xc420064ee0
main.main()
	/tmp/15658.go:34 +0x11f fp=0xc420064f88 sp=0xc420064f18
runtime.main()
	/usr/local/go/src/runtime/proc.go:185 +0x20a fp=0xc420064fe0 sp=0xc420064f88
runtime.goexit()
	/usr/local/go/src/runtime/asm_amd64.s:2197 +0x1 fp=0xc420064fe8 sp=0xc420064fe0

[...]

I tried the March 8, 2017 reproducer with seven variants, but none crashed within a few seconds. I haven’t seen variant (1) crash after 60 process-hours of execution.

My very slow and not terribly reliable reproducer (version c7141caadf in a private repo) is below:

package main

import (
	"context"
	"flag"
	"log"
	"os/exec"
	"sync"
	"sync/atomic"
)

func main() {
	var (
		workers = flag.Int("workers", 10, "worker count")
		cmdIter = flag.Int("cmd_iter", 10000, "iterations per command worker")
		cmd     = flag.String("cmd", "/bin/true", "command to run")
	)
	flag.Parse()

	ctx := context.Background()

	var wg sync.WaitGroup
	ctx, cancel := context.WithCancel(ctx)
	errs := make(chan error, 1)
	for i := 0; i < *workers; i++ {
		wg.Add(1)
		go func() {
			defer wg.Done()

			for j := 0; j < *cmdIter; j++ {
				sink.Store(make([]*byte, 1<<20))

				err := doCmd(ctx, *cmd)

				if err != nil {
					cancel()
					select {
					case errs <- err:
					default:
					}
					return
				}
			}
		}()
	}

	wg.Wait()
	cancel()
	close(errs)
	err := <-errs
	if err != nil {
		log.Fatalf("%v", err)
	}
}

var sink atomic.Value

func doCmd(ctx context.Context, command string) error {
	ctx, cancel := context.WithCancel(ctx)
	defer cancel()

	cmd := exec.Command(command)

	err := cmd.Start()
	if err != nil {
		return err
	}

	done := make(chan error, 1)
	go func() {
		err := cmd.Wait()
		done <- err
	}()

	select {
	case <-ctx.Done():
		err := cmd.Process.Kill()
		if err != nil {
			return err
		}
		return ctx.Err()
	case err = <-done:
		return err
	}
}

It crashed with the following error while running under perf trace record while running with the arguments -cmd=/bin/true -workers=10 -cmd_iter=300. That was one crash out of 4480 attempts.

The “stress” command here is golang.org/x/tools/cmd/stress

$ sudo ./stress -timeout=1h -p=10 -- bash -c 'trace_file="/tmp/perf-trace-$(date +%s)-$$" && echo "$trace_file" && perf trace record --quiet --output="$trace_file" -- ./20427.c7141caadf -cmd=/bin/true -workers=10 -cmd_iter=300 && (rm -- "$trace_file" || true)'

fatal error: unexpected signal during runtime execution
fatal error: unexpected signal during runtime execution
[signal SIGSEGV: segmentation violation code=0x1 addr=0x18 pc=0x42d1bf]

runtime stack:
runtime.throw(0x4e755d, 0x2a)
	/usr/local/go/src/runtime/panic.go:596 +0x95
runtime.sigpanic()
	/usr/local/go/src/runtime/signal_unix.go:274 +0x2db
runtime.execute(0xc4238c4000, 0xc42001b300)
	/usr/local/go/src/runtime/proc.go:1874 +0x17f
runtime.schedule()
	/usr/local/go/src/runtime/proc.go:2239 +0x127
runtime.exitsyscall0(0xc420001a00)
	/usr/local/go/src/runtime/proc.go:2772 +0xec
runtime.mcall(0x0)
	/usr/local/go/src/runtime/asm_amd64.s:269 +0x5b

goroutine 1 [semacquire]:
sync.runtime_Semacquire(0xc42001230c)
	/usr/local/go/src/runtime/sema.go:47 +0x34
sync.(*WaitGroup).Wait(0xc420012300)
	/usr/local/go/src/sync/waitgroup.go:131 +0x7a
main.main()
	main.go:47 +0x27e

[...]

I don’t see an obvious smoking gun in the perf trace output. I’ve shared a portion of it at https://gist.github.com/rhysh/be58b5a5f3a41e218a05f1d8c3522dc0: Line 7 shows thread 16347 begin a call to clone, line 671 and 672 show that call resulting in the creation of process 86746. Lines 677 and 688 show the execve call for /bin/true, and 727 shows the exit_group call that ends the /bin/true process. Line 984 shows thread 16347 “returning” from rt_sigreturn (I don’t understand how this works) with value 13, which happens to be the number of bytes in "fatal error: ", followed by a 42-byte write to fd 2 (probably “unexpected signal during runtime execution”) and a 1-byte write to fd 2 (probably “\n”).

Thank you all for the ideas. I’ll upgrade to go1.8.3 soon after it’s out—it looks like it’s slated to include cherry-picks of both CL 43294 and CL 43311.

This program doesn’t use GOEXPERIMENT=preemptibleloops, and I agree that we can likely rule out inter-runtime signal handler disputes since it’s built with CGO_ENABLED=0.

The program uses crypto/rand.Read, which tries to use getrandom(2) when available (on Linux 3.17+). Should we be suspicious of this feature?

I got the following crash from an instance of the program that was running with GODEBUG=gcrescanstacks=1,gccheckmark=1 (and GOGC=1). The crash doesn’t look like it’s from the GC’s assertions that those settings enabled. Setting GOGC=1 on the test instance doesn’t seem to have made the program crash more often.

unexpected fault address 0xd01ed0
fatal error: fault
[signal SIGSEGV: segmentation violation code=0x2 addr=0xd01ed0 pc=0xd01ed0]

goroutine 1153267 [running]:
runtime.throw(0xa56736, 0x5)
     /usr/local/go/src/runtime/panic.go:596 +0x95 fp=0xc42059fb08 sp=0xc42059fae8
runtime.sigpanic()
     /usr/local/go/src/runtime/signal_unix.go:297 +0x28c fp=0xc42059fb58 sp=0xc42059fb08
created by redacted
     /redacted.go:155 +0x46a

goroutine 1 [chan receive, 126 minutes]:
runtime.gopark(0xa73c38, 0xc4200e8298, 0xa5bd35, 0xc, 0xc4202b8717, 0x3)
     /usr/local/go/src/runtime/proc.go:271 +0xfd fp=0xc420062c38 sp=0xc420062c08
runtime.goparkunlock(0xc4200e8298, 0xa5bd35, 0xc, 0x42fd17, 0x3)
     /usr/local/go/src/runtime/proc.go:277 +0x5e fp=0xc420062c78 sp=0xc420062c38
runtime.chanrecv(0x9b1f60, 0xc4200e8240, 0x0, 0xc42027c201, 0xc4200e8240)
     /usr/local/go/src/runtime/chan.go:513 +0x24b fp=0xc420062d10 sp=0xc420062c78
runtime.chanrecv1(0x9b1f60, 0xc4200e8240, 0x0)
     /usr/local/go/src/runtime/chan.go:395 +0x35 fp=0xc420062d48 sp=0xc420062d10
[snip]

This program uses Unix domain sockets much more actively than most of our others. Some of the crashes are encountered near the netpoller (like the one below), but I don’t know if that’s because of memory corruption coming from the netpoller, or if the program is just as likely to crash on any active goroutine and a lot of the active goroutines are working with UDS.

fatal error: netpollblock: corrupted state

goroutine 340603 [running]:
runtime.throw(0x894220, 0x1d)
	/usr/local/go/src/runtime/panic.go:596 +0x95 fp=0xc420a68ae0 sp=0xc420a68ac0
runtime.netpollblock(0x7f7c182d1e00, 0x72, 0xb)
	/usr/local/go/src/runtime/netpoll.go:350 +0x105 fp=0xc420a68b28 sp=0xc420a68ae0
net.runtime_pollWait(0x7f7c182d1e00, 0x72, 0x14)
	/usr/local/go/src/runtime/netpoll.go:164 +0x59 fp=0xc420a68b50 sp=0xc420a68b28
net.(*pollDesc).wait(0xc4201724c8, 0x72, 0xa68080, 0xa643c8)
	/usr/local/go/src/net/fd_poll_runtime.go:75 +0x38 fp=0xc420a68b78 sp=0xc420a68b50
net.(*pollDesc).waitRead(0xc4201724c8, 0xc420a08a00, 0x200)
	/usr/local/go/src/net/fd_poll_runtime.go:80 +0x34 fp=0xc420a68ba8 sp=0xc420a68b78
net.(*netFD).Read(0xc420172460, 0xc420a08a00, 0x200, 0x200, 0x0, 0xa68080, 0xa643c8)
	/usr/local/go/src/net/fd_unix.go:250 +0x1b7 fp=0xc420a68c10 sp=0xc420a68ba8
net.(*conn).Read(0xc4205cc0c8, 0xc420a08a00, 0x200, 0x200, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:181 +0x70 fp=0xc420a68c80 sp=0xc420a68c10
bytes.(*Buffer).ReadFrom(0xc420a68d20, 0x7f7c184f1108, 0xc4205cc0c8, 0xc420a08a00, 0x0, 0x200)
	/usr/local/go/src/bytes/buffer.go:179 +0x160 fp=0xc420a68cf0 sp=0xc420a68c80
io/ioutil.readAll(0x7f7c184f1108, 0xc4205cc0c8, 0x200, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/io/ioutil/ioutil.go:33 +0x150 fp=0xc420a68d98 sp=0xc420a68cf0
io/ioutil.ReadAll(0x7f7c184f1108, 0xc4205cc0c8, 0xc4205cc0c8, 0x7f7c184f1108, 0xc4205cc0c8, 0x0, 0x0)
	/usr/local/go/src/io/ioutil/ioutil.go:42 +0x3e fp=0xc420a68de8 sp=0xc420a68d98
[snip]