Repository: cockroachdb/pebble
Pull request #447 (2019-12-21 19:45:30)

internal/metamorphic: add -fail flag
Add a `-fail` flag which specifies a regular expression to match against
the the results of operations. When the regular expression matches, the
test is failed, saving the in-memory FS state to allow for post-mortem
debugging. This is useful for debugging problems that
non-deterministically fail in ways that are not detectable from an
individual test run. For example, we might uncover a failure in the
output between two tests, determine which of the two outputs is in
error, then add additional instrumentation to debug the erroneous
output. But if that erroneous output only occurs once out of every 100
runs reproduction becomes onerous. With the `-fail` flag you can specify
a regular expression to detect the erroneous output and run with:

  `-count 100 -fail <re>`


Patch:
diff --git a/internal/metamorphic/history.go b/internal/metamorphic/history.go
index 8a638c1f..3311b3be 100644
--- a/internal/metamorphic/history.go
+++ b/internal/metamorphic/history.go
@@ -8,6 +8,7 @@ import (
 	"fmt"
 	"io"
 	"log"
+	"regexp"
 	"strings"
 
 	"github.com/cockroachdb/pebble"
@@ -15,12 +16,17 @@ import (
 
 // history records the results of running a series of operations.
 type history struct {
-	log *log.Logger
-	seq int
+	failed bool
+	failRE *regexp.Regexp
+	log    *log.Logger
+	seq    int
 }
 
-func newHistory(writers ...io.Writer) *history {
+func newHistory(failRE string, writers ...io.Writer) *history {
 	h := &history{}
+	if len(failRE) > 0 {
+		h.failRE = regexp.MustCompile(failRE)
+	}
 	h.log = log.New(io.MultiWriter(writers...), "", 0)
 	return h
 }
@@ -38,7 +44,18 @@ func (h *history) Recordf(format string, args ...interface{}) {
 	// history output, which ruins the line number information in the diff
 	// output.
 	h.seq++
-	h.log.Print(fmt.Sprintf(format, args...) + fmt.Sprintf(" #%d", h.seq))
+	m := fmt.Sprintf(format, args...) + fmt.Sprintf(" #%d", h.seq)
+	h.log.Print(m)
+
+	if h.failRE != nil && h.failRE.MatchString(m) {
+		h.failed = true
+	}
+}
+
+// Failed returns true if the fail regular expression has matched the results
+// of an operation.
+func (h *history) Failed() bool {
+	return h.failed
 }
 
 // Logger returns a pebble.Logger that will output to history.


Test patch:
diff --git a/internal/metamorphic/history_test.go b/internal/metamorphic/history_test.go
index b6403761..46771fd9 100644
--- a/internal/metamorphic/history_test.go
+++ b/internal/metamorphic/history_test.go
@@ -7,11 +7,13 @@ package metamorphic
 import (
 	"bytes"
 	"testing"
+
+	"github.com/stretchr/testify/require"
 )
 
 func TestHistoryLogger(t *testing.T) {
 	var buf bytes.Buffer
-	h := newHistory(&buf)
+	h := newHistory("", &buf)
 	l := h.Logger()
 	l.Infof("hello\nworld\n")
 	l.Fatalf("hello\n\nworld")
@@ -26,3 +28,12 @@ func TestHistoryLogger(t *testing.T) {
 		t.Fatalf("expected\n%s\nbut found\n%s", expected, actual)
 	}
 }
+
+func TestHistoryFail(t *testing.T) {
+	var buf bytes.Buffer
+	h := newHistory("foo", &buf)
+	h.Recordf("bar")
+	require.False(t, h.Failed())
+	h.Recordf("foo bar")
+	require.True(t, h.Failed())
+}
diff --git a/internal/metamorphic/meta_test.go b/internal/metamorphic/meta_test.go
index b3374fc5..cc21e7e2 100644
--- a/internal/metamorphic/meta_test.go
+++ b/internal/metamorphic/meta_test.go
@@ -48,9 +48,11 @@ var (
 	compare = flag.Bool("compare", false, "")
 	dir     = flag.String("dir", "_meta", "")
 	disk    = flag.Bool("disk", false, "")
-	keep    = flag.Bool("keep", false, "")
-	ops     = randvar.NewFlag("uniform:5000-10000")
-	runDir  = flag.String("run-dir", "", "")
+	failRE  = flag.String("fail", "",
+		"fail the test if the supplied regular expression matches the output")
+	keep   = flag.Bool("keep", false, "")
+	ops    = randvar.NewFlag("uniform:5000-10000")
+	runDir = flag.String("run-dir", "", "")
 )
 
 func init() {
@@ -110,13 +112,18 @@ func testMetaRun(t *testing.T, runDir string) {
 	if testing.Verbose() {
 		writers = append(writers, os.Stdout)
 	}
-	h := newHistory(writers...)
+	h := newHistory(*failRE, writers...)
 
 	m := newTest(ops)
 	if err := m.init(h, opts.FS.PathJoin(runDir, "data"), opts); err != nil {
 		t.Fatal(err)
 	}
 	for m.step(h) {
+		if h.Failed() {
+			fmt.Fprintf(os.Stderr, "failure regex %q matched\n", *failRE)
+			m.maybeSaveData()
+			os.Exit(1)
+		}
 	}
 	m.finish(h)
 }
diff --git a/internal/metamorphic/test.go b/internal/metamorphic/test.go
index b4535f9e..a8991d06 100644
--- a/internal/metamorphic/test.go
+++ b/internal/metamorphic/test.go
@@ -20,6 +20,7 @@ type test struct {
 	ops []op
 	idx int
 	// The DB the test is run on.
+	dir    string
 	db     *pebble.DB
 	opts   *pebble.Options
 	tmpDir string
@@ -37,6 +38,7 @@ func newTest(ops []op) *test {
 }
 
 func (t *test) init(h *history, dir string, opts *pebble.Options) error {
+	t.dir = dir
 	t.opts = opts.EnsureDefaults()
 	t.opts.Logger = h.Logger()
 	t.opts.EventListener = pebble.MakeLoggingEventListener(t.opts.Logger)
@@ -47,20 +49,11 @@ func (t *test) init(h *history, dir string, opts *pebble.Options) error {
 	// the on-disk FS isn't desirable because there is a large performance
 	// difference between in-memory and on-disk which causes different code paths
 	// and timings to be exercised.
-	maybeSaveData := func() {
-		if t.opts.FS == vfs.Default {
-			return
-		}
-		_ = os.RemoveAll(dir)
-		if _, err := vfs.Clone(t.opts.FS, vfs.Default, dir, dir); err != nil {
-			t.opts.Logger.Infof("unable to clone: %s: %v", dir, err)
-		}
-	}
 	maybeExit := func(err error) {
 		if err == nil {
 			return
 		}
-		maybeSaveData()
+		t.maybeSaveData()
 		os.Exit(1)
 	}
 
@@ -119,6 +112,17 @@ func (t *test) init(h *history, dir string, opts *pebble.Options) error {
 	return nil
 }
 
+// If an in-memory FS is being used, save the contents to disk.
+func (t *test) maybeSaveData() {
+	if t.opts.FS == vfs.Default {
+		return
+	}
+	_ = os.RemoveAll(t.dir)
+	if _, err := vfs.Clone(t.opts.FS, vfs.Default, t.dir, t.dir); err != nil {
+		t.opts.Logger.Infof("unable to clone: %s: %v", t.dir, err)
+	}
+}
+
 func (t *test) step(h *history) bool {
 	if t.idx >= len(t.ops) {
 		return false