Add basic tracing support

Emit messages for four main steps of the evaluation process:

1. new expression (eval)
2. trying to evaluate a plugged expression (try)
3. successfully evaluated a plugged expression (success)
4. finished evaluating a query (finish)

Also refactored query interface slightly to take a params struct. This will be
a bit more future proof.

eval/compare.go

@@ -4,7 +4,10 @@
 
 package eval
 
-import "sort"
+import (
+	"fmt"
+	"sort"
+)
 
 // Compare returns 0 if a equals b, -1 if a is less than b, and 1 if b is than a.
 //
@@ -117,7 +120,8 @@ func Compare(a, b interface{}) int {
 			return 1
 		}
 	}
-	panic("unreachable")
+
+	panic(fmt.Sprintf("illegal arguments of type %T and type %T", a, b))
 }
 
 const (
@@ -144,5 +148,5 @@ func sortOrder(v interface{}) int {
 	case map[string]interface{}:
 		return objectSort
 	}
-	panic("unreachable")
+	panic(fmt.Sprintf("illegal argument of type %T", v))
 }

eval/topdown.go

@@ -19,32 +19,19 @@ type TopDownContext struct {
 	Index    int
 	Previous *TopDownContext
 	Store    Storage
+	Tracer   Tracer
 }
 
-// Current returns the current expression to evaluate.
-func (ctx *TopDownContext) Current() *opalog.Expr {
-	return ctx.Query[ctx.Index]
-}
-
-// Step returns a new context to evaluate the next expression.
-func (ctx *TopDownContext) Step() *TopDownContext {
-	return &TopDownContext{
-		Query:    ctx.Query,
-		Bindings: ctx.Bindings,
-		Index:    ctx.Index + 1,
-		Previous: ctx.Previous,
-		Store:    ctx.Store,
-	}
-}
-
-// Child returns a new context to evaluate a rule that was referenced by this context.
-func (ctx *TopDownContext) Child(rule *opalog.Rule, bindings *hashMap) *TopDownContext {
-	return &TopDownContext{
-		Query:    rule.Body,
-		Bindings: bindings,
-		Previous: ctx,
-		Store:    ctx.Store,
-	}
+// BindRef returns a new TopDownContext with bindings that map the reference to the value.
+func (ctx *TopDownContext) BindRef(ref opalog.Ref, value opalog.Value) *TopDownContext {
+	cpy := *ctx
+	cpy.Bindings = newHashMap()
+	ctx.Bindings.Iter(func(k opalog.Value, v opalog.Value) bool {
+		cpy.Bindings.Put(k, v)
+		return false
+	})
+	cpy.Bindings.Put(ref, value)
+	return &cpy
 }
 
 // BindVar returns a new TopDownContext with bindings that map the variable to the value.
@@ -88,18 +75,52 @@ func (ctx *TopDownContext) BindVar(variable opalog.Var, value opalog.Value) *Top
 	return &cpy
 }
 
-// BindRef returns a new TopDownContext with bindings that map the reference to the value.
-func (ctx *TopDownContext) BindRef(ref opalog.Ref, value opalog.Value) *TopDownContext {
+// Child returns a new context to evaluate a rule that was referenced by this context.
+func (ctx *TopDownContext) Child(rule *opalog.Rule, bindings *hashMap) *TopDownContext {
 	cpy := *ctx
-	cpy.Bindings = newHashMap()
-	ctx.Bindings.Iter(func(k opalog.Value, v opalog.Value) bool {
-		cpy.Bindings.Put(k, v)
-		return false
-	})
-	cpy.Bindings.Put(ref, value)
+	cpy.Query = rule.Body
+	cpy.Bindings = bindings
+	cpy.Previous = ctx
+	return &cpy
+}
+
+// Current returns the current expression to evaluate.
+func (ctx *TopDownContext) Current() *opalog.Expr {
+	return ctx.Query[ctx.Index]
+}
+
+// Step returns a new context to evaluate the next expression.
+func (ctx *TopDownContext) Step() *TopDownContext {
+	cpy := *ctx
+	cpy.Index++
 	return &cpy
 }
 
+func (ctx *TopDownContext) trace(f string, a ...interface{}) {
+	if ctx.Tracer == nil {
+		return
+	}
+	if ctx.Tracer.Enabled() {
+		ctx.Tracer.Trace(ctx, f, a...)
+	}
+}
+
+func (ctx *TopDownContext) traceEval() {
+	ctx.trace("Eval %v", ctx.Current())
+}
+
+func (ctx *TopDownContext) traceTry(expr *opalog.Expr) {
+	ctx.trace(" Try %v", expr)
+}
+
+func (ctx *TopDownContext) traceSuccess(expr *opalog.Expr) {
+	ctx.trace("  Success %v", expr)
+}
+
+func (ctx *TopDownContext) traceFinish() {
+	ctx.trace("   Finish %v", ctx.Bindings)
+}
+
 // TopDownIterator is the interface for processing contexts.
 type TopDownIterator func(*TopDownContext) error
 
@@ -110,19 +131,26 @@ func TopDown(ctx *TopDownContext, iter TopDownIterator) error {
 	return evalContext(ctx, iter)
 }
 
+// TopDownQueryParams defines input parameters for the query interface.
+type TopDownQueryParams struct {
+	Store  Storage
+	Tracer Tracer
+	Path   []string
+}
+
 // TopDownQuery returns the document identified by the path.
 //
 // If the storage node identified by the path is a collection of rules, then the TopDown
 // algorithm is run to generate the virtual document defined by the rules.
-func TopDownQuery(store Storage, path []string) (interface{}, error) {
+func TopDownQuery(params *TopDownQueryParams) (interface{}, error) {
 
 	var ref opalog.Ref
-	ref = append(ref, opalog.VarTerm(path[0]))
-	for _, v := range path[1:] {
+	ref = append(ref, opalog.VarTerm(params.Path[0]))
+	for _, v := range params.Path[1:] {
 		ref = append(ref, opalog.StringTerm(v))
 	}
 
-	node, err := store.Lookup(ref)
+	node, err := params.Store.Lookup(ref)
 	if err != nil {
 		return nil, err
 	}
@@ -136,11 +164,11 @@ func TopDownQuery(store Storage, path []string) (interface{}, error) {
 		// type. This is checked at compile time.
 		switch node[0].DocKind() {
 		case opalog.CompleteDoc:
-			return topDownQueryCompleteDoc(store, node)
+			return topDownQueryCompleteDoc(params, node)
 		case opalog.PartialObjectDoc:
-			return topDownQueryPartialObjectDoc(store, node)
+			return topDownQueryPartialObjectDoc(params, node)
 		case opalog.PartialSetDoc:
-			return topDownQueryPartialSetDoc(store, node)
+			return topDownQueryPartialSetDoc(params, node)
 		default:
 			return nil, fmt.Errorf("invalid document (kind: %v): %v", node[0].DocKind(), ref)
 		}
@@ -176,9 +204,12 @@ func dereferenceVar(v opalog.Var, ctx *TopDownContext) (interface{}, error) {
 func evalContext(ctx *TopDownContext, iter TopDownIterator) error {
 
 	if ctx.Index >= len(ctx.Query) {
+		ctx.traceFinish()
 		return iter(ctx)
 	}
 
+	ctx.traceEval()
+
 	if ctx.Current().Negated {
 		return evalContextNegated(ctx, iter)
 	}
@@ -193,16 +224,14 @@ func evalContext(ctx *TopDownContext, iter TopDownIterator) error {
 
 func evalContextNegated(ctx *TopDownContext, iter TopDownIterator) error {
 
-	negation := &TopDownContext{
-		Query:    opalog.Body([]*opalog.Expr{ctx.Current().Complement()}),
-		Bindings: ctx.Bindings,
-		Previous: ctx,
-		Store:    ctx.Store,
-	}
+	negation := *ctx
+	negation.Query = opalog.Body([]*opalog.Expr{ctx.Current().Complement()})
+	negation.Index = 0
+	negation.Previous = ctx
 
 	isDefined := false
 
-	err := evalContext(negation, func(*TopDownContext) error {
+	err := evalContext(&negation, func(*TopDownContext) error {
 		isDefined = true
 		return nil
 	})
@@ -224,7 +253,10 @@ func evalEq(ctx *TopDownContext, expr *opalog.Expr, iter TopDownIterator) error
 	a := operands[1].Value
 	b := operands[2].Value
 
-	return evalEqUnify(ctx, a, b, iter)
+	return evalEqUnify(ctx, a, b, func(ctx *TopDownContext) error {
+		ctx.traceSuccess(expr)
+		return iter(ctx)
+	})
 }
 
 func evalEqGround(ctx *TopDownContext, a opalog.Value, b opalog.Value, iter TopDownIterator) error {
@@ -481,6 +513,7 @@ func evalEqUnifyVar(ctx *TopDownContext, a opalog.Var, b opalog.Value, iter TopD
 
 func evalExpr(ctx *TopDownContext, iter TopDownIterator) error {
 	expr := plugExpr(ctx.Current(), ctx.Bindings)
+	ctx.traceTry(expr)
 	switch tt := expr.Terms.(type) {
 	case []*opalog.Term:
 		builtin := builtinFunctions[tt[0].Value.(opalog.Var)]
@@ -997,7 +1030,7 @@ func plugValue(v opalog.Value, bindings *hashMap) opalog.Value {
 	}
 }
 
-func topDownQueryCompleteDoc(store Storage, rules []*opalog.Rule) (interface{}, error) {
+func topDownQueryCompleteDoc(params *TopDownQueryParams, rules []*opalog.Rule) (interface{}, error) {
 
 	if len(rules) > 1 {
 		return nil, fmt.Errorf("multiple conflicting rules: %v", rules[0].Name)
@@ -1008,7 +1041,8 @@ func topDownQueryCompleteDoc(store Storage, rules []*opalog.Rule) (interface{},
 	ctx := &TopDownContext{
 		Query:    rule.Body,
 		Bindings: newHashMap(),
-		Store:    store,
+		Store:    params.Store,
+		Tracer:   params.Tracer,
 	}
 
 	isDefined := false
@@ -1026,15 +1060,16 @@ func topDownQueryCompleteDoc(store Storage, rules []*opalog.Rule) (interface{},
 	return valueToInterface(rule.Value.Value, ctx)
 }
 
-func topDownQueryPartialObjectDoc(store Storage, rules []*opalog.Rule) (interface{}, error) {
+func topDownQueryPartialObjectDoc(params *TopDownQueryParams, rules []*opalog.Rule) (interface{}, error) {
 
 	result := map[string]interface{}{}
 
 	for _, rule := range rules {
 		ctx := &TopDownContext{
 			Query:    rule.Body,
 			Bindings: newHashMap(),
-			Store:    store,
+			Store:    params.Store,
+			Tracer:   params.Tracer,
 		}
 		key := rule.Key.Value.(opalog.Var)
 		value := rule.Value.Value.(opalog.Var)
@@ -1062,13 +1097,14 @@ func topDownQueryPartialObjectDoc(store Storage, rules []*opalog.Rule) (interfac
 	return result, nil
 }
 
-func topDownQueryPartialSetDoc(store Storage, rules []*opalog.Rule) (interface{}, error) {
+func topDownQueryPartialSetDoc(params *TopDownQueryParams, rules []*opalog.Rule) (interface{}, error) {
 	result := []interface{}{}
 	for _, rule := range rules {
 		ctx := &TopDownContext{
 			Query:    rule.Body,
 			Bindings: newHashMap(),
-			Store:    store,
+			Store:    params.Store,
+			Tracer:   params.Tracer,
 		}
 		key := rule.Key.Value.(opalog.Var)
 		err := TopDown(ctx, func(ctx *TopDownContext) error {

eval/topdown_test.go

@@ -605,7 +605,7 @@ func runTopDownTestCase(t *testing.T, data map[string]interface{}, i int, note s
 	switch e := expected.(type) {
 
 	case error:
-		result, err := TopDownQuery(store, []string{"p"})
+		result, err := TopDownQuery(&TopDownQueryParams{Store: store, Path: []string{"p"}})
 		if err == nil {
 			t.Errorf("Test case %d (%v): expected error but got: %v", i+1, note, result)
 			return
@@ -616,7 +616,7 @@ func runTopDownTestCase(t *testing.T, data map[string]interface{}, i int, note s
 
 	case string:
 		expected := loadExpectedResult(e)
-		result, err := TopDownQuery(store, []string{"p"})
+		result, err := TopDownQuery(&TopDownQueryParams{Store: store, Path: []string{"p"}})
 		if err != nil {
 			t.Errorf("Test case %d (%v): unexpected error: %v", i+1, note, err)
 			return

eval/tracer.go

@@ -0,0 +1,38 @@
+// Copyright 2016 The OPA Authors.  All rights reserved.
+// Use of this source code is governed by an Apache2
+// license that can be found in the LICENSE file.
+
+package eval
+
+import (
+	"fmt"
+	"strings"
+)
+
+// Tracer defines the interface for tracing evaluation.
+type Tracer interface {
+
+	// Enabled returns true if the tracer is enabled.
+	Enabled() bool
+
+	// Trace emits a message if the tracer is enabled.
+	Trace(ctx *TopDownContext, f string, a ...interface{})
+}
+
+// StdoutTracer writes trace messages to stdout.
+type StdoutTracer struct{}
+
+// Enabled always returns true.
+func (t *StdoutTracer) Enabled() bool { return true }
+
+// Trace writes a trace message to stdout.
+func (t *StdoutTracer) Trace(ctx *TopDownContext, f string, a ...interface{}) {
+	var padding string
+	i := 0
+	for ; ctx != nil; ctx = ctx.Previous {
+		padding += strings.Repeat(" ", ctx.Index+i)
+		i++
+	}
+	f = padding + f + "\n"
+	fmt.Printf(f, a...)
+}