testing: would be useful to record fuzz crashers which cause OOM kills #47572
Description
What version of Go are you using (go version)?
$ go version go version devel go1.17-2a0825d01f Tue Jul 20 00:06:06 2021 +0000 linux/amd64
Does this issue reproduce with the latest release?
n/a
What operating system and processor architecture are you using (go env)?
go env Output
$ go env GO111MODULE="" GOARCH="amd64" GOBIN="" GOCACHE="/home/stevie/.cache/go-build" GOENV="/home/stevie/.config/go/env" GOEXE="" GOFLAGS="" GOHOSTARCH="amd64" GOHOSTOS="linux" GOINSECURE="" GOMODCACHE="/home/stevie/go/pkg/mod" GONOPROXY="" GONOSUMDB="" GOOS="linux" GOPATH="/home/stevie/go" GOPRIVATE="" GOPROXY="https://proxy.golang.org,direct" GOROOT="/home/stevie/sdk/gotip" GOSUMDB="sum.golang.org" GOTMPDIR="" GOTOOLDIR="/home/stevie/sdk/gotip/pkg/tool/linux_amd64" GOVCS="" GOVERSION="devel go1.17-2a0825d01f Tue Jul 20 00:06:06 2021 +0000" GCCGO="gccgo" AR="ar" CC="gcc" CXX="g++" CGO_ENABLED="1" GOMOD="/home/stevie/binarycookies/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-build1094836245=/tmp/go-build -gno-record-gcc-switches"
What did you do?
Tried out the new fuzzer on https://github.com/cixtor/binarycookies on this fork: https://github.com/stevenjohnstone/binarycookies/tree/sjj/beta_fuzz. Started with a very simple fuzzer with two test cases added to the corpus:
https://github.com/stevenjohnstone/binarycookies/commit/6ba73d0cab7dca809098da87fc32ac7a271691e1
Immediately finds out of memory bugs 🎉
gotip test -fuzz=Fuzz
fatal error: runtime: out of memory
runtime stack:
runtime.throw({0x5e45ef, 0x400000000})
/home/stevie/sdk/gotip/src/runtime/panic.go:1198 +0x71
runtime.sysMap(0xc006800000, 0x4292e0, 0xc00004de90)
/home/stevie/sdk/gotip/src/runtime/mem_linux.go:169 +0x96
runtime.(*mheap).grow(0x73af00, 0x200000)
/home/stevie/sdk/gotip/src/runtime/mheap.go:1393 +0x225
runtime.(*mheap).allocSpan(0x73af00, 0x200000, 0x0, 0x1)
/home/stevie/sdk/gotip/src/runtime/mheap.go:1179 +0x165
runtime.(*mheap).alloc.func1()
/home/stevie/sdk/gotip/src/runtime/mheap.go:913 +0x69
runtime.systemstack()
/home/stevie/sdk/gotip/src/runtime/asm_amd64.s:383 +0x49
goroutine 44 [running]:
runtime.systemstack_switch()
/home/stevie/sdk/gotip/src/runtime/asm_amd64.s:350 fp=0xc0001f3430 sp=0xc0001f3428 pc=0x464e20
runtime.(*mheap).alloc(0x400000000, 0x200000, 0x18, 0x0)
/home/stevie/sdk/gotip/src/runtime/mheap.go:907 +0x73 fp=0xc0001f3480 sp=0xc0001f3430 pc=0x425613
runtime.(*mcache).allocLarge(0x2448912244, 0x3fffffc10, 0x0, 0x1)
/home/stevie/sdk/gotip/src/runtime/mcache.go:227 +0x89 fp=0xc0001f34e0 sp=0xc0001f3480 pc=0x416289
runtime.mallocgc(0x3fffffc10, 0x5b1fa0, 0x1)
/home/stevie/sdk/gotip/src/runtime/malloc.go:1082 +0x5c5 fp=0xc0001f3568 sp=0xc0001f34e0 pc=0x40cc65
runtime.makeslice(0xc0001c40c0, 0xc0001381b8, 0x4)
/home/stevie/sdk/gotip/src/runtime/slice.go:98 +0x52 fp=0xc0001f3590 sp=0xc0001f3568 pc=0x44c112
github.com/cixtor/binarycookies.(*BinaryCookies).readOnePage(0xc0001f36d0, 0x1)
/home/stevie/binarycookies/decoder.go:127 +0x2ad fp=0xc0001f3698 sp=0xc0001f3590 pc=0x59820d
github.com/cixtor/binarycookies.(*BinaryCookies).Decode(0xc0001f36d0)
/home/stevie/binarycookies/decoder.go:28 +0x14e fp=0xc0001f36c0 sp=0xc0001f3698 pc=0x59792e
github.com/cixtor/binarycookies.Fuzz.func1(0x0, {0xc000200000, 0x295, 0x63fff9c})
/home/stevie/binarycookies/fuzz_test.go:15 +0xd0 fp=0xc0001f3740 sp=0xc0001f36c0 pc=0x59fd50
runtime.call32(0xc00011c420, 0x5edf00, 0x0, 0x0, 0x0, 0x20, 0xc0001f3cc8)
/home/stevie/sdk/gotip/src/runtime/asm_amd64.s:626 +0x49 fp=0xc0001f3770 sp=0xc0001f3740 pc=0x465409
runtime.reflectcall(0x5b0560, 0xc000130120, 0x4, 0x5e3187, 0x0, 0x12, 0x5b0560)
<autogenerated>:1 +0x3c fp=0xc0001f37b0 sp=0xc0001f3770 pc=0x46957c
reflect.Value.call({0x5b4220, 0x5edf00, 0x13}, {0x5dfb84, 0x4}, {0xc0001c4090, 0x2, 0x2})
/home/stevie/sdk/gotip/src/reflect/value.go:543 +0xf0d fp=0xc0001f3de8 sp=0xc0001f37b0 pc=0x4d4a0d
reflect.Value.Call({0x5b4220, 0x5edf00, 0xc0001e4000}, {0xc0001c4090, 0x2, 0x2})
/home/stevie/sdk/gotip/src/reflect/value.go:339 +0x13e fp=0xc0001f3e68 sp=0xc0001f3de8 pc=0x4d3a3e
testing.(*F).Fuzz.func1.1(0xc0000980c0)
/home/stevie/sdk/gotip/src/testing/fuzz.go:377 +0x1c6 fp=0xc0001f3f70 sp=0xc0001f3e68 pc=0x50f766
testing.tRunner(0xc000001a00, 0xc0001e2000)
/home/stevie/sdk/gotip/src/testing/testing.go:1335 +0x102 fp=0xc0001f3fc0 sp=0xc0001f3f70 pc=0x5167c2
testing.(*F).Fuzz.func1·dwrap·8()
/home/stevie/sdk/gotip/src/testing/fuzz.go:366 +0x2a fp=0xc0001f3fe0 sp=0xc0001f3fc0 pc=0x50f56a
runtime.goexit()
/home/stevie/sdk/gotip/src/runtime/asm_amd64.s:1581 +0x1 fp=0xc0001f3fe8 sp=0xc0001f3fe0 pc=0x466f01
created by testing.(*F).Fuzz.func1
/home/stevie/sdk/gotip/src/testing/fuzz.go:366 +0x505
goroutine 1 [chan receive]:
testing.runFuzzing({0x61f980, 0x751b98}, {0x719870, 0x1, 0x40})
/home/stevie/sdk/gotip/src/testing/fuzz.go:624 +0x9aa
testing.(*M).Run(0xc00013a140)
/home/stevie/sdk/gotip/src/testing/testing.go:1621 +0x853
main.main()
_testmain.go:87 +0x1b5
goroutine 34 [chan receive]:
testing.(*F).Fuzz.func1({{0x0, 0x0}, {0x0, 0x0}, {0x0, 0x0, 0x0}, {0xc0001d4040, 0x1, 0x1}, ...})
/home/stevie/sdk/gotip/src/testing/fuzz.go:379 +0x518
internal/fuzz.(*workerServer).fuzz(0xc00008fae0, {0x61bb10, 0xc000126840}, {0x5f5e100, 0x0, 0x0, {0xc0001c6000, 0x2191, 0x2193}})
/home/stevie/sdk/gotip/src/internal/fuzz/worker.go:681 +0x6ba
internal/fuzz.(*workerServer).serve(0xc00008fae0, {0x61bb10, 0xc000126840})
/home/stevie/sdk/gotip/src/internal/fuzz/worker.go:608 +0x26d
internal/fuzz.RunFuzzWorker({0x61bb10, 0xc000126840}, 0xc00011c450)
/home/stevie/sdk/gotip/src/internal/fuzz/worker.go:466 +0xfd
testing/internal/testdeps.TestDeps.RunFuzzWorker({}, 0xc000114be0)
/home/stevie/sdk/gotip/src/testing/internal/testdeps/deps.go:178 +0xaf
testing.(*F).Fuzz(0xc000162000, {0x5b4220, 0x5edf00})
/home/stevie/sdk/gotip/src/testing/fuzz.go:420 +0x6aa
github.com/cixtor/binarycookies.Fuzz(0x0)
/home/stevie/binarycookies/fuzz_test.go:14 +0xd7
testing.fRunner(0xc000162000, 0x5edf08)
/home/stevie/sdk/gotip/src/testing/fuzz.go:728 +0xd1
created by testing.runFuzzing
/home/stevie/sdk/gotip/src/testing/fuzz.go:623 +0x994
goroutine 36 [syscall]:
os/signal.signal_recv()
/home/stevie/sdk/gotip/src/runtime/sigqueue.go:169 +0x98
os/signal.loop()
/home/stevie/sdk/gotip/src/os/signal/signal_unix.go:24 +0x19
created by os/signal.Notify.func1.1
/home/stevie/sdk/gotip/src/os/signal/signal.go:151 +0x2c
goroutine 37 [select]:
os/signal.NotifyContext.func1()
/home/stevie/sdk/gotip/src/os/signal/signal.go:288 +0x76
created by os/signal.NotifyContext
/home/stevie/sdk/gotip/src/os/signal/signal.go:287 +0x169
found a crash, minimizing...
fatal error: runtime: out of memory
runtime stack:
runtime.throw({0x5e45ef, 0x400000000})
/home/stevie/sdk/gotip/src/runtime/panic.go:1198 +0x71
runtime.sysMap(0xc000400000, 0x4292e0, 0xc00004de90)
/home/stevie/sdk/gotip/src/runtime/mem_linux.go:169 +0x96
runtime.(*mheap).grow(0x73af00, 0x200000)
/home/stevie/sdk/gotip/src/runtime/mheap.go:1393 +0x225
runtime.(*mheap).allocSpan(0x73af00, 0x200000, 0x0, 0x1)
/home/stevie/sdk/gotip/src/runtime/mheap.go:1179 +0x165
runtime.(*mheap).alloc.func1()
/home/stevie/sdk/gotip/src/runtime/mheap.go:913 +0x69
runtime.systemstack()
/home/stevie/sdk/gotip/src/runtime/asm_amd64.s:383 +0x49
goroutine 12 [running]:
runtime.systemstack_switch()
/home/stevie/sdk/gotip/src/runtime/asm_amd64.s:350 fp=0xc0000c1430 sp=0xc0000c1428 pc=0x464e20
runtime.(*mheap).alloc(0xc000060160, 0x3, 0x20, 0x0)
/home/stevie/sdk/gotip/src/runtime/mheap.go:907 +0x73 fp=0xc0000c1480 sp=0xc0000c1430 pc=0x425613
runtime.(*mcache).allocLarge(0x2448912244, 0x3fffffc10, 0x0, 0x1)
/home/stevie/sdk/gotip/src/runtime/mcache.go:227 +0x89 fp=0xc0000c14e0 sp=0xc0000c1480 pc=0x416289
runtime.mallocgc(0x3fffffc10, 0x5b1fa0, 0x1)
/home/stevie/sdk/gotip/src/runtime/malloc.go:1082 +0x5c5 fp=0xc0000c1568 sp=0xc0000c14e0 pc=0x40cc65
runtime.makeslice(0xc000074b70, 0xc0000144f8, 0x4)
/home/stevie/sdk/gotip/src/runtime/slice.go:98 +0x52 fp=0xc0000c1590 sp=0xc0000c1568 pc=0x44c112
github.com/cixtor/binarycookies.(*BinaryCookies).readOnePage(0xc0000c16d0, 0x1)
/home/stevie/binarycookies/decoder.go:127 +0x2ad fp=0xc0000c1698 sp=0xc0000c1590 pc=0x59820d
github.com/cixtor/binarycookies.(*BinaryCookies).Decode(0xc0000c16d0)
/home/stevie/binarycookies/decoder.go:28 +0x14e fp=0xc0000c16c0 sp=0xc0000c1698 pc=0x59792e
github.com/cixtor/binarycookies.Fuzz.func1(0x0, {0xc0000d62c0, 0x95, 0x2c0})
/home/stevie/binarycookies/fuzz_test.go:15 +0xd0 fp=0xc0000c1740 sp=0xc0000c16c0 pc=0x59fd50
runtime.call32(0xc000074a80, 0x5edf00, 0x0, 0x0, 0x0, 0x20, 0xc0000c1cc8)
/home/stevie/sdk/gotip/src/runtime/asm_amd64.s:626 +0x49 fp=0xc0000c1770 sp=0xc0000c1740 pc=0x465409
runtime.reflectcall(0x5b0560, 0xc00000c348, 0x4, 0x5e3187, 0x0, 0x12, 0x5b0560)
<autogenerated>:1 +0x3c fp=0xc0000c17b0 sp=0xc0000c1770 pc=0x46957c
reflect.Value.call({0x5b4220, 0x5edf00, 0x13}, {0x5dfb84, 0x4}, {0xc000074a50, 0x2, 0x2})
/home/stevie/sdk/gotip/src/reflect/value.go:543 +0xf0d fp=0xc0000c1de8 sp=0xc0000c17b0 pc=0x4d4a0d
reflect.Value.Call({0x5b4220, 0x5edf00, 0xc0000775f0}, {0xc000074a50, 0x2, 0x2})
/home/stevie/sdk/gotip/src/reflect/value.go:339 +0x13e fp=0xc0000c1e68 sp=0xc0000c1de8 pc=0x4d3a3e
testing.(*F).Fuzz.func1.1(0xc0000103c0)
/home/stevie/sdk/gotip/src/testing/fuzz.go:377 +0x1c6 fp=0xc0000c1f70 sp=0xc0000c1e68 pc=0x50f766
testing.tRunner(0xc0000ad040, 0xc0000c2100)
/home/stevie/sdk/gotip/src/testing/testing.go:1335 +0x102 fp=0xc0000c1fc0 sp=0xc0000c1f70 pc=0x5167c2
testing.(*F).Fuzz.func1·dwrap·8()
/home/stevie/sdk/gotip/src/testing/fuzz.go:366 +0x2a fp=0xc0000c1fe0 sp=0xc0000c1fc0 pc=0x50f56a
runtime.goexit()
/home/stevie/sdk/gotip/src/runtime/asm_amd64.s:1581 +0x1 fp=0xc0000c1fe8 sp=0xc0000c1fe0 pc=0x466f01
created by testing.(*F).Fuzz.func1
/home/stevie/sdk/gotip/src/testing/fuzz.go:366 +0x505
goroutine 1 [chan receive]:
testing.runFuzzing({0x61f980, 0x751b98}, {0x719870, 0x1, 0x40})
/home/stevie/sdk/gotip/src/testing/fuzz.go:624 +0x9aa
testing.(*M).Run(0xc000086140)
/home/stevie/sdk/gotip/src/testing/testing.go:1621 +0x853
main.main()
_testmain.go:87 +0x1b5
goroutine 6 [chan receive]:
testing.(*F).Fuzz.func1({{0x0, 0x0}, {0x0, 0x0}, {0x0, 0x0, 0x0}, {0xc000054880, 0x1, 0x1}, ...})
/home/stevie/sdk/gotip/src/testing/fuzz.go:379 +0x518
internal/fuzz.(*workerServer).minimizeInput.func2({0x5b0560, 0xc00000c330})
/home/stevie/sdk/gotip/src/internal/fuzz/worker.go:799 +0xa04
internal/fuzz.minimizeBytes({0xc0000d62c0, 0x722ce0, 0x2c0}, 0xc0000d1778, 0xc0000d1750)
/home/stevie/sdk/gotip/src/internal/fuzz/minimize.go:29 +0x604
internal/fuzz.(*workerServer).minimizeInput(0xc0000d1ae0, {0x61ba68, 0xc0000106c0}, {0xc000054880, 0xc0000882a8, 0x1}, 0x7fe6e0da2000, 0x0)
/home/stevie/sdk/gotip/src/internal/fuzz/worker.go:853 +0x2e9
internal/fuzz.(*workerServer).minimize(0xc0000d1ae0, {0x61bb10, 0xc000024880}, {0x10, 0xc000042800})
/home/stevie/sdk/gotip/src/internal/fuzz/worker.go:723 +0x2cf
internal/fuzz.(*workerServer).serve(0xc0000d1ae0, {0x61bb10, 0xc000024880})
/home/stevie/sdk/gotip/src/internal/fuzz/worker.go:610 +0x1c6
internal/fuzz.RunFuzzWorker({0x61bb10, 0xc000024880}, 0xc000074450)
/home/stevie/sdk/gotip/src/internal/fuzz/worker.go:466 +0xfd
testing/internal/testdeps.TestDeps.RunFuzzWorker({}, 0xc000070be0)
/home/stevie/sdk/gotip/src/testing/internal/testdeps/deps.go:178 +0xaf
testing.(*F).Fuzz(0xc00000a1e0, {0x5b4220, 0x5edf00})
/home/stevie/sdk/gotip/src/testing/fuzz.go:420 +0x6aa
github.com/cixtor/binarycookies.Fuzz(0x0)
/home/stevie/binarycookies/fuzz_test.go:14 +0xd7
testing.fRunner(0xc00000a1e0, 0x5edf08)
/home/stevie/sdk/gotip/src/testing/fuzz.go:728 +0xd1
created by testing.runFuzzing
/home/stevie/sdk/gotip/src/testing/fuzz.go:623 +0x994
goroutine 8 [runnable]:
os/signal.loop()
/home/stevie/sdk/gotip/src/os/signal/signal_unix.go:22
created by os/signal.Notify.func1.1
/home/stevie/sdk/gotip/src/os/signal/signal.go:151 +0x2c
goroutine 9 [runnable]:
os/signal.NotifyContext.func1()
/home/stevie/sdk/gotip/src/os/signal/signal.go:287
created by os/signal.NotifyContext
/home/stevie/sdk/gotip/src/os/signal/signal.go:287 +0x169
fuzzing process terminated unexpectedly while minimizing: exit status 2
fuzzing, elapsed: 2.2s, execs: 193 (90/sec), workers: 8, interesting: 11
--- FAIL: Fuzz (2.15s)
fuzzing process terminated unexpectedly: exit status 2
Crash written to testdata/corpus/Fuzz/430b901e441a6da1e86aacf6ccc066642ea132de2679067102f9af63980939d6
To re-run:
go test github.com/cixtor/binarycookies -run=Fuzz/430b901e441a6da1e86aacf6ccc066642ea132de2679067102f9af63980939d6
FAIL
exit status 1
FAIL github.com/cixtor/binarycookies 2.167s
I made some fixes (guided by the output above) and continued fuzzing. I then ran into bugs where the process is killed because of OOM: "fuzzing process terminated by unexpected signal; no crash will be recorded: signal: killed". Without a crash recorded, the information is reduced to "you have a memory bug".
I think OOM is encountered with this code in a couple of ways:
- when quoting an enormous buffer with
fmt.Errorf("%q", buf) - when allocating buffers with
makewhere the size is calculated by the difference of two unsigned ints a -b where a < b
What did you expect to see?
I'd like to see crashes recorded for processes which are killed. Out of memory bugs resulting in the OS killing the process are critical as there's no panic to catch so can't be mitigated.
What did you see instead?
No crash recorded when the fuzzer encounters buggy code making huge memory allocations.