Merge pull request #21 from jaypipes/trace

rework debug/print into a tracing context

context/context.go

@@ -16,6 +16,7 @@ type ContextKey string
 
 var (
 	debugKey    = ContextKey("gdt.debug")
+	traceKey    = ContextKey("gdt.trace")
 	pluginsKey  = ContextKey("gdt.plugins")
 	fixturesKey = ContextKey("gdt.fixtures")
 	priorRunKey = ContextKey("gdt.run.prior")
@@ -41,11 +42,11 @@ type ContextModifier func(context.Context) context.Context
 //		   require.Nil(err)
 //
 //		   ctx := gdtcontext.New(gdtcontext.WithDebug())
-//	    s, err := scenario.FromReader(
-//	        f,
-//	        scenario.WithPath(fp),
-//	        scenario.WithContext(ctx),
-//	    )
+//	       s, err := scenario.FromReader(
+//	          f,
+//	          scenario.WithPath(fp),
+//	          scenario.WithContext(ctx),
+//	       )
 //		   require.Nil(err)
 //		   require.NotNil(s)
 //
@@ -154,6 +155,29 @@ func StorePriorRun(
 	return context.WithValue(ctx, priorRunKey, merged)
 }
 
+// PushTrace pushes a debug/trace name onto the debug/trace stack. It is used
+// by plugins to track where in the processing of a test or assertion the
+// plugin is and gets output at the start of a debug.Printf/Println message.
+func PushTrace(
+	ctx context.Context,
+	name string,
+) context.Context {
+	stack := TraceStack(ctx)
+	stack = append(stack, name)
+	return context.WithValue(ctx, traceKey, stack)
+}
+
+// PopTrace pops the last name off the debug/trace stack. It is used by plugins
+// to track where in the processing of a test or assertion the plugin is and
+// gets output at the start of a debug.Printf/Println message.
+func PopTrace(
+	ctx context.Context,
+) context.Context {
+	stack := TraceStack(ctx)
+	stack = stack[:len(stack)-1]
+	return context.WithValue(ctx, traceKey, stack)
+}
+
 // New returns a new Context
 func New(mods ...ContextModifier) context.Context {
 	ctx := context.TODO()

context/getter.go

@@ -7,19 +7,46 @@ package context
 import (
 	"context"
 	"io"
+	"strings"
 
 	gdttypes "github.com/gdt-dev/gdt/types"
 )
 
+const (
+	traceDelimiter = "/"
+)
+
+// Trace gets a context's trace name stack joined together with
+func Trace(ctx context.Context) string {
+	if ctx == nil {
+		return ""
+	}
+	if v := ctx.Value(traceKey); v != nil {
+		return strings.Join(v.([]string), traceDelimiter)
+	}
+	return ""
+}
+
+// TraceStack gets a context's trace name stack
+func TraceStack(ctx context.Context) []string {
+	if ctx == nil {
+		return []string{}
+	}
+	if v := ctx.Value(traceKey); v != nil {
+		return v.([]string)
+	}
+	return []string{}
+}
+
 // Debug gets a context's Debug writer
 func Debug(ctx context.Context) []io.Writer {
 	if ctx == nil {
-		return nil
+		return []io.Writer{}
 	}
 	if v := ctx.Value(debugKey); v != nil {
 		return v.([]io.Writer)
 	}
-	return nil
+	return []io.Writer{}
 }
 
 // Plugins gets a context's Plugins

debug/print.go

@@ -8,7 +8,6 @@ import (
 	"context"
 	"fmt"
 	"strings"
-	"testing"
 
 	gdtcontext "github.com/gdt-dev/gdt/context"
 )
@@ -17,19 +16,18 @@ import (
 // Debug output.
 func Printf(
 	ctx context.Context,
-	t *testing.T,
 	format string,
 	args ...interface{},
 ) {
-	t.Helper()
 	writers := gdtcontext.Debug(ctx)
 	if len(writers) == 0 {
 		return
 	}
-	t.Logf(format, args...)
+
+	trace := gdtcontext.Trace(ctx)
 
 	if !strings.HasPrefix(format, "[gdt] ") {
-		format = "[gdt] " + t.Name() + " " + format
+		format = "[gdt] [" + trace + "] " + format
 	}
 	msg := fmt.Sprintf(format, args...)
 	for _, w := range writers {
@@ -41,20 +39,18 @@ func Printf(
 // Debug output, ensuring there is a newline in the message line.
 func Println(
 	ctx context.Context,
-	t *testing.T,
 	format string,
 	args ...interface{},
 ) {
-	t.Helper()
 	writers := gdtcontext.Debug(ctx)
 	if len(writers) == 0 {
 		return
 	}
-	// NOTE(jaypipes): T.Logf() automatically adds newlines...
-	t.Logf(format, args...)
+
+	trace := gdtcontext.Trace(ctx)
 
 	if !strings.HasPrefix(format, "[gdt] ") {
-		format = "[gdt] " + t.Name() + " " + format
+		format = "[gdt] [" + trace + "] " + format
 	}
 	if !strings.HasSuffix(format, "\n") {
 		format += "\n"

plugin/exec/action.go

@@ -56,7 +56,7 @@ func (a *Action) Do(
 		args = []string{"-c", a.Exec}
 	}
 
-	debug.Println(ctx, t, "exec: %s %s", target, args)
+	debug.Println(ctx, "exec: %s %s", target, args)
 
 	var cmd *exec.Cmd
 	cmd = exec.CommandContext(ctx, target, args...)
@@ -80,13 +80,13 @@ func (a *Action) Do(
 	if outbuf != nil {
 		outbuf.ReadFrom(outpipe)
 		if outbuf.Len() > 0 {
-			debug.Println(ctx, t, "exec: stdout: %s", outbuf.String())
+			debug.Println(ctx, "exec: stdout: %s", outbuf.String())
 		}
 	}
 	if errbuf != nil {
 		errbuf.ReadFrom(errpipe)
 		if errbuf.Len() > 0 {
-			debug.Println(ctx, t, "exec: stderr: %s", errbuf.String())
+			debug.Println(ctx, "exec: stderr: %s", errbuf.String())
 		}
 	}
 

plugin/exec/assertions.go

@@ -47,10 +47,6 @@ type pipeAssertions struct {
 	name string
 	// failures contains the set of error messages for failed assertions.
 	failures []error
-	// terminal indicates there was a failure in evaluating the assertions that
-	// should be considered a terminal condition (and therefore the test action
-	// should not be retried).
-	terminal bool
 }
 
 // Fail appends a supplied error to the set of failed assertions
@@ -66,15 +62,6 @@ func (a *pipeAssertions) Failures() []error {
 	return a.failures
 }
 
-// Terminal returns a bool indicating the assertions failed in a way that is
-// not retryable.
-func (a *pipeAssertions) Terminal() bool {
-	if a == nil {
-		return false
-	}
-	return a.terminal
-}
-
 // OK checks all the assertions in the pipeAssertions against the supplied pipe
 // contents and returns true if all assertions pass.
 func (a *pipeAssertions) OK(ctx context.Context) bool {
@@ -130,10 +117,6 @@ func (a *pipeAssertions) OK(ctx context.Context) bool {
 type assertions struct {
 	// failures contains the set of error messages for failed assertions
 	failures []error
-	// terminal indicates there was a failure in evaluating the assertions that
-	// should be considered a terminal condition (and therefore the test action
-	// should not be retried).
-	terminal bool
 	// expExitCode contains the expected exit code
 	expExitCode int
 	// exitCode is the exit code we got from the execution
@@ -157,15 +140,6 @@ func (a *assertions) Failures() []error {
 	return a.failures
 }
 
-// Terminal returns a bool indicating the assertions failed in a way that is
-// not retryable.
-func (a *assertions) Terminal() bool {
-	if a == nil {
-		return false
-	}
-	return a.terminal
-}
-
 // OK checks all the assertions against the supplied arguments and returns true
 // if all assertions pass.
 func (a *assertions) OK(ctx context.Context) bool {

plugin/exec/eval.go

@@ -40,7 +40,7 @@ func (s *Spec) Eval(ctx context.Context, t *testing.T) *result.Result {
 				errbuf.Reset()
 				err := s.On.Fail.Do(ctx, t, outbuf, errbuf, nil)
 				if err != nil {
-					debug.Println(ctx, t, "error in on.fail.exec: %s", err)
+					debug.Println(ctx, "error in on.fail.exec: %s", err)
 				}
 			}
 		}

scenario/run.go

@@ -59,6 +59,10 @@ func (s *Scenario) Run(ctx context.Context, t *testing.T) error {
 		}
 	}
 	t.Run(s.Title(), func(t *testing.T) {
+		ctx = gdtcontext.PushTrace(ctx, s.Title())
+		defer func() {
+			ctx = gdtcontext.PopTrace(ctx)
+		}()
 		for _, spec := range s.Tests {
 			// Create a brand new context that inherits the top-level context's
 			// cancel func. We want to set deadlines for each test spec and if
@@ -70,7 +74,7 @@ func (s *Scenario) Run(ctx context.Context, t *testing.T) error {
 			sb := spec.Base()
 			wait := sb.Wait
 			if wait != nil && wait.Before != "" {
-				debug.Println(ctx, t, "wait: %s before", wait.Before)
+				debug.Println(ctx, "wait: %s before", wait.Before)
 				time.Sleep(wait.BeforeDuration())
 			}
 
@@ -93,7 +97,7 @@ func (s *Scenario) Run(ctx context.Context, t *testing.T) error {
 				ctx = gdtcontext.StorePriorRun(ctx, res.Data())
 			}
 			if wait != nil && wait.After != "" {
-				debug.Println(ctx, t, "wait: %s after", wait.After)
+				debug.Println(ctx, "wait: %s after", wait.After)
 				time.Sleep(wait.AfterDuration())
 			}
 		}
@@ -112,14 +116,14 @@ func specTimeout(
 ) *gdttypes.Timeout {
 	if specTimeout != nil {
 		debug.Println(
-			ctx, t, "using timeout of %s (expected: %t)",
+			ctx, "using timeout of %s (expected: %t)",
 			specTimeout.After, specTimeout.Expected,
 		)
 		return specTimeout
 	}
 	if scenDefaults != nil && scenDefaults.Timeout != nil {
 		debug.Println(
-			ctx, t, "using timeout of %s (expected: %t) [scenario default]",
+			ctx, "using timeout of %s (expected: %t) [scenario default]",
 			scenDefaults.Timeout.After, scenDefaults.Timeout.Expected,
 		)
 		return scenDefaults.Timeout

scenario/run_test.go

@@ -88,7 +88,7 @@ func TestDebugFlushing(t *testing.T) {
 	w.Flush()
 	require.NotEqual(b.Len(), 0)
 	debugout := b.String()
-	require.Contains(debugout, "TestDebugFlushing/foo-debug-wait-flush wait: 250ms before")
+	require.Contains(debugout, "[gdt] [foo-debug-wait-flush] wait: 250ms before")
 }
 
 func TestTimeoutCascade(t *testing.T) {

scenario/stub_plugins_test.go

@@ -223,7 +223,11 @@ func (s *fooSpec) UnmarshalYAML(node *yaml.Node) error {
 func (s *fooSpec) Eval(ctx context.Context, t *testing.T) *result.Result {
 	fails := []error{}
 	t.Run(s.Title(), func(t *testing.T) {
-		debug.Printf(ctx, t, "in %s Foo=%s", s.Title(), s.Foo)
+		ctx = gdtcontext.PushTrace(ctx, s.Title())
+		defer func() {
+			ctx = gdtcontext.PopTrace(ctx)
+		}()
+		debug.Println(ctx, "in %s Foo=%s", s.Title(), s.Foo)
 		// This is just a silly test to demonstrate how to write Eval() methods
 		// for plugin Spec specialization classes.
 		if s.Name == "bar" && s.Foo != "bar" {