runtime: slice bounds out of range in mheap on darwin/arm64 (iOS 10)

[crawshaw]

Testing Go on an iPhone at 9cf06ed.

(lldb) fatal error: slice bounds out of range
(lldb) 
runtime stack:
runtime.throw(0x4284e5c, 0x19)
	/Users/crawshaw/go/src/runtime/panic.go:(lldb) 596 +0x70
runtime.panicCheckMalloc(0x433f0e0, 0x434fd10)
	/Users/crawshaw/go/src/runtime/panic.go:20 +0x68
runtime.panicslice()
	/Users/crawshaw/go/src/runtime/panic.go:34 +0x38(lldb) 
runtime.(*mheap).mapSpans(0x435dc20, 0x88968000)
	/Users/crawshaw/go/src/runtime/mheap.go:455 +0xbc
runtime.(*mheap).sysAlloc(0x435dc20, 0x40010000, 0x0)
	(lldb) /Users/crawshaw/go/src/runtime/malloc.go:412 +0x434
runtime.(*mheap).grow(0x435dc20, 0x20008, 0x0)
	/Users/crawshaw/go/src/runtime/mheap.go(lldb) :774 +0x50
runtime.(*mheap).allocSpanLocked(0x435dc20, 0x20001, 0xffffffffffffffff)
	/Users/crawshaw/go/src/runtime/mheap.go:678 +0x3c8
runtime.(*mheap).alloc_m(0x435dc20, 0x20001, 0x100000000, 0x87c0680)
	/Users/crawshaw/go/src/runtime/mheap.go:562 +0(lldb) xc0
runtime.(*mheap).alloc.func1()
	/Users/crawshaw/go/src/runtime/mheap.go:(lldb) 627 +0x40
runtime.systemstack(0x16e34adb8)
	/Users/crawshaw/go/src/runtime/asm_arm64.s:255 +0xb8
runtime.(*mheap).alloc(0x435dc20, 0x20001, 0x100000000, 0x4117988)
	/Users/crawshaw/go/src/runtime/mheap.go:628 +0x6c
runtime.largeAlloc(0x40002000, 0x411(lldb) a700, 0x88718000)
	/Users/crawshaw/go/src/runtime/malloc.go:795 +0x78
runtime.mallocgc.func1()
	/Users/crawshaw/go/src/runtime/malloc.go:690 +0x34
runtime.systemstack(0x8730000)
	/Users/crawshaw/go/src/runtime/asm_arm64.s:241 +0x90
runtime.mstart()
(lldb) 	/Users/crawshaw/go/src/runtime/proc.go:1132

goroutine 78 [running]:
runtime.systemstack_switch()
	/Users/crawshaw/go/src/runtime/asm_arm64.s:190 +0x8 fp=0x8748ba0 sp=0x8748b90
runtime.mallocgc(0x40002000, 0x0, 0x8748d00, 0x756ea16397212c)
	/Users/c(lldb) rawshaw/go/src/runtime/malloc.go:691 +0x818 fp=0x8748c40 sp=0x8748ba0
runtime.growslice(0x423c960, 0x872c070, 0x10, 0x10, 0x40000010, 0x40000000, 0x8748d10, 0x41d36c8)
	/Users/crawshaw/go/src/runtime/slice.go:140 +0x1cc fp=0x8748cc0 sp=0x8748c40
encodin(lldb) g/gob.encUint8Array(0x885a870, 0x88fe100, 0x423a7c0, 0x8720020, 0x97)
	/Users/crawshaw/go/src/encoding/gob/encode.go:251 +0x13c fp=0x8748d40 sp=0x8748cc0
encoding/gob.(*Encoder).encodeSingle(0x8792000, 0x8792038, 0x883d5c0, 0x423a7c0, 0x8720020, 0x97)
	(lldb) /Users/crawshaw/go/src/encoding/gob/encode.go:307 +0x168 fp=0x8748da0 sp=0x8748d40
encoding/gob.(*Encoder).encode(0x8792000, 0x8792038, 0x423a7c0, 0x8720020, 0x97, 0x8725240)
	/Users/crawshaw/go/src/encoding/gob/encode.go:709 +0xfc fp=0x8748df0 sp=0x8748(lldb) da0
encoding/gob.(*Encoder).EncodeValue(0x8792000, 0x423a7c0, 0x8720020, 0x97, 0x0, 0x0)
	/Users/crawshaw/go/src/encoding/gob/encoder.go:250 +0x2e8 fp=0x8748ea0 sp=0x8748df0
encoding/gob.(*Encoder).Encode(0x8792000, 0x423a7c0, 0x8720020, 0x8720020, 0x40(lldb) 000000)
	/Users/crawshaw/go/src/encoding/gob/encoder.go:175 +0x4c fp=0x8748ee0 sp=0x8748ea0
encoding/gob.TestHugeWriteFails(0x8b1f2b0)
	/Users/crawshaw/go/src/encoding/gob/encoder_test.go:1075 +0xe8 fp=0x8748fa0 sp=0x8748ee0
testing.tRunner(0x8b1f2b0, (lldb) 0x428c5a8)
	/Users/crawshaw/go/src/testing/testing.go:656 +0x84 fp=0x8748fc0 sp=0x8748fa0
runtime.goexit()
	/Users/crawshaw/go/src/runtime/asm_arm64.s:981 +0x4 fp=0x8748fc0 sp=0x8748fc0
created by testing.(*T).Run
	/Users/crawshaw/go/src/testing/testi(lldb) ng.go:693 +0x234

goroutine 1 [chan receive]:
testing.(*T).Run(0x87e40d0, 0x4282603, 0x12, 0x428c5a8, 0x1)
	/Users/crawshaw/go/src/testing/testing.go:694 +0x254
testing.runTests.func1(0x87e40d0)
	/Users/crawshaw/go/src/testing/testing.go:877 +0x58
t(lldb) esting.tRunner(0x87e40d0, 0x875dd60)
	/Users/crawshaw/go/src/testing/testing.go:656 +0x84
testing.runTests(0x87ea020, 0x4356a40, 0x5a, 0x5a, 0x41267d8)
	/Users/crawshaw/go/src/testing/testing.go:883 +0x260
testing.(*M).Run(0x875df28, 0x875ded8)
	/Users/crawshaw/go/src/testing/testing.go:818 +0xe0
main.main()
	encoding/gob/_test/_testmain.go:278 +0x314

goroutine 17 [syscall, locked to thread]:
runtime.goexit()
	/Users/crawshaw/go/src/runtime/asm_arm64.s:981 +0x(lldb) 4

goroutine 5 [syscall]:
os/signal.signal_recv(0x0)
	/Users/crawshaw/go/src/runtime/sigqueue.go:116 +0xe0
os/signal.loop()
	/Users/crawshaw/go/src/os/signal/signal_unix.go:22 +0x18
created by os/signal.init.1
	/Users/crawshaw/go/src/os/signal/signal_unix.go:28 +0x30

goroutine 6 [select, locked to thread]:
runtime.gopark(0x428d028, 0x0, 0x427f832, 0x6, 0x18, 0x2)
	/Users/crawshaw/go/src/runtime/proc.go:271 +0xfc
runtime.selectgoImpl(0x873c750, 0x18, 0x2)
	/Users/crawshaw/go/src/runtime/select(lldb) .go:423 +0xed0
runtime.selectgo(0x873c750)
	/Users/crawshaw/go/src/runtime/select.go:238 +0x10
runtime.ensureSigM.func1()
	/Users/crawshaw/go/src/runtime/signal_unix.go:434 +0x25c
runtime.goexit()
	/Users/crawshaw/go/src/runtime/asm_arm64.s:981 +0x4
(lldb) Process 4164 exited with status = 2 (0x00000002) 
(lldb) go_darwin_arm_exec: test timeout (test completion)
FAIL	encoding/gob	200.084s

In a subsequent run I saw:

(lldb) fatal error: runtime: out of memory
(lldb) 
runtime stack:
runtime.throw(0x4217f08, 0x16)
	/Users/crawshaw/go/src/runtime/panic.go:596 +0x70
runtime.sysMap(0x2690000, 0x3fec000, 0x888e8001, 0x4306b38)
	/Users/crawshaw/go/src/runtime/mem_darwin.go:58 +0xb0
runtime.(*mheap).mapBits(0x42f1bc0, 0(lldb) xc88f8000)
	/Users/crawshaw/go/src/runtime/mbitmap.go:159 +0xa8
runtime.(*mheap).sysAlloc(0x42f1bc0(lldb) , 0x40010000, 0x1)
	/Users/crawshaw/go/src/runtime/malloc.go:468 +0x250
runtime.(*mheap).grow(0x42f1bc0, 0x20008, 0x0)
	/Users/crawshaw/go/src/runtime/mheap.go:774 +0x50
runtime.(*mheap).allocSpanLocked(0x42f1bc0, 0x20001, 0x0)
	/Users/crawshaw/go/src(lldb) /runtime/mheap.go:678 +0x3c8
runtime.(*mheap).alloc_m(0x42f1bc0, 0x20001, 0xffffff0100000000, 0x40818b4)
	/Users/crawshaw/go/src/runtime/mheap.go:562 +0xc0
runtime.(*mheap).alloc.func1()
	/Users/crawshaw/go/src/runtime/mheap.go:627 +0x40
runtime.syste(lldb) mstack(0x16e3bedb8)
	/Users/crawshaw/go/src/runtime/asm_arm64.s:255 +0xb8
runtime.(*mheap).alloc(0x42f1bc0, 0x20001, 0x100000000, 0x408fd08)
	/Users/crawshaw/go/src/runtime/mheap.go:628 +0x6c
runtime.largeAlloc(0x40002000, 0x100000000, 0x0)
	/Users/cr(lldb) awshaw/go/src/runtime/malloc.go:795 +0x78
runtime.mallocgc.func1()
	/Users/crawshaw/go/src/runtime/malloc.go:690 +0x34
runtime.systemstack(0x86c0000)
	/Users/crawshaw/go/src/runtime/asm_arm64.s:241 +0x90
runtime.mstart()
	/Users/crawshaw/go/src/runti(lldb) me/proc.go:1132

goroutine 75 [running]:
runtime.systemstack_switch()
	/Users/crawshaw/go/src/runtime/asm_arm64.s:190 +0x8 fp=0x86dfba0 sp=0x86dfb90
runtime.mallocgc(0x40002000, 0x0, 0x86a5800, 0x4087f38)
	/Users/crawshaw/go/src/runtime/malloc.go:691(lldb)  +0x818 fp=0x86dfc40 sp=0x86dfba0
runtime.growslice(0x41d0900, 0x896fcf0, 0x10, 0x10, 0x40000010, 0x40000000, 0x86cec00, 0x4167c08)
	/Users/crawshaw/go/src/runtime/slice.go:140 +0x1cc fp=0x86dfcc0 sp=0x86dfc40
encoding/gob.encUint8Array(0x87dc8d0, 0x897(lldb) 73c0, 0x41ce760, 0x897f580, 0x97)
	/Users/crawshaw/go/src/encoding/gob/encode.go:251 +0x13c fp=0x86dfd40 sp=0x86dfcc0
encoding/gob.(*Encoder).encodeSingle(0x8addb80, 0x8addbb8, 0x87c5620, 0x41ce760, 0x897f580, 0x97)
	/Users/crawshaw/go/src/encoding/gob/(lldb) encode.go:307 +0x168 fp=0x86dfda0 sp=0x86dfd40
encoding/gob.(*Encoder).encode(0x8addb80, 0x8addbb8, 0x41ce760, 0x897f580, 0x97, 0x870d180)
	/Users/crawshaw/go/src/encoding/gob/encode.go:709 +0xfc fp=0x86dfdf0 sp=0x86dfda0
encoding/gob.(*Encoder).EncodeValue(0x8addb80, 0x41ce760, 0x897f580, 0x97, 0x0, 0x0)
	/Users/crawshaw/go/src/encoding/gob/encoder.go:250 +0x2e8 fp=0x86dfea0 sp=0x86dfdf0
(lldb) encoding/gob.(*Encoder).Encode(0x8addb80, 0x41ce760, 0x897f580, 0x897f580, 0x40000000)
	/Users/crawshaw/go/src/encoding/gob/encoder.go:175 +0x4c fp=0x86dfee0 sp=0x86dfea0
encoding/gob.TestHugeWriteFails(0x897bad0)
	/Users/crawshaw/go/src/encoding/gob/en(lldb) coder_test.go:1075 +0xe8 fp=0x86dffa0 sp=0x86dfee0
testing.tRunner(0x897bad0, 0x4220548)
	/Users/crawshaw/go/src/testing/testing.go:656 +0x84 fp=0x86dffc0 sp=0x86dffa0
runtime.goexit()
	/Users/crawshaw/go/src/runtime/asm_arm64.s:981 +0x4 fp=0x86dffc0 sp=0x86dffc0
created by testing.(*T).Run
	/Users/crawshaw/go/src/testing/testing.go:693 +0x234

goroutine 1 [chan receive]:
testing.(*T).Run(0x87780d0, 0x42165a3, 0x12, 0x4220548, 0x1)
	/Users/crawshaw/go/src/testing/testing.go:694 +0x254
testing.run(lldb) Tests.func1(0x87780d0)
	/Users/crawshaw/go/src/testing/testing.go:877 +0x58
testing.tRunner(0x87780d0, 0x86edd60)
	/Users/crawshaw/go/src/testing/testing.go:656 +0x84
testing.runTests(0x86b0080, 0x42ea9e0, 0x5a, 0x5a, 0x40bad18)
	/Users/crawshaw/go/sr(lldb) c/testing/testing.go:883 +0x260
testing.(*M).Run(0x86edf28, 0x86eded8)
	/Users/crawshaw/go/src/testing/testing.go:818 +0xe0
main.main()
	encoding/gob/_test/_testmain.go:278 +0x314

goroutine 17 [syscall, locked to thread]:
runtime.goexit()
	/Users/(lldb) crawshaw/go/src/runtime/asm_arm64.s:981 +0x4

goroutine 19 [syscall]:
os/signal.signal_recv(0x0)
	/Users/crawshaw/go/src/runtime/sigqueue.go:116 +0xe0
os/signal.loop()
	/Users/crawshaw/go/src/os/signal/signal_unix.go:22 +0x18(lldb) 
created by os/signal.init.1
	/Users/crawshaw/go/src/os/signal/signal_unix.go:28 +0x30

goroutine 20 [select, locked to thread]:
runtime.gopark(0x4220fc8, 0x0, 0x42137d2, 0x6, 0x18, 0x2)
	/Users/crawshaw/go/src/runtime/proc.go:271 +0xfc
runtime.selectgoImpl(0x86d8f50, 0x18, 0x2)
	/Users/crawshaw/go/src/runtime/select.go:423 +0xed0
runtime.selectgo(0x86d8f50)
	/Users/crawshaw/go/src/runtime/select.go:238 +0x10
runtime.ensureSigM.func1()
	/Users/crawshaw/go/src/runtime/signal_unix.go:434 +0x25c
runtime.goexit()
	/Users/crawshaw/go/src/runtime/asm_arm64.s:981 +0x4
(lldb) Process 4313 exited with status = 2 (0x00000002) 
(lldb) go_darwin_arm_exec: test timeout (test completion)
exit status 1
FAIL	encoding/gob	19.704s

Seems to be a moderately reliable failure.

(it is failing much faster than the test harness suggests, in under a second.)

cc @aclements

[aclements]

runtime.largeAlloc(0x40002000, 0x411a700, 0x88718000)
/Users/crawshaw/go/src/runtime/malloc.go:795 +0x78

This is doing a 1 GB allocation and it looks like a few lines earlier in TestHugeWriteFails the test did another 1 GB allocation (which seems to have succeeded). Darwin/arm64 only reserves 2 GB for the Go heap, so this should fail. The error message is no good, though.

The bad error message is because mheap.sysAlloc is a little confused. Because the darwin/arm64 heap is only 2 GB, we wound up in the 32-bit path. That's not so bad, except that it assumes we can grow the reservation up to 4 GB (_MaxArena32), but mallocinit only reserved auxiliary structures for a 2 GB heap. When we try to grow the spans array past mallocinit's reservation, it crashes.

I think this "worked" until 5915ce6 in late October because it silently walked off the end of the spans array and corrupted something else (probably the heap bitmap). In October I changed it to use a slice instead of ugly pointer math, so we now get bounds checking for free where we didn't have any sort of overflow check before.

(Also, given the name of the test, shouldn't gob fail gracefully before allocating a huge slice?)

[crawshaw]

Thanks for the analysis. Somehow I missed this was happening in a test that should be skipped in -short mode. That suggests there's something wrong with my test harness, I believe all.bash should run -short by default.

Then there is the issue of making this error clearer (and ideally, handled properly by encoding/gob), but I believe that is a pre-existing condition so we can punt it to 1.9.

[aclements]

Then there is the issue of making this error clearer (and ideally, handled properly by encoding/gob), but I believe that is a pre-existing condition so we can punt it to 1.9.

Sounds good. I'm fairly certain the only consequence of not changing this is that you get one panic instead of another, but trying to fix it may have other consequences. :)

I've got a fix queued up, which I'll send for Go 1.9.

[gopherbot]

CL https://golang.org/cl/35253 mentions this issue.

[gopherbot]

CL https://golang.org/cl/35252 mentions this issue.

[aclements]

/cc @robpike @rsc: Should encoding/gob's TestHugeWriteFails be failing before it attempts to allocate enough memory to encode the entire (huge) input? The runtime bug in this issue was tickled because TestHugeWriteFails attempted to allocate a 1 GB buffer rather than failing early on the huge input. The code is clearly written to encode the whole thing and only then check if it got too big, but I'm wondering if that's what it should be doing.

[robpike]

@aclements If you can write a simple reproducer, please file an issue and assign it to me.

[gopherbot]

CL https://golang.org/cl/35251 mentions this issue.

[nightlyone]

@aclements since https://golang.org/cl/35251 removes the broken ulimit -v check, could you link the issue tracking re-adding that check? Even if it's considered not worthy to re-add, people should at least be able to find the reasons.

[aclements]

@nightlyone, thanks. Added a reference to the commit message.