runtime: TestGdbPythonCgo failure with "malformed backtrace" on linux-amd64 builder

[bcmills]

2019-11-20T20:51:13-9852b4b/linux-amd64

--- FAIL: TestGdbPythonCgo (1.88s)
    runtime-gdb_test.go:69: gdb version 7.12
    runtime-gdb_test.go:236: gdb output: Loading Go Runtime support.
        Loading Go Runtime support.
        Breakpoint 1 at 0x490e7a: file /workdir/tmp/go-build468155886/main.go, line 15.
        [Thread debugging using libthread_db enabled]
        Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
        
        Thread 1 "a.exe" hit Breakpoint 1, main.main () at /workdir/tmp/go-build468155886/main.go:15
        15		fmt.Println("hi")
        BEGIN info goroutines
        * 1 running  runtime.systemstack_switch
        * 2 running  runtime.forcegchelper
          3 waiting  runtime.gopark
          4 waiting  runtime.gopark
          18 waiting  runtime.gopark
        END
        BEGIN print mapvar
        $1 = map[string]string = {["abc"] = "def", ["ghi"] = "jkl"}
        END
        BEGIN print strvar
        $2 = "abc"
        END
        BEGIN info locals
        mapvar = map[string]string = {["abc"] = "def", ["ghi"] = "jkl"}
        strvar = "abc"
        slicevar =  []string
        END
        BEGIN goroutine 1 bt
        #0  main.main () at /workdir/tmp/go-build468155886/main.go:15
        END
        BEGIN goroutine 2 bt
        #0  runtime.cgoSigtramp () at /workdir/go/src/runtime/sys_linux_amd64.s:398
        #1  <signal handler called>
        #2  0x0000000000433464 in runtime.casgstatus (gp=0xc000000d80, oldval=1, newval=2) at /workdir/go/src/runtime/proc.go:786
        #3  0x0000000000435dfd in runtime.execute (gp=0xc000000d80, inheritTime=false) at /workdir/go/src/runtime/proc.go:2083
        #4  0x00000000004372fc in runtime.schedule () at /workdir/go/src/runtime/proc.go:2597
        #5  0x0000000000433e9e in runtime.mstart1 () at /workdir/go/src/runtime/proc.go:1140
        #6  0x0000000000433dee in runtime.mstart () at /workdir/go/src/runtime/proc.go:1098
        #7  0x00000000004916c3 in crosscall_amd64 () at gcc_amd64.S:35
        #8  0x0000000000000003 in ?? ()
        #9  0x00007ffdcf609000 in ?? ()
        #10 0x00007fffffffe48f in ?? ()
        #11 0x00007fffffffe48e in ?? ()
        #12 0x000000c000001080 in ?? ()
        #13 0x0000000000433d80 in ?? () at <autogenerated>:1
        #14 0x0000000000491293 in threadentry (v=<optimized out>) at gcc_linux_amd64.c:97
        #15 0x00007ffff7bc34a4 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
        #16 0x00007ffff7905d0f in clone () from /lib/x86_64-linux-gnu/libc.so.6
        END
        BEGIN goroutine all bt
        #0  main.main () at /workdir/tmp/go-build468155886/main.go:15
        No such goroutine:  17
        #0  runtime.cgoSigtramp () at /workdir/go/src/runtime/sys_linux_amd64.s:398
        #1  <signal handler called>
        #2  0x0000000000433464 in runtime.casgstatus (gp=0xc000000d80, oldval=1, newval=2) at /workdir/go/src/runtime/proc.go:786
        #3  0x0000000000435dfd in runtime.execute (gp=0xc000000d80, inheritTime=false) at /workdir/go/src/runtime/proc.go:2083
        #4  0x00000000004372fc in runtime.schedule () at /workdir/go/src/runtime/proc.go:2597
        #5  0x0000000000433e9e in runtime.mstart1 () at /workdir/go/src/runtime/proc.go:1140
        #6  0x0000000000433dee in runtime.mstart () at /workdir/go/src/runtime/proc.go:1098
        #7  0x00000000004916c3 in crosscall_amd64 () at gcc_amd64.S:35
        #8  0x0000000000000003 in ?? ()
        #9  0x00007ffdcf609000 in ?? ()
        #10 0x00007fffffffe48f in ?? ()
        #11 0x00007fffffffe48e in ?? ()
        #12 0x000000c000001080 in ?? ()
        #13 0x0000000000433d80 in ?? () at <autogenerated>:1
        #14 0x0000000000491293 in threadentry (v=<optimized out>) at gcc_linux_amd64.c:97
        #15 0x00007ffff7bc34a4 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
        #16 0x00007ffff7905d0f in clone () from /lib/x86_64-linux-gnu/libc.so.6
        #0  runtime.gopark (unlockf={void (runtime.g *, void *, bool *)} 0xc00002d7a8, lock=0x75e920 <runtime.sweep>, reason=12 '\f', traceEv=20 '\024', traceskip=1) at /workdir/go/src/runtime/proc.go:305
        #1  0x00000000004200cc in runtime.goparkunlock (lock=<optimized out>, reason=<optimized out>, traceEv=<optimized out>, traceskip=<optimized out>) at /workdir/go/src/runtime/proc.go:310
        #2  runtime.bgsweep (c=0xc000016070) at /workdir/go/src/runtime/mgcsweep.go:70
        #3  0x000000000045b311 in runtime.goexit () at /workdir/go/src/runtime/asm_amd64.s:1375
        #4  0x000000c000016070 in ?? ()
        #5  0x0000000000000000 in ?? ()
        #0  runtime.gopark (unlockf={void (runtime.g *, void *, bool *)} 0xc00002df50, lock=0x75e8e0 <runtime.scavenge>, reason=13 '\r', traceEv=20 '\024', traceskip=1) at /workdir/go/src/runtime/proc.go:305
        #1  0x000000000041e8b3 in runtime.goparkunlock (lock=<optimized out>, reason=<optimized out>, traceEv=<optimized out>, traceskip=<optimized out>) at /workdir/go/src/runtime/proc.go:310
        #2  runtime.bgscavenge (c=0xc000016070) at /workdir/go/src/runtime/mgcscavenge.go:220
        #3  0x000000000045b311 in runtime.goexit () at /workdir/go/src/runtime/asm_amd64.s:1375
        #4  0x000000c000016070 in ?? ()
        #5  0x0000000000000000 in ?? ()
        #0  runtime.gopark (unlockf={void (runtime.g *, void *, bool *)} 0xc00002c758, lock=0x777de0 <runtime.finlock>, reason=16 '\020', traceEv=20 '\024', traceskip=1) at /workdir/go/src/runtime/proc.go:305
        #1  0x0000000000416053 in runtime.goparkunlock (lock=<optimized out>, reason=<optimized out>, traceEv=<optimized out>, traceskip=<optimized out>) at /workdir/go/src/runtime/proc.go:310
        #2  runtime.runfinq () at /workdir/go/src/runtime/mfinal.go:175
        #3  0x000000000045b311 in runtime.goexit () at /workdir/go/src/runtime/asm_amd64.s:1375
        #4  0x0000000000000000 in ?? ()
        END
        Breakpoint 2 at 0x490efd: file /workdir/tmp/go-build468155886/main.go, line 19.
        hi
        
        Thread 1 "a.exe" hit Breakpoint 2, main.main () at /workdir/tmp/go-build468155886/main.go:20
        20	}  // END_OF_PROGRAM
        BEGIN goroutine 1 bt at the end
        #0  main.main () at /workdir/tmp/go-build468155886/main.go:20
        END
        
    runtime-gdb_test.go:98: malformed backtrace at line 10: #10 0x00007fffffffe48f in ?? ()
FAIL
FAIL	runtime	29.184s

See previously #31569, #27608, and perhaps others. This failure mode is similar, but somewhat different.

CC @cherrymui

[cherrymui]

I think generally it is hard to trace back through a C-Go boundary, as the ABI may be different. Does it just start to fail recently? I don't know how it worked before...

For this particular case, it seems the traceback failed at crosscall_amd64. Maybe adding CFI directives in that function could make it work? cc @ianlancetaylor

[ianlancetaylor]

The test is only seeing the cgo backtrace because it's trying to backtrace from the signal handler. The test does not expect that to happen, as there is no signals involved. So this may have been caused by signal preemption, somehow. Perhaps the test should disable signal preemption, although it's hard to know for sure since I can't recreate the problem myself.