runtime: fmt.Sprintf crash the process

[Hansanshi]

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

1.16.9

Does this issue reproduce with the latest release?

never try the latest release of go.

One process will crash every few days in production environment ( not very frequent, about 100 processes in total).

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

go env Output

GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/root/.cache/go-build"
GOENV="/root/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/root/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/root/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.16.9"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/dev/null"
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-build2624293184=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Note: real used version is 1.16.9

https://go.dev/play/p/W9ut43Jar8b

This is simplified simulated code, but can't reproduce the problem.

Basically, I have a complex struct and its value will be concurrently modified (which I guess is the key). After all, the complex struct will be printed and the whole process crash occasionally.

I set GOTRACEBACK=crash, so I can get the core dump and analyse it with delve.

below is the backtrace

0  0x0000000000482de1 in runtime.raise
    at /usr/local/go/src/runtime/sys_linux_amd64.s:164
 1  0x000000000045ea1d in runtime.dieFromSignal
    at /usr/local/go/src/runtime/signal_unix.go:768
 2  0x000000000045f071 in runtime.sigfwdgo
    at /usr/local/go/src/runtime/signal_unix.go:982
 3  0x000000000045d894 in runtime.sigtrampgo
    at /usr/local/go/src/runtime/signal_unix.go:416
 4  0x0000000000483163 in runtime.sigtramp
    at /usr/local/go/src/runtime/sys_linux_amd64.s:399
 5  0x00007f98d33fb630 in ???
    at ?:-1
 6  0x00000000004473ac in runtime.crash
    at /usr/local/go/src/runtime/signal_unix.go:860
 7  0x00000000004473ac in runtime.fatalpanic
    at /usr/local/go/src/runtime/panic.go:1217
 8  0x0000000000446ce5 in runtime.gopanic
    at /usr/local/go/src/runtime/panic.go:1065
 9  0x00000000004449fb in runtime.panicmem
    at /usr/local/go/src/runtime/panic.go:212
10  0x000000000045e853 in runtime.sigpanic
    at /usr/local/go/src/runtime/signal_unix.go:734
11  0x00000000004824fc in runtime.memmove
    at /usr/local/go/src/runtime/memmove_amd64.s:185
12  0x000000000050654e in fmt.(*buffer).writeString
    at /usr/local/go/src/fmt/print.go:82
13  0x000000000050654e in fmt.(*fmt).padString
    at /usr/local/go/src/fmt/format.go:110
14  0x00000000005074a5 in fmt.(*fmt).fmtS
    at /usr/local/go/src/fmt/format.go:359
15  0x000000000050a951 in fmt.(*pp).fmtString
    at /usr/local/go/src/fmt/print.go:443
16  0x000000000050f056 in fmt.(*pp).printValue
    at /usr/local/go/src/fmt/print.go:757
17  0x000000000050e9a8 in fmt.(*pp).printValue
    at /usr/local/go/src/fmt/print.go:806
18  0x000000000050e9a8 in fmt.(*pp).printValue
    at /usr/local/go/src/fmt/print.go:806
19  0x000000000050e797 in fmt.(*pp).printValue
    at /usr/local/go/src/fmt/print.go:876
20  0x000000000050c813 in fmt.(*pp).printArg
    at /usr/local/go/src/fmt/print.go:712
21  0x000000000050fe48 in fmt.(*pp).doPrintf
    at /usr/local/go/src/fmt/print.go:1026
22  0x0000000000509186 in fmt.Sprintf
    at /usr/local/go/src/fmt/print.go:219

THE code of frame 12 is:

func (b *buffer) writeString(s string) {
	*b = append(*b, s...)
}

I'm sure b is not nil, because I examine it in frame 13, while str can't be examined

> runtime.raise() /usr/local/go/src/runtime/sys_linux_amd64.s:164 (PC: 0x482de1)
Warning: debugging optimized function
Frame 13: /usr/local/go/src/fmt/format.go:110 (PC: 50654e)
   105:	}
   106:
   107:	// padString appends s to f.buf, padded on left (!f.minus) or right (f.minus).
   108:	func (f *fmt) padString(s string) {
   109:		if !f.widPresent || f.wid == 0 {
=> 110:			f.buf.writeString(s)
   111:			return
   112:		}
   113:		width := f.wid - utf8.RuneCountInString(s)
   114:		if !f.minus {
   115:			// left padding
(dlv) print f
*fmt.fmt {
	buf: *fmt.buffer len: 197, cap: 65536, [...+133 more],
	fmtFlags: fmt.fmtFlags {widPresent: false, precPresent: false, minus: false, plus: false, sharp: false, space: false, zero: false, plusV: true, sharpV: false},
	wid: 0,
	prec: 2,
	intbuf: [68]uint8 [0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,49,48,56,55,57,53,53,56,53,51,50,55,50,48,50,50,...+4 more],}
(dlv) args
f = (*fmt.fmt)(0xc038f08930)
s = (unreadable empty OP stack)
b = *(unreadable read out of bounds)

What did you expect to see?

I wanna know the reason.

What did you see instead?

[ALTree]

The code has a data race, which in a bigger and more complex program in the long run probably ends up corrupting some internal data. In general, there is no guarantee that a racy program will behave in a predictable way. You'll need to protect access to shared resources with locks or by using atomic operations.

Running the program with -race will print race warnings that point to the exact location of the data race.

Closing here since this is not a bug in Go.