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

runtime: crash with "invalid pc-encoded table" in TSAN mode #27540

Closed
crxpandion opened this issue Sep 6, 2018 · 42 comments
Closed

runtime: crash with "invalid pc-encoded table" in TSAN mode #27540

crxpandion opened this issue Sep 6, 2018 · 42 comments
Assignees
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. okay-after-beta1 Used by release team to mark a release-blocker issue as okay to resolve either before or after beta1 release-blocker
Milestone

Comments

@crxpandion
Copy link

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

go 1.11

Does this issue reproduce with the latest release?

yes

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/users/kai.hayashi/go"
GORACE=""
GOROOT="/usr/local/go"
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build387775402=/tmp/go-build -gno-record-gcc-switches"
CXX="g++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"

What did you do?

I am running a fairly run-of-the-mill production api server. I have observed one crash so far on this code since upgrading to go1.11 with fatal error: invalid runtime symbol table. I am running a library in this server code that periodically captures a cpu, block, and mutex profile every few minutes. The sample rates on the mutex profile is 1/10 and 1 block profile every second.

What did you expect to see?

No crashes

What did you see instead?

runtime: invalid pc-encoded table [...]
fatal error: invalid runtime symbol table
goroutine 0 [idle]:
runtime.throw(0x10501de, 0x1c)
      /usr/local/go/src/runtime/panic.go:608 +0x72 fp=0xc00064f258 sp=0xc00064f228 pc=0x42c2b2
runtime.pcvalue(0x179ed90, 0x19f6800, 0xXXXXXXXX005ea0e7, 0xaaf94c, 0xc00064f480, 0xXXXXXXXXXXXXXX01, 0xXXXXXXXX00000000)
      /usr/local/go/src/runtime/symtab.go:791 +0x50a fp=0xc00064f300 sp=0xc00064f258 pc=0x449d3a
runtime.funcspdelta(0x179ed90, 0x19f6800, 0xaaf94c, 0xc00064f480, 0xXXXXXXXX00000000)
     /usr/local/go/src/runtime/symtab.go:843 +0x5f fp=0xc00064f370 sp=0xc00064f300 pc=0x44a1ef
runtime.gentraceback(0x45d5d5, 0xc0005f3e00, 0x0, 0xc0004d1080, 0x0, 0xc00064f6d8, 0x40, 0x0, 0x0, 0x6, ...)
      /usr/local/go/src/runtime/traceback.go:208 +0x1828 fp=0xc00064f678 sp=0xc00064f370 pc=0x450ca8
runtime.sigprof(0x45d5d5, 0xc0005f3e00, 0x0, 0xc0004d1080, 0xc000244380)
      /usr/local/go/src/runtime/proc.go:3823 +0x4b6 fp=0xc00064f928 sp=0xc00064f678 pc=0x436cd6
runtime.sighandler(0xc00000001b, 0xc00064fbf0, 0xc00064fac0, 0xc0004d1080)
      /usr/local/go/src/runtime/signal_sighandler.go:38 +0x73c fp=0xc00064f9b8 sp=0xc00064f928 pc=0x440dec

This crash is reminiscent of a bug I was hoping would be fixed with the 1.11 release related to #24925.
The crashes do seem less frequent than when I was running the same code under 1.10.

CC @heschik and @rhysh

@crxpandion crxpandion changed the title runtime: crash with "invalid ps-encoded table" runtime: crash with "invalid pc-encoded table" Sep 6, 2018
@heschi
Copy link
Contributor

heschi commented Sep 6, 2018

Yeah, this is pretty similar. I don't think I can do anything at all about this without seeing the part of the error you've hidden behind [...] and 0xXXXXXX though.

@heschi
Copy link
Contributor

heschi commented Sep 6, 2018

...actually, reading back through the internal bug where we diagnosed this, I think that error might not be relevant. (All the logs I was looking have expired so I'm trying to piece it back together from memory.) What we need is the stack that was being scanned by gentraceback. So, starting with a core file and a crash dump like the above:

  • What is the function at the first argument of sigprof, above 0x45d5d5?
  • What do the first, say, 64 words of the stack starting at the second argument of sigprof, above 0xc0005f3e00, look like? Many of them will be saved return PCs, in which case it would help to have them annotated with the functions they're in.

@andybons andybons added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Sep 6, 2018
@andybons andybons added this to the Unplanned milestone Sep 6, 2018
@crxpandion
Copy link
Author

(gdb) x 0x45d5d5
0x45d5d5 <runtime.nanotime+69>:	0x00f88348

(gdb) x/64xg 0xc0005f3e00
0xc0005f3e00:	0x0000000000aaf94c	0x000000003713e20f
0xc0005f3e10:	0x000000c0005f3e68	0x0000000000430000 <runtime.scang+192 at /usr/local/go/src/runtime/proc.go:981>:	0x244c8b4824048b48
0xc0005f3e20:	0x0027ced50000000a	0x0000000200001002
0xc0005f3e30:	0x0000000000000001	0x000000c0005f3ea8
0xc0005f3e40:	0x0027ced59b81e2c3	0x0000000000000cbc
0xc0005f3e50:	0x0027ced59b81e2c3	0x00000000019ed033 <runtime.oneptrmask>:	0x4f7d7b007c0a0101
0xc0005f3e60:	0x000000c012a66fb4	0x000000c0005f3ea8
0xc0005f3e70:	0x000000000045776d <runtime.markroot.func1+109 at /usr/local/go/src/runtime/mgcmark.go:264>:	0x75c084172444b60f	0x000000c012a66f00
0xc0005f3e80:	0x000000c000063c70	0x00007f6c035a2100
0xc0005f3e90:	0x00007f6c03f71248	0x000000c000206780
0xc0005f3ea0:	0x00007f6c03f712d0	0x000000c0005f3f28
0xc0005f3eb0:	0x000000000041d009 <runtime.markroot+777 at /usr/local/go/src/runtime/mgcmark.go:189>:	0x03f983fffffe07e9	0x000000c0005f3f10
0xc0005f3ec0:	0x000000000000002e	0x00007f6c068e7cc3
0xc0005f3ed0:	0x000000c000063c70	0x0000000000000000
0xc0005f3ee0:	0x0000000300000024	0x0000000000000003
0xc0005f3ef0:	0x0000000000000001	0x0000000000000000
0xc0005f3f00:	0x000000c000048f00	0x000000c00000c000
0xc0005f3f10:	0x0000000000457700 <runtime.markroot.func1 at /usr/local/go/src/runtime/mgcmark.go:245>:0xfffff8250c8b4864	0x000000c012a66f00
0xc0005f3f20:	0x000000c000063c70	0x000000c0005f3f80
0xc0005f3f30:	0x000000000041e507 <runtime.gcDrain+279 at /usr/local/go/src/runtime/mgcmark.go:883>:	0xd285484024548b48	0x000000c000063c70
0xc0005f3f40:	0x0000000000000c33	0x0000000000000000
0xc0005f3f50:	0x7fffffffffffffff	0x000000000042f295 <runtime.ready+165 at /usr/local/go/src/runtime/proc.go:663>:	0xc085016076d5058b
0xc0005f3f60:	0x000000c000048f00	0x000000c00f766d80
0xc0005f3f70:	0x000000c000206780	0x0000000000000000
0xc0005f3f80:	0x000000c0005f3fc0	0x00000000004575b0 <runtime.gcBgMarkWorker.func2+128 at /usr/local/go/src/runtime/mgc.go:1840>:	0x4800841824448b48
0xc0005f3f90:	0x000000c000063c70	0x0000000000000005
0xc0005f3fa0:	0x0000000000000004	0x000000c000206780
0xc0005f3fb0:	0x000000c000062a00	0x000000c000063c70
0xc0005f3fc0:	0x000000c0002eff58	0x0000000000459c76 <runtime.systemstack+102 at /usr/local/go/src/runtime/asm_amd64.s:355>:	0xfffff825048b4864
0xc0005f3fd0:	0x0000000000430b60 <runtime.mstart at /usr/local/go/src/runtime/proc.go:1229>:	0x246c894820ec8348	0xXXXXXXXXXXXXXXXX
0xc0005f3fe0:	0xXXXXXXXXXXXXXXXX 	0x000000c0005f2000
0xc0005f3ff0:	0x000000c0005a9ed0	0x000000000045da33 <runtime.clone+115 at /usr/local/go/src/runtime/sys_linux_amd64.s:586>:	0x003cb80000006fbf

Sorry about the 0xXX stuff - trying to avoid exposing memory with ascii.

@heschi
Copy link
Contributor

heschi commented Sep 6, 2018

No problem.

This looks exactly the same as the previous bug, which is worrying. gentraceback was called from

go/src/runtime/proc.go

Lines 3822 to 3823 in 41e62b8

} else if traceback {
n = gentraceback(pc, sp, lr, gp, 0, &stk[0], len(stk), nil, nil, _TraceTrap|_TraceJumpStack)
which means traceback was true. That means that either mp was nil or vdsoSP was 0. We can see in the backtrace that mp (last arg to sigprof) was 0xc000244380, so vsdoSP must have been 0. (You could confirm this by printing *mp in gdb.) vdsoSP is supposed to be set in nanotime well before the stack alignment that confuses the backtrace:
MOVQ DX, m_vdsoPC(BX)

so I don't get it. Maybe the pcsp table is wrong even before the stack alignment? What does disass 0x45d5d5 look like? This is unmodified go 1.11?

@crxpandion
Copy link
Author

(gdb) disass 0x45d5d5
Dump of assembler code for function runtime.nanotime:
   0x000000000045d590 <+0>:	mov    %rsp,%rbp
   0x000000000045d593 <+3>:	mov    %fs:0xfffffffffffffff8,%rax
   0x000000000045d59c <+12>:	mov    0x30(%rax),%rbx
   0x000000000045d5a0 <+16>:	mov    (%rsp),%rdx
   0x000000000045d5a4 <+20>:	mov    %rdx,0x330(%rbx)
   0x000000000045d5ab <+27>:	lea    (%rsp),%rdx
   0x000000000045d5af <+31>:	mov    %rdx,0x328(%rbx)
   0x000000000045d5b6 <+38>:	cmp    0xc0(%rbx),%rax
   0x000000000045d5bd <+45>:	jne    0x45d5c6 <runtime.nanotime+54 at /usr/local/go/src/runtime/sys_linux_amd64.s:254>
   0x000000000045d5bf <+47>:	mov    (%rbx),%rdx
   0x000000000045d5c2 <+50>:	mov    0x38(%rdx),%rsp
   0x000000000045d5c6 <+54>:	sub    $0x10,%rsp
   0x000000000045d5ca <+58>:	and    $0xfffffffffffffff0,%rsp
   0x000000000045d5ce <+62>:	mov    0x15f90c3(%rip),%rax        # 0x1a56698 <runtime.vdsoClockgettimeSym>
   0x000000000045d5d5 <+69>:	cmp    $0x0,%rax
   0x000000000045d5d9 <+73>:	je     0x45d60d <runtime.nanotime+125 at /usr/local/go/src/runtime/sys_linux_amd64.s:274>
   0x000000000045d5db <+75>:	mov    $0x1,%edi
   0x000000000045d5e0 <+80>:	lea    (%rsp),%rsi
   0x000000000045d5e4 <+84>:	callq  *%rax
   0x000000000045d5e6 <+86>:	mov    (%rsp),%rax
   0x000000000045d5ea <+90>:	mov    0x8(%rsp),%rdx
   0x000000000045d5ef <+95>:	mov    %rbp,%rsp
   0x000000000045d5f2 <+98>:	movq   $0x0,0x328(%rbx)
   0x000000000045d5fd <+109>:	imul   $0x3b9aca00,%rax,%rax
   0x000000000045d604 <+116>:	add    %rdx,%rax
   0x000000000045d607 <+119>:	mov    %rax,0x8(%rsp)
   0x000000000045d60c <+124>:	retq   
   0x000000000045d60d <+125>:	lea    (%rsp),%rdi
   0x000000000045d611 <+129>:	mov    $0x0,%rsi
   0x000000000045d618 <+136>:	mov    0x158ff39(%rip),%rax        # 0x19ed558 <runtime.vdsoGettimeofdaySym>
   0x000000000045d61f <+143>:	callq  *%rax
   0x000000000045d621 <+145>:	mov    (%rsp),%rax
   0x000000000045d625 <+149>:	mov    0x8(%rsp),%edx
   0x000000000045d629 <+153>:	mov    %rbp,%rsp
   0x000000000045d62c <+156>:	movq   $0x0,0x328(%rbx)
   0x000000000045d637 <+167>:	imul   $0x3e8,%rdx,%rdx
   0x000000000045d63e <+174>:	imul   $0x3b9aca00,%rax,%rax
   0x000000000045d645 <+181>:	add    %rdx,%rax
   0x000000000045d648 <+184>:	mov    %rax,0x8(%rsp)
   0x000000000045d64d <+189>:	retq   
End of assembler dump.

yes this is unmodified go1.11

@heschi
Copy link
Contributor

heschi commented Sep 7, 2018

Cool! This makes absolutely no sense to me. Can you print/x *mp in the sigprof frame? I'd like to confirm that it generally matches the other args passed to sigprof.

@crxpandion
Copy link
Author

(gdb) x 0xc000244380
0xc000244380:	0x004d1080
(gdb) x 0x004d1080
0x4d1080 <fmt.(*ss).hexByte+464>:	0xfff38a4c

I have not been able to drop into the sigprof frame (which is weird to me a thread apply all bt does not contain sigprof) but I admit gdb confounds me.

@heschi
Copy link
Contributor

heschi commented Sep 7, 2018

Okay, then please do (from memory):

set lang c
print/x *(('runtime.m'*)0xc000244380)

which should print the structure of an m with contents that make sense.

@crxpandion
Copy link
Author

crxpandion commented Sep 7, 2018

(gdb) print/x *(('runtime.m'*)0xc000244380)
$1 = {g0 = 0xc0004d1080, morebuf = {sp = 0x0, pc = 0x0, g = 0x0, ctxt = 0x0, 
    ret = 0x0, lr = 0x0, bp = 0x0}, divmod = 0x0, procid = 0x7055, 
  gsignal = 0xc0004d0f00, goSigStack = {stack = {lo = 0x0, hi = 0x0}, 
    stackguard0 = 0x0, stackguard1 = 0x0, stktopsp = 0x0}, sigmask = {0x0, 
    0x0}, tls = {0xc0004d0f00, 0x0, 0x0, 0x0, 0x0, 0x0}, mstartfn = 0xc0, 
  curg = 0xc000206780, caughtsig = 0x0, p = 0xc000062a00, nextp = 0x0, 
  id = 0x19, mallocing = 0x2, throwing = 0x1, preemptoff = {str = 0x0, 
    len = 0x0}, locks = 0x1, dying = 0x1, profilehz = 0x64, helpgc = 0x0, 
  spinning = 0x0, blocked = 0x0, inwb = 0x0, newSigstack = 0x1, 
  printlock = 0x0, incgo = 0x0, freeWait = 0x0, fastrand = {0x80981164, 
    0x4ba9cbdf}, needextram = 0x0, traceback = 0x0, ncgocall = 0x0, 
  ncgo = 0x0, cgoCallersUse = 0x0, cgoCallers = 0x0, park = {key = 0x0}, 
  alllink = 0xc00049d880, schedlink = 0xc0001a3500, mcache = 0x7f6c068ea768, 
  lockedg = 0x0, createstack = {0x0 <repeats 32 times>}, lockedExt = 0x0, 
  lockedInt = 0x0, nextwaitm = 0x0, waitunlockf = 0x0, waitlock = 0x0, 
  waittraceev = 0x19, waittraceskip = 0x4, startingtrace = 0x0, 
  syscalltick = 0x6d522d4, thread = 0x0, freelink = 0x0, libcall = {
    fn = 0x0, n = 0x0, args = 0x0, r1 = 0x0, r2 = 0x0, err = 0x0}, 
  libcallpc = 0x0, libcallsp = 0x0, libcallg = 0x0, syscall = {fn = 0x0, 
    n = 0x0, args = 0x0, r1 = 0x0, r2 = 0x0, err = 0x0}, vdsoSP = 0x0, 
  vdsoPC = 0x452a8a, mOS = {<No data fields>}}

@heschi
Copy link
Contributor

heschi commented Sep 7, 2018

Okay. I don't understand how vdsoSP can possibly be 0 given that it would have been set immediately before the point at which the signal was caught.

@aclements, @ianlancetaylor, any ideas?

@ianlancetaylor
Copy link
Contributor

What is the function at address 0x452a8a?

@ianlancetaylor
Copy link
Contributor

This is very unlikely, but does your program ever call runtime.SetCgoTraceback? Does your program use cgo at all?

@crxpandion
Copy link
Author

(gdb) x 0x452a8a
0x452a8a <runtime.goroutineheader+538>:	0x24048b48

@crxpandion
Copy link
Author

This program doesn't use cgo, but it does mmap a file.

@ianlancetaylor
Copy link
Contributor

The value of m.vdsoPC shows that nanotime was called by goroutineheader. The value of g passed to sighandler and the printout of *mp shows that the program was running on g0 when the signal occurred. The fact that the traceback field of *mp is 0 means that goroutineheader was not called by runtime.Stack. As far as I can tell the only other ways that we could see a call to goroutineheader all involve some sort of program crash or panic, but in that case I would have expected that something else would be printed out first. And you would have told us in that case, right?

My conclusion so far is like @heschik 's: this is impossible. Unless somehow mp.g0.m != mp, where mp is the value 0xc000244380 you printed out above. But that too should be impossible.

@crxpandion
Copy link
Author

I definitely would have told you if I found something else printed out. :)
Maybe the best thing to do is to see if another of these happens and try and get more information from a second crash.

@mark-rushakoff
Copy link
Contributor

Since nobody else has asked yet: are any data races detected if you run your executable built with -race?

@crxpandion
Copy link
Author

no races detected. the frequency of crashes observed so far is low (only 1 per week so far under reasonable load) as well.

@cherrymui
Copy link
Member

I noticed that in sys_linux_amd64.s,

        LEAQ    ret+0(SP), DX
        MOVQ    DX, m_vdsoSP(BX)

the ret+0(SP) should probably be ret+0(FP).

But even so, I don't understand how vdsoSP could be 0.

@ianlancetaylor
Copy link
Contributor

I didn't spell it out above, but vdsoSP could be 0 if something in the signal handler, or anything else using the same m, called nanotime between the time that the profiling signal was received and the time that we started asking for the traceback. The value of vdsoPC makes it clear that the function that called nanotime was goroutineheader. The question is whether goroutineheader was called before or after the profiling signal (if after, it was presumably when the profiling signal occurred during a different execution of nanotime).

The problem is that no matter what I don't see any way that goroutineheader could have called nanotime without causing other side effects. So clearly I'm missing something.

@heschi
Copy link
Contributor

heschi commented Sep 10, 2018

Sorry, I think it was a mistake to ask for the printout of mp, it's a red herring. I believe this is a core dump for a process that threw with GOTRACEBACK=crash, so all the output we're getting is after the crash dump was printed. I didn't realize that the process of crashing would make a vdso call -- since it does, everything in m will have been overwritten.

@jasonpfox
Copy link

jasonpfox commented Feb 9, 2019

We recently updated one of our production data analysis servers from 1.10.x to 1.11.5 (then reverted to 1.11.0) and seem to have encountered either this or a similar issue.

As with the original reporter, we are running a complex system (~35k go routines) and have continuous background profiling enabled which we capture and save out for diagnostic when prompted by certain conditions in our software.

We are reading data files from disk, processing, and saving results at the maximum possible speed, generally achieving >70% total processor utilization. We typically run an analysis case for hours to days.

@jkolansky

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

go 1.11.5
go 1.11.0

Does this issue reproduce with the latest release?

yes

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

this is after revert to 1.11.0

set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\Jerem\AppData\Local\go-build
set GOEXE=.exe
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOOS=windows
set GOPATH=C:\AxionAt\Go
set GOPROXY=
set GORACE=
set GOROOT=C:\Go
set GOTMPDIR=
set GOTOOLDIR=C:\Go\pkg\tool\windows_amd64
set GCCGO=gccgo
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0 -fdebug-prefix-map=C:\Users\Jerem\AppData\Local\Temp\go-build886809306=/tmp/go-build -gno-record-gcc-switches```

### What did you do?
We are running a processing intensive signal processing and data analysis server.  As with the original reporter, we are running a relatively complex system (~35k go routines) and have continuous background profiling enabled which we capture and save out for diagnostic when prompted by certain conditions in our software.  We are reading data files from disk, processing, and saving results at the maximum possible speed, generally achieving 70+% total processor utilization for analysis cases that execute for hours to days.  Go 1.11.5 seemed to run for seconds to minutes before crashing

### What did you expect to see?
No crashes, specificallly, if the profiler data collection encounters invalid or corrupted data, ignore or skip the data and *don't crash the program*. 

I would not expect that a background profiling process would ever be wanted to allow a fatal crash that aborts the program itself.

### What did you see instead?
I dug into the stack trace and found what appears to be a profiler process being called from assembly that encounters an invalid PC / symbol table.

```1.11.5 stack trace:
runtime: invalid pc-encoded table f=
runtime.goexit pc=0x45ce57 targetpc=0x45ce57 tab=[0/0]0x0
	value=0 until pc=0x45ce57
fatal error: invalid runtime symbol table


runtime stack:

runtime.throw
(0xdc3d55, 0x1c)
	C:/Go/src/runtime/panic.go:608 +
0x79
runtime.pcvalue(0x11f0e30, 0x170e6a0, 0x8bd68, 0x45ce57, 0x721f080, 0x1, 0x8)
	C:/Go/src/runtime/symtab.go:791 +0x518
runtime.funcspdelta(0x11f0e30, 0x170e6a0, 0x45ce57, 0x721f080, 0x8)
	C:/Go/src/runtime/symtab.go:843 +0x66
runtime.gentraceback(0x45e690, 0x469faf0, 
0x0, 0xc0002c4000, 
0x0
, 0x721f2d8, 0x40, 0x0, 
0x0, 0x6, ...)
	C:/Go/src/runtime/traceback.go:208 +0x1836

runtime.sigprof(0x45e690, 
0x469faf0
, 0x0, 0xc0002c4000, 0xc0002c0000)
	C:/Go/src/runtime/proc.go:3823 +0x521
runtime.profilem(0xc0002c0000)
	C:/Go/src/runtime/os_windows.go:870 +0xea
runtime.profileloop1(0x0, 0x0)
	
C:/Go/src/runtime/os_windows.go
:889 +0xe9
runtime.externalthreadhandler
(
0x721fc10, 0x0, 0x0, 0x0, 0x0
, 
0x0, 0x0, 0x0, 0x0
, 
0x0, ...)
	C:/Go/src/runtime/sys_windows_amd64.s:263 +0x95

goroutine 1 [chan receive]:

github.com/axionat/eagle/cmd.glob..func3
(0x1977820, 0xc00027e400, 0x0, 
0x4
)
	C:/AxionAt/Go/src/github.com/axionat/eagle/cmd/mcp.go:240 +0x4e


github.com/axionat/eagle/vendor/github.com/spf13/cobra.(*Command).execute(0x1977820, 0xc00027e240, 0x4, 0x4, 0x1977820
, 0xc00027e240)
	C:/AxionAt/Go/src/github.com/axionat/eagle/vendor/github.com/spf13/cobra/command.go:619 +0x2c0
github.com/axionat/eagle/vendor/github.com/spf13/cobra.(*Command).ExecuteC(0x1977a40
, 
0xc0008e9bd0, 0x4e23c8, 0xc0002dc0c0)
	
C:/AxionAt/Go/src/github.com/axionat/eagle/vendor/github.com/spf13/cobra/command.go
:689 +0x2d3
github.com/axionat/eagle/vendor/github.com/spf13/cobra.(*Command).Execute(0x1977a40, 0x1, 
0x0
)
	C:/AxionAt/Go/src/github.com/axionat/eagle/vendor/github.com/spf13/cobra/command.go:648 +0x32

github.com/axionat/eagle/cmd.Execute
()
	C:/AxionAt/Go/src/github.com/axionat/eagle/cmd/root.go:63 +0x34
main.main()
	C:/AxionAt/Go/src/github.com/axionat/eagle/main.go:78 +0x9b8
...

fatal error: 
unexpected signal during runtime execution

[signal 
0xc0000005 code=0x0 addr=0x45304b8 pc=0x45265a]

runtime stack:
runtime.throw(0xdd1d80, 0x2a)
	C:/Go/src/runtime/panic.go:608 +0x79
runtime.sigpanic()
	C:/Go/src/runtime/signal_windows.go:198 +0x16f
runtime.gentraceback(0x45e6ae, 0x452fd60, 0x0, 0xc000236480, 0x0, 0x700f2d8
, 0x40, 0x0, 0x0, 0x6, ...
)
	C:/Go/src/runtime/traceback.go:239 +0x14ba
runtime.sigprof(
0x45e6ae
, 0x452fd60
, 0x0, 0xc000236480, 0xc000232700)
	C:/Go/src/runtime/proc.go:3823 +0x521
runtime.profilem(0xc000232700)
	C:/Go/src/runtime/os_windows.go:870 +0xea
runtime.profileloop1(0x0, 0x0)
	C:/Go/src/runtime/os_windows.go:889 +0xe9
runtime.externalthreadhandler(0x700fc10, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	C:/Go/src/runtime/sys_windows_amd64.s:263 +0x95

goroutine 1 [chan receive, 31 minutes]:

github.com/axionat/eagle/cmd.glob..func3(0x1977820, 0xc0003be9c0, 0x0, 0x4)
	C:/AxionAt/Go/src/github.com/axionat/eagle/cmd/mcp.go:240 +0x4e
github.com/axionat/eagle/vendor/github.com/spf13/cobra.(*Command).execute(0x1977820, 0xc0003be880, 0x4, 0x4, 0x1977820, 0xc0003be880)

	C:/AxionAt/Go/src/github.com/axionat/eagle/vendor/github.com/spf13/cobra/command.go:619 +0x2c0

github.com/axionat/eagle/vendor/github.com/spf13/cobra.(*Command).ExecuteC(0x1977a40, 0xc0003ddbd0, 0x4e23c8, 0xc0002f8180)
	C:/AxionAt/Go/src/github.com/axionat/eagle/vendor/github.com/spf13/cobra/command.go:689 +
0x2d3

github.com/axionat/eagle/vendor/github.com/spf13/cobra.(*Command).Execute
(0x1977a40, 0x1, 0x0
)
	C:/AxionAt/Go/src/github.com/axionat/eagle/vendor/github.com/spf13/cobra/command.go:648
 +0x32
github.com/axionat/eagle/cmd.Execute()
	C:/AxionAt/Go/src/github.com/axionat/eagle/cmd/root.go:63 +0x34
main.main()
	
C:/AxionAt/Go/src/github.com/axionat/eagle/main.go
:78 +0x9b8

...```


@jasonpfox
Copy link

One other data point that may be helpful, 1.11.0 ran for just over 30 minutes (about 30 min, 20 sec). I record system resource state snapshots to logs every 5 minutes and the last capture I had was:
Mem - GB Heap Alloc= 16.9
Mem - GB Sys= 32.2
Mem - Mil Heap Obj= 90.337
Num Routines=77999
Uptime=30.0 min

1.11.5 crashed after ~20 seconds and I don't have a snapshot, but it would have been most of the way piped up to this level, both were running on the same data set.

@rkuska
Copy link
Contributor

rkuska commented Mar 10, 2019

FYI; Still present with 1.12.0, same story as others, service with profiling (cloud.google.com/go/profiler)

Some tracebacks from the failure if it helps:

runtime.throw(0xee6853, 0x1c)
	/usr/local/go/src/runtime/panic.go:617 +0x72
runtime.pcvalue(0x13e4228, 0x1919980, 0x33984f, 0x85abc6, 0xc000c2b4d0, 0x1123701, 0x0)
	/usr/local/go/src/runtime/symtab.go:704 +0x53f
runtime.funcspdelta(0x13e4228, 0x1919980, 0x85abc6, 0xc000c2b4d0, 0xc000000000)
	/usr/local/go/src/runtime/symtab.go:756 +0x5f
runtime.gentraceback(0x45ddb6, 0x7f8ff17f9b90, 0x0, 0xc000483500, 0x0, 0xc000c2b728, 0x40, 0x0, 0x0, 0x6, ...)
	/usr/local/go/src/runtime/traceback.go:222 +0x1811
runtime.sigprof(0x45ddb6, 0x7f8ff17f9b90, 0x0, 0xc000483500, 0xc000ca4000)
	/usr/local/go/src/runtime/proc.go:3754 +0x425
runtime.sighandler(0xc00000001b, 0xc000c2bbf0, 0xc000c2bac0, 0xc000483500)
	/usr/local/go/src/runtime/signal_sighandler.go:38 +0x6e7
runtime.sigtrampgo(0x1b, 0xc000c2bbf0, 0xc000c2bac0)
	/usr/local/go/src/runtime/signal_unix.go:351 +0x1f2
runtime: unexpected return pc for runtime.sigtramp called from 0xc5a5e0
runtime.sigtramp(0x7, 0x0, 0xc000c24000, 0xc000000000, 0x8000, 0x136a7c658dead1, 0x7fff2a5b6080, 0x1, 0xbc9fb4be, 0x2, ...)
	/usr/local/go/src/runtime/sys_linux_amd64.s:357 +0x43

goroutine 1177223 [GC worker (idle)]:
runtime.systemstack_switch()
	/usr/local/go/src/runtime/asm_amd64.s:311 fp=0xc005591760 sp=0xc005591758 pc=0x45a260
runtime.gcBgMarkWorker(0xc000054000)
	/usr/local/go/src/runtime/mgc.go:1890 +0x1be fp=0xc0055917d8 sp=0xc005591760 pc=0x41d69e
runtime.goexit()
	/usr/local/go/src/runtime/asm_amd64.s:1337 +0x1 fp=0xc0055917e0 sp=0xc0055917d8 pc=0x45c331
created by runtime.gcBgMarkStartWorkers
	/usr/local/go/src/runtime/mgc.go:1784 +0x77

goroutine 1 [chan receive, 1884 minutes]:
main.main()
	/conveyance-store/cmd/storage/conveyance-api.go:274 +0x1173

goroutine 19 [syscall, 1884 minutes]:
os/signal.signal_recv(0x0)
	/usr/local/go/src/runtime/sigqueue.go:139 +0x9c
os/signal.loop()
	/usr/local/go/src/os/signal/signal_unix.go:23 +0x22
created by os/signal.init.0
	/usr/local/go/src/os/signal/signal_unix.go:29 +0x41

goroutine 367539921 [IO wait, 110 minutes]:
internal/poll.runtime_pollWait(0x7f906813c858, 0x72, 0xffffffffffffffff)
	/usr/local/go/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc00ae38a98, 0x72, 0x1000, 0x1000, 0xffffffffffffffff)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc00ae38a80, 0xc00d4bb000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:169 +0x19b
net.(*netFD).Read(0xc00ae38a80, 0xc00d4bb000, 0x1000, 0x1000, 0xc000048500, 0xc0089ebb08, 0x6b05ca)
	/usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc000844440, 0xc00d4bb000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:177 +0x69
net/http.(*connReader).Read(0xc00f5884b0, 0xc00d4bb000, 0x1000, 0x1000, 0x0, 0x0, 0x72)
	/usr/local/go/src/net/http/server.go:787 +0x107
bufio.(*Reader).fill(0xc00e496960)
	/usr/local/go/src/bufio/bufio.go:100 +0x10f
bufio.(*Reader).Peek(0xc00e496960, 0x4, 0x0, 0x0, 0x0, 0x0, 0x4bceba)
	/usr/local/go/src/bufio/bufio.go:138 +0x4f
net/http.(*conn).readRequest(0xc00a088820, 0x104e480, 0xc00bc74f80, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/server.go:964 +0xb03
net/http.(*conn).serve(0xc00a088820, 0x104e480, 0xc00bc74f80)
	/usr/local/go/src/net/http/server.go:1819 +0x6a8
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2884 +0x2f4

goroutine 378316985 [IO wait, 51 minutes]:
internal/poll.runtime_pollWait(0x7f9058038d18, 0x72, 0xffffffffffffffff)
	/usr/local/go/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc005612998, 0x72, 0x1000, 0x1000, 0xffffffffffffffff)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc005612980, 0xc004a86000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:169 +0x19b
net.(*netFD).Read(0xc005612980, 0xc004a86000, 0x1000, 0x1000, 0xc00005af00, 0xc012171b08, 0x6b05ca)
	/usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc000a3e2b8, 0xc004a86000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:177 +0x69
net/http.(*connReader).Read(0xc0065b0ba0, 0xc004a86000, 0x1000, 0x1000, 0x0, 0x0, 0x72)
	/usr/local/go/src/net/http/server.go:787 +0x107
bufio.(*Reader).fill(0xc004e38000)
	/usr/local/go/src/bufio/bufio.go:100 +0x10f
bufio.(*Reader).Peek(0xc004e38000, 0x4, 0x0, 0x0, 0x0, 0x0, 0xfa)
	/usr/local/go/src/bufio/bufio.go:138 +0x4f
net/http.(*conn).readRequest(0xc00a6c68c0, 0x104e480, 0xc00b83cd00, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/server.go:964 +0xb03
net/http.(*conn).serve(0xc00a6c68c0, 0x104e480, 0xc00b83cd00)
	/usr/local/go/src/net/http/server.go:1819 +0x6a8
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2884 +0x2f4

goroutine 370175441 [IO wait, 97 minutes]:
internal/poll.runtime_pollWait(0x7f903c47d2b8, 0x72, 0xffffffffffffffff)
	/usr/local/go/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc00778b298, 0x72, 0x1000, 0x1000, 0xffffffffffffffff)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc00778b280, 0xc010efe000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:169 +0x19b
net.(*netFD).Read(0xc00778b280, 0xc010efe000, 0x1000, 0x1000, 0xc000064500, 0xc014bbbb08, 0x6b05ca)
	/usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc000d0c440, 0xc010efe000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:177 +0x69
net/http.(*connReader).Read(0xc00e1fdd10, 0xc010efe000, 0x1000, 0x1000, 0x0, 0x0, 0x72)
	/usr/local/go/src/net/http/server.go:787 +0x107
bufio.(*Reader).fill(0xc003cca540)
	/usr/local/go/src/bufio/bufio.go:100 +0x10f
bufio.(*Reader).Peek(0xc003cca540, 0x4, 0x0, 0x0, 0x0, 0x0, 0x4bceba)
	/usr/local/go/src/bufio/bufio.go:138 +0x4f
net/http.(*conn).readRequest(0xc00c221cc0, 0x104e480, 0xc00555c300, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/server.go:964 +0xb03
net/http.(*conn).serve(0xc00c221cc0, 0x104e480, 0xc00555c300)
	/usr/local/go/src/net/http/server.go:1819 +0x6a8
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2884 +0x2f4

goroutine 387659619 [IO wait]:
internal/poll.runtime_pollWait(0x7f9068245180, 0x72, 0xffffffffffffffff)
	/usr/local/go/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc011601b18, 0x72, 0x1000, 0x1000, 0xffffffffffffffff)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc011601b00, 0xc01339f000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:169 +0x19b
net.(*netFD).Read(0xc011601b00, 0xc01339f000, 0x1000, 0x1000, 0xc000066a00, 0xc013789b08, 0x6b05ca)
	/usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc019cd4838, 0xc01339f000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:177 +0x69
net/http.(*connReader).Read(0xc00716e6f0, 0xc01339f000, 0x1000, 0x1000, 0x0, 0x0, 0x72)
	/usr/local/go/src/net/http/server.go:787 +0x107
bufio.(*Reader).fill(0xc0045981e0)
	/usr/local/go/src/bufio/bufio.go:100 +0x10f
bufio.(*Reader).Peek(0xc0045981e0, 0x4, 0x0, 0x0, 0x0, 0x0, 0x4bceba)
	/usr/local/go/src/bufio/bufio.go:138 +0x4f
net/http.(*conn).readRequest(0xc0040c43c0, 0x104e480, 0xc00829ce80, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/server.go:964 +0xb03
net/http.(*conn).serve(0xc0040c43c0, 0x104e480, 0xc00829ce80)
	/usr/local/go/src/net/http/server.go:1819 +0x6a8
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2884 +0x2f4

goroutine 375849207 [IO wait, 65 minutes]:
internal/poll.runtime_pollWait(0x7f9068413c30, 0x72, 0xffffffffffffffff)
	/usr/local/go/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc00dc83918, 0x72, 0x1000, 0x1000, 0xffffffffffffffff)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc00dc83900, 0xc01371c000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:169 +0x19b
net.(*netFD).Read(0xc00dc83900, 0xc01371c000, 0x1000, 0x1000, 0xc000056500, 0xc006a9bb08, 0x6b05ca)
	/usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc0007d4250, 0xc01371c000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:177 +0x69
net/http.(*connReader).Read(0xc00c9c4b70, 0xc01371c000, 0x1000, 0x1000, 0x0, 0x0, 0x72)
	/usr/local/go/src/net/http/server.go:787 +0x107
bufio.(*Reader).fill(0xc011a97c80)
	/usr/local/go/src/bufio/bufio.go:100 +0x10f
bufio.(*Reader).Peek(0xc011a97c80, 0x4, 0x0, 0x0, 0x0, 0x0, 0x4bceba)
	/usr/local/go/src/bufio/bufio.go:138 +0x4f
net/http.(*conn).readRequest(0xc00566a0a0, 0x104e480, 0xc00103ee80, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/server.go:964 +0xb03
net/http.(*conn).serve(0xc00566a0a0, 0x104e480, 0xc00103ee80)
	/usr/local/go/src/net/http/server.go:1819 +0x6a8
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2884 +0x2f4

goroutine 377139601 [IO wait, 58 minutes]:
internal/poll.runtime_pollWait(0x7f90682031d8, 0x72, 0xffffffffffffffff)
	/usr/local/go/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc01184c298, 0x72, 0x1000, 0x1000, 0xffffffffffffffff)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc01184c280, 0xc00d694000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:169 +0x19b
net.(*netFD).Read(0xc01184c280, 0xc00d694000, 0x1000, 0x1000, 0xc000080500, 0xc012221b08, 0x6b05ca)
	/usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc0000106e8, 0xc00d694000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:177 +0x69
net/http.(*connReader).Read(0xc001a828a0, 0xc00d694000, 0x1000, 0x1000, 0x0, 0x0, 0x72)
	/usr/local/go/src/net/http/server.go:787 +0x107
bufio.(*Reader).fill(0xc0043db380)
	/usr/local/go/src/bufio/bufio.go:100 +0x10f
bufio.(*Reader).Peek(0xc0043db380, 0x4, 0x0, 0x0, 0x0, 0x0, 0x4bceba)
	/usr/local/go/src/bufio/bufio.go:138 +0x4f
net/http.(*conn).readRequest(0xc00b25f540, 0x104e480, 0xc007b37d00, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/server.go:964 +0xb03
net/http.(*conn).serve(0xc00b25f540, 0x104e480, 0xc007b37d00)
	/usr/local/go/src/net/http/server.go:1819 +0x6a8
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2884 +0x2f4

goroutine 375323721 [IO wait, 68 minutes]:
internal/poll.runtime_pollWait(0x7f9058039058, 0x72, 0xffffffffffffffff)
	/usr/local/go/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc008c1c018, 0x72, 0x1000, 0x1000, 0xffffffffffffffff)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc008c1c000, 0xc01d0a2000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:169 +0x19b
net.(*netFD).Read(0xc008c1c000, 0xc01d0a2000, 0x1000, 0x1000, 0xc000064500, 0xc00a22bb08, 0x6b05ca)
	/usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc0000101e0, 0xc01d0a2000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:177 +0x69
net/http.(*connReader).Read(0xc00632c090, 0xc01d0a2000, 0x1000, 0x1000, 0x0, 0x0, 0x72)
	/usr/local/go/src/net/http/server.go:787 +0x107
bufio.(*Reader).fill(0xc01c9ba000)
	/usr/local/go/src/bufio/bufio.go:100 +0x10f
bufio.(*Reader).Peek(0xc01c9ba000, 0x4, 0x0, 0x0, 0x0, 0x0, 0x4bceba)
	/usr/local/go/src/bufio/bufio.go:138 +0x4f
net/http.(*conn).readRequest(0xc007a61040, 0x104e480, 0xc0155d4240, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/server.go:964 +0xb03
net/http.(*conn).serve(0xc007a61040, 0x104e480, 0xc0155d4240)
	/usr/local/go/src/net/http/server.go:1819 +0x6a8
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2884 +0x2f4

goroutine 371375030 [IO wait, 91 minutes]:
internal/poll.runtime_pollWait(0x7f9068063400, 0x72, 0xffffffffffffffff)
	/usr/local/go/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc01485de98, 0x72, 0x1000, 0x1000, 0xffffffffffffffff)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc01485de80, 0xc017f21000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:169 +0x19b
net.(*netFD).Read(0xc01485de80, 0xc017f21000, 0x1000, 0x1000, 0xc000058a00, 0xc0145e9b08, 0x6b05ca)
	/usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc0008ce370, 0xc017f21000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:177 +0x69
net/http.(*connReader).Read(0xc001a83f20, 0xc017f21000, 0x1000, 0x1000, 0x0, 0x0, 0x72)
	/usr/local/go/src/net/http/server.go:787 +0x107
bufio.(*Reader).fill(0xc01486a120)
	/usr/local/go/src/bufio/bufio.go:100 +0x10f
bufio.(*Reader).Peek(0xc01486a120, 0x4, 0x0, 0x0, 0x0, 0x0, 0x4bceba)
	/usr/local/go/src/bufio/bufio.go:138 +0x4f
net/http.(*conn).readRequest(0xc002328820, 0x104e480, 0xc0053474c0, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/server.go:964 +0xb03
net/http.(*conn).serve(0xc002328820, 0x104e480, 0xc0053474c0)
	/usr/local/go/src/net/http/server.go:1819 +0x6a8
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2884 +0x2f4

goroutine 14 [select]:
go.opencensus.io/stats/view.(*worker).start(0xc000509000)
	/go/pkg/mod/go.opencensus.io@v0.14.0/stats/view/worker.go:146 +0xdd
created by go.opencensus.io/stats/view.init.0
	/go/pkg/mod/go.opencensus.io@v0.14.0/stats/view/worker.go:29 +0x57

goroutine 79 [IO wait]:
internal/poll.runtime_pollWait(0x7f9070054578, 0x72, 0xffffffffffffffff)
	/usr/local/go/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc000476098, 0x72, 0x1000, 0x1000, 0xffffffffffffffff)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000476080, 0xc000856000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:169 +0x19b
net.(*netFD).Read(0xc000476080, 0xc000856000, 0x1000, 0x1000, 0x43f5bd, 0xc0003f94f8, 0x0)
	/usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc000010110, 0xc000856000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:177 +0x69
bufio.(*Reader).Read(0xc000403140, 0xc000103c68, 0x1, 0x9, 0x2, 0x3, 0x80)
	/usr/local/go/src/bufio/bufio.go:223 +0x22f
io.ReadAtLeast(0x1033de0, 0xc000403140, 0xc000103c68, 0x1, 0x9, 0x1, 0x38, 0xc00942d740, 0x0)
	/usr/local/go/src/io/io.go:310 +0x88
io.ReadFull(...)
	/usr/local/go/src/io/io.go:329
github.com/gocql/gocql.readHeader(0x1033de0, 0xc000403140, 0xc000103c68, 0x9, 0x9, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/go/pkg/mod/github.com/scylladb/gocql@v1.0.1/frame.go:446 +0xab
github.com/gocql/gocql.(*Conn).recv(0xc000103c20, 0x0, 0x0)
	/go/pkg/mod/github.com/scylladb/gocql@v1.0.1/conn.go:526 +0xf8
github.com/gocql/gocql.(*Conn).serve(0xc000103c20)
	/go/pkg/mod/github.com/scylladb/gocql@v1.0.1/conn.go:490 +0x31
created by github.com/gocql/gocql.(*Session).dial
	/go/pkg/mod/github.com/scylladb/gocql@v1.0.1/conn.go:259 +0x749

goroutine 86 [select, 49 minutes]:
google.golang.org/grpc.(*ccBalancerWrapper).watcher(0xc000509a80)
	/go/pkg/mod/google.golang.org/grpc@v1.18.0/balancer_conn_wrappers.go:122 +0x110
created by google.golang.org/grpc.newCCBalancerWrapper
	/go/pkg/mod/google.golang.org/grpc@v1.18.0/balancer_conn_wrappers.go:113 +0x14f

goroutine 4602 [IO wait, 1884 minutes]:
internal/poll.runtime_pollWait(0x7f90682db498, 0x72, 0xffffffffffffffff)
	/usr/local/go/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc000685998, 0x72, 0x1000, 0x1000, 0xffffffffffffffff)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000685980, 0xc001b0a000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:169 +0x19b
net.(*netFD).Read(0xc000685980, 0xc001b0a000, 0x1000, 0x1000, 0x43f5bd, 0xc0009b40b8, 0x0)
	/usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc0008440c8, 0xc001b0a000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:177 +0x69
bufio.(*Reader).Read(0xc000b89080, 0xc000dddb48, 0x1, 0x9, 0x2, 0x3, 0x80)
	/usr/local/go/src/bufio/bufio.go:223 +0x22f
io.ReadAtLeast(0x1033de0, 0xc000b89080, 0xc000dddb48, 0x1, 0x9, 0x1, 0x38, 0xc000a0a2c0, 0x0)
	/usr/local/go/src/io/io.go:310 +0x88
io.ReadFull(...)
	/usr/local/go/src/io/io.go:329
github.com/gocql/gocql.readHeader(0x1033de0, 0xc000b89080, 0xc000dddb48, 0x9, 0x9, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/go/pkg/mod/github.com/scylladb/gocql@v1.0.1/frame.go:446 +0xab
github.com/gocql/gocql.(*Conn).recv(0xc000dddb00, 0x0, 0x0)
	/go/pkg/mod/github.com/scylladb/gocql@v1.0.1/conn.go:526 +0xf8
github.com/gocql/gocql.(*Conn).serve(0xc000dddb00)
	/go/pkg/mod/github.com/scylladb/gocql@v1.0.1/conn.go:490 +0x31
created by github.com/gocql/gocql.(*Session).dial
	/go/pkg/mod/github.com/scylladb/gocql@v1.0.1/conn.go:259 +0x749

goroutine 88 [select]:
gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer.(*tracer).worker(0xc0000f5860)
	/go/pkg/mod/gopkg.in/!data!dog/dd-trace-go.v1@v1.9.0/ddtrace/tracer/tracer.go:149 +0x1a8
created by gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer.newTracer
	/go/pkg/mod/gopkg.in/!data!dog/dd-trace-go.v1@v1.9.0/ddtrace/tracer/tracer.go:136 +0x30f

goroutine 4987 [IO wait, 1884 minutes]:
internal/poll.runtime_pollWait(0x7f907009d010, 0x72, 0xffffffffffffffff)
	/usr/local/go/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc000685898, 0x72, 0x1000, 0x1000, 0xffffffffffffffff)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000685880, 0xc001aac000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:169 +0x19b
net.(*netFD).Read(0xc000685880, 0xc001aac000, 0x1000, 0x1000, 0x43f5bd, 0xc00024baf8, 0x0)
	/usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc000ce00c0, 0xc001aac000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:177 +0x69
bufio.(*Reader).Read(0xc00173c840, 0xc001a12168, 0x1, 0x9, 0x2, 0x3, 0x80)
	/usr/local/go/src/bufio/bufio.go:223 +0x22f
io.ReadAtLeast(0x1033de0, 0xc00173c840, 0xc001a12168, 0x1, 0x9, 0x1, 0x38, 0xc000b3c740, 0x0)
	/usr/local/go/src/io/io.go:310 +0x88
io.ReadFull(...)
	/usr/local/go/src/io/io.go:329
github.com/gocql/gocql.readHeader(0x1033de0, 0xc00173c840, 0xc001a12168, 0x9, 0x9, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/go/pkg/mod/github.com/scylladb/gocql@v1.0.1/frame.go:446 +0xab
github.com/gocql/gocql.(*Conn).recv(0xc001a12120, 0x0, 0x0)
	/go/pkg/mod/github.com/scylladb/gocql@v1.0.1/conn.go:526 +0xf8
github.com/gocql/gocql.(*Conn).serve(0xc001a12120)
	/go/pkg/mod/github.com/scylladb/gocql@v1.0.1/conn.go:490 +0x31
created by github.com/gocql/gocql.(*Session).dial
	/go/pkg/mod/github.com/scylladb/gocql@v1.0.1/conn.go:259 +0x749

goroutine 4447 [IO wait, 1884 minutes]:
internal/poll.runtime_pollWait(0x7f90700fbfe8, 0x72, 0xffffffffffffffff)
	/usr/local/go/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc000685798, 0x72, 0x1000, 0x1000, 0xffffffffffffffff)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000685780, 0xc001a0e000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:169 +0x19b
net.(*netFD).Read(0xc000685780, 0xc001a0e000, 0x1000, 0x1000, 0x43f5bd, 0xc0000d0b38, 0x0)
	/usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc0007d4158, 0xc001a0e000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:177 +0x69
bufio.(*Reader).Read(0xc001118ae0, 0xc001918288, 0x1, 0x9, 0x7f906855b6d8, 0x41, 0x80)
	/usr/local/go/src/bufio/bufio.go:223 +0x22f
io.ReadAtLeast(0x1033de0, 0xc001118ae0, 0xc001918288, 0x1, 0x9, 0x1, 0x38, 0xc000b1b040, 0x0)
	/usr/local/go/src/io/io.go:310 +0x88
io.ReadFull(...)
	/usr/local/go/src/io/io.go:329
github.com/gocql/gocql.readHeader(0x1033de0, 0xc001118ae0, 0xc001918288, 0x9, 0x9, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/go/pkg/mod/github.com/scylladb/gocql@v1.0.1/frame.go:446 +0xab
github.com/gocql/gocql.(*Conn).recv(0xc001918240, 0x0, 0x0)
	/go/pkg/mod/github.com/scylladb/gocql@v1.0.1/conn.go:526 +0xf8
github.com/gocql/gocql.(*Conn).serve(0xc001918240)
	/go/pkg/mod/github.com/scylladb/gocql@v1.0.1/conn.go:490 +0x31
created by github.com/gocql/gocql.(*Session).dial
	/go/pkg/mod/github.com/scylladb/gocql@v1.0.1/conn.go:259 +0x749

goroutine 87 [select]:
github.com/googleapis/gax-go.Sleep(0x104e540, 0xc00024d200, 0x2540be400, 0x0, 0x0)
	/go/pkg/mod/github.com/googleapis/gax-go@v2.0.0+incompatible/invoke.go:55 +0xd2
cloud.google.com/go/profiler.(*agent).profileAndUpload(0xc000509ac0, 0x104e540, 0xc00024d200, 0xc00945a1c0)
	/go/pkg/mod/cloud.google.com/go@v0.34.0/profiler/profiler.go:311 +0x5b5
cloud.google.com/go/profiler.pollProfilerService(0x104e540, 0xc00024d200, 0xc000509ac0)
	/go/pkg/mod/cloud.google.com/go@v0.34.0/profiler/profiler.go:527 +0x6f
created by cloud.google.com/go/profiler.start
	/go/pkg/mod/cloud.google.com/go@v0.34.0/profiler/profiler.go:204 +0x491

goroutine 30 [chan receive, 49 minutes]:
google.golang.org/grpc.(*addrConn).resetTransport(0xc0002d0000)
	/go/pkg/mod/google.golang.org/grpc@v1.18.0/clientconn.go:1070 +0x9e5
created by google.golang.org/grpc.(*addrConn).connect
	/go/pkg/mod/google.golang.org/grpc@v1.18.0/clientconn.go:684 +0xb6

goroutine 1818 [IO wait]:
internal/poll.runtime_pollWait(0x7f9068499008, 0x72, 0xffffffffffffffff)
	/usr/local/go/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc000150718, 0x72, 0x1000, 0x1000, 0xffffffffffffffff)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000150700, 0xc001068000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:169 +0x19b
net.(*netFD).Read(0xc000150700, 0xc001068000, 0x1000, 0x1000, 0x43f5bd, 0xc000168118, 0x0)
	/usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc000010020, 0xc001068000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:177 +0x69
bufio.(*Reader).Read(0xc000946540, 0xc000ddc288, 0x1, 0x9, 0x2, 0x3, 0x80)
	/usr/local/go/src/bufio/bufio.go:223 +0x22f
io.ReadAtLeast(0x1033de0, 0xc000946540, 0xc000ddc288, 0x1, 0x9, 0x1, 0x38, 0xc0157a5440, 0x0)
	/usr/local/go/src/io/io.go:310 +0x88
io.ReadFull(...)
	/usr/local/go/src/io/io.go:329
github.com/gocql/gocql.readHeader(0x1033de0, 0xc000946540, 0xc000ddc288, 0x9, 0x9, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/go/pkg/mod/github.com/scylladb/gocql@v1.0.1/frame.go:446 +0xab
github.com/gocql/gocql.(*Conn).recv(0xc000ddc240, 0x0, 0x0)

@scarbo87
Copy link

scarbo87 commented Nov 6, 2019

Hi to everyone, I catched the same problem:

runtime: invalid pc-encoded table f=myproject/vendor/github.com/ugorji/go/codec.fastpathT.DecSliceUintN pc=0xa633f1 targetpc=0xa633f6 tab=[0/0]0x0
	value=0 until pc=0xa631d7
2019/11/06 21:58:37 2019-11-06 21:58:37.572165556 +0000 UTC 370458512998-2-23-5-404612000001-404612000001=7045535961053964897
	value=88 until pc=0xa6333f
	value=02019/11/06 21:58:37 2019-11-06 21:58:37.57217838 +0000 UTC 370458512999-2-23-18-1573077492-1573077515=7045535964200119947
 until pc=0xa63340
2019/11/06 21:58:37 2019-11-06 21:58:37.572197437 +0000 UTC 370458513000-2-23-6-405062000000-405062000000=7045536774324119978
	value=88 until pc=0xa6335f2019/11/06 21:58:37 2019-11-06 21:58:37.572208358 +0000 UTC 370458513001-2-23-18-1573077515-1573077515=7045536777470275051

	value=2019/11/06 21:58:37 2019-11-06 21:58:37.572221159 +0000 UTC CMD OK #8205492792
02019/11/06 21:58:37 2019-11-06 21:58:37.572228878 +0000 UTC EID #17236529052
 until pc=0xa63360
	value=88 until pc=0xa633d5
	value=0 until pc=0xa633d6
	value=88 until pc=0xa633df
	value=0 until pc=0xa633e0
	value=88 until pc=0xa633e7
	value=0 until pc=0xa633f1
fatal error: invalid runtime symbol table

goroutine 0 [idle]:
runtime: unexpected return pc for runtime.sigreturn called from 0x7
stack: frame={sp:0xc003263ac0, fp:0xc003263ac8} stack=[0xc00325c000,0xc003264000)
000000c0032639c0:  000000c003263bf0  000000c003263ac0 
000000c0032639d0:  000000c003224600  0000000000000000 
000000c0032639e0:  0000000000000000  0000000000000000 
000000c0032639f0:  0000000000000000  0000000000000000 
000000c003263a00:  0000000000000000  0000000000000000 
000000c003263a10:  000000c003224600  0000000000000000 
000000c003263a20:  0000000000000000  0000000000000000 
000000c003263a30:  0000000000000000  0000000000000000 
000000c003263a40:  0000000000000000  0000000000000000 
000000c003263a50:  0000000000000000  000000c003263ab0 
000000c003263a60:  000000000045eb43 <runtime.sigtramp+67>  000000000000001b 
000000c003263a70:  000000c003263bf0  000000c003263ac0 
000000c003263a80:  0000000000000000  0000000000000000 
000000c003263a90:  00000000015beb60  0000000000000002 
000000c003263aa0:  000000c003263ab0  000000c003222380 
000000c003263ab0:  000000c00321fe20  000000000045ec30 <runtime.sigreturn+0> 
000000c003263ac0: <0000000000000007 >0000000000000000 
000000c003263ad0:  000000c00325c000  0000000000000000 
000000c003263ae0:  0000000000008000  000000000000fe9b 
000000c003263af0:  000000000160cfe8  001b5ec101d087a0 
000000c003263b00:  0000000000000001  0000000000000002 
000000c003263b10:  00000000015beb60  0000000000000000 
000000c003263b20:  0000000000000000  0000000000000001 
000000c003263b30:  000000c00321fe10  000000c00321fe20 
000000c003263b40:  000000c003222380  000000001ba8148a 
000000c003263b50:  0000000000a633f6 <myproject/vendor/github.com/ugorji/go/codec.fastpathT.DecSliceUintN+566>  0000000000000018 
000000c003263b60:  000000c00321fe10  000000000045e9df <runtime.nanotime+95> 
000000c003263b70:  0000000000000246  002b000000000033 
000000c003263b80:  0000000000000000  0000000000000000 
000000c003263b90:  0000000000000000  0000000000000000 
000000c003263ba0:  000000c003263c80  0000000000000000 
000000c003263bb0:  0000000000000000  0000000000000000 
000000c003263bc0:  0000000000000000 
runtime.throw(0xe064c9, 0x1c)
	/usr/local/Cellar/go/1.12.7/libexec/src/runtime/panic.go:617 +0x72
runtime.pcvalue(0x145d770, 0x15beb60, 0x4d4daf, 0xa633f6, 0xc0032634d0, 0xff8b01, 0x0)
	/usr/local/Cellar/go/1.12.7/libexec/src/runtime/symtab.go:704 +0x53f
runtime.funcspdelta(0x145d770, 0x15beb60, 0xa633f6, 0xc0032634d0, 0xc000000000)
	/usr/local/Cellar/go/1.12.7/libexec/src/runtime/symtab.go:756 +0x5f
runtime.gentraceback(0x45e9df, 0xc00321fe10, 0x0, 0xc003224600, 0x0, 0xc003263728, 0x40, 0x0, 0x0, 0x6, ...)
	/usr/local/Cellar/go/1.12.7/libexec/src/runtime/traceback.go:222 +0x1888
runtime.sigprof(0x45e9df, 0xc00321fe10, 0x0, 0xc003224600, 0xc003222380)
	/usr/local/Cellar/go/1.12.7/libexec/src/runtime/proc.go:3754 +0x432
runtime.sighandler(0xc00000001b, 0xc003263bf0, 0xc003263ac0, 0xc003224600)
	/usr/local/Cellar/go/1.12.7/libexec/src/runtime/signal_sighandler.go:38 +0x723
runtime.sigtrampgo(0x1b, 0xc003263bf0, 0xc003263ac0)
	/usr/local/Cellar/go/1.12.7/libexec/src/runtime/signal_unix.go:351 +0x1f2
runtime.sigtramp(0x7, 0x0, 0xc00325c000, 0x0, 0x8000, 0xfe9b, 0x160cfe8, 0x1b5ec101d087a0, 0x1, 0x2, ...)
	/usr/local/Cellar/go/1.12.7/libexec/src/runtime/sys_linux_amd64.s:357 +0x43
runtime: unexpected return pc for runtime.sigreturn called from 0x7
stack: frame={sp:0xc003263ac0, fp:0xc003263ac8} stack=[0xc00325c000,0xc003264000)
000000c0032639c0:  000000c003263bf0  000000c003263ac0 
000000c0032639d0:  000000c003224600  0000000000000000 
000000c0032639e0:  0000000000000000  0000000000000000 
000000c0032639f0:  0000000000000000  0000000000000000 
000000c003263a00:  0000000000000000  0000000000000000 
000000c003263a10:  000000c003224600  0000000000000000 
000000c003263a20:  0000000000000000  0000000000000000 
000000c003263a30:  0000000000000000  0000000000000000 
000000c003263a40:  0000000000000000  0000000000000000 
000000c003263a50:  0000000000000000  000000c003263ab0 
000000c003263a60:  000000000045eb43 <runtime.sigtramp+67>  000000000000001b 
000000c003263a70:  000000c003263bf0  000000c003263ac0 
000000c003263a80:  0000000000000000  0000000000000000 
000000c003263a90:  00000000015beb60  0000000000000002 
000000c003263aa0:  000000c003263ab0  000000c003222380 
000000c003263ab0:  000000c00321fe20  000000000045ec30 <runtime.sigreturn+0> 
000000c003263ac0: <0000000000000007 >0000000000000000 
000000c003263ad0:  000000c00325c000  0000000000000000 
000000c003263ae0:  0000000000008000  000000000000fe9b 
000000c003263af0:  000000000160cfe8  001b5ec101d087a0 
000000c003263b00:  0000000000000001  0000000000000002 
000000c003263b10:  00000000015beb60  0000000000000000 
000000c003263b20:  0000000000000000  0000000000000001 
000000c003263b30:  000000c00321fe10  000000c00321fe20 
000000c003263b40:  000000c003222380  000000001ba8148a 
000000c003263b50:  0000000000a633f6 <myproject/vendor/github.com/ugorji/go/codec.fastpathT.DecSliceUintN+566>  0000000000000018 
000000c003263b60:  000000c00321fe10  000000000045e9df <runtime.nanotime+95> 
000000c003263b70:  0000000000000246  002b000000000033 
000000c003263b80:  0000000000000000  0000000000000000 
000000c003263b90:  0000000000000000  0000000000000000 
000000c003263ba0:  000000c003263c80  0000000000000000 
000000c003263bb0:  0000000000000000  0000000000000000 
000000c003263bc0:  0000000000000000 
runtime.sigreturn(0x0, 0xc00325c000, 0x0, 0x8000, 0xfe9b, 0x160cfe8, 0x1b5ec101d087a0, 0x1, 0x2, 0x15beb60, ...)
	/usr/local/Cellar/go/1.12.7/libexec/src/runtime/sys_linux_amd64.s:449

I used go 1.12.7 version
What should i do?

@jasonpfox
Copy link

@scarbo87 I was running into this issue regularly when I had a background profiling process running periodically on a long-running process. My only fix so far has been to shift to only collecting profiles on demand or when prompted by specific anomalous events. Does not really solve the issue but significantly reduces the chance of tripping it....

@prattmic
Copy link
Member

It is not totally clear to me what is happening here, but this issue seems like it may be related to, and fixed by http://golang.org/cl/246763.

Has anyone encountered this issue on 1.16?

@xuchenCN
Copy link

It is not totally clear to me what is happening here, but this issue seems like it may be related to, and fixed by http://golang.org/cl/246763.

Has anyone encountered this issue on 1.16?

Yep, go1.16.5 (╥﹏╥)

@bcmills
Copy link
Contributor

bcmills commented Nov 19, 2021

@bcmills
Copy link
Contributor

bcmills commented Jan 7, 2022

greplogs --dashboard -md -l -e 'runtime: invalid pc-encoded table f=[^ ]+ pc=0x[0-9a-f]+' --since=2021-11-20

2022-01-07T00:15:59-07525e1/linux-amd64-bullseye

@bcmills bcmills modified the milestones: Unplanned, Go1.19 Jan 7, 2022
@bcmills
Copy link
Contributor

bcmills commented Jan 7, 2022

This failure mode reproduces on the builders for linux-arm and linux-amd64, which are both first-class ports, and from the crash dumps folks have pasted above we know that it also affects real users at a nonzero rate.

This doesn't reproduce frequently enough to be a blocker for Go 1.18, but it isn't appropriate in the Unplanned milestone either. If there isn't enough information in the tracebacks we're getting to diagnose the problem, then a good next step might be to improve the diagnostics so that we can make progress the next time it happens on the builders.

@cherrymui
Copy link
Member

There are different failure modes, albeit all being related "invalid pc-encoded table" and profiling signals. The last two seem specific to TSAN, due to its delayed delivery of signals. The problem is that when the signal is delivered the signal context no longer matches the thread's state, so unwinding would fail.

The earlier ones are probably related to VDSO.

@aclements
Copy link
Member

We fixed several issues related to VDSOs that could cause this. We haven't done anything about the TSAN issue (we're not sure what to do). We should probably look at more recent builder failures and categorize them to see if they're all TSAN or if we still have some other issue.

@aclements
Copy link
Member

For TSAN, given the delayed signal issue, should we just disallow profiling signals in TSAN builds? Is there any way to work around this?

@bcmills
Copy link
Contributor

bcmills commented Apr 6, 2022

We should probably look at more recent builder failures and categorize them to see if they're all TSAN or if we still have some other issue.

It looks like the linux/amd64 failures are both in TestTSAN/tsan9, which is explicitly checking for the interaction of SIGPROF and TSAN. I don't think it's viable to “disallow” SIGPROF in TSAN builds, because it may be explicitly generated by some third-party C library in a cgo-enabled build. However, it might make sense for the runtime to avoid generating profiles in response to that signal..?

(Or, could we do something like ignore the signal context when handling the profiling signal under TSAN?)

@bcmills
Copy link
Contributor

bcmills commented Apr 6, 2022

The linux/arm crashes were all 2020 or earlier, and the user-reported crashes were all Go 1.16.5 or earlier.

Were the VDSO fixes landed around that timeframe? If so, then it seems plausible that TSAN is the only remaining cause for this failure mode.

@bcmills
Copy link
Contributor

bcmills commented Apr 6, 2022

(TestTSAN/tsan9 is the regression test for #18328.)

@heschi heschi changed the title runtime: crash with "invalid pc-encoded table" runtime: crash with "invalid pc-encoded table" in TSAN mode May 11, 2022
@heschi
Copy link
Contributor

heschi commented May 11, 2022

cc @golang/runtime

@heschi heschi added the okay-after-beta1 Used by release team to mark a release-blocker issue as okay to resolve either before or after beta1 label May 11, 2022
@rhysh
Copy link
Contributor

rhysh commented May 11, 2022

For what it's worth, the original bug report did not involve TSAN. That app was (is) an RPC server that serves requests with net/http and calls some backends with net/http. It appeared to be crashing due to its combination of regular CPU profiling (receiving SIGPROF) and enabling the block/mutex profiles (frequent vDSO calls to find the current time).

I checked in with that team a couple weeks ago, and we weren't able to find any recent crashes (though the machines the app runs on no longer report in the same way they used to when a process dumps core, so it's a bit harder to tell).

@bcmills
Copy link
Contributor

bcmills commented May 12, 2022

For what it's worth, the original bug report did not involve TSAN.

Indeed. I think this issue has ended up tracking something like three distinct but time-overlapping bugs with similar symptoms. (Hopefully we'll eventually reach a state where we don't have so many time-overlapping bugs and they'll be easier to distinguish! 😅)

@gopherbot
Copy link

Change https://go.dev/cl/408218 mentions this issue: runtime: don't inspect the stack for delayed signals from TSAN

@prattmic prattmic self-assigned this Jun 24, 2022
@golang golang locked and limited conversation to collaborators Jun 24, 2023
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. okay-after-beta1 Used by release team to mark a release-blocker issue as okay to resolve either before or after beta1 release-blocker
Projects
None yet
Development

No branches or pull requests