Unknown panic deep in the standard library memory management?

[alankm]

What version of Go are you using (go version)?

$ go version
go version go1.12.9 linux/amd64

Does this issue reproduce with the latest release?

Unfortunately I do not know. I do not even know how reproducible it is in the release I'm using.

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/alan/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/alan/go"
GOPROXY=""
GORACE=""
GOROOT="/usr/local/go"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="/usr/bin/gcc"
CXX="/usr/bin/g++"
CGO_ENABLED="1"
GOMOD=""
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-build941886845=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I am unable to provide a working example for you to use for a few reasons, but I will at least try and explain what the code does. It's not particularly complicated, but it does exist under some uncommon circumstances.

Basically, it's a standard Go HTTP server made to serve a single request for a client that authenticates with a client certificate. The client is POSTing a potentially large file that has been gzipped, and the server is saving it to disk. It does not preload the whole file into memory or anything, at least not in my logic. Here is a snippet from the code within the HTTP response handler.

        gz, err := gzip.NewReader(r.Body)
	if err != nil {
		code := http.StatusBadRequest
		http.Error(w, "Payload is not valid gzip encoded data", code)
		return
	}
        defer gz.Close()

        f, err := os.OpenFile(path, os.O_WRONLY|os.O_SYNC, 0777)
	if err != nil {
		code := http.StatusInternalServerError
		http.Error(w, http.StatusText(code), code)
		return
	}
	defer f.Close()

	hasher := md5.New()
	mw := io.MultiWriter(hasher, f)

	k, err := io.Copy(mw, gz)
	if err != nil {
		code := http.StatusInternalServerError
		http.Error(w, http.StatusText(code), code)
		return
	}

Note: 'r' is the '*http.Request'.

The server is running with swap space disabled, which may be relevant since I see that the issue seems to occur somewhere in the malloc logic. However, the server should have plenty of RAM. In this case when it failed the server had 8 GiB of RAM and was receiving a payload that decompresses to only 1 GiB. No other programs were running so I expect that nearly all of that 8 GiB should be available to it.

What did you expect to see?

No errors.

What did you see instead?

The following stack traces and no others. Not a single line in these stack traces refers to one of my *.go files. I don't even know how that is possible in Go.

fatal error: slice bounds out of range

runtime stack:
runtime.throw(0x705794, 0x19)
	/usr/local/go/src/runtime/panic.go:617 +0x72
runtime.panicslice()
	/usr/local/go/src/runtime/panic.go:51 +0x8e
runtime.pcvalue(0x8c7dd0, 0x91d720, 0x4f337609, 0x5fc364, 0xc000047d68, 0x7d8401, 0x91d720)
	/usr/local/go/src/runtime/symtab.go:652 +0x54d
runtime.funcspdelta(0x8c7dd0, 0x91d720, 0x5fc364, 0xc000047d68, 0xc000047d68)
	/usr/local/go/src/runtime/symtab.go:756 +0x5f
runtime.gentraceback(0x426a36, 0xc0000db150, 0x0, 0xc00010a000, 0x0, 0xc0000db198, 0x20, 0x0, 0x0, 0x0, ...)
	/usr/local/go/src/runtime/traceback.go:222 +0x1888
runtime.callers.func1()
	/usr/local/go/src/runtime/traceback.go:814 +0x83
runtime.systemstack(0x0)
	/usr/local/go/src/runtime/asm_amd64.s:351 +0x66
runtime.mstart()
	/usr/local/go/src/runtime/proc.go:1153

goroutine 19 [running]:
runtime.systemstack_switch()
	/usr/local/go/src/runtime/asm_amd64.s:311 fp=0xc0000db0e8 sp=0xc0000db0e0 pc=0x4551a0
runtime.callers(0x4, 0xc0000db198, 0x20, 0x20, 0xc00013cc60)
	/usr/local/go/src/runtime/traceback.go:813 +0xbb fp=0xc0000db150 sp=0xc0000db0e8 pc=0x44d97b
runtime.mProf_Malloc(0xc0003aba80, 0x20)
	/usr/local/go/src/runtime/mprof.go:342 +0x76 fp=0xc0000db2c8 sp=0xc0000db150 pc=0x426a36
runtime.profilealloc(0xc000036380, 0xc0003aba80, 0x20)
	/usr/local/go/src/runtime/malloc.go:1095 +0x58 fp=0xc0000db2e8 sp=0xc0000db2c8 pc=0x40c078
runtime.mallocgc(0x20, 0x6bf700, 0x6ee501, 0x75fca0)
	/usr/local/go/src/runtime/malloc.go:1019 +0x44f fp=0xc0000db388 sp=0xc0000db2e8 pc=0x40b74f
runtime.newobject(0x6bf700, 0x2f1)
	/usr/local/go/src/runtime/malloc.go:1068 +0x38 fp=0xc0000db3b8 sp=0xc0000db388 pc=0x40be78
crypto/tls.(*Conn).readFromUntil(0xc000106380, 0x75fca0, 0xc000102018, 0x113, 0xc000102018, 0x0)
	/usr/local/go/src/crypto/tls/conn.go:783 +0xb1 fp=0xc0000db408 sp=0xc0000db3b8 pc=0x58f691
crypto/tls.(*Conn).readRecordOrCCS(0xc000106380, 0x715400, 0xc0001064b8, 0x62f14a)
	/usr/local/go/src/crypto/tls/conn.go:635 +0x591 fp=0xc0000db5d8 sp=0xc0000db408 pc=0x58e031
crypto/tls.(*Conn).readRecord(...)
	/usr/local/go/src/crypto/tls/conn.go:558
crypto/tls.(*Conn).Read(0xc000106380, 0xc00016a000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/crypto/tls/conn.go:1236 +0x137 fp=0xc0000db620 sp=0xc0000db5d8 pc=0x591dc7
net/http.(*connReader).Read(0xc000100960, 0xc00016a000, 0x1000, 0x1000, 0xc00016a000, 0x1000, 0x1000)
	/usr/local/go/src/net/http/server.go:787 +0x107 fp=0xc0000db688 sp=0xc0000db620 pc=0x62f7e7
bufio.(*Reader).fill(0xc00012c420)
	/usr/local/go/src/bufio/bufio.go:100 +0x10f fp=0xc0000db6d8 sp=0xc0000db688 pc=0x46bbff
bufio.(*Reader).ReadSlice(0xc00012c420, 0xc000100a0a, 0xc00016a0f4, 0x2, 0x2, 0x1000, 0xc00016a000)
	/usr/local/go/src/bufio/bufio.go:356 +0x3d fp=0xc0000db720 sp=0xc0000db6d8 pc=0x46c62d
fatal error: slice bounds out of range
panic during panic

runtime stack:
runtime.throw(0x705794, 0x19)
	/usr/local/go/src/runtime/panic.go:617 +0x72
runtime.panicslice()
	/usr/local/go/src/runtime/panic.go:51 +0x8e
runtime.pcvalue(0x8c7dd0, 0x91d720, 0x4f337609, 0x5fc364, 0xc0000475e8, 0x6ff501, 0x1)
	/usr/local/go/src/runtime/symtab.go:652 +0x54d
runtime.funcspdelta(0x8c7dd0, 0x91d720, 0x5fc364, 0xc0000475e8, 0x20)
	/usr/local/go/src/runtime/symtab.go:756 +0x5f
runtime.gentraceback(0xffffffffffffffff, 0xffffffffffffffff, 0x0, 0xc00010a000, 0x0, 0x0, 0x64, 0x0, 0x0, 0x0, ...)
	/usr/local/go/src/runtime/traceback.go:222 +0x1888
runtime.traceback1(0xffffffffffffffff, 0xffffffffffffffff, 0x0, 0xc00010a000, 0x0)
	/usr/local/go/src/runtime/traceback.go:746 +0xf1
runtime.traceback(0xffffffffffffffff, 0xffffffffffffffff, 0x0, 0xc00010a000)
	/usr/local/go/src/runtime/traceback.go:700 +0x52
runtime.tracebackothers(0xc000000900)
	/usr/local/go/src/runtime/traceback.go:935 +0x28d
runtime.dopanic_m(0xc000000900, 0x42b6e2, 0xc000047b10, 0x1)
	/usr/local/go/src/runtime/panic.go:817 +0x2a0
runtime.fatalthrow.func1()
	/usr/local/go/src/runtime/panic.go:672 +0x5f
runtime.fatalthrow()
	/usr/local/go/src/runtime/panic.go:669 +0x57
runtime.throw(0x705794, 0x19)
	/usr/local/go/src/runtime/panic.go:617 +0x72
runtime.panicslice()
	/usr/local/go/src/runtime/panic.go:51 +0x8e
runtime.pcvalue(0x8c7dd0, 0x91d720, 0x4f337609, 0x5fc364, 0xc000047d68, 0x7d8401, 0x91d720)
	/usr/local/go/src/runtime/symtab.go:652 +0x54d
runtime.funcspdelta(0x8c7dd0, 0x91d720, 0x5fc364, 0xc000047d68, 0xc000047d68)
	/usr/local/go/src/runtime/symtab.go:756 +0x5f
runtime.gentraceback(0x426a36, 0xc0000db150, 0x0, 0xc00010a000, 0x0, 0xc0000db198, 0x20, 0x0, 0x0, 0x0, ...)
	/usr/local/go/src/runtime/traceback.go:222 +0x1888
runtime.callers.func1()
	/usr/local/go/src/runtime/traceback.go:814 +0x83
runtime.systemstack(0x0)
	/usr/local/go/src/runtime/asm_amd64.s:351 +0x66
runtime.mstart()

[randall77]

Something is going very wrong when trying to do a stack backtrace.

runtime.pcvalue(0x8c7dd0, 0x91d720, 0x4f337609, 0x5fc364, 0xc000047d68, 0x7d8401, 0x91d720)
	/usr/local/go/src/runtime/symtab.go:652 +0x54d

The 3rd argument here, 0x4f337609, looks weird. It's huge - it is an offset into some descriptor information for a function, so it should be small. That huge value is used to index the descriptor information, and it results in an out of bounds error.

That value is coming from funcInfo structures. The pointers shown in the trace seem like reasonable values. The location read is in the read-only section, so I don't see how it could become corrupted.

Could you fire up your binary in a debugger and dump the 64 bytes at the address 0x8c7dd0 and post them here? The weird huge value is generated from a 4-byte load from offset 20 of the data structure at 0x8c7dd0.
While you're at it, dump the 256 bytes at 0x91d720.

[alankm]

In the context where this error occurs I don't think I can actually run the binary in a debugger. Having said that, there is a chance that I have just figured out how it happened.

Some time after the binary is running and serving requests there's a chance that another process is unmounting the device the binary is stored on and writing to it directly as a raw character device. Possibly overwriting the binary itself. It did not initially occur to me that this could cause problems after the binary was loaded into memory, but after thinking about it for a while I've realized that demand-paging could be loading sectors from the disk into the run-time later than I anticipated. After reading your take on the issue this seems even more likely to me.

I've added an mlockall syscall using the MCL_FUTURE and MCL_CURRENT flags at the very beginning of my Go program in an attempt to force Linux to load it all in right away. This change has not been extensively tested, but the error has not reproduced since.

Looks like I might have found a way to corrupt "read-only" memory.

I think I'll close this issue and reopen it if the problem shows up again.