traceback_system_test.go

     1  // Copyright 2024 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 runtime_test
     6  
     7  // This test of GOTRACEBACK=system has its own file,
     8  // to minimize line-number perturbation.
     9  
    10  import (
    11  	"bytes"
    12  	"fmt"
    13  	"internal/testenv"
    14  	"io"
    15  	"os"
    16  	"path/filepath"
    17  	"reflect"
    18  	"runtime"
    19  	"runtime/debug"
    20  	"strconv"
    21  	"strings"
    22  	"testing"
    23  )
    24  
    25  // This is the entrypoint of the child process used by
    26  // TestTracebackSystem/panic. It prints a crash report to stdout.
    27  func crashViaPanic() {
    28  	// Ensure that we get pc=0x%x values in the traceback.
    29  	debug.SetTraceback("system")
    30  	writeSentinel(os.Stdout)
    31  	debug.SetCrashOutput(os.Stdout, debug.CrashOptions{})
    32  
    33  	go func() {
    34  		// This call is typically inlined.
    35  		child1()
    36  	}()
    37  	select {}
    38  }
    39  
    40  // This is the entrypoint of the child process used by
    41  // TestTracebackSystem/trap. It prints a crash report to stdout.
    42  func crashViaTrap() {
    43  	// Ensure that we get pc=0x%x values in the traceback.
    44  	debug.SetTraceback("system")
    45  	writeSentinel(os.Stdout)
    46  	debug.SetCrashOutput(os.Stdout, debug.CrashOptions{})
    47  
    48  	go func() {
    49  		// This call is typically inlined.
    50  		trap1()
    51  	}()
    52  	select {}
    53  }
    54  
    55  func child1() {
    56  	child2()
    57  }
    58  
    59  func child2() {
    60  	child3()
    61  }
    62  
    63  func child3() {
    64  	child4()
    65  }
    66  
    67  func child4() {
    68  	child5()
    69  }
    70  
    71  //go:noinline
    72  func child5() { // test trace through second of two call instructions
    73  	child6bad()
    74  	child6() // appears in stack trace
    75  }
    76  
    77  //go:noinline
    78  func child6bad() {
    79  }
    80  
    81  //go:noinline
    82  func child6() { // test trace through first of two call instructions
    83  	child7() // appears in stack trace
    84  	child7bad()
    85  }
    86  
    87  //go:noinline
    88  func child7bad() {
    89  }
    90  
    91  //go:noinline
    92  func child7() {
    93  	// Write runtime.Caller's view of the stack to stderr, for debugging.
    94  	var pcs [16]uintptr
    95  	n := runtime.Callers(1, pcs[:])
    96  	fmt.Fprintf(os.Stderr, "Callers: %#x\n", pcs[:n])
    97  	io.WriteString(os.Stderr, formatStack(pcs[:n]))
    98  
    99  	// Cause the crash report to be written to stdout.
   100  	panic("oops")
   101  }
   102  
   103  func trap1() {
   104  	trap2()
   105  }
   106  
   107  var sinkPtr *int
   108  
   109  func trap2() {
   110  	trap3(sinkPtr)
   111  }
   112  
   113  func trap3(i *int) {
   114  	*i = 42
   115  }
   116  
   117  // TestTracebackSystem tests that the syntax of crash reports produced
   118  // by GOTRACEBACK=system (see traceback2) contains a complete,
   119  // parseable list of program counters for the running goroutine that
   120  // can be parsed and fed to runtime.CallersFrames to obtain accurate
   121  // information about the logical call stack, even in the presence of
   122  // inlining.
   123  //
   124  // The test is a distillation of the crash monitor in
   125  // golang.org/x/telemetry/crashmonitor.
   126  func TestTracebackSystem(t *testing.T) {
   127  	testenv.MustHaveExec(t)
   128  	if runtime.GOOS == "android" {
   129  		t.Skip("Can't read source code for this file on Android")
   130  	}
   131  
   132  	tests := []struct {
   133  		name string
   134  		want string
   135  	}{
   136  		{
   137  			name: "panic",
   138  			want: `redacted.go:0: runtime.gopanic
   139  traceback_system_test.go:100: runtime_test.child7: 	panic("oops")
   140  traceback_system_test.go:83: runtime_test.child6: 	child7() // appears in stack trace
   141  traceback_system_test.go:74: runtime_test.child5: 	child6() // appears in stack trace
   142  traceback_system_test.go:68: runtime_test.child4: 	child5()
   143  traceback_system_test.go:64: runtime_test.child3: 	child4()
   144  traceback_system_test.go:60: runtime_test.child2: 	child3()
   145  traceback_system_test.go:56: runtime_test.child1: 	child2()
   146  traceback_system_test.go:35: runtime_test.crashViaPanic.func1: 		child1()
   147  redacted.go:0: runtime.goexit
   148  `,
   149  		},
   150  		{
   151  			// Test panic via trap. x/telemetry is aware that trap
   152  			// PCs follow runtime.sigpanic and need to be
   153  			// incremented to offset the decrement done by
   154  			// CallersFrames.
   155  			name: "trap",
   156  			want: `redacted.go:0: runtime.gopanic
   157  redacted.go:0: runtime.panicmem
   158  redacted.go:0: runtime.sigpanic
   159  traceback_system_test.go:114: runtime_test.trap3: 	*i = 42
   160  traceback_system_test.go:110: runtime_test.trap2: 	trap3(sinkPtr)
   161  traceback_system_test.go:104: runtime_test.trap1: 	trap2()
   162  traceback_system_test.go:50: runtime_test.crashViaTrap.func1: 		trap1()
   163  redacted.go:0: runtime.goexit
   164  `,
   165  		},
   166  	}
   167  
   168  	for _, tc := range tests {
   169  		t.Run(tc.name, func(t *testing.T) {
   170  			// Fork+exec the crashing process.
   171  			exe, err := os.Executable()
   172  			if err != nil {
   173  				t.Fatal(err)
   174  			}
   175  			cmd := testenv.Command(t, exe)
   176  			cmd.Env = append(cmd.Environ(), entrypointVar+"="+tc.name)
   177  			var stdout, stderr bytes.Buffer
   178  			cmd.Stdout = &stdout
   179  			cmd.Stderr = &stderr
   180  			cmd.Run() // expected to crash
   181  			t.Logf("stderr:\n%s\nstdout: %s\n", stderr.Bytes(), stdout.Bytes())
   182  			crash := stdout.String()
   183  
   184  			// If the only line is the sentinel, it wasn't a crash.
   185  			if strings.Count(crash, "\n") < 2 {
   186  				t.Fatalf("child process did not produce a crash report")
   187  			}
   188  
   189  			// Parse the PCs out of the child's crash report.
   190  			pcs, err := parseStackPCs(crash)
   191  			if err != nil {
   192  				t.Fatal(err)
   193  			}
   194  
   195  			// Unwind the stack using this executable's symbol table.
   196  			got := formatStack(pcs)
   197  			if strings.TrimSpace(got) != strings.TrimSpace(tc.want) {
   198  				t.Errorf("got:\n%swant:\n%s", got, tc.want)
   199  			}
   200  		})
   201  	}
   202  }
   203  
   204  // parseStackPCs parses the parent process's program counters for the
   205  // first running goroutine out of a GOTRACEBACK=system traceback,
   206  // adjusting them so that they are valid for the child process's text
   207  // segment.
   208  //
   209  // This function returns only program counter values, ensuring that
   210  // there is no possibility of strings from the crash report (which may
   211  // contain PII) leaking into the telemetry system.
   212  //
   213  // (Copied from golang.org/x/telemetry/crashmonitor.parseStackPCs.)
   214  func parseStackPCs(crash string) ([]uintptr, error) {
   215  	// getSymbol parses the symbol name out of a line of the form:
   216  	// SYMBOL(ARGS)
   217  	//
   218  	// Note: SYMBOL may contain parens "pkg.(*T).method". However, type
   219  	// parameters are always replaced with ..., so they cannot introduce
   220  	// more parens. e.g., "pkg.(*T[...]).method".
   221  	//
   222  	// ARGS can contain parens. We want the first paren that is not
   223  	// immediately preceded by a ".".
   224  	//
   225  	// TODO(prattmic): This is mildly complicated and is only used to find
   226  	// runtime.sigpanic, so perhaps simplify this by checking explicitly
   227  	// for sigpanic.
   228  	getSymbol := func(line string) (string, error) {
   229  		var prev rune
   230  		for i, c := range line {
   231  			if line[i] != '(' {
   232  				prev = c
   233  				continue
   234  			}
   235  			if prev == '.' {
   236  				prev = c
   237  				continue
   238  			}
   239  			return line[:i], nil
   240  		}
   241  		return "", fmt.Errorf("no symbol for stack frame: %s", line)
   242  	}
   243  
   244  	// getPC parses the PC out of a line of the form:
   245  	//     \tFILE:LINE +0xRELPC sp=... fp=... pc=...
   246  	getPC := func(line string) (uint64, error) {
   247  		_, pcstr, ok := strings.Cut(line, " pc=") // e.g. pc=0x%x
   248  		if !ok {
   249  			return 0, fmt.Errorf("no pc= for stack frame: %s", line)
   250  		}
   251  		return strconv.ParseUint(pcstr, 0, 64) // 0 => allow 0x prefix
   252  	}
   253  
   254  	var (
   255  		pcs            []uintptr
   256  		parentSentinel uint64
   257  		childSentinel  = sentinel()
   258  		on             = false // are we in the first running goroutine?
   259  		lines          = strings.Split(crash, "\n")
   260  		symLine        = true // within a goroutine, every other line is a symbol or file/line/pc location, starting with symbol.
   261  		currSymbol     string
   262  		prevSymbol     string // symbol of the most recent previous frame with a PC.
   263  	)
   264  	for i := 0; i < len(lines); i++ {
   265  		line := lines[i]
   266  
   267  		// Read sentinel value.
   268  		if parentSentinel == 0 && strings.HasPrefix(line, "sentinel ") {
   269  			_, err := fmt.Sscanf(line, "sentinel %x", &parentSentinel)
   270  			if err != nil {
   271  				return nil, fmt.Errorf("can't read sentinel line")
   272  			}
   273  			continue
   274  		}
   275  
   276  		// Search for "goroutine GID [STATUS]"
   277  		if !on {
   278  			if strings.HasPrefix(line, "goroutine ") &&
   279  				strings.Contains(line, " [running]:") {
   280  				on = true
   281  
   282  				if parentSentinel == 0 {
   283  					return nil, fmt.Errorf("no sentinel value in crash report")
   284  				}
   285  			}
   286  			continue
   287  		}
   288  
   289  		// A blank line marks end of a goroutine stack.
   290  		if line == "" {
   291  			break
   292  		}
   293  
   294  		// Skip the final "created by SYMBOL in goroutine GID" part.
   295  		if strings.HasPrefix(line, "created by ") {
   296  			break
   297  		}
   298  
   299  		// Expect a pair of lines:
   300  		//   SYMBOL(ARGS)
   301  		//   \tFILE:LINE +0xRELPC sp=0x%x fp=0x%x pc=0x%x
   302  		// Note: SYMBOL may contain parens "pkg.(*T).method"
   303  		// The RELPC is sometimes missing.
   304  
   305  		if symLine {
   306  			var err error
   307  			currSymbol, err = getSymbol(line)
   308  			if err != nil {
   309  				return nil, fmt.Errorf("error extracting symbol: %v", err)
   310  			}
   311  
   312  			symLine = false // Next line is FILE:LINE.
   313  		} else {
   314  			// Parse the PC, and correct for the parent and child's
   315  			// different mappings of the text section.
   316  			pc, err := getPC(line)
   317  			if err != nil {
   318  				// Inlined frame, perhaps; skip it.
   319  
   320  				// Done with this frame. Next line is a new frame.
   321  				//
   322  				// Don't update prevSymbol; we only want to
   323  				// track frames with a PC.
   324  				currSymbol = ""
   325  				symLine = true
   326  				continue
   327  			}
   328  
   329  			pc = pc - parentSentinel + childSentinel
   330  
   331  			// If the previous frame was sigpanic, then this frame
   332  			// was a trap (e.g., SIGSEGV).
   333  			//
   334  			// Typically all middle frames are calls, and report
   335  			// the "return PC". That is, the instruction following
   336  			// the CALL where the callee will eventually return to.
   337  			//
   338  			// runtime.CallersFrames is aware of this property and
   339  			// will decrement each PC by 1 to "back up" to the
   340  			// location of the CALL, which is the actual line
   341  			// number the user expects.
   342  			//
   343  			// This does not work for traps, as a trap is not a
   344  			// call, so the reported PC is not the return PC, but
   345  			// the actual PC of the trap.
   346  			//
   347  			// runtime.Callers is aware of this and will
   348  			// intentionally increment trap PCs in order to correct
   349  			// for the decrement performed by
   350  			// runtime.CallersFrames. See runtime.tracebackPCs and
   351  			// runtume.(*unwinder).symPC.
   352  			//
   353  			// We must emulate the same behavior, otherwise we will
   354  			// report the location of the instruction immediately
   355  			// prior to the trap, which may be on a different line,
   356  			// or even a different inlined functions.
   357  			//
   358  			// TODO(prattmic): The runtime applies the same trap
   359  			// behavior for other "injected calls", see injectCall
   360  			// in runtime.(*unwinder).next. Do we want to handle
   361  			// those as well? I don't believe we'd ever see
   362  			// runtime.asyncPreempt or runtime.debugCallV2 in a
   363  			// typical crash.
   364  			if prevSymbol == "runtime.sigpanic" {
   365  				pc++
   366  			}
   367  
   368  			pcs = append(pcs, uintptr(pc))
   369  
   370  			// Done with this frame. Next line is a new frame.
   371  			prevSymbol = currSymbol
   372  			currSymbol = ""
   373  			symLine = true
   374  		}
   375  	}
   376  	return pcs, nil
   377  }
   378  
   379  // The sentinel function returns its address. The difference between
   380  // this value as observed by calls in two different processes of the
   381  // same executable tells us the relative offset of their text segments.
   382  //
   383  // It would be nice if SetCrashOutput took care of this as it's fiddly
   384  // and likely to confuse every user at first.
   385  func sentinel() uint64 {
   386  	return uint64(reflect.ValueOf(sentinel).Pointer())
   387  }
   388  
   389  func writeSentinel(out io.Writer) {
   390  	fmt.Fprintf(out, "sentinel %x\n", sentinel())
   391  }
   392  
   393  // formatStack formats a stack of PC values using the symbol table,
   394  // redacting information that cannot be relied upon in the test.
   395  func formatStack(pcs []uintptr) string {
   396  	// When debugging, show file/line/content of files other than this one.
   397  	const debug = false
   398  
   399  	var buf strings.Builder
   400  	i := 0
   401  	frames := runtime.CallersFrames(pcs)
   402  	for {
   403  		fr, more := frames.Next()
   404  		if debug {
   405  			fmt.Fprintf(&buf, "pc=%x ", pcs[i])
   406  			i++
   407  		}
   408  		if base := filepath.Base(fr.File); base == "traceback_system_test.go" || debug {
   409  			content, err := os.ReadFile(fr.File)
   410  			if err != nil {
   411  				panic(err)
   412  			}
   413  			lines := bytes.Split(content, []byte("\n"))
   414  			fmt.Fprintf(&buf, "%s:%d: %s: %s\n", base, fr.Line, fr.Function, lines[fr.Line-1])
   415  		} else {
   416  			// For robustness, don't show file/line for functions from other files.
   417  			fmt.Fprintf(&buf, "redacted.go:0: %s\n", fr.Function)
   418  		}
   419  
   420  		if !more {
   421  			break
   422  		}
   423  	}
   424  	return buf.String()
   425  }
   426
View as plain text