From e3c62400822bfdeedfe3ed349c1f52b9f94b7521 Mon Sep 17 00:00:00 2001 From: Patrick East Date: Fri, 3 Apr 2020 16:43:27 -0700 Subject: [PATCH] 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 --- cmd/test.go | 55 ++++++++--- cmd/test_test.go | 192 +++++++++++++++++++++++++++++++++++++ topdown/lineage/lineage.go | 9 +- 3 files changed, 240 insertions(+), 16 deletions(-) create mode 100644 cmd/test_test.go diff --git a/cmd/test.go b/cmd/test.go index 66e4035661..67736889fa 100644 --- a/cmd/test.go +++ b/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 [...]]", 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") diff --git a/cmd/test_test.go b/cmd/test_test.go new file mode 100644 index 0000000000..924b94bc1a --- /dev/null +++ b/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 +} diff --git a/topdown/lineage/lineage.go b/topdown/lineage/lineage.go index 39a70f886a..393d1c38dc 100644 --- a/topdown/lineage/lineage.go +++ b/topdown/lineage/lineage.go @@ -11,7 +11,7 @@ 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 }) } @@ -19,12 +19,15 @@ func Notes(trace []*topdown.Event) []*topdown.Event { // 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{}