runtime: unexpected fault address 0xdfe1bd

[titanous]

$ go version
go version go1.5beta2 linux/amd64
$ uname -a
Linux flynn 3.19.0-22-generic #22~14.04.1-Ubuntu SMP Wed Jun 17 10:03:13 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux

While running go test:

WORK=/tmp/go-build365645106
mkdir -p $WORK/github.com/flynn/flynn/router/proxy/_test/github.com/flynn/flynn/router/
mkdir -p $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/poly1305/_obj/
mkdir -p $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/
mkdir -p $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa/_obj/
mkdir -p $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/
cd /home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/poly1305
/vagrant/util/_toolchain/go/pkg/tool/linux_amd64/compile -o $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/poly1305.a -trimpath $WORK -p github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/poly1305 -buildid 98ac4b17e9c7615cd4e12c8d41cf91187390c708 -D _/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/poly1305 -I $WORK -pack -asmhdr $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/poly1305/_obj/go_asm.h ./poly1305.go ./sum_amd64.go
cd /home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa
/vagrant/util/_toolchain/go/pkg/tool/linux_amd64/compile -o $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa.a -trimpath $WORK -p github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa -buildid c13f10f0f394750003bd4f6eda2844332ffe73c9 -D _/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa -I $WORK -pack -asmhdr $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa/_obj/go_asm.h ./hsalsa20.go ./salsa208.go ./salsa20_amd64.go
cd /home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/poly1305
/vagrant/util/_toolchain/go/pkg/tool/linux_amd64/asm -o $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/poly1305/_obj/const_amd64.o -trimpath $WORK -I $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/poly1305/_obj/ -I /vagrant/util/_toolchain/go/pkg/include -D GOOS_linux -D GOARCH_amd64 ./const_amd64.s
cd /home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa
/vagrant/util/_toolchain/go/pkg/tool/linux_amd64/asm -o $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa/_obj/salsa2020_amd64.o -trimpath $WORK -I $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa/_obj/ -I /vagrant/util/_toolchain/go/pkg/include -D GOOS_linux -D GOARCH_amd64 ./salsa2020_amd64.s
/vagrant/util/_toolchain/go/pkg/tool/linux_amd64/old6a -o $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa/_obj/salsa2020_amd64.o.new -trimpath $WORK -I $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa/_obj/ -I /vagrant/util/_toolchain/go/pkg/include -D GOOS_linux -D GOARCH_amd64 ./salsa2020_amd64.s
pack r $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa.a $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa/_obj/salsa2020_amd64.o # internal
# github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/poly1305
unexpected fault address 0xdfe1bd
fatal error: fault
[signal 0xb code=0x1 addr=0xdfe1bd pc=0x46daf2]

goroutine 1 [running, locked to thread]:
runtime.throw(0x60d668, 0x5)
    /usr/local/go/src/runtime/panic.go:527 +0x96 fp=0xc820045838 sp=0xc820045820
runtime.sigpanic()
    /usr/local/go/src/runtime/sigpanic_unix.go:27 +0x2ab fp=0xc820045888 sp=0xc820045838
fmt.(*pp).doPrintf(0xc820072c30, 0x608988, 0x2, 0xc820045ca8, 0x1, 0x1)
    /usr/local/go/src/fmt/print.go:1114 +0x1f62 fp=0xc820045c10 sp=0xc820045888
fmt.Sprintf(0x608988, 0x2, 0xc820045ca8, 0x1, 0x1, 0x0, 0x0)
    /usr/local/go/src/fmt/print.go:203 +0x6f fp=0xc820045c60 sp=0xc820045c10
flag.(*boolValue).String(0xc820010430, 0x0, 0x0)
    /usr/local/go/src/flag/flag.go:96 +0xea fp=0xc820045cd8 sp=0xc820045c60
flag.(*FlagSet).Var(0xc8200200c0, 0x7f2942734298, 0xc820010430, 0x60d410, 0x5, 0x6384a0, 0x24)
    /usr/local/go/src/flag/flag.go:766 +0x6e fp=0xc820045df0 sp=0xc820045cd8
flag.(*FlagSet).BoolVar(0xc8200200c0, 0xc820010430, 0x60d410, 0x5, 0x510a939c47aec300, 0x6384a0, 0x24)
    /usr/local/go/src/flag/flag.go:549 +0x8b fp=0xc820045e48 sp=0xc820045df0
flag.(*FlagSet).Bool(0xc8200200c0, 0x60d410, 0x5, 0xc820090000, 0x6384a0, 0x24, 0x57c381)
    /usr/local/go/src/flag/flag.go:562 +0x71 fp=0xc820045e90 sp=0xc820045e48
flag.Bool(0x60d410, 0x5, 0xc82001a400, 0x6384a0, 0x24, 0xc82001a4b0)
    /usr/local/go/src/flag/flag.go:569 +0x54 fp=0xc820045ed0 sp=0xc820045e90
cmd/asm/internal/flags.init()
    /usr/local/go/src/cmd/asm/internal/flags/flags.go:17 +0x8e fp=0xc820045f10 sp=0xc820045ed0
cmd/asm/internal/asm.init()
    /usr/local/go/src/cmd/asm/internal/asm/parse.go:983 +0x5b fp=0xc820045f48 sp=0xc820045f10
main.init()
    /usr/local/go/src/cmd/asm/main.go:67 +0x54 fp=0xc820045f50 sp=0xc820045f48
runtime.main()
    /usr/local/go/src/runtime/proc.go:100 +0x28e fp=0xc820045fa0 sp=0xc820045f50
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1696 +0x1 fp=0xc820045fa8 sp=0xc820045fa0

goroutine 2 [force gc (idle)]:
runtime.gopark(0x6586c0, 0x7107a0, 0x6138d0, 0xf, 0x14, 0x1)
    /usr/local/go/src/runtime/proc.go:185 +0x169 fp=0xc82002e758 sp=0xc82002e730
runtime.goparkunlock(0x7107a0, 0x6138d0, 0xf, 0xc820000114, 0x1)
    /usr/local/go/src/runtime/proc.go:191 +0x54 fp=0xc82002e790 sp=0xc82002e758
runtime.forcegchelper()
    /usr/local/go/src/runtime/proc.go:152 +0xb8 fp=0xc82002e7c0 sp=0xc82002e790
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1696 +0x1 fp=0xc82002e7c8 sp=0xc82002e7c0
created by runtime.init.4
    /usr/local/go/src/runtime/proc.go:141 +0x2b

goroutine 3 [GC sweep wait]:
runtime.gopark(0x6586c0, 0x710900, 0x6108d0, 0xd, 0x41cc14, 0x1)
    /usr/local/go/src/runtime/proc.go:185 +0x169 fp=0xc82002ef48 sp=0xc82002ef20
runtime.goparkunlock(0x710900, 0x6108d0, 0xd, 0x14, 0x1)
    /usr/local/go/src/runtime/proc.go:191 +0x54 fp=0xc82002ef80 sp=0xc82002ef48
runtime.bgsweep(0xc820018070)
    /usr/local/go/src/runtime/mgcsweep.go:51 +0xb1 fp=0xc82002efb8 sp=0xc82002ef80
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1696 +0x1 fp=0xc82002efc0 sp=0xc82002efb8
created by runtime.gcenable
    /usr/local/go/src/runtime/mgc.go:200 +0x53

goroutine 4 [finalizer wait]:
runtime.gopark(0x6586c0, 0x82f190, 0x613520, 0xe, 0x14, 0x1)
    /usr/local/go/src/runtime/proc.go:185 +0x169 fp=0xc82002f718 sp=0xc82002f6f0
runtime.goparkunlock(0x82f190, 0x613520, 0xe, 0x14, 0x1)
    /usr/local/go/src/runtime/proc.go:191 +0x54 fp=0xc82002f750 sp=0xc82002f718
runtime.runfinq()
    /usr/local/go/src/runtime/mfinal.go:154 +0xaa fp=0xc82002f7c0 sp=0xc82002f750
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1696 +0x1 fp=0xc82002f7c8 sp=0xc82002f7c0
created by runtime.createfing
    /usr/local/go/src/runtime/mfinal.go:135 +0x60
$WORK/github.com/flynn/flynn/router/proxy/_test/proxy.test -test.run=xxxxx
FAIL    github.com/flynn/flynn/router/proxy [build failed]

Core dump: https://cl.ly/3O2A112y3w3b

This happens pretty rarely (less than 1 in 1000 builds).

[ianlancetaylor]

CC @aclements @RLH

This may be optimistic thinking, but it's possible that this is another instance of #11617 .

[titanous]

This one looks similar:

WORK=/tmp/go-build853776322
mkdir -p $WORK/github.com/flynn/flynn/router/proxy/_test/github.com/flynn/flynn/router/
mkdir -p $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/poly1305/_obj/
mkdir -p $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/
mkdir -p $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa/_obj/
mkdir -p $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/
cd /home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/poly1305
/vagrant/util/_toolchain/go/pkg/tool/linux_amd64/compile -o $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/poly1305.a -trimpath $WORK -p github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/poly1305 -buildid 98ac4b17e9c7615cd4e12c8d41cf91187390c708 -D _/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/poly1305 -I $WORK -pack -asmhdr $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/poly1305/_obj/go_asm.h ./poly1305.go ./sum_amd64.go
cd /home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa
/vagrant/util/_toolchain/go/pkg/tool/linux_amd64/compile -o $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa.a -trimpath $WORK -p github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa -buildid c13f10f0f394750003bd4f6eda2844332ffe73c9 -D _/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa -I $WORK -pack -asmhdr $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa/_obj/go_asm.h ./hsalsa20.go ./salsa208.go ./salsa20_amd64.go
cd /home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/poly1305
/vagrant/util/_toolchain/go/pkg/tool/linux_amd64/asm -o $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/poly1305/_obj/const_amd64.o -trimpath $WORK -I $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/poly1305/_obj/ -I /vagrant/util/_toolchain/go/pkg/include -D GOOS_linux -D GOARCH_amd64 ./const_amd64.s
cd /home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa
/vagrant/util/_toolchain/go/pkg/tool/linux_amd64/asm -o $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa/_obj/salsa2020_amd64.o -trimpath $WORK -I $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa/_obj/ -I /vagrant/util/_toolchain/go/pkg/include -D GOOS_linux -D GOARCH_amd64 ./salsa2020_amd64.s
/vagrant/util/_toolchain/go/pkg/tool/linux_amd64/old6a -o $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa/_obj/salsa2020_amd64.o.new -trimpath $WORK -I $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa/_obj/ -I /vagrant/util/_toolchain/go/pkg/include -D GOOS_linux -D GOARCH_amd64 ./salsa2020_amd64.s
pack r $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa.a $WORK/github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/salsa20/salsa/_obj/salsa2020_amd64.o # internal
# github.com/flynn/flynn/Godeps/_workspace/src/golang.org/x/crypto/poly1305
unexpected fault address 0x0
fatal error: fault
[signal 0x7 code=0x80 addr=0x0 pc=0x45a2c4]

goroutine 1 [running, locked to thread]:
runtime.throw(0x60d668, 0x5)
    /usr/local/go/src/runtime/panic.go:527 +0x96 fp=0xc820041d98 sp=0xc820041d80
runtime.sigpanic()
    /usr/local/go/src/runtime/sigpanic_unix.go:21 +0x10c fp=0xc820041de8 sp=0xc820041d98
flag.(*FlagSet).Var(0xc8200200c0, 0x7f6317cf8298, 0xc820010430, 0x60d410, 0x5, 0x6384a0, 0x24)
    /usr/local/go/src/flag/flag.go:764 +0x4 fp=0xc820041df0 sp=0xc820041de8
flag.(*FlagSet).BoolVar(0xc8200200c0, 0xc820010430, 0x60d410, 0x5, 0xcdb15c74a9711e00, 0x6384a0, 0x24)
    /usr/local/go/src/flag/flag.go:549 +0x8b fp=0xc820041e48 sp=0xc820041df0
flag.(*FlagSet).Bool(0xc8200200c0, 0x60d410, 0x5, 0xc82007c000, 0x6384a0, 0x24, 0x57c381)
    /usr/local/go/src/flag/flag.go:562 +0x71 fp=0xc820041e90 sp=0xc820041e48
flag.Bool(0x60d410, 0x5, 0xc82001a400, 0x6384a0, 0x24, 0xc82001a4b0)
    /usr/local/go/src/flag/flag.go:569 +0x54 fp=0xc820041ed0 sp=0xc820041e90
cmd/asm/internal/flags.init()
    /usr/local/go/src/cmd/asm/internal/flags/flags.go:17 +0x8e fp=0xc820041f10 sp=0xc820041ed0
cmd/asm/internal/asm.init()
    /usr/local/go/src/cmd/asm/internal/asm/parse.go:983 +0x5b fp=0xc820041f48 sp=0xc820041f10
main.init()
    /usr/local/go/src/cmd/asm/main.go:67 +0x54 fp=0xc820041f50 sp=0xc820041f48
runtime.main()
    /usr/local/go/src/runtime/proc.go:100 +0x28e fp=0xc820041fa0 sp=0xc820041f50
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1696 +0x1 fp=0xc820041fa8 sp=0xc820041fa0

goroutine 2 [force gc (idle)]:
runtime.gopark(0x6586c0, 0x7107a0, 0x6138d0, 0xf, 0x14, 0x1)
    /usr/local/go/src/runtime/proc.go:185 +0x169 fp=0xc82002e758 sp=0xc82002e730
runtime.goparkunlock(0x7107a0, 0x6138d0, 0xf, 0xc820000114, 0x1)
    /usr/local/go/src/runtime/proc.go:191 +0x54 fp=0xc82002e790 sp=0xc82002e758
runtime.forcegchelper()
    /usr/local/go/src/runtime/proc.go:152 +0xb8 fp=0xc82002e7c0 sp=0xc82002e790
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1696 +0x1 fp=0xc82002e7c8 sp=0xc82002e7c0
created by runtime.init.4
    /usr/local/go/src/runtime/proc.go:141 +0x2b

goroutine 3 [GC sweep wait]:
runtime.gopark(0x6586c0, 0x710900, 0x6108d0, 0xd, 0x41cc14, 0x1)
    /usr/local/go/src/runtime/proc.go:185 +0x169 fp=0xc82002ef48 sp=0xc82002ef20
runtime.goparkunlock(0x710900, 0x6108d0, 0xd, 0x14, 0x1)
    /usr/local/go/src/runtime/proc.go:191 +0x54 fp=0xc82002ef80 sp=0xc82002ef48
runtime.bgsweep(0xc820018070)
    /usr/local/go/src/runtime/mgcsweep.go:51 +0xb1 fp=0xc82002efb8 sp=0xc82002ef80
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1696 +0x1 fp=0xc82002efc0 sp=0xc82002efb8
created by runtime.gcenable
    /usr/local/go/src/runtime/mgc.go:200 +0x53

goroutine 4 [finalizer wait]:
runtime.gopark(0x6586c0, 0x82f190, 0x613520, 0xe, 0x14, 0x1)
    /usr/local/go/src/runtime/proc.go:185 +0x169 fp=0xc82002f718 sp=0xc82002f6f0
runtime.goparkunlock(0x82f190, 0x613520, 0xe, 0x14, 0x1)
    /usr/local/go/src/runtime/proc.go:191 +0x54 fp=0xc82002f750 sp=0xc82002f718
runtime.runfinq()
    /usr/local/go/src/runtime/mfinal.go:154 +0xaa fp=0xc82002f7c0 sp=0xc82002f750
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1696 +0x1 fp=0xc82002f7c8 sp=0xc82002f7c0
created by runtime.createfing
    /usr/local/go/src/runtime/mfinal.go:135 +0x60
$WORK/github.com/flynn/flynn/router/proxy/_test/proxy.test -test.run=xxxxx
FAIL    github.com/flynn/flynn/router/proxy [build failed]

Core dump: https://cl.ly/2S1O1y202f2T

[aclements]

@titanous, can you reproduce any of these faults outside of Vagrant? The instruction at PC 0x46daf2 doesn't even access memory, so it makes no sense for it to trigger a SIGSEGV.

(FWIW, I tried reproducing by just running go build of salsa20/salsa from another one of your issues in a loop and wasn't able to trigger any failures after ~40,000 runs.)

[titanous]

@aclements I have not attempted to. I will run a build loop on a real machine.

[rsc]

Collectively, your recently filed bugs look like somehow the instruction memory for the Go binary is being lost, or not loaded correctly to begin with. All the failures are very early in the life of a program, possibly the first time a particular instruction page is hit. This sounds like possibly a kernel problem or a virtual hardware problem (you're running Vagrant; is it backed by QEMU?). Maybe something Go does tickles a bug that most C binaries do not.

One thing maybe worth trying is to turn off hugepage support, which seems to be

echo never > /sys/kernel/mm/transparent_hugepage/enabled

And then see whether the failure rate changes.

Go does unmap data memory, so possibly Go could get confused and unmap text memory, but there is nothing in the core file maps to support that, and the failures happen so early in the lifetime of the program that the unmapper almost certainly hasn't gotten a chance to run. It seems more likely that the instruction pages are somehow not being loaded into memory properly. If that's true, the question is why and whether we can do anything to Go binaries to work around the problem.

Thanks.

[titanous]

I'm using VirtualBox 4.3.28 on OS X 10.10.4. I've been unable to reproduce this on another bare metal host with an older kernel (3.16). I'll continue to test by doing the following:

1. Disabling huge pages as suggested.
2. Upgrading to the same kernel I have in VirtualBox (3.19) on the bare metal box.
3. Testing on various versions of VirtualBox on different hosts.

[titanous]

Preliminary testing indicates the following:

1. Disabling hugepages did not appear to change the failure rate.
2. Unable to reproduce on bare metal with Linux 3.19.
3. Unable to reproduce on VirtualBox 4.3.30.
4. Unable to reproduce on VirtualBox 5.0.

I'll leave the builders running for a few more hours, but I'm almost satisfied that this is caused by a bug in VirtualBox 4.3.28 (and possibly older versions).

[titanous]

I'm now confident that this issue is only reproducible in VirtualBox 4.3.28 and possibly older versions. I'll leave it to you folks to determine if this is an issue, but since I can just update to 4.3.30 or 5.0 I don't consider it to be a problem.