feat(tests): add comprehensive logging for debugging fixtures and variable expansion

Added V(2)-V(6) level logging throughout fixture execution to aid debugging: build commands, variable expansion, working directory resolution, and template data transformations. Simplified build execution to run synchronously before fixtures instead of as a task dependency. Added test case documenting logging output.

Author: moshloop

fixtures/expand.go

@@ -3,6 +3,8 @@ package fixtures
 import (
 	"fmt"
 	"os"
+
+	"github.com/flanksource/commons/logger"
 )
 
 // ExpandVars replaces $VAR and ${VAR} references in s with values from vars.
@@ -11,7 +13,9 @@ import (
 func ExpandVars(s string, vars map[string]any) string {
 	return os.Expand(s, func(key string) string {
 		if v, ok := vars[key]; ok {
-			return fmt.Sprintf("%v", v)
+			val := fmt.Sprintf("%v", v)
+			logger.V(6).Infof("ExpandVars: $%s → %s", key, val)
+			return val
 		}
 		return "$" + key
 	})

fixtures/runner.go

@@ -2,6 +2,7 @@ package fixtures
 
 import (
 	"bytes"
+	"context"
 	"fmt"
 	"os"
 	"os/exec"
@@ -163,21 +164,15 @@ func (r *Runner) executeFixtures() (*FixtureGroup, error) {
 		Summary: Stats{},
 	}
 
-	// Check if any fixtures need build
+	// Run build command synchronously before any fixtures
 	buildCmd := r.getBuildCommand()
-	var buildTask *clicky.Task
-
-	// Create build task if needed (as dependency for other tasks)
 	if buildCmd != "" {
-		buildTypedTask := clicky.StartTask[bool](
-			fmt.Sprintf("Build: %s", buildCmd),
-			func(ctx flanksourceContext.Context, t *task.Task) (bool, error) {
-				err := r.executeBuildCommand(ctx, buildCmd)
-				return err == nil, err
-			},
-			clicky.WithTaskTimeout(5*time.Minute),
-		)
-		buildTask = buildTypedTask.Task
+		logger.V(2).Infof("Running build command: %s", buildCmd)
+		ctx := flanksourceContext.NewContext(context.Background())
+		if err := r.executeBuildCommand(ctx, buildCmd); err != nil {
+			return nil, fmt.Errorf("build failed, skipping all fixtures: %w", err)
+		}
+		logger.V(2).Infof("Build completed successfully")
 	}
 
 	// Create typed task group for fixture execution
@@ -188,7 +183,7 @@ func (r *Runner) executeFixtures() (*FixtureGroup, error) {
 		if node.Test != nil {
 			typedTask := fixtureGroup.Add(node.Test.String(), func(ctx flanksourceContext.Context, t *task.Task) (FixtureResult, error) {
 				return r.executeFixture(ctx, *node.Test)
-			}, clicky.WithDependencies(buildTask), clicky.WithTaskTimeout(2*time.Minute))
+			}, clicky.WithTaskTimeout(2*time.Minute))
 			taskToNodeMap[typedTask] = node
 		}
 	})

fixtures/testdata/logging-paths.md

@@ -0,0 +1,24 @@
+---
+exec: bash
+args: ["-c", "{{.cmd}}"]
+build: "echo build-ok"
+---
+
+## Build and variable expansion logging
+
+Exercises code paths that produce V(2)-V(6) log output.
+Run with -vvvvvv to see all levels.
+
+| Name | cmd | CEL Validation |
+|------|-----|----------------|
+| build ran | echo ok | exitCode == 0 |
+| expand exec var | echo $GOOS | stdout.trim() == GOOS |
+| expand arg var | echo $GIT_ROOT_DIR | stdout.trim() == GIT_ROOT_DIR |
+| expand multiple | echo $GOOS/$GOARCH | stdout.contains("/") |
+
+## CWD resolution logging
+
+| Name | cwd | cmd | CEL Validation |
+|------|-----|-----|----------------|
+| relative cwd | . | pwd | exitCode == 0 |
+| var in cwd | $GIT_ROOT_DIR | pwd | stdout.trim() == GIT_ROOT_DIR |

fixtures/types.go

@@ -6,13 +6,15 @@ import (
 	"os/exec"
 	"path/filepath"
 	"runtime"
+	"sort"
 	"strconv"
 	"strings"
 	"time"
 
 	"github.com/flanksource/clicky"
 	"github.com/flanksource/clicky/api"
 	"github.com/flanksource/clicky/task"
+	"github.com/flanksource/commons/logger"
 	"github.com/flanksource/gomplate/v3"
 )
 
@@ -170,6 +172,12 @@ func (e ExecFixtureBase) IsEmpty() bool {
 func (e ExecFixtureBase) Template(data map[string]any) (ExecFixtureBase, error) {
 	var err error
 
+	logger.V(5).Infof("Template data keys: %v", sortedKeys(data))
+
+	orig := e
+	origArgs := make([]string, len(e.Args))
+	copy(origArgs, e.Args)
+
 	e.Exec = ExpandVars(e.Exec, data)
 	if e.Exec, err = gomplate.RunTemplate(data, gomplate.Template{
 		Template: e.Exec,
@@ -200,9 +208,41 @@ func (e ExecFixtureBase) Template(data map[string]any) (ExecFixtureBase, error)
 			return ExecFixtureBase{}, err
 		}
 	}
+
+	// Log a single consolidated summary of all changed fields
+	if logger.IsLevelEnabled(4) {
+		var changes []string
+		if e.Exec != orig.Exec {
+			changes = append(changes, fmt.Sprintf("exec: %q→%q", orig.Exec, e.Exec))
+		}
+		if e.Build != orig.Build {
+			changes = append(changes, fmt.Sprintf("build: %q→%q", orig.Build, e.Build))
+		}
+		if e.CWD != orig.CWD {
+			changes = append(changes, fmt.Sprintf("cwd: %q→%q", orig.CWD, e.CWD))
+		}
+		for i, a := range e.Args {
+			if i < len(origArgs) && a != origArgs[i] {
+				changes = append(changes, fmt.Sprintf("args[%d]: %q→%q", i, origArgs[i], a))
+			}
+		}
+		if len(changes) > 0 {
+			logger.V(4).Infof("Template: %s", strings.Join(changes, ", "))
+		}
+	}
+
 	return e, nil
 }
 
+func sortedKeys(m map[string]any) []string {
+	keys := make([]string, 0, len(m))
+	for k := range m {
+		keys = append(keys, k)
+	}
+	sort.Strings(keys)
+	return keys
+}
+
 func (e ExecFixtureBase) AsMap() map[string]string {
 	envMap := map[string]string{}
 	if e.CWD != "" {
@@ -433,6 +473,14 @@ func (f FixtureResult) Pretty() api.Text {
 	isFailed := f.Status == task.StatusFAIL || f.Status == task.StatusERR || f.Status == task.StatusFailed
 	verbosity := clicky.Flags.LevelCount
 
+	if verbosity >= 2 && f.Command != "" {
+		cmd := f.Command
+		if f.CWD != "" {
+			cmd += " (cwd: " + relativePath(f.CWD) + ")"
+		}
+		t = t.Append("$ "+cmd, "text-gray-500")
+	}
+
 	if isFailed {
 		switch {
 		case verbosity >= 2:

fixtures/types/exec.go

@@ -50,6 +50,10 @@ func (e *ExecFixture) Run(ctx context.Context, fixture fixtures.FixtureTest, opt
 		rootDir = baseDir
 	}
 
+	if gitRoot != goRoot {
+		logger.V(3).Infof("Directories: base=%s git=%s go=%s root=%s", baseDir, gitRoot, goRoot, rootDir)
+	}
+
 	// Inject auto-injected vars into TemplateVars so they're available
 	// in both Template() expansion and CEL evaluation via AsMap()
 	if fixture.TemplateVars == nil {
@@ -88,6 +92,9 @@ func (e *ExecFixture) Run(ctx context.Context, fixture fixtures.FixtureTest, opt
 			workDir = filepath.Join(baseDir, exec.CWD)
 		}
 	}
+	if workDir != baseDir {
+		logger.V(3).Infof("WorkDir: %s (expanded from %s)", workDir, exec.CWD)
+	}
 
 	if exec.Env == nil {
 		exec.Env = make(map[string]any)
@@ -98,19 +105,6 @@ func (e *ExecFixture) Run(ctx context.Context, fixture fixtures.FixtureTest, opt
 		}
 	}
 
-	bash := clicky.Exec("bash", "-c").AsWrapper()
-
-	// Execute build command if specified (but skip it in task mode since build task handles it)
-	if exec.Build != "" {
-		logger.V(4).Infof("🔨 Build command: %s", exec.Build)
-
-		p, err := bash(exec.Build)
-		if err != nil {
-			return result.Errorf(err, "build failed: %s", p.Pretty().ANSI())
-		}
-
-	}
-
 	if exec.Exec == "" {
 		return result.Errorf(fmt.Errorf("no command specified"), "no command specified")
 	}
@@ -190,13 +184,16 @@ func ResolveWorkDir(fixture fixtures.FixtureTest, opts fixtures.RunOptions) stri
 
 	// Get the merged CWD (file-level frontmatter + test-level override)
 	cwd := fixture.ExecBase().CWD
+	var result string
 	if cwd == "" || cwd == "." {
-		return baseDir
-	}
-	if filepath.IsAbs(cwd) {
-		return cwd
+		result = baseDir
+	} else if filepath.IsAbs(cwd) {
+		result = cwd
+	} else {
+		result = filepath.Join(baseDir, cwd)
 	}
-	return filepath.Join(baseDir, cwd)
+	logger.V(4).Infof("ResolveWorkDir: opts.WorkDir=%s sourceDir=%s cwd=%s → %s", opts.WorkDir, fixture.SourceDir, cwd, result)
+	return result
 }
 
 // GetRequiredFields returns required fields