runtime: wrong goroutine in newstack

[hryamzik]

Please answer these questions before submitting your issue. Thanks!

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

1.6.2

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

Build on MacOS, run on linux x64. Running prometheus/node_exporter build with 1.6.2 ended up with an unresponsive.

time curl 127.0.0.1:9100/metrics
curl: (56) Recv failure: Connection reset by peer

real    1m48.762s

Here's some info from gdb:

(gdb) thread apply all bt

Thread 1 (process 47084):
#0  runtime.futex () at /usr/local/Cellar/go/1.6.2/libexec/src/runtime/sys_linux_amd64.s:307
#1  0x000000000042c473 in runtime.futexsleep (addr=0xd73828 <runtime.m0+264>, val=0, ns=-1) at /usr/local/Cellar/go/1.6.2/libexec/src/runtime/os1_linux.go:40
#2  0x0000000000410cf4 in runtime.notesleep (n=0xd73828 <runtime.m0+264>) at /usr/local/Cellar/go/1.6.2/libexec/src/runtime/lock_futex.go:145
#3  0x0000000000434a2b in runtime.stopm () at /usr/local/Cellar/go/1.6.2/libexec/src/runtime/proc.go:1538
#4  0x0000000000435488 in runtime.gcstopm () at /usr/local/Cellar/go/1.6.2/libexec/src/runtime/proc.go:1742
#5  0x000000000043628c in runtime.schedule () at /usr/local/Cellar/go/1.6.2/libexec/src/runtime/proc.go:2039
#6  0x0000000000436834 in runtime.goschedImpl (gp=0xc820a41c80) at /usr/local/Cellar/go/1.6.2/libexec/src/runtime/proc.go:2155
#7  0x00000000004368d2 in runtime.gopreempt_m (gp=0xc820a41c80) at /usr/local/Cellar/go/1.6.2/libexec/src/runtime/proc.go:2170
#8  0x00000000004479cc in runtime.newstack () at /usr/local/Cellar/go/1.6.2/libexec/src/runtime/stack.go:932
#9  0x000000000045e81f in runtime.morestack () at /usr/local/Cellar/go/1.6.2/libexec/src/runtime/asm_amd64.s:359
#10 0x0000000000d73100 in runtime.work ()
#11 0x00007ffcfc0e9b00 in ?? ()
#12 0x0000000000d73180 in runtime.work ()
#13 0x0000000000433912 in runtime.mstart () at /usr/local/Cellar/go/1.6.2/libexec/src/runtime/proc.go:1068
#14 0x000000000045e568 in runtime.rt0_go () at /usr/local/Cellar/go/1.6.2/libexec/src/runtime/asm_amd64.s:149
#15 0x0000000000000003 in ?? ()
#16 0x00007ffcfc0e9b48 in ?? ()
#17 0x0000000000000003 in ?? ()
#18 0x00007ffcfc0e9b48 in ?? ()
#19 0x0000000000000000 in ?? ()

(gdb) info goroutines
  1 runnable runtime.createfing
  2 runnable runtime.gopark
  17 waiting  runtime.gopark
  18 waiting  runtime.gopark
  38 waiting  runtime.gopark
  82 waiting  runtime.gopark
  65 waiting  runtime.gopark
  81 waiting  runtime.gopark
  53261 runnable runtime.convT2E
  39 waiting  runtime.gopark
  40 waiting  runtime.gopark
  41 waiting  runtime.gopark
  42 waiting  runtime.gopark
  43 waiting  runtime.gopark
  44 waiting  runtime.gopark
  45 waiting  runtime.gopark
  46 waiting  runtime.gopark
  66 waiting  runtime.gopark
  47 waiting  runtime.gopark
  97 waiting  runtime.gopark
  98 waiting  runtime.gopark
  99 waiting  runtime.gopark
  100 waiting  runtime.gopark
  101 waiting  runtime.gopark
  102 waiting  runtime.gopark
  103 waiting  runtime.gopark
  67 waiting  runtime.gopark
  104 waiting  runtime.gopark
  83 waiting  runtime.gopark
  84 waiting  runtime.gopark
  85 waiting  runtime.gopark
  86 waiting  runtime.gopark
  87 waiting  runtime.gopark
  88 waiting  runtime.gopark
  89 waiting  runtime.gopark
  113 waiting  runtime.gopark
  114 waiting  runtime.gopark
  53289 runnable runtime.slicebytetostring
* 53282 running  runtime.systemstack_switch
  53283 runnable runtime.slicebytetostring

(gdb) goroutine 53282 bt
#0  runtime.systemstack_switch () at /usr/local/Cellar/go/1.6.2/libexec/src/runtime/asm_amd64.s:245
#1  0x000000000042f334 in runtime.startpanic () at /usr/local/Cellar/go/1.6.2/libexec/src/runtime/panic.go:525
#2  0x000000000042f433 in runtime.throw (s="unexpected signal during runtime execution") at /usr/local/Cellar/go/1.6.2/libexec/src/runtime/panic.go:546
#3  0x0000000000443bca in runtime.sigpanic () at /usr/local/Cellar/go/1.6.2/libexec/src/runtime/sigpanic_unix.go:12
#4  0x00000000000011fd in ?? ()
#5  0x0000000000000000 in ?? ()

And here's the panic log:

fatal error: unexpected signal during runtime execution
fatal error: unexpected signal during runtime execution
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: unexpected signal during runtime execution
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
runtime: unexpected return pc for sort.quickSort called from 0x0
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: unknown caller pc
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: systemstack called from unexpected goroutine
fatal error: runtime·unlock: lock count
fatal error: systemstack called from unexpected goroutine
fatal error: systemstack called from unexpected goroutine
fatal error: runtime·unlock: lock count
fatal error: systemstack called from unexpected goroutine
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: systemstack called from unexpected goroutine
fatal error: systemstack called from unexpected goroutine
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: runtime·unlock: lock count
fatal error: systemstack called from unexpected goroutine
fatal error: runtime·unlock: lock count
fatal error: systemstack called from unexpected goroutine
fatal error: runtime·unlock: lock count
fatal error: systemstack called from unexpected goroutine
fatal error: systemstack called from unexpected goroutine
fatal error: runtime·unlock: lock count
fatal error: systemstack called from unexpected goroutine
fatal error: runtime·unlock: lock count
runtime: newstack called from g=0xc820991980
    m=0xc820549c00 m->curg=0x0 m->g0=0xc820580300 m->gsignal=0xc820580180
strings.Join(0xc820230ac8, 0x2, 0x2, 0xa61978, 0x1, 0x0, 0x0)
    /usr/local/Cellar/go/1.6.2/libexec/src/strings/strings.go:363 +0xee
path.Join(0xc820230ac8, 0x2, 0x2, 0x0, 0x0)
    /usr/local/Cellar/go/1.6.2/libexec/src/path/path.go:153 +0xfa
github.com/prometheus/node_exporter/collector.procFilePath(0xa69eb8, 0x4, 0x0, 0x0)
    /Users/hryamzik/gopath/src/github.com/prometheus/node_exporter/collector/paths.go:30 +0xd2
github.com/prometheus/node_exporter/collector.(*statCollector).Update(0xc820196d40, 0xc820471b60, 0x0, 0x0)
    /Users/hryamzik/gopath/src/github.com/prometheus/node_exporter/collector/stat_linux.go:89 +0x6f
main.execute(0x7ffcfc0e9f34, 0x4, 0x7f8157c87130, 0xc820196d40, 0xc820471b60)
    /Users/hryamzik/gopath/src/github.com/prometheus/node_exporter/node_exporter.go:96 +0x82
main.NodeCollector.Collect.func1(0xc820471b60, 0xc820a06000, 0x7ffcfc0e9f34, 0x4, 0x7f8157c87130, 0xc820196d40)
    /Users/hryamzik/gopath/src/github.com/prometheus/node_exporter/node_exporter.go:75 +0x49
created by main.NodeCollector.Collect
    /Users/hryamzik/gopath/src/github.com/prometheus/node_exporter/node_exporter.go:77 +0x137
fatal error: runtime: wrong goroutine in newstack

[minux]

Does the application use unsafe? Cgo? Have you tried to run it under race detector?

[hryamzik]

Yes, github finds some cgo calls there and unsafe as well. I didn't run race detector, shall I give it a try?

[minux]

Yeah, run it under the race detector and double check all the unsafe and cgo usages.

[josharian]

Trying out the new msan instrumentation might also be helpful.

[hryamzik]

I've updated to latest version of node_exporter and do not face this any more (with go 1.5). Unfortunately I don't have time for debugging this, so I'll close this for now.

[ianlancetaylor]

@hryamzik Thanks for following up.