Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fmt: panic in (*fmt).padString #18542

Closed
jdknezek opened this issue Jan 6, 2017 · 10 comments
Closed

fmt: panic in (*fmt).padString #18542

jdknezek opened this issue Jan 6, 2017 · 10 comments

Comments

@jdknezek
Copy link

@jdknezek jdknezek commented Jan 6, 2017

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

go version devel +9cd3c06 Thu Dec 15 20:06:07 2016 +0000 windows/amd64 (go1.8beta2)

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

set GOARCH=amd64
set GOBIN=
set GOEXE=.exe
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOOS=windows
set GOPATH=...
set GORACE=
set GOROOT=C:\dev\go
set GOTOOLDIR=C:\dev\go\pkg\tool\windows_amd64
set GCCGO=gccgo
set CC=gcc
set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0 -fdebug-prefix-map=C:\...\go-build983357635=/tmp/go-build -gno-record-gcc-switches
set CXX=g++
set CGO_ENABLED=1
set PKG_CONFIG=pkg-config
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2

What did you do?

I have a call with an environment like this:

type datum struct {
	name string
	kind uint16
}

kindToString := map[uint16]string{...}

d := datum{...}

fmt.Sprintf("%s:%s", d.name, kindToString[d.kind])

Unfortunately this happens only occasionally on our production servers, and I can't duplicate on my development machine or the playground.

What did you expect to see?

No panics

What did you see instead?

fmt.(*fmt).padString(0xc042cbc400, 0x0, 0x17)
        C:/dev/go/src/fmt/format.go:110 +0xa3
fmt.(*fmt).fmt_s(0xc042cbc400, 0x0, 0x17)
        C:/dev/go/src/fmt/format.go:328 +0x68
fmt.(*pp).fmtString(0xc042cbc3c0, 0x0, 0x17, 0xc000000073)
        C:/dev/go/src/fmt/print.go:433 +0x19f
fmt.(*pp).printArg(0xc042cbc3c0, 0x745800, 0xc0425d19d0, 0xc000000073)
        C:/dev/go/src/fmt/print.go:664 +0x803
fmt.(*pp).doPrintf(0xc042cbc3c0, 0x7c3a9b, 0x5, 0xc042aefd10, 0x2, 0x2)
        C:/dev/go/src/fmt/print.go:998 +0x11fa
fmt.Sprintf(0x7c3a9b, 0x5, 0xc042aefd10, 0x2, 0x2, 0xc0425d19c0, 0xc042aefd30)
        C:/dev/go/src/fmt/print.go:196 +0x71

The root function is:

// padString appends s to f.buf, padded on left (!f.minus) or right (f.minus).
func (f *fmt) padString(s string) {
	if !f.widPresent || f.wid == 0 {
		f.buf.WriteString(s) /* PANIC HERE - f.buf is nil? */
		return
	}
	...
}
@jdknezek
Copy link
Author

@jdknezek jdknezek commented Jan 6, 2017

Ugh, of course I accidentally snipped the actual panic cause from the stack trace.

The original panic was a nil dereference. I'll add the message back as soon as it happens again.

@dsnet
Copy link
Member

@dsnet dsnet commented Jan 6, 2017

Hi, unfortunately, this is not alot of information to go on.

Some questions to help understand the situation better:

  • Does this manifest itself in Go 1.7 at all?
  • Is there any use of unsafe, or cgo?
  • Does the race detector report any issues?
@jdknezek
Copy link
Author

@jdknezek jdknezek commented Jan 6, 2017

  • I don't have any record of it occurring in 1.7, but I'll give it a try.
  • Neither, to my knowledge
  • I've rebuilt the binary with the race detector enabled and am attempting to duplicate the issue.
@josharian
Copy link
Contributor

@josharian josharian commented Jan 6, 2017

You might also re-try with the latest tip. An important runtime fix went in a few hours ago. Unlikely to be related, but worth checking if it is easy. Thanks.

@jdknezek
Copy link
Author

@jdknezek jdknezek commented Jan 9, 2017

There's been no crash since I enabled the race detector. We usually have one crash per day, but it's possible we had less traffic over the weekend.

Would enabling the race detector prevent a crash that otherwise would have occurred?

@bradfitz
Copy link
Contributor

@bradfitz bradfitz commented Jan 9, 2017

Would enabling the race detector prevent a crash that otherwise would have occurred?

Unlikely.

@bradfitz bradfitz added this to the Go1.9Maybe milestone Jan 13, 2017
@jdknezek
Copy link
Author

@jdknezek jdknezek commented Jan 17, 2017

After running for a week on go1.8beta2 with the race detector enabled, there were no crashes. When go1.8rc1 was released I upgraded and after a few days (without the race detector enabled) got the same crash:

panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xc0000005 code=0x0 addr=0x0 pc=0x458887]

goroutine 10740463 [running]:
fmt.(*fmt).padString(0xc04346c100, 0x0, 0x27)
        C:/dev/go/src/fmt/format.go:110 +0xa3
fmt.(*fmt).fmt_s(0xc04346c100, 0x0, 0x27)
        C:/dev/go/src/fmt/format.go:328 +0x68
fmt.(*pp).fmtString(0xc04346c0c0, 0x0, 0x27, 0xc000000073)
        C:/dev/go/src/fmt/print.go:433 +0x19f
fmt.(*pp).printArg(0xc04346c0c0, 0x7477a0, 0xc042beade0, 0xc000000073)
        C:/dev/go/src/fmt/print.go:664 +0x803
fmt.(*pp).doPrintf(0xc04346c0c0, 0x7c60bd, 0x5, 0xc044275d10, 0x2, 0x2)
        C:/dev/go/src/fmt/print.go:998 +0x11ee
fmt.Sprintf(0x7c60bd, 0x5, 0xc044275d10, 0x2, 0x2, 0xc042beadd0, 0xc044275d30)
        C:/dev/go/src/fmt/print.go:196 +0x71

I'm going to try go1.7.x now and see if it still happens.

@bradfitz
Copy link
Contributor

@bradfitz bradfitz commented Jan 17, 2017

This looks suspicious:

fmt.(*fmt).padString(0xc042cbc400, 0x0, 0x17)
        C:/dev/go/src/fmt/format.go:110 +0xa3

That means padString is being called with a non-nil *fmt, but the string's data pointer is nil (0x0), and it has length 0x27 or 0x17 (earlier).

Are you sure there's no unsafe going on in the code, making bogus strings manually?

Alternatively, maybe the runtime code to return a zero value of a string is bogus, at least for this case. (Unlikely?)

Or, are you concurrently modifying and accessing the map from different goroutines without locking?

Is the code available somewhere?

/cc @aclements @randall77

@aclements
Copy link
Member

@aclements aclements commented Jan 17, 2017

I'm not sure what's going on, but I can say that the panic is from attempting to deference the nil string pointer (in particular, f.buf is not nil).

fmt.(*fmt).padString(0xc04346c100, 0x0, 0x27)
        C:/dev/go/src/fmt/format.go:110 +0xa3

f.buf.WriteString got inlined here. The nil pointer dereference actually happened in runtime.memmove called from f.buf.WriteString via the append. memmove isn't being shown by because it's an unexported runtime function. The nil pointer dereference is from memmove trying to copy 0x27 bytes from the nil string pointer.

@jdknezek
Copy link
Author

@jdknezek jdknezek commented Feb 14, 2017

Sorry for the long silence on this.

I was able to identify a race condition where the datum's string was being modified concurrently with it being used as a dictionary key, and since fixing this I haven't observed any more panics.

I'll re-open the issue if they occur again, but I believe it's just a data race. Thank you all for your help!

@jdknezek jdknezek closed this Feb 14, 2017
@golang golang locked and limited conversation to collaborators Feb 14, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
6 participants
You can’t perform that action at this time.