From 1886a278353d4a794e1daae2a96f7955a35dc601 Mon Sep 17 00:00:00 2001 From: Jay Pipes Date: Sat, 1 Jun 2024 07:50:23 -0400 Subject: [PATCH] rework debug/print into a tracing context Changes the way that `gdtcontext.WithDebug()` and `gdtdebug.Printf/ln` work to remove the dependence on a `*testing.T` argument and using a stack concept for tracing where in the test evaluation we are. Signed-off-by: Jay Pipes --- context/context.go | 34 +++++++++++++++++++++++++++++----- context/getter.go | 31 +++++++++++++++++++++++++++++-- debug/print.go | 16 ++++++---------- plugin/exec/action.go | 6 +++--- plugin/exec/assertions.go | 26 -------------------------- plugin/exec/eval.go | 2 +- scenario/run.go | 12 ++++++++---- scenario/run_test.go | 2 +- scenario/stub_plugins_test.go | 6 +++++- 9 files changed, 82 insertions(+), 53 deletions(-) diff --git a/context/context.go b/context/context.go index d666f45..6d7da7c 100644 --- a/context/context.go +++ b/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() diff --git a/context/getter.go b/context/getter.go index 019b93c..f4f666a 100644 --- a/context/getter.go +++ b/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 diff --git a/debug/print.go b/debug/print.go index 87567de..8aa9d28 100644 --- a/debug/print.go +++ b/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" diff --git a/plugin/exec/action.go b/plugin/exec/action.go index cadd4b8..da3f753 100644 --- a/plugin/exec/action.go +++ b/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()) } } diff --git a/plugin/exec/assertions.go b/plugin/exec/assertions.go index b72553a..6e361c2 100644 --- a/plugin/exec/assertions.go +++ b/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 { diff --git a/plugin/exec/eval.go b/plugin/exec/eval.go index 565ab16..36040cc 100644 --- a/plugin/exec/eval.go +++ b/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) } } } diff --git a/scenario/run.go b/scenario/run.go index c1fec8a..7baa5d6 100644 --- a/scenario/run.go +++ b/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 diff --git a/scenario/run_test.go b/scenario/run_test.go index 722313e..842461d 100644 --- a/scenario/run_test.go +++ b/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) { diff --git a/scenario/stub_plugins_test.go b/scenario/stub_plugins_test.go index e48fba1..70287cb 100644 --- a/scenario/stub_plugins_test.go +++ b/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" {