[WIP] Improve acceptance test performance and reliability

.github/workflows/checks-codecov.yaml

@@ -109,18 +109,35 @@ jobs:
       - name: Checkout repository
         uses: actions/checkout@de0fac2e4500dabe0009e67214ff5f5447ce83dd # v6.0.2
 
-      - name: Restore Cache
-        uses: actions/cache/restore@668228422ae6a00e4ad889ee87cd7109ec5666a7 # v5.0.4
+      - name: Cache Go build and module artifacts
+        uses: actions/cache@668228422ae6a00e4ad889ee87cd7109ec5666a7 # v5.0.4
         with:
-          key: main
-          path: '**'
+          path: |
+            ~/.cache/go-build
+            ~/go/pkg/mod
+          key: go-acceptance-${{ runner.os }}-${{ hashFiles('go.sum', 'tools/go.sum', 'tools/kubectl/go.sum') }}
+          restore-keys: |
+            go-acceptance-${{ runner.os }}-
 
       - name: Setup Go environment
         uses: actions/setup-go@4b73464bb391d4059bd26b0524d20df3927bd417 # v6.3.0
         with:
           go-version-file: go.mod
           cache: false
 
+      - name: Install tkn CLI
+        run: |
+          TKN_VERSION=$(grep 'tektoncd/cli' tools/go.mod | awk '{print $2}' | sed 's/^v//')
+          curl -fsSL "https://github.com/tektoncd/cli/releases/download/v${TKN_VERSION}/tkn_${TKN_VERSION}_Linux_x86_64.tar.gz" \
+            | sudo tar xz -C /usr/local/bin tkn
+
+      - name: Install kubectl
+        run: |
+          KUBECTL_VERSION=$(grep 'k8s.io/kubernetes' tools/kubectl/go.mod | grep -oE 'v[0-9]+\.[0-9]+\.[0-9]+')
+          sudo curl -fsSL "https://dl.k8s.io/release/${KUBECTL_VERSION}/bin/linux/amd64/kubectl" \
+            -o /usr/local/bin/kubectl
+          sudo chmod +x /usr/local/bin/kubectl
+
       - name: Update podman
         run: |
           "${GITHUB_WORKSPACE}/hack/ubuntu-podman-update.sh"
@@ -132,6 +149,19 @@ jobs:
         id: acceptance_test
         run: E2E_INSTRUMENTATION=true make acceptance
 
+      - name: Print profiling report
+        if: always()
+        run: cat /tmp/ec-profile/report.txt 2>/dev/null || echo "No profiling report found"
+
+      - name: Upload profiling data
+        if: always()
+        uses: actions/upload-artifact@b7c566a772e6b6bfb58ed0dc250532a479d7789f # v6.0.0
+        with:
+          name: acceptance-profiling
+          path: /tmp/ec-profile/
+          retention-days: 7
+          if-no-files-found: ignore
+
       - name: Upload acceptance coverage artifact
         uses: actions/upload-artifact@b7c566a772e6b6bfb58ed0dc250532a479d7789f # v6.0.0
         with:

Makefile

@@ -121,17 +121,23 @@ ACCEPTANCE_TIMEOUT:=20m
 .PHONY: acceptance
 
 acceptance: ## Run all acceptance tests
-	@ACCEPTANCE_WORKDIR="$$(mktemp -d)"; \
+	@SECONDS=0; \
+	echo "[`date '+%H:%M:%S'`] Starting acceptance tests"; \
+	ACCEPTANCE_WORKDIR="$$(mktemp -d)"; \
 	cleanup() { \
 		cp "$${ACCEPTANCE_WORKDIR}"/features/__snapshots__/* "$(ROOT_DIR)"/features/__snapshots__/; \
 	}; \
 	mkdir -p "$${ACCEPTANCE_WORKDIR}/coverage"; \
 	trap cleanup EXIT; \
 	cp -R . "$$ACCEPTANCE_WORKDIR"; \
 	cd "$$ACCEPTANCE_WORKDIR" && \
-	$(MAKE) build && \
+	$(MAKE) build E2E_INSTRUMENTATION=true && \
+	echo "[`date '+%H:%M:%S'`] Build done, running tests"; \
 	export GOCOVERDIR="$${ACCEPTANCE_WORKDIR}/coverage"; \
-	cd acceptance && go test -timeout $(ACCEPTANCE_TIMEOUT) ./... ; go tool covdata textfmt -i=$${GOCOVERDIR} -o="$(ROOT_DIR)/coverage-acceptance.out"
+	cd acceptance && go test -timeout $(ACCEPTANCE_TIMEOUT) ./... && test_passed=1 || test_passed=0; \
+	echo "[`date '+%H:%M:%S'`] Tests finished in $$((SECONDS/60))m$$((SECONDS%60))s"; \
+	go tool covdata textfmt -i=$${GOCOVERDIR} -o="$(ROOT_DIR)/coverage-acceptance.out"; \
+	[ "$$test_passed" = "1" ]
 
 # Add @focus above the feature you're hacking on to use this
 # (Mainly for use with the feature-% target below)
@@ -340,9 +346,10 @@ TASKS ?= tasks/verify-enterprise-contract/0.1/verify-enterprise-contract.yaml,ta
 ifneq (,$(findstring localhost:,$(TASK_REPO)))
 SKOPEO_ARGS=--src-tls-verify=false --dest-tls-verify=false
 endif
+TKN ?= $(shell command -v tkn 2>/dev/null || echo "go run -modfile tools/go.mod github.com/tektoncd/cli/cmd/tkn")
 .PHONY: task-bundle
 task-bundle: ## Push the Tekton Task bundle to an image repository
-	@go run -modfile tools/go.mod github.com/tektoncd/cli/cmd/tkn bundle push $(TASK_REPO):$(TASK_TAG) $(addprefix -f ,$(TASKS)) --annotate org.opencontainers.image.revision="$(TASK_TAG)"
+	@$(TKN) bundle push $(TASK_REPO):$(TASK_TAG) $(addprefix -f ,$(TASKS)) --annotate org.opencontainers.image.revision="$(TASK_TAG)"
 
 .PHONY: task-bundle-snapshot
 task-bundle-snapshot: task-bundle ## Push task bundle and then tag with "snapshot"

acceptance/acceptance_test.go

@@ -20,6 +20,7 @@ import (
 	"context"
 	"flag"
 	"fmt"
+	"io"
 	"os"
 	"path/filepath"
 	"runtime"
@@ -28,6 +29,7 @@ import (
 
 	"github.com/cucumber/godog"
 	"github.com/gkampitakis/go-snaps/snaps"
+	"k8s.io/klog/v2"
 
 	"github.com/conforma/cli/acceptance/cli"
 	"github.com/conforma/cli/acceptance/conftest"
@@ -37,6 +39,7 @@ import (
 	"github.com/conforma/cli/acceptance/kubernetes"
 	"github.com/conforma/cli/acceptance/log"
 	"github.com/conforma/cli/acceptance/pipeline"
+	"github.com/conforma/cli/acceptance/profile"
 	"github.com/conforma/cli/acceptance/registry"
 	"github.com/conforma/cli/acceptance/rekor"
 	"github.com/conforma/cli/acceptance/tekton"
@@ -55,17 +58,23 @@ var restore = flag.Bool("restore", false, "restore last persisted environment")
 
 var noColors = flag.Bool("no-colors", false, "disable colored output")
 
+var verbose = flag.Bool("verbose", false, "show stdout/stderr in failure output")
+
 // specify a subset of scenarios to run filtering by given tags
 var tags = flag.String("tags", "", "select scenarios to run based on tags")
 
 // random seed to use
 var seed = flag.Int64("seed", -1, "random seed to use for the tests")
 
+// godog output formatter (pretty, progress, cucumber, junit, events)
+var format = flag.String("format", "", "godog output formatter (default: progress, or set EC_ACCEPTANCE_FORMAT)")
+
 // failedScenario tracks information about a failed scenario
 type failedScenario struct {
 	Name     string
 	Location string
 	Error    error
+	LogFile  string
 }
 
 // scenarioTracker tracks failed scenarios across all test runs
@@ -74,17 +83,18 @@ type scenarioTracker struct {
 	failedScenarios []failedScenario
 }
 
-func (st *scenarioTracker) addFailure(name, location string, err error) {
+func (st *scenarioTracker) addFailure(name, location, logFile string, err error) {
 	st.mu.Lock()
 	defer st.mu.Unlock()
 	st.failedScenarios = append(st.failedScenarios, failedScenario{
 		Name:     name,
 		Location: location,
 		Error:    err,
+		LogFile:  logFile,
 	})
 }
 
-func (st *scenarioTracker) printSummary(t *testing.T) {
+func (st *scenarioTracker) printSummary() {
 	st.mu.Lock()
 	defer st.mu.Unlock()
 
@@ -99,8 +109,8 @@ func (st *scenarioTracker) printSummary(t *testing.T) {
 	for i, fs := range st.failedScenarios {
 		fmt.Fprintf(os.Stderr, "%d. %s\n", i+1, fs.Name)
 		fmt.Fprintf(os.Stderr, "   Location: %s\n", fs.Location)
-		if fs.Error != nil {
-			fmt.Fprintf(os.Stderr, "   Error: %v\n", fs.Error)
+		if fs.LogFile != "" {
+			fmt.Fprintf(os.Stderr, "   Log file: %s\n", fs.LogFile)
 		}
 		if i < len(st.failedScenarios)-1 {
 			fmt.Fprintf(os.Stderr, "\n")
@@ -131,31 +141,23 @@ func initializeScenario(sc *godog.ScenarioContext) {
 	sc.Before(func(ctx context.Context, sc *godog.Scenario) (context.Context, error) {
 		logger, ctx := log.LoggerFor(ctx)
 		logger.Name(sc.Name)
+		ctx = profile.ScenarioStart(ctx)
 
 		return context.WithValue(ctx, testenv.Scenario, sc), nil
 	})
 
 	sc.After(func(ctx context.Context, scenario *godog.Scenario, scenarioErr error) (context.Context, error) {
-		// Log scenario end with status - write to /dev/tty to bypass capture
-		if tty, err := os.OpenFile("/dev/tty", os.O_WRONLY, 0); err == nil {
-			// Strip the working directory prefix to show relative paths
-			uri := scenario.Uri
-			if cwd, err := os.Getwd(); err == nil {
-				if rel, err := filepath.Rel(cwd, uri); err == nil {
-					uri = rel
-				}
-			}
-
-			if scenarioErr != nil {
-				fmt.Fprintf(tty, "✗ FAILED: %s (%s)\n", scenario.Name, uri)
-			} else {
-				fmt.Fprintf(tty, "✓ PASSED: %s (%s)\n", scenario.Name, uri)
-			}
-			tty.Close()
-		}
+		profile.ScenarioEnd(ctx, scenario.Name, scenario.Uri)
+		logger, ctx := log.LoggerFor(ctx)
+
+		logFile := logger.LogFile()
+		logger.Close()
 
 		if scenarioErr != nil {
-			tracker.addFailure(scenario.Name, scenario.Uri, scenarioErr)
+			tracker.addFailure(scenario.Name, scenario.Uri, logFile, scenarioErr)
+		} else {
+			// Clean up log files for passing scenarios
+			os.Remove(logFile)
 		}
 
 		_, err := testenv.Persist(ctx)
@@ -176,6 +178,7 @@ func setupContext(t *testing.T) context.Context {
 	ctx = context.WithValue(ctx, testenv.PersistStubEnvironment, *persist)
 	ctx = context.WithValue(ctx, testenv.RestoreStubEnvironment, *restore)
 	ctx = context.WithValue(ctx, testenv.NoColors, *noColors)
+	ctx = context.WithValue(ctx, testenv.VerboseOutput, *verbose)
 
 	return ctx
 }
@@ -196,8 +199,16 @@ func TestFeatures(t *testing.T) {
 
 	ctx := setupContext(t)
 
+	godogFormat := "progress:/dev/null"
+	if f := os.Getenv("EC_ACCEPTANCE_FORMAT"); f != "" {
+		godogFormat = f
+	}
+	if *format != "" {
+		godogFormat = *format
+	}
+
 	opts := godog.Options{
-		Format:         "pretty",
+		Format:         godogFormat,
 		Paths:          []string{featuresDir},
 		Randomize:      *seed,
 		Concurrency:    runtime.NumCPU(),
@@ -216,18 +227,26 @@ func TestFeatures(t *testing.T) {
 
 	exitCode := suite.Run()
 
-	// Print summary of failed scenarios
-	tracker.printSummary(t)
-
 	if exitCode != 0 {
-		// Exit directly without t.Fatal to avoid verbose Go test output
-		os.Exit(1)
+		t.Fatalf("acceptance test suite failed with exit code %d", exitCode)
 	}
 }
 
 func TestMain(t *testing.M) {
+	// Suppress k8s client-side throttling warnings that pollute test output.
+	// LogToStderr(false) is required because klog defaults to writing directly
+	// to stderr, ignoring any writer set via SetOutput.
+	klog.LogToStderr(false)
+	klog.SetOutput(io.Discard)
+
+	profile.Init()
+
 	v := t.Run()
 
+	// Print summaries after all go test output so they appear last
+	tracker.printSummary()
+	profile.Report()
+
 	// After all tests have run `go-snaps` can check for not used snapshots
 	snaps.Clean(t)
 

acceptance/cli/cli.go

@@ -560,7 +560,12 @@ func theStandardErrorShouldContain(ctx context.Context, expected *godog.DocStrin
 		return nil
 	}
 
-	return fmt.Errorf("expected error:\n%s\nnot found in standard error:\n%s", expected, stderr)
+	var b bytes.Buffer
+	if diffErr := diff.Text("stderr", "expected", status.stderr, expectedStdErr, &b); diffErr != nil {
+		return fmt.Errorf("expected error:\n%s\nnot found in standard error:\n%s", expected, stderr)
+	}
+
+	return fmt.Errorf("expected and actual stderr differ:\n%s", b.String())
 }
 
 // theStandardOutputShouldMatchBaseline reads the expected text from a file instead of directly
@@ -714,40 +719,44 @@ func EcStatusFrom(ctx context.Context) (*status, error) {
 // logExecution logs the details of the execution and offers hits as how to
 // troubleshoot test failures by using persistent environment
 func logExecution(ctx context.Context) {
-	noColors := testenv.NoColorOutput(ctx)
-	if c.SUPPORT_COLOR != !noColors {
-		c.SUPPORT_COLOR = !noColors
-	}
-
 	s, err := ecStatusFrom(ctx)
 	if err != nil {
 		return // the ec wasn't invoked no status was stored
 	}
 
-	output := &strings.Builder{}
-	outputSegment := func(name string, v any) {
-		output.WriteString("\n\n")
-		output.WriteString(c.Underline(c.Bold(name)))
-		output.WriteString(fmt.Sprintf("\n%v", v))
+	noColors := testenv.NoColorOutput(ctx)
+	if c.SUPPORT_COLOR != !noColors {
+		c.SUPPORT_COLOR = !noColors
 	}
 
-	outputSegment("Command", s.Cmd)
-	outputSegment("State", fmt.Sprintf("Exit code: %d\nPid: %d", s.ProcessState.ExitCode(), s.ProcessState.Pid()))
-	outputSegment("Environment", strings.Join(s.Env, "\n"))
-	var varsStr []string
-	for k, v := range s.vars {
-		varsStr = append(varsStr, fmt.Sprintf("%s=%s", k, v))
-	}
-	outputSegment("Variables", strings.Join(varsStr, "\n"))
-	if s.stdout.Len() == 0 {
-		outputSegment("Stdout", c.Italic("* No standard output"))
-	} else {
-		outputSegment("Stdout", c.Green(s.stdout.String()))
-	}
-	if s.stderr.Len() == 0 {
-		outputSegment("Stdout", c.Italic("* No standard error"))
-	} else {
-		outputSegment("Stderr", c.Red(s.stderr.String()))
+	verbose, _ := ctx.Value(testenv.VerboseOutput).(bool)
+	if verbose {
+		output := &strings.Builder{}
+		outputSegment := func(name string, v any) {
+			output.WriteString("\n\n")
+			output.WriteString(c.Underline(c.Bold(name)))
+			output.WriteString(fmt.Sprintf("\n%v", v))
+		}
+
+		outputSegment("Command", s.Cmd)
+		outputSegment("State", fmt.Sprintf("Exit code: %d\nPid: %d", s.ProcessState.ExitCode(), s.ProcessState.Pid()))
+		outputSegment("Environment", strings.Join(s.Env, "\n"))
+		var varsStr []string
+		for k, v := range s.vars {
+			varsStr = append(varsStr, fmt.Sprintf("%s=%s", k, v))
+		}
+		outputSegment("Variables", strings.Join(varsStr, "\n"))
+		if s.stdout.Len() == 0 {
+			outputSegment("Stdout", c.Italic("* No standard output"))
+		} else {
+			outputSegment("Stdout", c.Green(s.stdout.String()))
+		}
+		if s.stderr.Len() == 0 {
+			outputSegment("Stderr", c.Italic("* No standard error"))
+		} else {
+			outputSegment("Stderr", c.Red(s.stderr.String()))
+		}
+		fmt.Print(output.String())
 	}
 
 	if testenv.Persisted(ctx) {
@@ -758,12 +767,11 @@ func logExecution(ctx context.Context) {
 			}
 		}
 
-		output.WriteString("\n" + c.Bold("NOTE") + ": " + fmt.Sprintf("The test environment is persisted, to recreate the failure run:\n%s %s\n\n", strings.Join(environment, " "), strings.Join(s.Cmd.Args, " ")))
+		fmt.Printf("\n%s: The test environment is persisted, to recreate the failure run:\n%s %s\n\n",
+			c.Bold("NOTE"), strings.Join(environment, " "), strings.Join(s.Cmd.Args, " "))
 	} else {
-		output.WriteString("\n" + c.Bold("HINT") + ": To recreate the failure re-run the test with `-args -persist` to persist the stubbed environment\n\n")
+		fmt.Printf("\n%s: To recreate the failure re-run the test with `-args -persist` to persist the stubbed environment, or `-args -verbose` for detailed execution output\n\n", c.Bold("HINT"))
 	}
-
-	fmt.Print(output.String())
 }
 
 func matchSnapshot(ctx context.Context) error {
@@ -852,7 +860,9 @@ func AddStepsTo(sc *godog.ScenarioContext) {
 	sc.Step(`^a file named "([^"]*)" containing$`, createGenericFile)
 	sc.Step(`^a track bundle file named "([^"]*)" containing$`, createTrackBundleFile)
 	sc.After(func(ctx context.Context, sc *godog.Scenario, err error) (context.Context, error) {
-		logExecution(ctx)
+		if err != nil {
+			logExecution(ctx)
+		}
 
 		return ctx, nil
 	})