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
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Milestone

Comments

@jdknezek
Copy link

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 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 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?

@dsnet dsnet added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jan 6, 2017
@jdknezek
Copy link
Author

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

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.

@bradfitz bradfitz added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Jan 6, 2017
@jdknezek
Copy link
Author

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 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

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

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

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

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!

@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.
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Development

No branches or pull requests

6 participants