diff --git a/op-acceptor/config.go b/op-acceptor/config.go index 78899c0a..2b71abe4 100644 --- a/op-acceptor/config.go +++ b/op-acceptor/config.go @@ -15,29 +15,30 @@ import ( // Config holds the application configuration type Config struct { - TestDir string - ValidatorConfig string - TargetGate string - GatelessMode bool - GoBinary string - RunInterval time.Duration // Interval between test runs - RunOnce bool // Indicates if the service should exit after one test run - AllowSkips bool // Allow tests to be skipped instead of failing when preconditions are not met - DefaultTimeout time.Duration // Default timeout for individual tests, can be overridden by test config - Timeout time.Duration // Timeout for gateless mode tests (if specified) - LogDir string // Directory to store test logs - OutputRealtimeLogs bool // If enabled, test logs will be outputted in realtime - TestLogLevel string // Log level to be used for the tests - Orchestrator flags.OrchestratorType // Devstack orchestrator type - DevnetEnvURL string // URL or path to the devnet environment file - Serial bool // Whether to run tests serially instead of in parallel - Concurrency int // Number of concurrent test workers (0 = auto-determine) - ShowProgress bool // Whether to show periodic progress updates during test execution - ProgressInterval time.Duration // Interval between progress updates when ShowProgress is 'true' - FlakeShake bool // Enable flake-shake mode for test stability validation - FlakeShakeIterations int // Number of times to run each test in flake-shake mode - Log log.Logger - ExcludeGates []string // List of gate IDs whose tests should be excluded + TestDir string + ValidatorConfig string + TargetGate string + GatelessMode bool + GoBinary string + RunInterval time.Duration // Interval between test runs + RunOnce bool // Indicates if the service should exit after one test run + AllowSkips bool // Allow tests to be skipped instead of failing when preconditions are not met + DefaultTimeout time.Duration // Default timeout for individual tests, can be overridden by test config + Timeout time.Duration // Timeout for gateless mode tests (if specified) + LogDir string // Directory to store test logs + OutputRealtimeLogs bool // If enabled, test logs will be outputted in realtime + StripCodeLinePrefixes bool // If enabled, file:line prefixes will be stripped from test logs + TestLogLevel string // Log level to be used for the tests + Orchestrator flags.OrchestratorType // Devstack orchestrator type + DevnetEnvURL string // URL or path to the devnet environment file + Serial bool // Whether to run tests serially instead of in parallel + Concurrency int // Number of concurrent test workers (0 = auto-determine) + ShowProgress bool // Whether to show periodic progress updates during test execution + ProgressInterval time.Duration // Interval between progress updates when ShowProgress is 'true' + FlakeShake bool // Enable flake-shake mode for test stability validation + FlakeShakeIterations int // Number of times to run each test in flake-shake mode + Log log.Logger + ExcludeGates []string // List of gate IDs whose tests should be excluded } // NewConfig creates a new Config from cli context @@ -114,29 +115,30 @@ func NewConfig(ctx *cli.Context, log log.Logger, testDir string, validatorConfig } return &Config{ - TestDir: absTestDir, - ValidatorConfig: absValidatorConfig, - TargetGate: gate, - GatelessMode: gatelessMode, - GoBinary: ctx.String(flags.GoBinary.Name), - RunInterval: runInterval, - RunOnce: runOnce, - AllowSkips: ctx.Bool(flags.AllowSkips.Name), - DefaultTimeout: ctx.Duration(flags.DefaultTimeout.Name), - Timeout: ctx.Duration(flags.Timeout.Name), - OutputRealtimeLogs: ctx.Bool(flags.OutputRealtimeLogs.Name), - TestLogLevel: ctx.String(flags.TestLogLevel.Name), - Orchestrator: orchestrator, - DevnetEnvURL: devnetEnvURL, - Serial: ctx.Bool(flags.Serial.Name), - Concurrency: ctx.Int(flags.Concurrency.Name), - ShowProgress: ctx.Bool(flags.ShowProgress.Name), - ProgressInterval: ctx.Duration(flags.ProgressInterval.Name), - FlakeShake: ctx.Bool(flags.FlakeShake.Name), - FlakeShakeIterations: ctx.Int(flags.FlakeShakeIterations.Name), - LogDir: logDir, - Log: log, - ExcludeGates: excludeGates, + TestDir: absTestDir, + ValidatorConfig: absValidatorConfig, + TargetGate: gate, + GatelessMode: gatelessMode, + GoBinary: ctx.String(flags.GoBinary.Name), + RunInterval: runInterval, + RunOnce: runOnce, + AllowSkips: ctx.Bool(flags.AllowSkips.Name), + DefaultTimeout: ctx.Duration(flags.DefaultTimeout.Name), + Timeout: ctx.Duration(flags.Timeout.Name), + OutputRealtimeLogs: ctx.Bool(flags.OutputRealtimeLogs.Name), + StripCodeLinePrefixes: ctx.Bool(flags.StripCodeLinePrefixes.Name), + TestLogLevel: ctx.String(flags.TestLogLevel.Name), + Orchestrator: orchestrator, + DevnetEnvURL: devnetEnvURL, + Serial: ctx.Bool(flags.Serial.Name), + Concurrency: ctx.Int(flags.Concurrency.Name), + ShowProgress: ctx.Bool(flags.ShowProgress.Name), + ProgressInterval: ctx.Duration(flags.ProgressInterval.Name), + FlakeShake: ctx.Bool(flags.FlakeShake.Name), + FlakeShakeIterations: ctx.Int(flags.FlakeShakeIterations.Name), + LogDir: logDir, + Log: log, + ExcludeGates: excludeGates, }, nil } diff --git a/op-acceptor/flags/flags.go b/op-acceptor/flags/flags.go index 4dc3cfe3..73498a3b 100644 --- a/op-acceptor/flags/flags.go +++ b/op-acceptor/flags/flags.go @@ -121,6 +121,12 @@ var ( EnvVars: opservice.PrefixEnvVar(EnvVarPrefix, "OUTPUT_REALTIME_LOGS"), Usage: "If enabled, test logs will be outputted to the console in realtime. Defaults to false.", } + StripCodeLinePrefixes = &cli.BoolFlag{ + Name: "strip-code-line-prefixes", + Value: true, + EnvVars: opservice.PrefixEnvVar(EnvVarPrefix, "STRIP_CODE_LINE_PREFIXES"), + Usage: "Strip file:line prefixes (e.g. 'test.go:123:') from test logs. Defaults to true.", + } ShowProgress = &cli.BoolFlag{ Name: "show-progress", Value: false, @@ -196,6 +202,7 @@ var optionalFlags = []cli.Flag{ LogDir, TestLogLevel, OutputRealtimeLogs, + StripCodeLinePrefixes, ShowProgress, ProgressInterval, Orchestrator, diff --git a/op-acceptor/logging/clean_log_output_test.go b/op-acceptor/logging/clean_log_output_test.go new file mode 100644 index 00000000..95409e38 --- /dev/null +++ b/op-acceptor/logging/clean_log_output_test.go @@ -0,0 +1,227 @@ +package logging + +import ( + "testing" + + "github.com/stretchr/testify/assert" +) + +func TestCleanLogOutput(t *testing.T) { + tests := []struct { + name string + input string + expected string + }{ + { + name: "empty string", + input: "", + expected: "", + }, + { + name: "simple text without special characters", + input: "hello world", + expected: "hello world", + }, + { + name: "text with leading and trailing whitespace", + input: " hello world ", + expected: "hello world", + }, + { + name: "text with multiple spaces", + input: "hello world", + expected: "hello world", + }, + { + name: "text with tabs", + input: "hello\t\tworld", + expected: "hello world", + }, + { + name: "text with newlines", + input: "hello\nworld", + expected: "hello world", + }, + { + name: "text with mixed whitespace", + input: "hello \t\n world", + expected: "hello world", + }, + { + name: "file:line prefix simple", + input: "test.go:123: error message", + expected: "error message", + }, + { + name: "file:line prefix with underscore", + input: "da_footprint_test.go:188: some log output", + expected: "some log output", + }, + { + name: "file:line prefix with leading whitespace", + input: " test_file.go:456: message here", + expected: "message here", + }, + { + name: "file:line prefix with hyphen", + input: "my-file.go:99: content", + expected: "content", + }, + { + name: "ANSI color codes", + input: "\x1b[31mred text\x1b[0m", + expected: "red text", + }, + { + name: "ANSI codes with other formatting", + input: "\x1b[1;32mbold green\x1b[0m normal", + expected: "bold green normal", + }, + { + name: "combination: file prefix, ANSI codes, and whitespace", + input: " test.go:42: \x1b[31m error: failed\x1b[0m ", + expected: "error: failed", + }, + { + name: "combination: multiple whitespace types", + input: "test.go:1: hello\t\t world \n foo", + expected: "hello world foo", + }, + { + name: "text that looks like but isn't a file:line prefix", + input: "this is not file.go:123: a prefix because text comes before", + expected: "this is not file.go:123: a prefix because text comes before", + }, + { + name: "multiple lines with different prefixes", + input: "file1.go:10: first line\nfile2.go:20: second line", + expected: "first line file2.go:20: second line", + }, + { + name: "no file extension in prefix", + input: "file:123: should not match", + expected: "file:123: should not match", + }, + { + name: "wrong extension in prefix", + input: "file.txt:123: should not match", + expected: "file.txt:123: should not match", + }, + { + name: "real-world example with geth logger output", + input: " da_test.go:188: \x1b[36mINFO\x1b[0m [01-01|00:00:00.000] Transaction submitted hash=0x123", + expected: "INFO [01-01|00:00:00.000] Transaction submitted hash=0x123", + }, + { + name: "multiple consecutive newlines", + input: "line1\n\n\nline2", + expected: "line1 line2", + }, + { + name: "only whitespace", + input: " \t\n ", + expected: "", + }, + { + name: "unicode characters preserved", + input: "hello δΈ–η•Œ 🌍", + expected: "hello δΈ–η•Œ 🌍", + }, + { + name: "file prefix at start preserves rest of content", + input: "test.go:1: key=value another=thing", + expected: "key=value another=thing", + }, + { + name: "real log from da_footprint_test", + input: " da_footprint_test.go:188: INFO [10-29|23:42:54.881] \"Block 0xbf9f2a47f13a639f439c3bb04070d3186019972b78d694e56e4e61647d4433a0:228357 has DA footprint (0) <= gasUsed (46218), trying next...\"", + expected: "INFO [10-29|23:42:54.881] \"Block 0xbf9f2a47f13a639f439c3bb04070d3186019972b78d694e56e4e61647d4433a0:228357 has DA footprint (0) <= gasUsed (46218), trying next...\"", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + result := CleanLogOutput(tt.input, true, true) + assert.Equal(t, tt.expected, result, "CleanLogOutput(%q, true, true) = %q, want %q", tt.input, result, tt.expected) + }) + } +} + +func TestCleanLogOutputWithoutStrippingPrefixes(t *testing.T) { + tests := []struct { + name string + input string + expected string + }{ + { + name: "file:line prefix preserved", + input: "da_footprint_test.go:188: some log output", + expected: "da_footprint_test.go:188: some log output", + }, + { + name: "file:line prefix preserved with whitespace collapsed", + input: "test.go:1: hello\t\t world \n foo", + expected: "test.go:1: hello world foo", + }, + { + name: "ANSI codes still stripped", + input: "test.go:42: \x1b[31mred text\x1b[0m", + expected: "test.go:42: red text", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + result := CleanLogOutput(tt.input, false, true) + assert.Equal(t, tt.expected, result, "CleanLogOutput(%q, false, true) = %q, want %q", tt.input, result, tt.expected) + }) + } +} + +func TestCleanLogOutputRegexPatterns(t *testing.T) { + t.Run("fileLinePrefixRegex matches valid patterns", func(t *testing.T) { + validPatterns := []string{ + "test.go:123: ", + " test.go:1: ", + "my_file.go:999: ", + "My-File.go:1: ", + "FILE123.go:456: ", + } + for _, pattern := range validPatterns { + assert.True(t, fileLinePrefixRegex.MatchString(pattern), + "fileLinePrefixRegex should match %q", pattern) + } + }) + + t.Run("fileLinePrefixRegex does not match invalid patterns", func(t *testing.T) { + invalidPatterns := []string{ + "file.txt:123: ", // not .go file + "prefix file.go:123: ", // not at start + "file.go:abc: ", // not a number + "file:123: ", // missing .go + ".go:123: ", // no filename + "file.go:", // missing line number + } + for _, pattern := range invalidPatterns { + assert.False(t, fileLinePrefixRegex.MatchString(pattern), + "fileLinePrefixRegex should not match %q", pattern) + } + }) + + t.Run("multipleWhitespaceRegex collapses various whitespace", func(t *testing.T) { + testCases := []struct { + input string + expected string + }{ + {"a b", "a b"}, + {"a\tb", "a b"}, + {"a\nb", "a b"}, + {"a\r\nb", "a b"}, + {"a \t\n b", "a b"}, + } + for _, tc := range testCases { + result := multipleWhitespaceRegex.ReplaceAllString(tc.input, " ") + assert.Equal(t, tc.expected, result) + } + }) +} diff --git a/op-acceptor/logging/filelogger.go b/op-acceptor/logging/filelogger.go index 2bb250fe..3389cb38 100644 --- a/op-acceptor/logging/filelogger.go +++ b/op-acceptor/logging/filelogger.go @@ -7,6 +7,7 @@ import ( "io" "os" "path/filepath" + "regexp" "strings" "sync" "time" @@ -24,6 +25,41 @@ const ( RunDirectoryPrefix = "testrun-" // Standardized prefix for run directories ) +// Regex patterns for log cleanup +var ( + // Collapse multiple whitespace characters into a single space + multipleWhitespaceRegex = regexp.MustCompile(`\s+`) + + // Match file:line prefixes like "file.go:123:" or "file_test.go:456:" + // This captures test output file:line prefixes from geth logger and similar + fileLinePrefixRegex = regexp.MustCompile(`^\s*[a-zA-Z0-9_\-]+\.go:\d+:\s*`) +) + +// CleanLogOutput cleans up log output by removing ANSI codes, escape sequences, +// optionally removing file:line prefixes, optionally collapsing whitespace, and trimming. +// When collapseWhitespace is true, multiple consecutive whitespace characters (spaces, tabs, +// newlines) are collapsed into single spaces, which cleans up structured logging output. +func CleanLogOutput(s string, stripCodeLinePrefixes bool, collapseWhitespace bool) string { + // Strip ANSI escape codes + cleaned := stripansi.Strip(s) + + // Optionally remove file:line prefixes (e.g., "da_footprint_test.go:188: ") + if stripCodeLinePrefixes { + cleaned = fileLinePrefixRegex.ReplaceAllString(cleaned, "") + } + + // Optionally collapse multiple whitespace characters into single spaces + if collapseWhitespace { + // Collapse all consecutive whitespace (spaces, tabs, newlines) into single spaces + cleaned = multipleWhitespaceRegex.ReplaceAllString(cleaned, " ") + } + + // Trim leading and trailing whitespace + cleaned = strings.TrimSpace(cleaned) + + return cleaned +} + // ResultSink is an interface for different ways of consuming test results type ResultSink interface { // Consume processes a single test result @@ -34,15 +70,16 @@ type ResultSink interface { // FileLogger handles writing test output to files type FileLogger struct { - baseDir string // Base directory for logs - logDir string // Root log directory - failedDir string // Directory for failed tests - summaryFile string // Path to the summary file - allLogsFile string // Path to the combined log file - mu sync.Mutex // Protects concurrent file operations - sinks []ResultSink // Collection of result consumers - asyncWriters map[string]*AsyncFile // Map of async file writers - runID string // Current run ID + baseDir string // Base directory for logs + logDir string // Root log directory + failedDir string // Directory for failed tests + summaryFile string // Path to the summary file + allLogsFile string // Path to the combined log file + mu sync.Mutex // Protects concurrent file operations + sinks []ResultSink // Collection of result consumers + asyncWriters map[string]*AsyncFile // Map of async file writers + runID string // Current run ID + stripCodeLinePrefixes bool // Whether to strip file:line prefixes from logs } // AsyncFile provides non-blocking file writing capabilities @@ -119,7 +156,7 @@ func (af *AsyncFile) Close() error { } // NewFileLogger creates a new FileLogger with given configuration -func NewFileLogger(baseDir string, runID string, networkName, gateRun string) (*FileLogger, error) { +func NewFileLogger(baseDir string, runID string, networkName, gateRun string, stripCodeLinePrefixes bool) (*FileLogger, error) { if runID == "" { return nil, fmt.Errorf("runID cannot be empty") } @@ -150,14 +187,15 @@ func NewFileLogger(baseDir string, runID string, networkName, gateRun string) (* // Initialize all sinks logger := &FileLogger{ - baseDir: baseDir, - logDir: logDir, - failedDir: failedDir, - summaryFile: summaryFile, - allLogsFile: allLogsFile, - sinks: make([]ResultSink, 0), - asyncWriters: make(map[string]*AsyncFile), - runID: runID, + baseDir: baseDir, + logDir: logDir, + failedDir: failedDir, + summaryFile: summaryFile, + allLogsFile: allLogsFile, + sinks: make([]ResultSink, 0), + asyncWriters: make(map[string]*AsyncFile), + runID: runID, + stripCodeLinePrefixes: stripCodeLinePrefixes, } // Initialize the AllLogsFileSink @@ -816,15 +854,20 @@ func (s *PerTestFileSink) createPlaintextFile(result *types.TestResult, filePath // First, try to parse as JSON (go test -json output) parser := NewJSONOutputParser(result.Stdout) parser.ProcessJSONOutput(func(_ map[string]interface{}, outputText string) { - // Strip ANSI escape sequences from the output - plaintext.WriteString(stripansi.Strip(outputText)) + // Clean the output (strip ANSI codes, optionally file:line prefixes) + // Collapse whitespace to clean up structured logging output + cleaned := CleanLogOutput(outputText, s.logger.stripCodeLinePrefixes, true) + if cleaned != "" { + plaintext.WriteString(cleaned) + plaintext.WriteString("\n") + } }) // If JSON parsing produced no output, the Stdout might already be plain text // (e.g., for subtests extracted from a package run) if plaintext.Len() == 0 && strings.Contains(result.Stdout, "===") { - // It's already plain text, strip ANSI sequences and use it - plaintext.WriteString(stripansi.Strip(result.Stdout)) + // It's already plain text, clean it and use it + plaintext.WriteString(CleanLogOutput(result.Stdout, s.logger.stripCodeLinePrefixes, true)) } } diff --git a/op-acceptor/logging/filelogger_output_test.go b/op-acceptor/logging/filelogger_output_test.go index b22378c1..fd221eb9 100644 --- a/op-acceptor/logging/filelogger_output_test.go +++ b/op-acceptor/logging/filelogger_output_test.go @@ -15,7 +15,7 @@ import ( func TestPlaintextFileCreation(t *testing.T) { // Setup tempDir := t.TempDir() - logger, err := NewFileLogger(tempDir, "test-run", "test-network", "test-gate") + logger, err := NewFileLogger(tempDir, "test-run", "test-network", "test-gate", true) require.NoError(t, err) sink := &PerTestFileSink{logger: logger} @@ -33,7 +33,7 @@ func TestPlaintextFileCreation(t *testing.T) { {"Time":"2025-09-23T10:00:01Z","Action":"output","Package":"test/pkg","Test":"TestExample","Output":" test.go:10: Log message\n"} {"Time":"2025-09-23T10:00:02Z","Action":"output","Package":"test/pkg","Test":"TestExample","Output":"--- PASS: TestExample (1.00s)\n"}`, shouldContain: []string{ - "=== RUN TestExample", + "=== RUN TestExample", // Whitespace collapsed "Log message", "--- PASS: TestExample", }, @@ -45,7 +45,7 @@ func TestPlaintextFileCreation(t *testing.T) { test.go:10: Log message --- PASS: TestExample (1.00s)`, shouldContain: []string{ - "=== RUN TestExample", + "=== RUN TestExample", // Whitespace collapsed "Log message", "--- PASS: TestExample", }, @@ -116,7 +116,7 @@ func TestPlaintextFileCreation(t *testing.T) { func TestSubtestOutputHandling(t *testing.T) { // Setup tempDir := t.TempDir() - logger, err := NewFileLogger(tempDir, "test-run", "test-network", "test-gate") + logger, err := NewFileLogger(tempDir, "test-run", "test-network", "test-gate", true) require.NoError(t, err) sink := &PerTestFileSink{logger: logger} diff --git a/op-acceptor/logging/filelogger_test.go b/op-acceptor/logging/filelogger_test.go index 37fed024..420eb534 100644 --- a/op-acceptor/logging/filelogger_test.go +++ b/op-acceptor/logging/filelogger_test.go @@ -21,7 +21,7 @@ func TestFileLogger(t *testing.T) { // Create a new FileLogger with a valid runID runID := "test-run-123" - logger, err := NewFileLogger(tmpDir, runID, "test-network", "test-gate") + logger, err := NewFileLogger(tmpDir, runID, "test-network", "test-gate", true) require.NoError(t, err) // Get the directory with the testrun- prefix @@ -153,12 +153,12 @@ func TestLoggerWithEmptyRunID(t *testing.T) { defer func() { _ = os.RemoveAll(tmpDir) }() // Test that an error is returned when an empty runID is provided to NewFileLogger - _, err = NewFileLogger(tmpDir, "", "test-network", "test-gate") + _, err = NewFileLogger(tmpDir, "", "test-network", "test-gate", true) assert.Error(t, err, "Expected error when creating logger with empty runID") assert.Contains(t, err.Error(), "runID cannot be empty") // Create a valid logger to test the LogTestResult with empty runID - logger, err := NewFileLogger(tmpDir, "valid-run-id", "test-network", "test-gate") + logger, err := NewFileLogger(tmpDir, "valid-run-id", "test-network", "test-gate", true) require.NoError(t, err) // Create a test result @@ -193,7 +193,7 @@ func TestLoggingWithRunID(t *testing.T) { // Create a new FileLogger with a valid runID defaultRunID := "default-run-id" - logger, err := NewFileLogger(tmpDir, defaultRunID, "test-network", "test-gate") + logger, err := NewFileLogger(tmpDir, defaultRunID, "test-network", "test-gate", true) require.NoError(t, err) // We'll use a different runID for this test @@ -333,7 +333,7 @@ func TestCustomResultSink(t *testing.T) { // Create a new FileLogger with a valid runID runID := "custom-sink-test" - logger, err := NewFileLogger(tmpDir, runID, "test-network", "test-gate") + logger, err := NewFileLogger(tmpDir, runID, "test-network", "test-gate", true) require.NoError(t, err) // Create a custom sink for testing @@ -390,7 +390,7 @@ func TestPerTestFileSink_WritesTestOutput(t *testing.T) { runID := "test-pertest-sink" // Create a file logger - logger, err := NewFileLogger(tmpDir, runID, "test-network", "test-gate") + logger, err := NewFileLogger(tmpDir, runID, "test-network", "test-gate", true) require.NoError(t, err) // Access the PerTestFileSink directly @@ -465,7 +465,7 @@ func TestPerTestFileSink_WritesTestOutput(t *testing.T) { passedTxtContent, err := os.ReadFile(passedTxtPath) require.NoError(t, err, "Should be able to read the passing test plaintext file") passedTxtStr := string(passedTxtContent) - assert.Contains(t, passedTxtStr, "=== RUN TestPass") + assert.Contains(t, passedTxtStr, "=== RUN TestPass") // Whitespace collapsed assert.Contains(t, passedTxtStr, "--- PASS: TestPass (1.00s)") // Should NOT contain headers since this is a separate file assert.NotContains(t, passedTxtStr, "PLAINTEXT OUTPUT:") @@ -497,11 +497,11 @@ func TestPerTestFileSink_WritesTestOutput(t *testing.T) { failedTxtContent, err := os.ReadFile(failedTxtPath) require.NoError(t, err, "Should be able to read the failing test plaintext file") failedTxtStr := string(failedTxtContent) - assert.Contains(t, failedTxtStr, "=== RUN TestFail") + assert.Contains(t, failedTxtStr, "=== RUN TestFail") // Whitespace collapsed assert.Contains(t, failedTxtStr, "Error Trace:") assert.Contains(t, failedTxtStr, "Error:") assert.Contains(t, failedTxtStr, "expected: int(42)") - assert.Contains(t, failedTxtStr, "actual : int(43)") + assert.Contains(t, failedTxtStr, "actual : int(43)") // Whitespace collapsed assert.Contains(t, failedTxtStr, "Messages:") // Should NOT contain headers since this is a separate file assert.NotContains(t, failedTxtStr, "PLAINTEXT OUTPUT:") @@ -533,7 +533,7 @@ func TestHTMLSummarySink_GeneratesHTMLReport(t *testing.T) { runID := "test-html-summary" // Create a file logger - logger, err := NewFileLogger(tmpDir, runID, "test-network", "test-gate") + logger, err := NewFileLogger(tmpDir, runID, "test-network", "test-gate", true) require.NoError(t, err) // Create a mix of test results @@ -645,7 +645,7 @@ func TestHTMLSummarySink_WithSubtestsAndNetworkInfo(t *testing.T) { gateRun := "isthmus" // Create a file logger with network and gate information - logger, err := NewFileLogger(tmpDir, runID, networkName, gateRun) + logger, err := NewFileLogger(tmpDir, runID, networkName, gateRun, true) require.NoError(t, err) // Create subtests @@ -758,7 +758,7 @@ func TestPerTestFileSink_CreatesSubtestFiles(t *testing.T) { runID := "test-subtests" // Create a file logger - logger, err := NewFileLogger(tmpDir, runID, "test-network", "test-gate") + logger, err := NewFileLogger(tmpDir, runID, "test-network", "test-gate", true) require.NoError(t, err) // Access the PerTestFileSink directly @@ -859,7 +859,7 @@ func TestDuplicationFix(t *testing.T) { runID := "duplication-test" // Create a file logger - logger, err := NewFileLogger(logDir, runID, "test-network", "test-gate") + logger, err := NewFileLogger(logDir, runID, "test-network", "test-gate", true) require.NoError(t, err) // Create a test result that would have caused duplication before @@ -953,7 +953,7 @@ func TestHTMLSink_TestsWithSubtestsAlwaysDisplayed(t *testing.T) { gateRun := "test-gate" // Create a file logger - logger, err := NewFileLogger(tmpDir, runID, networkName, gateRun) + logger, err := NewFileLogger(tmpDir, runID, networkName, gateRun, true) require.NoError(t, err) // Simulate the fjord scenario: a test with subtests but minimal metadata diff --git a/op-acceptor/logging/integration_test.go b/op-acceptor/logging/integration_test.go index 3a0869d6..4bbcdcc2 100644 --- a/op-acceptor/logging/integration_test.go +++ b/op-acceptor/logging/integration_test.go @@ -16,7 +16,7 @@ func TestIntegrationSubtestOutputCapture(t *testing.T) { // Setup tempDir := t.TempDir() runID := "test-run-" + time.Now().Format("20060102-150405") - logger, err := NewFileLogger(tempDir, runID, "test-network", "test-gate") + logger, err := NewFileLogger(tempDir, runID, "test-network", "test-gate", true) require.NoError(t, err) // Create a main test result with subtests that have plain text output @@ -120,7 +120,7 @@ func TestRealTestOutputCapture(t *testing.T) { // Setup tempDir := t.TempDir() runID := "real-test-run" - logger, err := NewFileLogger(tempDir, runID, "optimism", "connectivity") + logger, err := NewFileLogger(tempDir, runID, "optimism", "connectivity", true) require.NoError(t, err) // Simulate a test result for TestRPCConnectivity with actual logger output diff --git a/op-acceptor/logging/raw_json_sink_test.go b/op-acceptor/logging/raw_json_sink_test.go index 1c523376..1a0b6927 100644 --- a/op-acceptor/logging/raw_json_sink_test.go +++ b/op-acceptor/logging/raw_json_sink_test.go @@ -25,7 +25,7 @@ func TestRawJSONSink(t *testing.T) { // Create a new FileLogger with a valid runID runID := "test-run-raw-json" - logger, err := NewFileLogger(tmpDir, runID, "test-network", "test-gate") + logger, err := NewFileLogger(tmpDir, runID, "test-network", "test-gate", true) require.NoError(t, err) // Get the RawJSONSink from the logger @@ -227,7 +227,7 @@ func TestFail(t *testing.T) { // Create a test result and file logger runID := "real-go-test-run" - logger, err := NewFileLogger(tmpDir, runID, "test-network", "test-gate") + logger, err := NewFileLogger(tmpDir, runID, "test-network", "test-gate", true) require.NoError(t, err) // Get the RawJSONSink @@ -404,7 +404,7 @@ func TestRawJSONSink_ComprehensiveLogging(t *testing.T) { // Create a new FileLogger with a valid runID runID := "comprehensive-test-run" - logger, err := NewFileLogger(tmpDir, runID, "test-network", "test-gate") + logger, err := NewFileLogger(tmpDir, runID, "test-network", "test-gate", true) require.NoError(t, err) // Get the RawJSONSink from the logger @@ -663,7 +663,7 @@ func TestSkippedIntegration(t *testing.T) { // Create a file logger to test our raw JSON sink runID := "integration-test-run" - logger, err := NewFileLogger(tmpDir, runID, "test-network", "test-gate") + logger, err := NewFileLogger(tmpDir, runID, "test-network", "test-gate", true) require.NoError(t, err) // Get the RawJSONSink diff --git a/op-acceptor/metrics/metrics.go b/op-acceptor/metrics/metrics.go index 27453958..867e7c4b 100644 --- a/op-acceptor/metrics/metrics.go +++ b/op-acceptor/metrics/metrics.go @@ -157,6 +157,101 @@ var ( "gate", "suite", }) + + // Test duration histogram to track distribution of test execution times + testDurationHistogram = promauto.NewHistogramVec(prometheus.HistogramOpts{ + Namespace: MetricsNamespace, + Name: "test_duration_histogram_seconds", + Help: "Histogram of test execution durations in seconds", + Buckets: []float64{0.1, 0.5, 1, 2, 5, 10, 30, 60, 120, 300, 600}, // 100ms to 10min + }, []string{ + "network_name", + "test_name", + "gate", + "suite", + }) + + // Test timeout tracking + testTimeouts = promauto.NewCounterVec(prometheus.CounterOpts{ + Namespace: MetricsNamespace, + Name: "test_timeouts_total", + Help: "Total number of tests that timed out", + }, []string{ + "network_name", + "run_id", + "test_name", + "gate", + "suite", + }) + + // Gate-level aggregated metrics + gateTestsTotal = promauto.NewCounterVec(prometheus.CounterOpts{ + Namespace: MetricsNamespace, + Name: "gate_tests_total", + Help: "Total number of tests per gate", + }, []string{ + "network_name", + "gate", + }) + + gateTestsPassed = promauto.NewCounterVec(prometheus.CounterOpts{ + Namespace: MetricsNamespace, + Name: "gate_tests_passed_total", + Help: "Total number of passed tests per gate", + }, []string{ + "network_name", + "gate", + }) + + gateTestsFailed = promauto.NewCounterVec(prometheus.CounterOpts{ + Namespace: MetricsNamespace, + Name: "gate_tests_failed_total", + Help: "Total number of failed tests per gate", + }, []string{ + "network_name", + "gate", + }) + + gateDurationSeconds = promauto.NewGaugeVec(prometheus.GaugeOpts{ + Namespace: MetricsNamespace, + Name: "gate_duration_seconds", + Help: "Duration of gate execution in seconds", + }, []string{ + "network_name", + "run_id", + "gate", + }) + + // Suite-level metrics + suiteTestsTotal = promauto.NewCounterVec(prometheus.CounterOpts{ + Namespace: MetricsNamespace, + Name: "suite_tests_total", + Help: "Total number of tests per suite", + }, []string{ + "network_name", + "gate", + "suite", + }) + + suiteTestsPassed = promauto.NewCounterVec(prometheus.CounterOpts{ + Namespace: MetricsNamespace, + Name: "suite_tests_passed_total", + Help: "Total number of passed tests per suite", + }, []string{ + "network_name", + "gate", + "suite", + }) + + suiteTestsFailed = promauto.NewCounterVec(prometheus.CounterOpts{ + Namespace: MetricsNamespace, + Name: "suite_tests_failed_total", + Help: "Total number of failed tests per suite", + }, []string{ + "network_name", + "gate", + "suite", + }) ) // errToLabel tries to make the error string a more valid Prometheus label @@ -270,3 +365,28 @@ func RecordIndividualTest( func isValidResult(result types.TestStatus) bool { return slices.Contains(validResults, result) } + +// RecordTestDurationHistogram records test duration in a histogram for distribution analysis +func RecordTestDurationHistogram(network string, testName string, gate string, suite string, duration time.Duration) { + testDurationHistogram.WithLabelValues(network, testName, gate, suite).Observe(duration.Seconds()) +} + +// RecordTestTimeout records when a test times out +func RecordTestTimeout(network string, runID string, testName string, gate string, suite string) { + testTimeouts.WithLabelValues(network, runID, testName, gate, suite).Inc() +} + +// RecordGateMetrics records aggregated metrics for a gate +func RecordGateMetrics(network string, runID string, gate string, total int, passed int, failed int, duration time.Duration) { + gateTestsTotal.WithLabelValues(network, gate).Add(float64(total)) + gateTestsPassed.WithLabelValues(network, gate).Add(float64(passed)) + gateTestsFailed.WithLabelValues(network, gate).Add(float64(failed)) + gateDurationSeconds.WithLabelValues(network, runID, gate).Set(duration.Seconds()) +} + +// RecordSuiteMetrics records aggregated metrics for a suite +func RecordSuiteMetrics(network string, gate string, suite string, total int, passed int, failed int) { + suiteTestsTotal.WithLabelValues(network, gate, suite).Add(float64(total)) + suiteTestsPassed.WithLabelValues(network, gate, suite).Add(float64(passed)) + suiteTestsFailed.WithLabelValues(network, gate, suite).Add(float64(failed)) +} diff --git a/op-acceptor/nat.go b/op-acceptor/nat.go index 76dc0841..d3ef9d2a 100644 --- a/op-acceptor/nat.go +++ b/op-acceptor/nat.go @@ -162,20 +162,21 @@ func New(ctx context.Context, config *Config, version string, shutdownCallback f workDir := strings.TrimSuffix(config.TestDir, "/...") testRunner, err := runner.NewTestRunner(runner.Config{ - Registry: reg, - WorkDir: workDir, - Log: config.Log, - TargetGate: targetGate, - GoBinary: config.GoBinary, - AllowSkips: config.AllowSkips, - OutputRealtimeLogs: config.OutputRealtimeLogs, - TestLogLevel: config.TestLogLevel, - NetworkName: networkName, - DevnetEnv: devnetEnv, - Serial: config.Serial, - Concurrency: config.Concurrency, - ShowProgress: config.ShowProgress, - ProgressInterval: config.ProgressInterval, + Registry: reg, + WorkDir: workDir, + Log: config.Log, + TargetGate: targetGate, + GoBinary: config.GoBinary, + AllowSkips: config.AllowSkips, + OutputRealtimeLogs: config.OutputRealtimeLogs, + StripCodeLinePrefixes: config.StripCodeLinePrefixes, + TestLogLevel: config.TestLogLevel, + NetworkName: networkName, + DevnetEnv: devnetEnv, + Serial: config.Serial, + Concurrency: config.Concurrency, + ShowProgress: config.ShowProgress, + ProgressInterval: config.ProgressInterval, }) if err != nil { return nil, fmt.Errorf("failed to create test runner: %w", err) @@ -389,7 +390,7 @@ func (n *nat) runTests(ctx context.Context) error { n.config.Log.Debug("Generated new runID for test run", "runID", runID) // Create a new file logger with the runID - fileLogger, err := logging.NewFileLogger(n.config.LogDir, runID, n.networkName, n.config.TargetGate) + fileLogger, err := logging.NewFileLogger(n.config.LogDir, runID, n.networkName, n.config.TargetGate, n.config.StripCodeLinePrefixes) if err != nil { n.config.Log.Error("Error creating file logger", "error", err) return fmt.Errorf("failed to create file logger: %w", err) @@ -577,10 +578,25 @@ func (n *nat) runTests(ctx context.Context) error { n.result.Duration, ) - // Record metrics for individual tests + // Record metrics for individual tests and aggregated gate/suite metrics for _, gate := range n.result.Gates { + // Calculate gate-level aggregates + gateTotal := 0 + gatePassed := 0 + gateFailed := 0 + var gateDuration time.Duration + // Record direct gate tests for testName, test := range gate.Tests { + gateTotal++ + gateDuration += test.Duration + + if test.Status == types.TestStatusPass { + gatePassed++ + } else if test.Status == types.TestStatusFail { + gateFailed++ + } + metrics.RecordIndividualTest( n.networkName, n.result.RunID, @@ -591,6 +607,14 @@ func (n *nat) runTests(ctx context.Context) error { test.Duration, ) + // Record duration histogram + metrics.RecordTestDurationHistogram(n.networkName, testName, gate.ID, "", test.Duration) + + // Check for timeout in error message + if test.Error != nil && strings.Contains(test.Error.Error(), "timeout") { + metrics.RecordTestTimeout(n.networkName, n.result.RunID, testName, gate.ID, "") + } + // Record subtests if present for subTestName, subTest := range test.SubTests { metrics.RecordIndividualTest( @@ -602,12 +626,37 @@ func (n *nat) runTests(ctx context.Context) error { subTest.Status, subTest.Duration, ) + + // Record subtest duration histogram + metrics.RecordTestDurationHistogram(n.networkName, subTestName, gate.ID, "", subTest.Duration) + + // Check for timeout in subtest + if subTest.Error != nil && strings.Contains(subTest.Error.Error(), "timeout") { + metrics.RecordTestTimeout(n.networkName, n.result.RunID, subTestName, gate.ID, "") + } } } // Record suite tests for suiteName, suite := range gate.Suites { + // Calculate suite-level aggregates + suiteTotal := 0 + suitePassed := 0 + suiteFailed := 0 + for testName, test := range suite.Tests { + gateTotal++ + suiteTotal++ + gateDuration += test.Duration + + if test.Status == types.TestStatusPass { + gatePassed++ + suitePassed++ + } else if test.Status == types.TestStatusFail { + gateFailed++ + suiteFailed++ + } + metrics.RecordIndividualTest( n.networkName, n.result.RunID, @@ -618,6 +667,14 @@ func (n *nat) runTests(ctx context.Context) error { test.Duration, ) + // Record duration histogram + metrics.RecordTestDurationHistogram(n.networkName, testName, gate.ID, suiteName, test.Duration) + + // Check for timeout + if test.Error != nil && strings.Contains(test.Error.Error(), "timeout") { + metrics.RecordTestTimeout(n.networkName, n.result.RunID, testName, gate.ID, suiteName) + } + // Record subtests if present for subTestName, subTest := range test.SubTests { metrics.RecordIndividualTest( @@ -629,8 +686,26 @@ func (n *nat) runTests(ctx context.Context) error { subTest.Status, subTest.Duration, ) + + // Record subtest duration histogram + metrics.RecordTestDurationHistogram(n.networkName, subTestName, gate.ID, suiteName, subTest.Duration) + + // Check for timeout in subtest + if subTest.Error != nil && strings.Contains(subTest.Error.Error(), "timeout") { + metrics.RecordTestTimeout(n.networkName, n.result.RunID, subTestName, gate.ID, suiteName) + } } } + + // Record suite-level metrics + if suiteTotal > 0 { + metrics.RecordSuiteMetrics(n.networkName, gate.ID, suiteName, suiteTotal, suitePassed, suiteFailed) + } + } + + // Record gate-level metrics + if gateTotal > 0 { + metrics.RecordGateMetrics(n.networkName, n.result.RunID, gate.ID, gateTotal, gatePassed, gateFailed, gateDuration) } } diff --git a/op-acceptor/nat_test.go b/op-acceptor/nat_test.go index aca1ccd8..e55bb320 100644 --- a/op-acceptor/nat_test.go +++ b/op-acceptor/nat_test.go @@ -100,7 +100,7 @@ func setupTest(t *testing.T) (*trackedMockRunner, *nat, context.Context, context logger := log.New() // Set up a mock file logger - mockFileLogger, err := logging.NewFileLogger(t.TempDir(), "test-run-id", "test-network", "test-gate") + mockFileLogger, err := logging.NewFileLogger(t.TempDir(), "test-run-id", "test-network", "test-gate", true) require.NoError(t, err) // Create service with the mock @@ -385,7 +385,7 @@ gates: "name": "%s", "l1": { "name": "test-l1", - "id": "1", + "id": "1", "nodes": [], "addresses": {}, "wallets": {} diff --git a/op-acceptor/runner/runner.go b/op-acceptor/runner/runner.go index 988415fe..03db7ebf 100644 --- a/op-acceptor/runner/runner.go +++ b/op-acceptor/runner/runner.go @@ -114,21 +114,22 @@ type TestRunnerWithFileLogger interface { // runner struct implements TestRunner interface type runner struct { - registry *registry.Registry - validators []types.ValidatorMetadata - workDir string // Directory for running tests - log log.Logger - runID string - goBinary string // Path to the Go binary - allowSkips bool // Whether to allow skipping tests when preconditions are not met - outputRealtimeLogs bool // If enabled, test logs will be outputted in realtime - testLogLevel string // Log level to be used for the tests - fileLogger *logging.FileLogger // Logger for storing test results - networkName string // Name of the network being tested - env *env.DevnetEnv - tracer trace.Tracer - serial bool // Whether to run tests serially instead of in parallel - concurrency int // Number of concurrent test workers (0 = auto-determine) + registry *registry.Registry + validators []types.ValidatorMetadata + workDir string // Directory for running tests + log log.Logger + runID string + goBinary string // Path to the Go binary + allowSkips bool // Whether to allow skipping tests when preconditions are not met + outputRealtimeLogs bool // If enabled, test logs will be outputted in realtime + stripCodeLinePrefixes bool // Whether to strip file:line prefixes from test logs + testLogLevel string // Log level to be used for the tests + fileLogger *logging.FileLogger // Logger for storing test results + networkName string // Name of the network being tested + env *env.DevnetEnv + tracer trace.Tracer + serial bool // Whether to run tests serially instead of in parallel + concurrency int // Number of concurrent test workers (0 = auto-determine) // New component fields executor TestExecutor @@ -140,21 +141,22 @@ type runner struct { // Config holds configuration for creating a new runner type Config struct { - Registry *registry.Registry - TargetGate string - WorkDir string - Log log.Logger - GoBinary string // path to the Go binary - AllowSkips bool // Whether to allow skipping tests when preconditions are not met - OutputRealtimeLogs bool // Whether to output test logs to the console - TestLogLevel string // Log level to be used for the tests - FileLogger *logging.FileLogger // Logger for storing test results - NetworkName string // Name of the network being tested - DevnetEnv *env.DevnetEnv - Serial bool // Whether to run tests serially instead of in parallel - Concurrency int // Number of concurrent test workers (0 = auto-determine) - ShowProgress bool // Whether to show periodic progress updates during test execution - ProgressInterval time.Duration // Interval between progress updates when ShowProgress is 'true' + Registry *registry.Registry + TargetGate string + WorkDir string + Log log.Logger + GoBinary string // path to the Go binary + AllowSkips bool // Whether to allow skipping tests when preconditions are not met + OutputRealtimeLogs bool // Whether to output test logs to the console + StripCodeLinePrefixes bool // Whether to strip file:line prefixes from test logs + TestLogLevel string // Log level to be used for the tests + FileLogger *logging.FileLogger // Logger for storing test results + NetworkName string // Name of the network being tested + DevnetEnv *env.DevnetEnv + Serial bool // Whether to run tests serially instead of in parallel + Concurrency int // Number of concurrent test workers (0 = auto-determine) + ShowProgress bool // Whether to show periodic progress updates during test execution + ProgressInterval time.Duration // Interval between progress updates when ShowProgress is 'true' } // NewTestRunner creates a new test runner instance @@ -191,20 +193,21 @@ func NewTestRunner(cfg Config) (TestRunner, error) { "allowSkips", cfg.AllowSkips, "goBinary", cfg.GoBinary, "networkName", networkName, "serial", cfg.Serial) r := &runner{ - registry: cfg.Registry, - validators: validators, - workDir: cfg.WorkDir, - log: cfg.Log, - goBinary: cfg.GoBinary, - allowSkips: cfg.AllowSkips, - outputRealtimeLogs: cfg.OutputRealtimeLogs, - testLogLevel: cfg.TestLogLevel, - fileLogger: cfg.FileLogger, - networkName: networkName, - env: cfg.DevnetEnv, - tracer: otel.Tracer("test runner"), - serial: cfg.Serial, - concurrency: cfg.Concurrency, + registry: cfg.Registry, + validators: validators, + workDir: cfg.WorkDir, + log: cfg.Log, + goBinary: cfg.GoBinary, + allowSkips: cfg.AllowSkips, + outputRealtimeLogs: cfg.OutputRealtimeLogs, + stripCodeLinePrefixes: cfg.StripCodeLinePrefixes, + testLogLevel: cfg.TestLogLevel, + fileLogger: cfg.FileLogger, + networkName: networkName, + env: cfg.DevnetEnv, + tracer: otel.Tracer("test runner"), + serial: cfg.Serial, + concurrency: cfg.Concurrency, } // Initialize new components @@ -766,12 +769,18 @@ func (r *runner) runSingleTest(ctx context.Context, metadata types.ValidatorMeta var testStartTime = time.Now() if r.outputRealtimeLogs { - stdoutLogger := &logWriter{logFn: func(msg string) { - r.log.Info("Test output", "test", metadata.FuncName, "output", msg) - }} - stderrLogger := &logWriter{logFn: func(msg string) { - r.log.Error("Test error output", "test", metadata.FuncName, "error", msg) - }} + stdoutLogger := &logWriter{ + logFn: func(msg string) { + r.log.Info("Test output", "test", metadata.FuncName, "output", msg) + }, + stripCodeLinePrefixes: r.stripCodeLinePrefixes, + } + stderrLogger := &logWriter{ + logFn: func(msg string) { + r.log.Error("Test error output", "test", metadata.FuncName, "error", msg) + }, + stripCodeLinePrefixes: r.stripCodeLinePrefixes, + } cmd.Stdout = io.MultiWriter(&stdout, stdoutLogger) cmd.Stderr = io.MultiWriter(&stderr, stderrLogger) @@ -1390,8 +1399,9 @@ var _ TestRunner = &runner{} var _ TestRunnerWithFileLogger = &runner{} type logWriter struct { - logFn func(msg string) - buf []byte + logFn func(msg string) + buf []byte + stripCodeLinePrefixes bool } func (w *logWriter) Write(p []byte) (n int, err error) { @@ -1406,12 +1416,25 @@ func (w *logWriter) Write(p []byte) (n int, err error) { // Try to parse as a test event event, err := parseTestEvent(line) - if err == nil && event.Action == ActionOutput { - // If it's a valid test event with output action, use the Output field - w.logFn(event.Output) + if err == nil { + // It's a valid test event JSON + if event.Action == ActionOutput { + // Only log the actual test output content + // Collapse whitespace to clean up structured logging output + cleaned := logging.CleanLogOutput(event.Output, w.stripCodeLinePrefixes, true) + if cleaned != "" { + w.logFn(cleaned) + } + } + // Skip logging other test events (start, run, pass, fail, skip) + // These are metadata used for parsing but not useful in realtime logs } else { - // If not a valid test event or not an output action, use the raw line - w.logFn(string(line)) + // Not a valid test event JSON - it's a raw line (e.g., direct stderr) + // Clean up and log it - collapse whitespace to clean up structured logging output + cleaned := logging.CleanLogOutput(string(line), w.stripCodeLinePrefixes, true) + if cleaned != "" { + w.logFn(cleaned) + } } } return len(p), nil