cmd/test: Default -v traces show notes and fails

The default value for `--explain` was used when `--verbose`/`-v` was
specified. Now if only a verbose flag is specified we will show both
"fails" and "notes", which is most likely what someone would want
when troubleshooting some test failure.

Fixes: #2068
Signed-off-by: Patrick East <east.patrick@gmail.com>

cmd/test.go

@@ -11,14 +11,14 @@ import (
 	"time"
 
 	"github.com/open-policy-agent/opa/storage/inmem"
+	"github.com/open-policy-agent/opa/topdown/lineage"
 
 	"github.com/open-policy-agent/opa/bundle"
 
+	"github.com/spf13/cobra"
+
 	"github.com/open-policy-agent/opa/internal/runtime"
 	"github.com/open-policy-agent/opa/storage"
-	"github.com/open-policy-agent/opa/topdown/lineage"
-
-	"github.com/spf13/cobra"
 
 	"github.com/open-policy-agent/opa/ast"
 	"github.com/open-policy-agent/opa/cover"
@@ -32,7 +32,7 @@ const (
 	testJSONOutput   = "json"
 )
 
-var testParams = struct {
+type testCommandParams struct {
 	verbose      bool
 	explain      *util.EnumFlag
 	errLimit     int
@@ -47,11 +47,17 @@ var testParams = struct {
 	benchMem     bool
 	runRegex     string
 	count        int
-}{
-	outputFormat: util.NewEnumFlag(testPrettyOutput, []string{testPrettyOutput, testJSONOutput, benchmarkGoBenchOutput}),
-	explain:      newExplainFlag([]string{explainModeFails, explainModeFull, explainModeNotes}),
 }
 
+func newTestCommandParams() *testCommandParams {
+	return &testCommandParams{
+		outputFormat: util.NewEnumFlag(testPrettyOutput, []string{testPrettyOutput, testJSONOutput, benchmarkGoBenchOutput}),
+		explain:      newExplainFlag([]string{explainModeFails, explainModeFull, explainModeNotes}),
+	}
+}
+
+var testParams = newTestCommandParams()
+
 var testCommand = &cobra.Command{
 	Use:   "test <path> [path [...]]",
 	Short: "Execute Rego test cases",
@@ -274,12 +280,7 @@ func runTests(ctx context.Context, txn storage.Transaction, runner *tester.Runne
 			if !tr.Pass() {
 				exitCode = 2
 			}
-			switch testParams.explain.String() {
-			case explainModeNotes:
-				tr.Trace = lineage.Notes(tr.Trace)
-			case explainModeFails:
-				tr.Trace = lineage.Fails(tr.Trace)
-			}
+			tr.Trace = filterTrace(testParams, tr.Trace)
 			dup <- tr
 		}
 	}()
@@ -297,6 +298,34 @@ func runTests(ctx context.Context, txn storage.Transaction, runner *tester.Runne
 	return exitCode
 }
 
+func filterTrace(params *testCommandParams, trace []*topdown.Event) []*topdown.Event {
+	ops := map[topdown.Op]struct{}{}
+	mode := params.explain.String()
+
+	if mode == explainModeFull {
+		// Don't bother filtering anything
+		return trace
+	}
+
+	// If an explain mode was specified, filter based
+	// on the mode. If no explain mode was specified,
+	// default to show both notes and fail events
+	showDefault := !params.explain.IsSet() && params.verbose
+
+	if mode == explainModeNotes || showDefault {
+		ops[topdown.NoteOp] = struct{}{}
+	}
+
+	if mode == explainModeFails || showDefault {
+		ops[topdown.FailOp] = struct{}{}
+	}
+
+	return lineage.Filter(trace, func(event *topdown.Event) bool {
+		_, relevant := ops[event.Op]
+		return relevant
+	})
+}
+
 func init() {
 	testCommand.Flags().BoolVarP(&testParams.verbose, "verbose", "v", false, "set verbose reporting mode")
 	testCommand.Flags().BoolVarP(&testParams.failureLine, "show-failure-line", "l", false, "show test failure line")

cmd/test_test.go

@@ -0,0 +1,192 @@
+package cmd
+
+import (
+	"bytes"
+	"context"
+	"testing"
+
+	"github.com/open-policy-agent/opa/rego"
+	"github.com/open-policy-agent/opa/topdown"
+)
+
+func TestFilterTraceDefault(t *testing.T) {
+	p := newTestCommandParams()
+	p.verbose = false
+	expected := `Enter data.testing.test_p = _
+| Enter data.testing.test_p
+| | Enter data.testing.p
+| | | Enter data.testing.q
+| | | | Enter data.testing.r
+| | | | | Fail x = data.x
+| | | | Fail data.testing.r[x]
+| | | Fail data.testing.q.foo
+| | Fail data.testing.p with data.x as "bar"
+| Fail data.testing.test_p = _
+`
+	verifyFilteredTrace(t, p, expected)
+}
+
+func TestFilterTraceVerbose(t *testing.T) {
+	p := newTestCommandParams()
+	p.verbose = true
+	expected := `Enter data.testing.test_p = _
+| Enter data.testing.test_p
+| | Enter data.testing.p
+| | | Note "test test"
+| | | Enter data.testing.q
+| | | | Note "got this far"
+| | | | Enter data.testing.r
+| | | | | Note "got this far2"
+| | | | | Fail x = data.x
+| | | | Fail data.testing.r[x]
+| | | Fail data.testing.q.foo
+| | Fail data.testing.p with data.x as "bar"
+| Fail data.testing.test_p = _
+`
+	verifyFilteredTrace(t, p, expected)
+}
+
+func TestFilterTraceExplainFails(t *testing.T) {
+	p := newTestCommandParams()
+	p.explain.Set(explainModeFails)
+	expected := `Enter data.testing.test_p = _
+| Enter data.testing.test_p
+| | Enter data.testing.p
+| | | Enter data.testing.q
+| | | | Enter data.testing.r
+| | | | | Fail x = data.x
+| | | | Fail data.testing.r[x]
+| | | Fail data.testing.q.foo
+| | Fail data.testing.p with data.x as "bar"
+| Fail data.testing.test_p = _
+`
+	verifyFilteredTrace(t, p, expected)
+}
+
+func TestFilterTraceExplainNotes(t *testing.T) {
+	p := newTestCommandParams()
+	p.explain.Set(explainModeNotes)
+	expected := `Enter data.testing.test_p = _
+| Enter data.testing.test_p
+| | Enter data.testing.p
+| | | Note "test test"
+| | | Enter data.testing.q
+| | | | Note "got this far"
+| | | | Enter data.testing.r
+| | | | | Note "got this far2"
+`
+	verifyFilteredTrace(t, p, expected)
+}
+
+func TestFilterTraceExplainFull(t *testing.T) {
+	p := newTestCommandParams()
+	p.explain.Set(explainModeFull)
+	expected := `Enter data.testing.test_p = _
+| Eval data.testing.test_p = _
+| Index data.testing.test_p = _ (matched 1 rule)
+| Enter data.testing.test_p
+| | Eval data.testing.p with data.x as "bar"
+| | Index data.testing.p with data.x as "bar" (matched 1 rule)
+| | Enter data.testing.p
+| | | Eval data.testing.x
+| | | Index data.testing.x (matched 1 rule)
+| | | Enter data.testing.x
+| | | | Eval data.testing.y
+| | | | Index data.testing.y (matched 1 rule)
+| | | | Enter data.testing.y
+| | | | | Eval true
+| | | | | Exit data.testing.y
+| | | | Exit data.testing.x
+| | | Eval trace("test test")
+| | | Note "test test"
+| | | Eval data.testing.q.foo
+| | | Index data.testing.q.foo (matched 1 rule)
+| | | Enter data.testing.q
+| | | | Eval trace("got this far")
+| | | | Note "got this far"
+| | | | Eval data.testing.r[x]
+| | | | Index data.testing.r[__local0__] (matched 1 rule)
+| | | | Enter data.testing.r
+| | | | | Eval trace("got this far2")
+| | | | | Note "got this far2"
+| | | | | Eval x = data.x
+| | | | | Fail x = data.x
+| | | | | Redo trace("got this far2")
+| | | | Fail data.testing.r[x]
+| | | | Redo trace("got this far")
+| | | Fail data.testing.q.foo
+| | | Redo trace("test test")
+| | | Redo data.testing.x
+| | | Redo data.testing.x
+| | | | Redo data.testing.y
+| | | | Redo data.testing.y
+| | | | | Redo true
+| | Fail data.testing.p with data.x as "bar"
+| Fail data.testing.test_p = _
+`
+	verifyFilteredTrace(t, p, expected)
+}
+
+func verifyFilteredTrace(t *testing.T, params *testCommandParams, expected string) {
+	filtered := filterTrace(params, failTrace(t))
+
+	var buff bytes.Buffer
+	topdown.PrettyTrace(&buff, filtered)
+	actual := buff.String()
+
+	if actual != expected {
+		t.Fatalf("Expected:\n\n%s\n\nGot:\n\n%s\n\n", expected, actual)
+	}
+}
+
+func failTrace(t *testing.T) []*topdown.Event {
+	t.Helper()
+	mod := `
+	package testing
+	
+	p {
+		x  # Always true
+		trace("test test")
+		q["foo"]
+	}
+	
+	x {
+		y
+	}
+	
+	y {
+		true
+	}
+	
+	q[x] {
+		some x
+		trace("got this far")
+		r[x]
+		trace("got this far1")
+	}
+	
+	r[x] {
+		trace("got this far2")
+		x := data.x
+	}
+	
+	test_p {
+		p with data.x as "bar"
+	}
+	`
+
+	tracer := topdown.NewBufferTracer()
+
+	_, err := rego.New(
+		rego.Module("test.rego", mod),
+		rego.Trace(true),
+		rego.Tracer(tracer),
+		rego.Query("data.testing.test_p"),
+	).Eval(context.Background())
+
+	if err != nil {
+		t.Fatalf("Unexpected error: %s", err)
+	}
+
+	return *tracer
+}

topdown/lineage/lineage.go

@@ -11,20 +11,23 @@ import (
 // Notes returns a filtered trace that contains Note events and context to
 // understand where the Note was emitted.
 func Notes(trace []*topdown.Event) []*topdown.Event {
-	return filter(trace, func(event *topdown.Event) bool {
+	return Filter(trace, func(event *topdown.Event) bool {
 		return event.Op == topdown.NoteOp
 	})
 }
 
 // Fails returns a filtered trace that contains Fail events and context to
 // understand where the Fail occurred.
 func Fails(trace []*topdown.Event) []*topdown.Event {
-	return filter(trace, func(event *topdown.Event) bool {
+	return Filter(trace, func(event *topdown.Event) bool {
 		return event.Op == topdown.FailOp
 	})
 }
 
-func filter(trace []*topdown.Event, filter func(*topdown.Event) bool) (result []*topdown.Event) {
+// Filter will filter a given trace using the specified filter function. The
+// filtering function should return true for events that should be kept, false
+// for events that should be filtered out.
+func Filter(trace []*topdown.Event, filter func(*topdown.Event) bool) (result []*topdown.Event) {
 
 	qids := map[uint64]*topdown.Event{}