Skip to content

Commit dbd8f3d

Browse files
committed
runtime: print hexdump on traceback failure
Currently, if anything goes wrong when printing a traceback, we simply cut off the traceback without any further diagnostics. Unfortunately, right now, we have a few issues that are difficult to debug because the traceback simply cuts off (#21431, #23484). This is an attempt to improve the debuggability of traceback failure by printing a diagnostic message plus a hex dump around the failed traceback frame when something goes wrong. The failures look like: goroutine 5 [running]: runtime: unexpected return pc for main.badLR2 called from 0xbad stack: frame={sp:0xc42004dfa8, fp:0xc42004dfc8} stack=[0xc42004d800,0xc42004e000) 000000c42004dea8: 0000000000000001 0000000000000001 000000c42004deb8: 000000c42004ded8 000000c42004ded8 000000c42004dec8: 0000000000427eea <runtime.dopanic+74> 000000c42004ded8 000000c42004ded8: 000000000044df70 <runtime.dopanic.func1+0> 000000c420001080 000000c42004dee8: 0000000000427b21 <runtime.gopanic+961> 000000c42004df08 000000c42004def8: 000000c42004df98 0000000000427b21 <runtime.gopanic+961> 000000c42004df08: 0000000000000000 0000000000000000 000000c42004df18: 0000000000000000 0000000000000000 000000c42004df28: 0000000000000000 0000000000000000 000000c42004df38: 0000000000000000 000000c420001080 000000c42004df48: 0000000000000000 0000000000000000 000000c42004df58: 0000000000000000 0000000000000000 000000c42004df68: 000000c4200010a0 0000000000000000 000000c42004df78: 00000000004c6400 00000000005031d0 000000c42004df88: 0000000000000000 0000000000000000 000000c42004df98: 000000c42004dfb8 00000000004ae7d9 <main.badLR2+73> 000000c42004dfa8: <00000000004c6400 00000000005031d0 000000c42004dfb8: 000000c42004dfd0 !0000000000000bad 000000c42004dfc8: >0000000000000000 0000000000000000 000000c42004dfd8: 0000000000451821 <runtime.goexit+1> 0000000000000000 000000c42004dfe8: 0000000000000000 0000000000000000 000000c42004dff8: 0000000000000000 main.badLR2(0x0) /go/src/runtime/testdata/testprog/badtraceback.go:42 +0x49 For #21431, #23484. Change-Id: I8718fc76ced81adb0b4b0b4f2293f3219ca80786 Reviewed-on: https://go-review.googlesource.com/89016 Run-TryBot: Austin Clements <[email protected]> TryBot-Result: Gobot Gobot <[email protected]> Reviewed-by: Cherry Zhang <[email protected]>
1 parent 2923b20 commit dbd8f3d

File tree

4 files changed

+169
-2
lines changed

4 files changed

+169
-2
lines changed

src/runtime/crash_test.go

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -607,3 +607,17 @@ retry:
607607
}
608608
t.Errorf("test ran %d times without producing expected output", tries)
609609
}
610+
611+
func TestBadTraceback(t *testing.T) {
612+
output := runTestProg(t, "testprog", "BadTraceback")
613+
for _, want := range []string{
614+
"runtime: unexpected return pc",
615+
"called from 0xbad",
616+
"00000bad", // Smashed LR in hex dump
617+
"<main.badLR", // Symbolization in hex dump (badLR1 or badLR2)
618+
} {
619+
if !strings.Contains(output, want) {
620+
t.Errorf("output does not contain %q:\n%s", want, output)
621+
}
622+
}
623+
}

src/runtime/print.go

Lines changed: 53 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@ package runtime
66

77
import (
88
"runtime/internal/atomic"
9+
"runtime/internal/sys"
910
"unsafe"
1011
)
1112

@@ -249,3 +250,55 @@ func printeface(e eface) {
249250
func printiface(i iface) {
250251
print("(", i.tab, ",", i.data, ")")
251252
}
253+
254+
// hexdumpWords prints a word-oriented hex dump of [p, end).
255+
//
256+
// If mark != nil, it will be called with each printed word's address
257+
// and should return a character mark to appear just before that
258+
// word's value. It can return 0 to indicate no mark.
259+
func hexdumpWords(p, end uintptr, mark func(uintptr) byte) {
260+
p1 := func(x uintptr) {
261+
var buf [2 * sys.PtrSize]byte
262+
for i := len(buf) - 1; i >= 0; i-- {
263+
if x&0xF < 10 {
264+
buf[i] = byte(x&0xF) + '0'
265+
} else {
266+
buf[i] = byte(x&0xF) - 10 + 'a'
267+
}
268+
x >>= 4
269+
}
270+
gwrite(buf[:])
271+
}
272+
273+
printlock()
274+
var markbuf [1]byte
275+
markbuf[0] = ' '
276+
for i := uintptr(0); p+i < end; i += sys.PtrSize {
277+
if i%16 == 0 {
278+
if i != 0 {
279+
println()
280+
}
281+
p1(p + i)
282+
print(": ")
283+
}
284+
285+
if mark != nil {
286+
markbuf[0] = mark(p + i)
287+
if markbuf[0] == 0 {
288+
markbuf[0] = ' '
289+
}
290+
}
291+
gwrite(markbuf[:])
292+
val := *(*uintptr)(unsafe.Pointer(p + i))
293+
p1(val)
294+
print(" ")
295+
296+
// Can we symbolize val?
297+
fn := findfunc(val)
298+
if fn.valid() {
299+
print("<", funcname(fn), "+", val-fn.entry, "> ")
300+
}
301+
}
302+
println()
303+
printunlock()
304+
}
Lines changed: 47 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,47 @@
1+
// Copyright 2018 The Go Authors. All rights reserved.
2+
// Use of this source code is governed by a BSD-style
3+
// license that can be found in the LICENSE file.
4+
5+
package main
6+
7+
import (
8+
"runtime"
9+
"runtime/debug"
10+
"unsafe"
11+
)
12+
13+
func init() {
14+
register("BadTraceback", BadTraceback)
15+
}
16+
17+
func BadTraceback() {
18+
// Disable GC to prevent traceback at unexpected time.
19+
debug.SetGCPercent(-1)
20+
21+
// Run badLR1 on its own stack to minimize the stack size and
22+
// exercise the stack bounds logic in the hex dump.
23+
go badLR1()
24+
select {}
25+
}
26+
27+
//go:noinline
28+
func badLR1() {
29+
// We need two frames on LR machines because we'll smash this
30+
// frame's saved LR.
31+
badLR2(0)
32+
}
33+
34+
//go:noinline
35+
func badLR2(arg int) {
36+
// Smash the return PC or saved LR.
37+
lrOff := unsafe.Sizeof(uintptr(0))
38+
if runtime.GOARCH == "ppc64" || runtime.GOARCH == "ppc64le" {
39+
lrOff = 32 // FIXED_FRAME or sys.MinFrameSize
40+
}
41+
lrPtr := (*uintptr)(unsafe.Pointer(uintptr(unsafe.Pointer(&arg)) - lrOff))
42+
*lrPtr = 0xbad
43+
44+
// Print a backtrace. This should include diagnostics for the
45+
// bad return PC and a hex dump.
46+
panic("backtrace")
47+
}

src/runtime/traceback.go

Lines changed: 55 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -204,8 +204,11 @@ func gentraceback(pc0, sp0, lr0 uintptr, gp *g, skip int, pcbuf *uintptr, max in
204204

205205
f := findfunc(frame.pc)
206206
if !f.valid() {
207-
if callback != nil {
207+
if callback != nil || printing {
208208
print("runtime: unknown pc ", hex(frame.pc), "\n")
209+
tracebackHexdump(gp.stack, &frame, 0)
210+
}
211+
if callback != nil {
209212
throw("unknown pc")
210213
}
211214
return 0
@@ -281,8 +284,11 @@ func gentraceback(pc0, sp0, lr0 uintptr, gp *g, skip int, pcbuf *uintptr, max in
281284
// In that context it is okay to stop early.
282285
// But if callback is set, we're doing a garbage collection and must
283286
// get everything, so crash loudly.
284-
if callback != nil {
287+
if callback != nil || printing {
285288
print("runtime: unexpected return pc for ", funcname(f), " called from ", hex(frame.lr), "\n")
289+
tracebackHexdump(gp.stack, &frame, lrPtr)
290+
}
291+
if callback != nil {
286292
throw("unknown caller pc")
287293
}
288294
}
@@ -866,6 +872,53 @@ func tracebackothers(me *g) {
866872
unlock(&allglock)
867873
}
868874

875+
// tracebackHexdump hexdumps part of stk around frame.sp and frame.fp
876+
// for debugging purposes. If the address bad is included in the
877+
// hexdumped range, it will mark it as well.
878+
func tracebackHexdump(stk stack, frame *stkframe, bad uintptr) {
879+
const expand = 32 * sys.PtrSize
880+
const maxExpand = 256 * sys.PtrSize
881+
// Start around frame.sp.
882+
lo, hi := frame.sp, frame.sp
883+
// Expand to include frame.fp.
884+
if frame.fp != 0 && frame.fp < lo {
885+
lo = frame.fp
886+
}
887+
if frame.fp != 0 && frame.fp > hi {
888+
hi = frame.fp
889+
}
890+
// Expand a bit more.
891+
lo, hi = lo-expand, hi+expand
892+
// But don't go too far from frame.sp.
893+
if lo < frame.sp-maxExpand {
894+
lo = frame.sp - maxExpand
895+
}
896+
if hi > frame.sp+maxExpand {
897+
hi = frame.sp + maxExpand
898+
}
899+
// And don't go outside the stack bounds.
900+
if lo < stk.lo {
901+
lo = stk.lo
902+
}
903+
if hi > stk.hi {
904+
hi = stk.hi
905+
}
906+
907+
// Print the hex dump.
908+
print("stack: frame={sp:", hex(frame.sp), ", fp:", hex(frame.fp), "} stack=[", hex(stk.lo), ",", hex(stk.hi), ")\n")
909+
hexdumpWords(lo, hi, func(p uintptr) byte {
910+
switch p {
911+
case frame.fp:
912+
return '>'
913+
case frame.sp:
914+
return '<'
915+
case bad:
916+
return '!'
917+
}
918+
return 0
919+
})
920+
}
921+
869922
// Does f mark the top of a goroutine stack?
870923
func topofstack(f funcInfo) bool {
871924
pc := f.entry

0 commit comments

Comments
 (0)