cmd/compile: attempt to deflake debug_test.go

Excluded when -short because it still runs relatively long,
but deflaked.

Removed timeouts from normal path and ensured that they were
not needed and that reference files did not change.

Use "tbreak" instead of "break" with gdb to reduce chance
of multiple hits on main.main.  (Seems not enough, but a
move in the right direction).

By default, testing ignores repeated lines that occur when
nexting.  This appears to sometimes be timing-dependent and
is the observed source of flakiness in testing so far.
Note that these can also be signs of a bug in the generated
debugging output, but it is one of the less-confusing bugs
that can occur.

By default, testing with gdb uses compilation with
inlining disabled to prevent dependence on library code
(it's a bug that library code is seen while Nexting, but
the bug is current behavior).

Also by default exclude all source files outside /testdata
to prevent accidental dependence on library code.  Note that
this is currently only applicable to dlv because (for the
debugging information we produce) gdb does not indicate a
change in the source file for inlined code.

Added flags -i and -r to make gdb testing compile with
inlining and be sensitive to repeats in the next stream.
This is for developer-testing and so we can describe these
problems in bug reports.

Updates #22206.

Change-Id: I9a30ebbc65aa0153fe77b1858cf19743bdc985e4
Reviewed-on: https://go-review.googlesource.com/69930
Run-TryBot: David Chase <drchase@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Russ Cox <rsc@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>

1 files changed, 120 insertions, 68 deletions

diff --git a/src/cmd/compile/internal/ssa/debug_test.go b/src/cmd/compile/internal/ssa/debug_test.go
index 975c1291a7..bc8512cb10 100644
--- a/src/cmd/compile/internal/ssa/debug_test.go
+++ b/src/cmd/compile/internal/ssa/debug_test.go
@@ -22,17 +22,21 @@ import (
 	"time"
 )
 
-var update = flag.Bool("u", false, "update debug_test reference files")
-var verbose = flag.Bool("v", false, "print more information about what's happening")
-var dryrun = flag.Bool("n", false, "just print the command line and first bits")
-var delve = flag.Bool("d", false, "use delve instead of gdb")
+var update = flag.Bool("u", false, "update test reference files")
+var verbose = flag.Bool("v", false, "print debugger interactions (very verbose)")
+var dryrun = flag.Bool("n", false, "just print the command line and first debugging bits")
+var delve = flag.Bool("d", false, "use Delve (dlv) instead of gdb, use dlv reverence files")
 var force = flag.Bool("f", false, "force run under not linux-amd64; also do not use tempdir")
 
+var repeats = flag.Bool("r", false, "detect repeats in debug steps and don't ignore them")
+var inlines = flag.Bool("i", false, "do inlining for gdb (makes testing flaky till inlining info is correct)")
+
 var hexRe = regexp.MustCompile("0x[a-zA-Z0-9]+")
 var numRe = regexp.MustCompile("-?[0-9]+")
 var stringRe = regexp.MustCompile("\"([^\\\"]|(\\.))*\"")
 
-var gdb = "gdb" // Might be "ggdb" on Darwin, because gdb no longer part of XCode
+var gdb = "gdb"      // Might be "ggdb" on Darwin, because gdb no longer part of XCode
+var debugger = "gdb" // For naming files, etc.
 
 // TestNexting go-builds a file, then uses a debugger (default gdb, optionally delve)
 // to next through the generated executable, recording each line landed at, and
@@ -42,6 +46,25 @@ var gdb = "gdb" // Might be "ggdb" on Darwin, because gdb no longer part of XCod
 // Flag -v is ever-so-slightly verbose.
 // Flag -n is for dry-run, and prints the shell and first debug commands.
 //
+// Because this test (combined with existing compiler deficiencies) is flaky,
+// for gdb-based testing by default inlining is disabled
+// (otherwise output depends on library internals)
+// and for both gdb and dlv by default repeated lines in the next stream are ignored
+// (because this appears to be timing-dependent in gdb, and the cleanest fix is in code common to gdb and dlv).
+//
+// Also by default, any source code outside of .../testdata/ is not mentioned
+// in the debugging histories.  This deals both with inlined library code once
+// the compiler is generating clean inline records, and also deals with
+// runtime code between return from main and process exit.  This is hidden
+// so that those files (in the runtime/library) can change without affecting
+// this test.
+//
+// These choices can be reversed with -i (inlining on) and -r (repeats detected) which
+// will also cause their own failures against the expected outputs.  Note that if the compiler
+// and debugger were behaving properly, the inlined code and repeated lines would not appear,
+// so the expected output is closer to what we hope to see, though it also encodes all our
+// current bugs.
+//
 // The file being tested may contain comments of the form
 // //DBG-TAG=(v1,v2,v3)
 // where DBG = {gdb,dlv} and TAG={dbg,opt}
@@ -60,12 +83,10 @@ var gdb = "gdb" // Might be "ggdb" on Darwin, because gdb no longer part of XCod
 // go test debug_test.go -args -u -d
 
 func TestNexting(t *testing.T) {
-	// Skip this test in an ordinary run.bash.  Too many things
-	// can cause it to break.
+	skipReasons := "" // Many possible skip reasons, list all that apply
 	if testing.Short() {
-		t.Skip("skipping in short mode; see issue #22206")
+		skipReasons = "not run in short mode; "
 	}
-
 	testenv.MustHaveGoBuild(t)
 
 	if !*delve && !*force && !(runtime.GOOS == "linux" && runtime.GOARCH == "amd64") {
@@ -75,37 +96,48 @@ func TestNexting(t *testing.T) {
 		// Various architectures tend to differ slightly sometimes, and keeping them
 		// all in sync is a pain for people who don't have them all at hand,
 		// so limit testing to amd64 (for now)
-
-		t.Skip("Skipped unless -d (delve), -f (force), or linux-amd64")
+		skipReasons += "not run unless linux-amd64 or -d or -f; "
 	}
 
 	if *delve {
+		debugger = "dlv"
 		_, err := exec.LookPath("dlv")
 		if err != nil {
-			t.Fatal("dlv specified on command line with -d but no dlv on path")
+			skipReasons += "not run because dlv (requested by -d option) not on path; "
 		}
 	} else {
 		_, err := exec.LookPath(gdb)
 		if err != nil {
 			if runtime.GOOS != "darwin" {
-				t.Skip("Skipped because gdb not available")
-			}
-			_, err = exec.LookPath("ggdb")
-			if err != nil {
-				t.Skip("Skipped because gdb (and also ggdb) not available")
+				skipReasons += "not run because gdb not on path; "
+			} else {
+				_, err = exec.LookPath("ggdb")
+				if err != nil {
+					skipReasons += "not run because gdb (and also ggdb) not on path; "
+				} else {
+					gdb = "ggdb"
+				}
 			}
-			gdb = "ggdb"
 		}
 	}
 
-	t.Run("dbg", func(t *testing.T) {
+	if skipReasons != "" {
+		t.Skip(skipReasons[:len(skipReasons)-2])
+	}
+
+	t.Run("dbg-"+debugger, func(t *testing.T) {
 		testNexting(t, "hist", "dbg", "-N -l")
 	})
-	t.Run("opt", func(t *testing.T) {
+	t.Run("opt-"+debugger, func(t *testing.T) {
 		// If this is test is run with a runtime compiled with -N -l, it is very likely to fail.
 		// This occurs in the noopt builders (for example).
 		if gogcflags := os.Getenv("GO_GCFLAGS"); *force || (!strings.Contains(gogcflags, "-N") && !strings.Contains(gogcflags, "-l")) {
-			testNexting(t, "hist", "opt", "")
+			if *delve || *inlines {
+				testNexting(t, "hist", "opt", "")
+			} else {
+				// For gdb, disable inlining so that a compiler test does not depend on library code.
+				testNexting(t, "hist", "opt", "-l")
+			}
 		} else {
 			t.Skip("skipping for unoptimized runtime")
 		}
@@ -115,12 +147,12 @@ func TestNexting(t *testing.T) {
 func testNexting(t *testing.T, base, tag, gcflags string) {
 	// (1) In testdata, build sample.go into sample
 	// (2) Run debugger gathering a history
-	// (3) Read expected history from testdata/sample.nexts
-	// optionally, write out testdata/sample.nexts
+	// (3) Read expected history from testdata/sample.<variant>.nexts
+	// optionally, write out testdata/sample.<variant>.nexts
 
 	exe := filepath.Join("testdata", base)
-	logbase := exe + "-" + tag
-	tmpbase := logbase + "-test"
+	logbase := exe + "." + tag
+	tmpbase := filepath.Join("testdata", "test-"+base+"."+tag)
 
 	if !*force {
 		tmpdir, err := ioutil.TempDir("", "debug_test")
@@ -141,15 +173,13 @@ func testNexting(t *testing.T, base, tag, gcflags string) {
 		runGo(t, "", "build", "-o", exe, "-gcflags", gcflags, filepath.Join("testdata", base+".go"))
 	}
 	var h1 *nextHist
-	var nextlog, tmplog string
+
+	nextlog := logbase + "-" + debugger + ".nexts"
+	tmplog := tmpbase + "-" + debugger + ".nexts"
 	if *delve {
 		h1 = dlvTest(tag, exe, 1000)
-		nextlog = logbase + ".delve-nexts"
-		tmplog = tmpbase + ".delve-nexts"
 	} else {
 		h1 = gdbTest(tag, exe, 1000)
-		nextlog = logbase + ".gdb-nexts"
-		tmplog = tmpbase + ".gdb-nexts"
 	}
 	if *dryrun {
 		fmt.Printf("# Tag for above is %s\n", tag)
@@ -176,12 +206,12 @@ func testNexting(t *testing.T, base, tag, gcflags string) {
 
 type dbgr interface {
 	start()
-	do(s string)
 	stepnext(s string) bool // step or next, possible with parameter, gets line etc.  returns true for success, false for unsure response
 	quit()
 	hist() *nextHist
 }
 
+// gdbTest runs the debugger test with gdb and returns the history
 func gdbTest(tag, executable string, maxNext int, args ...string) *nextHist {
 	dbg := newGdb(tag, executable, args...)
 	dbg.start()
@@ -197,6 +227,7 @@ func gdbTest(tag, executable string, maxNext int, args ...string) *nextHist {
 	return h
 }
 
+// dlvTest runs the debugger test with dlv and returns the history
 func dlvTest(tag, executable string, maxNext int, args ...string) *nextHist {
 	dbg := newDelve(tag, executable, args...)
 	dbg.start()
@@ -234,6 +265,7 @@ func runGo(t *testing.T, dir string, args ...string) string {
 	return stdout.String()
 }
 
+// tstring provides two strings, o (stdout) and e (stderr)
 type tstring struct {
 	o string
 	e string
@@ -245,13 +277,13 @@ func (t tstring) String() string {
 
 type pos struct {
 	line uint16
-	file uint8
+	file uint8 // Artifact of plans to implement differencing instead of calling out to diff.
 }
 
 type nextHist struct {
 	f2i   map[string]uint8
 	fs    []string
-	ps    []pos // TODO: plan to automatically do the minimum distance conversion between a reference and a run for nicer errors.
+	ps    []pos
 	texts []string
 	vars  [][]string
 }
@@ -310,7 +342,11 @@ func (h *nextHist) read(filename string) {
 	}
 }
 
-func (h *nextHist) add(file, line, text string) {
+func (h *nextHist) add(file, line, text string) bool {
+	// Only record source code in testdata unless the inlines flag is set
+	if !*inlines && !strings.Contains(file, "/testdata/") {
+		return false
+	}
 	fi := h.f2i[file]
 	if fi == 0 {
 		h.fs = append(h.fs, file)
@@ -327,9 +363,16 @@ func (h *nextHist) add(file, line, text string) {
 			panic(fmt.Sprintf("Non-numeric line: %s, error %v\n", line, err))
 		}
 	}
-	h.ps = append(h.ps, pos{line: uint16(li), file: fi})
-	h.texts = append(h.texts, text)
-	h.vars = append(h.vars, []string{})
+	l := len(h.ps)
+	p := pos{line: uint16(li), file: fi}
+
+	if l == 0 || *repeats || h.ps[l-1] != p {
+		h.ps = append(h.ps, p)
+		h.texts = append(h.texts, text)
+		h.vars = append(h.vars, []string{})
+		return true
+	}
+	return false
 }
 
 func (h *nextHist) addVar(text string) {
@@ -369,6 +412,9 @@ func (h *nextHist) equals(k *nextHist) bool {
 	return true
 }
 
+// canonFileName strips everything before "src/" from a filename.
+// This makes file names portable across different machines,
+// home directories, and temporary directories.
 func canonFileName(f string) string {
 	i := strings.Index(f, "/src/")
 	if i != -1 {
@@ -426,9 +472,13 @@ func (s *delveState) stepnext(ss string) bool {
 		s.file = fn
 		s.function = locations[1]
 		s.ioState.history.add(s.file, s.line, excerpt)
+		// TODO: here is where variable processing will be added.  See gdbState.stepnext as a guide.
+		// Adding this may require some amount of normalization so that logs are comparable.
 		return true
 	}
-	fmt.Printf("DID NOT MATCH EXPECTED NEXT OUTPUT\nO='%s'\nE='%s'\n", x.o, x.e)
+	if *verbose {
+		fmt.Printf("DID NOT MATCH EXPECTED NEXT OUTPUT\nO='%s'\nE='%s'\n", x.o, x.e)
+	}
 	return false
 }
 
@@ -445,16 +495,12 @@ func (s *delveState) start() {
 		panic(fmt.Sprintf("There was an error [start] running '%s', %v\n", line, err))
 	}
 	s.ioState.readExpecting(-1, 5000, "Type 'help' for list of commands.")
-	expect("Breakpoint [0-9]+ set at ", s.ioState.writeRead("b main.main\n"))
+	expect("Breakpoint [0-9]+ set at ", s.ioState.writeReadExpect("b main.main\n", "[(]dlv[)] "))
 	s.stepnext("c")
 }
 
 func (s *delveState) quit() {
-	s.do("q")
-}
-
-func (s *delveState) do(ss string) {
-	expect("", s.ioState.writeRead(ss+"\n"))
+	expect("", s.ioState.writeRead("q\n"))
 }
 
 /* Gdb */
@@ -493,7 +539,7 @@ func (s *gdbState) start() {
 	}
 	if *dryrun {
 		fmt.Printf("%s\n", asCommandLine("", s.cmd))
-		fmt.Printf("b main.main\n")
+		fmt.Printf("tbreak main.main\n")
 		fmt.Printf("%s\n", run)
 		return
 	}
@@ -502,7 +548,7 @@ func (s *gdbState) start() {
 		line := asCommandLine("", s.cmd)
 		panic(fmt.Sprintf("There was an error [start] running '%s', %v\n", line, err))
 	}
-	s.ioState.readExpecting(-1, 5000, "[(]gdb[)] ")
+	s.ioState.readExpecting(-1, -1, "[(]gdb[)] ")
 	x := s.ioState.writeReadExpect("b main.main\n", "[(]gdb[)] ")
 	expect("Breakpoint [0-9]+ at", x)
 	s.stepnext(run)
@@ -513,8 +559,11 @@ func (s *gdbState) stepnext(ss string) bool {
 	excerpts := s.atLineRe.FindStringSubmatch(x.o)
 	locations := s.funcFileLinePCre.FindStringSubmatch(x.o)
 	excerpt := ""
+	addedLine := false
 	if len(excerpts) == 0 && len(locations) == 0 {
-		fmt.Printf("DID NOT MATCH %s", x.o)
+		if *verbose {
+			fmt.Printf("DID NOT MATCH %s", x.o)
+		}
 		return false
 	}
 	if len(excerpts) > 0 {
@@ -531,16 +580,20 @@ func (s *gdbState) stepnext(ss string) bool {
 		s.line = locations[3]
 		s.file = fn
 		s.function = locations[1]
-		s.ioState.history.add(s.file, s.line, excerpt)
+		addedLine = s.ioState.history.add(s.file, s.line, excerpt)
 	}
 	if len(excerpts) > 0 {
 		if *verbose {
 			fmt.Printf("  %s\n", excerpts[2])
 		}
 		s.line = excerpts[2]
-		s.ioState.history.add(s.file, s.line, excerpt)
+		addedLine = s.ioState.history.add(s.file, s.line, excerpt)
 	}
 
+	if !addedLine {
+		// True if this was a repeat line
+		return true
+	}
 	// Look for //gdb-<tag>=(v1,v2,v3) and print v1, v2, v3
 	vars := varsToPrint(excerpt, "//gdb-"+s.tag+"=(")
 	for _, v := range vars {
@@ -550,7 +603,7 @@ func (s *gdbState) stepnext(ss string) bool {
 			substitutions = v[slashIndex:]
 			v = v[:slashIndex]
 		}
-		response := s.ioState.writeRead("p " + v + "\n").String()
+		response := s.ioState.writeReadExpect("p "+v+"\n", "[(]gdb[)] ").String()
 		// expect something like "$1 = ..."
 		dollar := strings.Index(response, "$")
 		cr := strings.Index(response, "\n")
@@ -583,6 +636,10 @@ func (s *gdbState) stepnext(ss string) bool {
 	return true
 }
 
+// varsToPrint takes a source code line, and extracts the comma-separated variable names
+// found between lookfor and the next ")".
+// For example, if line includes "... //gdb-foo=(v1,v2,v3)" and
+// lookfor="//gdb-foo=(", then varsToPrint returns ["v1", "v2", "v3"]
 func varsToPrint(line, lookfor string) []string {
 	var vars []string
 	if strings.Contains(line, lookfor) {
@@ -606,10 +663,6 @@ func (s *gdbState) quit() {
 	}
 }
 
-func (s *gdbState) do(ss string) {
-	expect("", s.ioState.writeRead(ss+"\n"))
-}
-
 type ioState struct {
 	stdout  io.ReadCloser
 	stderr  io.ReadCloser
@@ -685,10 +738,8 @@ func (s *ioState) hist() *nextHist {
 	return s.history
 }
 
-const (
-	interlineDelay = 300
-)
-
+// writeRead writes ss, then reads stdout and stderr, waiting 500ms to
+// be sure all the output has appeared.
 func (s *ioState) writeRead(ss string) tstring {
 	if *verbose {
 		fmt.Printf("=> %s", ss)
@@ -697,31 +748,32 @@ func (s *ioState) writeRead(ss string) tstring {
 	if err != nil {
 		panic(fmt.Sprintf("There was an error writing '%s', %v\n", ss, err))
 	}
-	return s.readWithDelay(-1, interlineDelay)
+	return s.readExpecting(-1, 500, "")
 }
 
-func (s *ioState) writeReadExpect(ss, expect string) tstring {
+// writeReadExpect writes ss, then reads stdout and stderr until something
+// that matches expectRE appears.  expectRE should not be ""
+func (s *ioState) writeReadExpect(ss, expectRE string) tstring {
 	if *verbose {
 		fmt.Printf("=> %s", ss)
 	}
+	if expectRE == "" {
+		panic("expectRE should not be empty; use .* instead")
+	}
 	_, err := io.WriteString(s.stdin, ss)
 	if err != nil {
 		panic(fmt.Sprintf("There was an error writing '%s', %v\n", ss, err))
 	}
-	return s.readExpecting(-1, interlineDelay, expect)
-}
-
-func (s *ioState) readWithDelay(millis, interlineTimeout int) tstring {
-	return s.readExpecting(millis, interlineTimeout, "")
+	return s.readExpecting(-1, -1, expectRE)
 }
 
-func (s *ioState) readExpecting(millis, interlineTimeout int, expected string) tstring {
+func (s *ioState) readExpecting(millis, interlineTimeout int, expectedRE string) tstring {
 	timeout := time.Millisecond * time.Duration(millis)
 	interline := time.Millisecond * time.Duration(interlineTimeout)
 	s.last = tstring{}
 	var re *regexp.Regexp
-	if expected != "" {
-		re = regexp.MustCompile(expected)
+	if expectedRE != "" {
+		re = regexp.MustCompile(expectedRE)
 	}
 loop:
 	for {