Skip to content

Improve acceptance tests logging #3098

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
st3penta wants to merge 1 commit into
base: main
Choose a base branch
from
Open

Improve acceptance tests logging #3098

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
82 changes: 80 additions & 2 deletions acceptance/acceptance_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,9 +19,11 @@ package acceptance
import (
"context"
"flag"
"fmt"
"os"
"path/filepath"
"runtime"
"sync"
"testing"

"github.com/cucumber/godog"
Expand Down Expand Up @@ -59,6 +61,56 @@ 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")

// failedScenario tracks information about a failed scenario
type failedScenario struct {
Name string
Location string
Error error
}

// scenarioTracker tracks failed scenarios across all test runs
type scenarioTracker struct {
mu sync.Mutex
failedScenarios []failedScenario
}

func (st *scenarioTracker) addFailure(name, location string, err error) {
st.mu.Lock()
defer st.mu.Unlock()
st.failedScenarios = append(st.failedScenarios, failedScenario{
Name: name,
Location: location,
Error: err,
})
}

func (st *scenarioTracker) printSummary(t *testing.T) {
st.mu.Lock()
defer st.mu.Unlock()

if len(st.failedScenarios) == 0 {
return
}

fmt.Fprintf(os.Stderr, "\n")
fmt.Fprintf(os.Stderr, "========================================\n")
fmt.Fprintf(os.Stderr, "FAILED SCENARIOS SUMMARY (%d)\n", len(st.failedScenarios))
fmt.Fprintf(os.Stderr, "========================================\n")
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 i < len(st.failedScenarios)-1 {
fmt.Fprintf(os.Stderr, "\n")
}
}
fmt.Fprintf(os.Stderr, "========================================\n")
}

var tracker = &scenarioTracker{}

// initializeScenario adds all steps and registers all hooks to the
// provided godog.ScenarioContext
func initializeScenario(sc *godog.ScenarioContext) {
Expand All @@ -80,10 +132,30 @@ func initializeScenario(sc *godog.ScenarioContext) {
logger, ctx := log.LoggerFor(ctx)
logger.Name(sc.Name)

// Log scenario start - write to /dev/tty to bypass all output capture
if tty, err := os.OpenFile("/dev/tty", os.O_WRONLY, 0); err == nil {
fmt.Fprintf(tty, "\n▶ STARTING: %s (%s)\n", sc.Name, sc.Uri)
tty.Close()
}

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 {
if scenarioErr != nil {
fmt.Fprintf(tty, "✗ FAILED: %s (%s)\n\n", scenario.Name, scenario.Uri)
} else {
fmt.Fprintf(tty, "✓ PASSED: %s (%s)\n\n", scenario.Name, scenario.Uri)
}
tty.Close()
}

if scenarioErr != nil {
tracker.addFailure(scenario.Name, scenario.Uri, scenarioErr)
}

_, err := testenv.Persist(ctx)
return ctx, err
})
Expand Down Expand Up @@ -139,8 +211,14 @@ func TestFeatures(t *testing.T) {
Options: &opts,
}

if suite.Run() != 0 {
t.Fatal("failure in acceptance tests")
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)
}
}

Expand Down
71 changes: 65 additions & 6 deletions acceptance/log/log.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@ package log
import (
"context"
"fmt"
"strings"
"sync/atomic"

"sigs.k8s.io/kind/pkg/log"
Expand Down Expand Up @@ -58,43 +59,101 @@ type logger struct {
t DelegateLogger
}

// shouldSuppress checks if a log message should be suppressed
// Suppresses verbose container operation logs to reduce noise
func shouldSuppress(msg string) bool {
suppressPatterns := []string{
"Creating container for image",
"Container created:",
"Starting container:",
"Container started:",
"Waiting for container id",
"Container is ready:",
"Skipping global cluster destruction",
"Released cluster to group",
"Destroying global cluster",
"Waiting for all consumers to finish",
"Last global cluster consumer finished",
}

for _, pattern := range suppressPatterns {
if strings.Contains(msg, pattern) {
return true
}
}
return false
}

// Log logs given arguments
func (l logger) Log(args ...any) {
l.t.Logf("(%010d: %s) %s", l.id, l.name, fmt.Sprint(args...))
msg := fmt.Sprint(args...)
if shouldSuppress(msg) {
return
}
l.t.Logf("(%010d: %s) %s", l.id, l.name, msg)
}

// Logf logs using given format and specified arguments
func (l logger) Logf(format string, args ...any) {
l.t.Logf("(%010d: %s) "+format, append([]any{l.id, l.name}, args...)...)
msg := fmt.Sprintf(format, args...)
if shouldSuppress(msg) {
return
}
l.t.Logf("(%010d: %s) %s", l.id, l.name, msg)
}

// Printf logs using given format and specified arguments
func (l logger) Printf(format string, args ...any) {
l.t.Logf("(%010d: %s) "+format, append([]any{l.id, l.name}, args...)...)
msg := fmt.Sprintf(format, args...)
if shouldSuppress(msg) {
return
}
l.t.Logf("(%010d: %s) %s", l.id, l.name, msg)
}

func (l logger) Warn(message string) {
if shouldSuppress(message) {
return
}
l.Logf("[WARN ] %s", message)
}

func (l logger) Warnf(format string, args ...any) {
l.Logf("[WARN ] "+format, args...)
msg := fmt.Sprintf(format, args...)
if shouldSuppress(msg) {
return
}
l.Logf("[WARN ] %s", msg)
}

func (l logger) Error(message string) {
if shouldSuppress(message) {
return
}
l.Logf("[ERROR] %s", message)
}

func (l logger) Errorf(format string, args ...any) {
l.Logf("[ERROR] "+format, args...)
msg := fmt.Sprintf(format, args...)
if shouldSuppress(msg) {
return
}
l.Logf("[ERROR] %s", msg)
}

func (l logger) Info(message string) {
if shouldSuppress(message) {
return
}
l.Logf("[INFO ] %s", message)
}

func (l logger) Infof(format string, args ...any) {
l.Logf("[INFO ] "+format, args...)
msg := fmt.Sprintf(format, args...)
if shouldSuppress(msg) {
return
}
l.Logf("[INFO ] %s", msg)
}

func (l logger) V(_ log.Level) log.InfoLogger {
Expand Down
Loading