Repository: cockroachdb/pebble
Pull request #738 (2020-06-11 21:43:03)

internal/metamorphic: fail tests on calls to Fatalf
internal/metamorphic: fail tests on calls to Fatalf

Fail the entire test if Pebble calls Fatalf on its Logger. This matches
the current behavior of errors surfaced through the EventListener.
Also, improve some of the output in failure scenarios to make it easier
to find the root error.

db: fix mergingIter corner case surrounding range tombstones

The metamorphic tests were seeing a failure where a levelIter would seek
beyond the upper bound and return the file's RANGEDEL boundary instead
of nil. A subsequent Prev call would cause the mergingIter to switch to
a max heap. Because the levelIter had returned a RANGEDEL key instead of
a nil key, the mergingIter would try to back the levelIter up through
Prev calls, which triggered the levelIter bounds invariant check.

The symmetric problem existed for a direction change in the opposite
direction.

This change updates switchTo{Max,Min}Heap to use the appropriate
absolute-positioning methods on levelIters at a RANGEDEL boundary.

petermattis: 

<!-- Reviewable:start -->
This change is [<img src="https://reviewable.io/review_button.png" height="34" align="absmiddle" alt="Reviewable"/>](https://reviewable.io/reviews/cockroachdb/pebble/738)
<!-- Reviewable:end -->


Patch:
diff --git a/internal/metamorphic/history.go b/internal/metamorphic/history.go
index 3311b3be..64c6aaa1 100644
--- a/internal/metamorphic/history.go
+++ b/internal/metamorphic/history.go
@@ -10,13 +10,17 @@ import (
 	"log"
 	"regexp"
 	"strings"
+	"sync/atomic"
 
-	"github.com/cockroachdb/pebble"
+	"github.com/cockroachdb/errors"
 )
 
 // history records the results of running a series of operations.
+//
+// history also implements the pebble.Logger interface, outputting to a stdlib
+// logger, prefixing the log messages with "//"-style comments.
 type history struct {
-	failed bool
+	err    atomic.Value
 	failRE *regexp.Regexp
 	log    *log.Logger
 	seq    int
@@ -48,29 +52,21 @@ func (h *history) Recordf(format string, args ...interface{}) {
 	h.log.Print(m)
 
 	if h.failRE != nil && h.failRE.MatchString(m) {
-		h.failed = true
+		err := errors.Errorf("failure regexp %q matched output: %s", h.failRE, m)
+		h.err.Store(err)
 	}
 }
 
-// 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.
-func (h *history) Logger() pebble.Logger {
-	return &historyLogger{log: h.log}
-}
-
-// historyLogger is an implementation of the pebble.Logger interface which
-// outputs to a stdlib logger, prefixing the log messages with "//"-style
-// comments.
-type historyLogger struct {
-	log *log.Logger
+// Error returns an error if the test has failed from log output, either a
+// failure regexp match or a call to Fatalf.
+func (h *history) Error() error {
+	if v := h.err.Load(); v != nil {
+		return v.(error)
+	}
+	return nil
 }
 
-func (h *historyLogger) format(prefix, format string, args ...interface{}) string {
+func (h *history) format(prefix, format string, args ...interface{}) string {
 	var buf strings.Builder
 	orig := fmt.Sprintf(format, args...)
 	for _, line := range strings.Split(strings.TrimSpace(orig), "\n") {
@@ -83,12 +79,13 @@ func (h *historyLogger) format(prefix, format string, args ...interface{}) strin
 
 // Infof implements the pebble.Logger interface. Note that the output is
 // commented.
-func (h *historyLogger) Infof(format string, args ...interface{}) {
+func (h *history) Infof(format string, args ...interface{}) {
 	_ = h.log.Output(2, h.format("// INFO: ", format, args...))
 }
 
 // Fatalf implements the pebble.Logger interface. Note that the output is
 // commented.
-func (h *historyLogger) Fatalf(format string, args ...interface{}) {
+func (h *history) Fatalf(format string, args ...interface{}) {
 	_ = h.log.Output(2, h.format("// FATAL: ", format, args...))
+	h.err.Store(errors.Errorf(format, args...))
 }
diff --git a/internal/metamorphic/ops.go b/internal/metamorphic/ops.go
index 63f213af..6532312e 100644
--- a/internal/metamorphic/ops.go
+++ b/internal/metamorphic/ops.go
@@ -7,7 +7,6 @@ package metamorphic
 import (
 	"fmt"
 	"io"
-	"os"
 	"strings"
 
 	"github.com/cockroachdb/errors"
@@ -634,8 +633,7 @@ type dbRestartOp struct {
 func (o *dbRestartOp) run(t *test, h *history) {
 	if err := t.restartDB(); err != nil {
 		h.Recordf("%s // %v", o, err)
-		fmt.Fprintf(os.Stderr, "terminating since dbRestartOp returned err %s\n", err)
-		h.failed = true
+		h.err.Store(errors.Wrap(err, "dbRestartOp"))
 	} else {
 		h.Recordf("%s", o)
 	}
diff --git a/level_iter.go b/level_iter.go
index 513218d3..cb835860 100644
--- a/level_iter.go
+++ b/level_iter.go
@@ -335,10 +335,10 @@ func (l *levelIter) verify(key *InternalKey, val []byte) (*InternalKey, []byte)
 		// bounds as such keys are always range tombstones which will be skipped by
 		// the Iterator.
 		if l.lower != nil && key != l.smallestBoundary && l.cmp(key.UserKey, l.lower) < 0 {
-			l.logger.Fatalf("levelIter: lower bound violation: %s < %s\n%s", key, l.lower, debug.Stack())
+			l.logger.Fatalf("levelIter %s: lower bound violation: %s < %s\n%s", l.level, key, l.lower, debug.Stack())
 		}
 		if l.upper != nil && key != l.largestBoundary && l.cmp(key.UserKey, l.upper) > 0 {
-			l.logger.Fatalf("levelIter: upper bound violation: %s > %s\n%s", key, l.upper, debug.Stack())
+			l.logger.Fatalf("levelIter %s: upper bound violation: %s > %s\n%s", l.level, key, l.upper, debug.Stack())
 		}
 	}
 	return key, val
diff --git a/merging_iter.go b/merging_iter.go
index 3ff76f7a..8f7d3e19 100644
--- a/merging_iter.go
+++ b/merging_iter.go
@@ -366,7 +366,7 @@ func (m *mergingIter) switchToMinHeap() {
 		if l == cur {
 			continue
 		}
-		if l.iterKey == nil {
+		if l.iterKey == nil || l.iterKey.Kind() == base.InternalKeyKindRangeDelete {
 			if m.lower != nil {
 				l.iterKey, l.iterValue = l.iter.SeekGE(m.lower)
 			} else {
@@ -415,7 +415,7 @@ func (m *mergingIter) switchToMaxHeap() {
 		if l == cur {
 			continue
 		}
-		if l.iterKey == nil {
+		if l.iterKey == nil || l.iterKey.Kind() == base.InternalKeyKindRangeDelete {
 			if m.upper != nil {
 				l.iterKey, l.iterValue = l.iter.SeekLT(m.upper)
 			} else {


Test patch:
diff --git a/internal/metamorphic/history_test.go b/internal/metamorphic/history_test.go
index 46771fd9..b7f34ae7 100644
--- a/internal/metamorphic/history_test.go
+++ b/internal/metamorphic/history_test.go
@@ -14,9 +14,8 @@ import (
 func TestHistoryLogger(t *testing.T) {
 	var buf bytes.Buffer
 	h := newHistory("", &buf)
-	l := h.Logger()
-	l.Infof("hello\nworld\n")
-	l.Fatalf("hello\n\nworld")
+	h.Infof("hello\nworld\n")
+	h.Fatalf("hello\n\nworld")
 
 	expected := `// INFO: hello
 // INFO: world
@@ -33,7 +32,7 @@ func TestHistoryFail(t *testing.T) {
 	var buf bytes.Buffer
 	h := newHistory("foo", &buf)
 	h.Recordf("bar")
-	require.False(t, h.Failed())
+	require.NoError(t, h.Error())
 	h.Recordf("foo bar")
-	require.True(t, h.Failed())
+	require.EqualError(t, h.Error(), `failure regexp "foo" matched output: foo bar #2`)
 }
diff --git a/internal/metamorphic/meta_test.go b/internal/metamorphic/meta_test.go
index 94ded260..a6153798 100644
--- a/internal/metamorphic/meta_test.go
+++ b/internal/metamorphic/meta_test.go
@@ -117,10 +117,8 @@ func testMetaRun(t *testing.T, runDir string) {
 	m := newTest(ops)
 	require.NoError(t, m.init(h, opts.FS.PathJoin(runDir, "data"), testOpts))
 	for m.step(h) {
-		if h.Failed() {
-			if len(*failRE) > 0 {
-				fmt.Fprintf(os.Stderr, "failure regex %q matched\n", *failRE)
-			}
+		if err := h.Error(); err != nil {
+			fmt.Fprintln(os.Stderr, err)
 			m.maybeSaveData()
 			os.Exit(1)
 		}
diff --git a/internal/metamorphic/test.go b/internal/metamorphic/test.go
index 26d2769b..8dc17b5a 100644
--- a/internal/metamorphic/test.go
+++ b/internal/metamorphic/test.go
@@ -49,7 +49,7 @@ func (t *test) init(h *history, dir string, testOpts *testOptions) error {
 		t.writeOpts = pebble.Sync
 	}
 	t.opts = testOpts.opts.EnsureDefaults()
-	t.opts.Logger = h.Logger()
+	t.opts.Logger = h
 	t.opts.EventListener = pebble.MakeLoggingEventListener(t.opts.Logger)
 	t.opts.DebugCheck = func(db *pebble.DB) error {
 		// Wrap the ordinary DebugCheckLevels with retrying
@@ -71,6 +71,7 @@ func (t *test) init(h *history, dir string, testOpts *testOptions) error {
 			return
 		}
 		t.maybeSaveData()
+		fmt.Fprintln(os.Stderr, err)
 		os.Exit(1)
 	}
 
diff --git a/testdata/merging_iter b/testdata/merging_iter
index c3576e87..8f85bad6 100644
--- a/testdata/merging_iter
+++ b/testdata/merging_iter
@@ -444,3 +444,61 @@ b#0,1:1
 a#0,1:1
 a#2,1:2
 .
+
+# Verify the upper bound is respected when switching directions at a RANGEDEL
+# boundary.
+
+define
+L
+kq.RANGEDEL.100 p.RANGEDEL.72057594037927935
+kq.RANGEDEL.100:p
+L
+b.SET.90 o.SET.65
+b.SET.90:90 cat.SET.70:70 g.SET.80:80 o.SET.65:65
+L
+a.SET.41 z.RANGEDEL.72057594037927935
+a.SET.41:41 koujdlp.MERGE.37:37 ok.SET.46:46 v.SET.43:43 v.RANGEDEL.19:z
+----
+1:
+  000019:[kq#100,RANGEDEL-p#72057594037927935,RANGEDEL]
+2:
+  000020:[b#90,SET-o#65,SET]
+3:
+  000021:[a#41,SET-z#72057594037927935,RANGEDEL]
+
+iter
+set-bounds upper=n
+seek-ge krgywquurww
+prev
+----
+p#72057594037927935,15:
+kq#100,15:
+
+# Verify the lower bound is respected when switching directions at a RANGEDEL
+# boundary.
+
+define
+L
+a.SET.103 jyk.RANGEDEL.72057594037927935
+a.SET.103:103 imd.SET.793:793 iwoeionch.SET.792:792 c.RANGEDEL.101:jyk
+L
+b.SET.90 o.SET.65
+b.SET.90:90 cat.SET.70:70 g.SET.80:80 o.SET.65:65
+L
+all.SET.0 zk.SET.722
+all.SET.0:0 c.SET.0:0 zk.SET.722:722
+----
+1:
+  000022:[a#103,SET-jyk#72057594037927935,RANGEDEL]
+2:
+  000023:[b#90,SET-o#65,SET]
+3:
+  000024:[all#0,SET-zk#722,SET]
+
+iter
+set-bounds lower=cz upper=jd
+seek-lt jd
+next
+----
+iwoeionch#792,1:792
+jyk#72057594037927935,15: