diff --git a/.gitignore b/.gitignore index 469fbd0..6556b58 100644 --- a/.gitignore +++ b/.gitignore @@ -15,6 +15,8 @@ custom-frontend integration-tests/screenshots/ integration-tests/flakey-test-runs.log integration-tests/flakey-test-runs.jsonl +service/flakey-test-runs.log +service/flakey-test-runs.jsonl .vscode/ webui/ server.log diff --git a/service/Makefile b/service/Makefile index 93b0d66..4855293 100644 --- a/service/Makefile +++ b/service/Makefile @@ -43,10 +43,22 @@ unittests: go test ./... -coverprofile reports/unittests.out go tool cover -html=reports/unittests.out -o reports/unittests.html +unittests-fast: + go test ./... -count=1 + +find-flakey-tests: + echo "Running unittests-fast infinitely" + sh -c "while $(MAKE) unittests-fast; do :; done" + +find-flakey-tests-inf: + go run ./scripts/find-flakey-tests-inf + go-tools: go install "github.com/fzipp/gocyclo/cmd/gocyclo" go install "github.com/go-critic/go-critic/cmd/gocritic" +.PHONY: unittests unittests-fast find-flakey-tests find-flakey-tests-inf + go-tools-all: go install "github.com/bufbuild/buf/cmd/buf" go install "github.com/fzipp/gocyclo/cmd/gocyclo" diff --git a/service/internal/api/api_log_arguments_test.go b/service/internal/api/api_log_arguments_test.go index 1b85f64..27f34cb 100644 --- a/service/internal/api/api_log_arguments_test.go +++ b/service/internal/api/api_log_arguments_test.go @@ -40,6 +40,22 @@ func waitForLogArguments(t *testing.T, ex *executor.Executor, trackingID string) return nil } +func waitForLogJustification(t *testing.T, ex *executor.Executor, trackingID, expected string) { + t.Helper() + + deadline := time.Now().Add(2 * time.Second) + for time.Now().Before(deadline) { + entry, ok := ex.GetLog(trackingID) + if ok && entry.Justification == expected { + return + } + + time.Sleep(5 * time.Millisecond) + } + + t.Fatalf("timed out waiting for justification %q on log %s", expected, trackingID) +} + func TestExecutionStatusIncludesStoredArguments(t *testing.T) { cfg := config.DefaultConfig() cfg.Actions = []*config.Action{ @@ -321,18 +337,14 @@ func TestRestartActionReusesStoredJustificationViaStartActionPath(t *testing.T) })) require.NoError(t, err) - originalLog, ok := ex.GetLog(startResp.Msg.ExecutionTrackingId) - require.True(t, ok) - assert.Equal(t, "maintenance window", originalLog.Justification) + waitForLogJustification(t, ex, startResp.Msg.ExecutionTrackingId, "maintenance window") restartResp, err := client.RestartAction(context.Background(), connect.NewRequest(&apiv1.RestartActionRequest{ ExecutionTrackingId: startResp.Msg.ExecutionTrackingId, })) require.NoError(t, err) - restartedLog, ok := ex.GetLog(restartResp.Msg.ExecutionTrackingId) - require.True(t, ok) - assert.Equal(t, "maintenance window", restartedLog.Justification) + waitForLogJustification(t, ex, restartResp.Msg.ExecutionTrackingId, "maintenance window") } func TestGetLogsIncludesStoredArguments(t *testing.T) { diff --git a/service/scripts/find-flakey-tests-inf/main.go b/service/scripts/find-flakey-tests-inf/main.go new file mode 100644 index 0000000..efeb33b --- /dev/null +++ b/service/scripts/find-flakey-tests-inf/main.go @@ -0,0 +1,304 @@ +package main + +import ( + "bufio" + "encoding/json" + "fmt" + "os" + "os/exec" + "path/filepath" + "strings" + "time" + + log "github.com/sirupsen/logrus" +) + +const ( + defaultLogFile = "flakey-test-runs.log" + defaultJSONLFile = "flakey-test-runs.jsonl" +) + +type testEvent struct { + Time time.Time `json:"Time"` + Action string `json:"Action"` + Package string `json:"Package"` + Test string `json:"Test"` + Output string `json:"Output"` + Elapsed float64 `json:"Elapsed"` +} + +type testFailure struct { + Package string `json:"package"` + Test string `json:"test"` + Output string `json:"output"` +} + +type runSummary struct { + Passes int `json:"passes"` + Failures int `json:"failures"` + Skipped int `json:"skipped"` +} + +type jsonlRecord struct { + Run int `json:"run"` + Timestamp string `json:"timestamp"` + ExitCode int `json:"exitCode"` + DurationMs int64 `json:"durationMs"` + Passes int `json:"passes"` + Failures int `json:"failures"` + Skipped int `json:"skipped"` + FailureDetails []testFailure `json:"failureDetails"` +} + +func initLog() { + logFormat := os.Getenv("OLIVETIN_LOG_FORMAT") + + if logFormat == "json" { + log.SetFormatter(&log.JSONFormatter{}) + } else { + log.SetFormatter(&log.TextFormatter{ + FullTimestamp: true, + ForceQuote: true, + }) + } + + log.SetLevel(log.InfoLevel) +} + +func serviceRoot() string { + exe, err := os.Executable() + if err == nil { + candidate := filepath.Join(filepath.Dir(exe), "..", "..") + if stat, statErr := os.Stat(filepath.Join(candidate, "go.mod")); statErr == nil && !stat.IsDir() { + return candidate + } + } + + wd, err := os.Getwd() + if err != nil { + return "." + } + + if stat, statErr := os.Stat(filepath.Join(wd, "go.mod")); statErr == nil && !stat.IsDir() { + return wd + } + + return filepath.Join(wd, "..") +} + +func envOrDefault(name, fallback string) string { + if value := strings.TrimSpace(os.Getenv(name)); value != "" { + return value + } + return fallback +} + +func formatFailure(failure testFailure) string { + lines := []string{ + fmt.Sprintf("FAILURE: %s", failure.Test), + fmt.Sprintf(" package: %s", failure.Package), + } + + output := strings.TrimSpace(failure.Output) + if output == "" { + output = "unknown" + } + lines = append(lines, fmt.Sprintf(" output: %s", output)) + + return strings.Join(lines, "\n") +} + +func formatRunCounts(summary runSummary) string { + return fmt.Sprintf("%d pass %d fail %d skip", summary.Passes, summary.Failures, summary.Skipped) +} + +func appendRunLog(logFile, jsonlFile string, run, exitCode int, summary runSummary, failures []testFailure, durationMs int64) error { + timestamp := time.Now().UTC().Format(time.RFC3339) + passed := exitCode == 0 + result := "PASS" + if !passed { + result = "FAIL" + } + + block := []string{ + fmt.Sprintf( + "=== RUN %d | %s | %s | %d pass %d fail %d skip | %.1fs ===", + run, + timestamp, + result, + summary.Passes, + summary.Failures, + summary.Skipped, + float64(durationMs)/1000, + ), + } + + for _, failure := range failures { + block = append(block, formatFailure(failure)) + } + + block = append(block, "") + if err := appendFile(logFile, strings.Join(block, "\n")+"\n"); err != nil { + return err + } + + record := jsonlRecord{ + Run: run, + Timestamp: timestamp, + ExitCode: exitCode, + DurationMs: durationMs, + Passes: summary.Passes, + Failures: summary.Failures, + Skipped: summary.Skipped, + FailureDetails: failures, + } + + encoded, err := json.Marshal(record) + if err != nil { + return err + } + + return appendFile(jsonlFile, string(encoded)+"\n") +} + +func appendFile(path, content string) error { + file, err := os.OpenFile(path, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o644) + if err != nil { + return err + } + defer file.Close() + + _, err = file.WriteString(content) + return err +} + +func runTestsOnce(rootDir string) (int, runSummary, []testFailure, error) { + cmd := exec.Command("go", "test", "./...", "-count=1", "-json") + cmd.Dir = rootDir + + stdout, err := cmd.StdoutPipe() + if err != nil { + return 1, runSummary{}, nil, err + } + + if err := cmd.Start(); err != nil { + return 1, runSummary{}, nil, err + } + + summary := runSummary{} + failures := make([]testFailure, 0) + failureOutput := make(map[string]*strings.Builder) + + scanner := bufio.NewScanner(stdout) + scanner.Buffer(make([]byte, 0, 64*1024), 1024*1024) + for scanner.Scan() { + var event testEvent + if err := json.Unmarshal(scanner.Bytes(), &event); err != nil { + continue + } + + switch event.Action { + case "pass": + if event.Test != "" { + summary.Passes++ + } + case "fail": + if event.Test != "" { + summary.Failures++ + key := event.Package + "\x00" + event.Test + failures = append(failures, testFailure{ + Package: event.Package, + Test: event.Test, + Output: "", + }) + failureOutput[key] = &strings.Builder{} + } + case "skip": + if event.Test != "" { + summary.Skipped++ + } + case "output": + if event.Test == "" { + continue + } + key := event.Package + "\x00" + event.Test + if builder, ok := failureOutput[key]; ok { + builder.WriteString(event.Output) + } + } + } + + if err := scanner.Err(); err != nil { + return 1, summary, failures, err + } + + if err := cmd.Wait(); err != nil { + if exitErr, ok := err.(*exec.ExitError); ok { + for index := range failures { + key := failures[index].Package + "\x00" + failures[index].Test + if builder, ok := failureOutput[key]; ok { + failures[index].Output = strings.TrimSpace(builder.String()) + } + } + return exitErr.ExitCode(), summary, failures, nil + } + return 1, summary, failures, err + } + + return 0, summary, failures, nil +} + +func main() { + initLog() + + rootDir := serviceRoot() + logFile := envOrDefault("FLAKEY_LOG_FILE", filepath.Join(rootDir, defaultLogFile)) + jsonlFile := envOrDefault("FLAKEY_JSONL_FILE", filepath.Join(rootDir, defaultJSONLFile)) + + header := strings.Join([]string{ + fmt.Sprintf("# Flaky test run log started %s", time.Now().UTC().Format(time.RFC3339)), + fmt.Sprintf("# Log file: %s", logFile), + fmt.Sprintf("# JSONL file: %s", jsonlFile), + "", + }, "\n") + "\n" + + if err := os.WriteFile(logFile, []byte(header), 0o644); err != nil { + log.WithError(err).Fatal("failed to initialize log file") + } + if err := os.WriteFile(jsonlFile, nil, 0o644); err != nil { + log.WithError(err).Fatal("failed to initialize jsonl file") + } + + log.Infof("Logging flaky test runs to %s", logFile) + log.Infof("Structured run data: %s", jsonlFile) + + run := 0 + for { + run++ + + start := time.Now() + exitCode, summary, failures, err := runTestsOnce(rootDir) + durationMs := time.Since(start).Milliseconds() + + if err != nil { + log.WithError(err).Errorf("Run %d failed to execute: %s", run, formatRunCounts(summary)) + _ = appendRunLog(logFile, jsonlFile, run, 1, summary, failures, durationMs) + os.Exit(1) + } + + if logErr := appendRunLog(logFile, jsonlFile, run, exitCode, summary, failures, durationMs); logErr != nil { + log.WithError(logErr).Fatal("failed to append run log") + } + + result := "PASS" + if exitCode != 0 { + result = "FAIL" + } + log.Infof("Run %d: %s | %s (%.1fs) — logged", run, result, formatRunCounts(summary), float64(durationMs)/1000) + + if exitCode != 0 { + log.Errorf("Failure on run %d, stopping. See %s", run, logFile) + os.Exit(exitCode) + } + } +}