diff --git a/op-acceptor/Dockerfile b/op-acceptor/Dockerfile index 2f33cafa..5ec72046 100644 --- a/op-acceptor/Dockerfile +++ b/op-acceptor/Dockerfile @@ -9,7 +9,9 @@ COPY op-acceptor/ . RUN just build -FROM alpine:3.21 +FROM golang:1.23.5-alpine3.21 + +RUN apk add --no-cache ca-certificates build-base git # Install Go binary # (we copy Go directly from the builder stage for simplicity and consistency) @@ -19,6 +21,7 @@ ENV GOPATH="/go" ENV PATH="${GOPATH}/bin:${PATH}" WORKDIR /app + RUN addgroup -S app && adduser -S app -G app && \ mkdir -p /devnets && \ chown -R app:app /devnets @@ -30,7 +33,12 @@ chown -R app:app /go COPY --from=builder /app/bin/op-acceptor /app/ COPY op-acceptor/example-validators.yaml /app/ + +# Set ownership of the /app directory to allow the application to write logs and other files at runtime +RUN chown -R app:app /app/ + USER app VOLUME /devnets + ENTRYPOINT ["/app/op-acceptor"] diff --git a/op-acceptor/config.go b/op-acceptor/config.go index 14b1c377..2bcadda0 100644 --- a/op-acceptor/config.go +++ b/op-acceptor/config.go @@ -13,17 +13,18 @@ import ( ) type Config struct { - TestDir string - ValidatorConfig string - TargetGate string - 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 - LogDir string // Directory to store test logs - - Log log.Logger + TestDir string + ValidatorConfig string + TargetGate string + 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 + 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 + Log log.Logger } // NewConfig creates a new Config instance @@ -64,15 +65,17 @@ func NewConfig(ctx *cli.Context, log log.Logger, testDir string, validatorConfig } return &Config{ - TestDir: absTestDir, - ValidatorConfig: absValidatorConfig, - TargetGate: gate, - GoBinary: ctx.String(flags.GoBinary.Name), - RunInterval: runInterval, - RunOnce: runOnce, - AllowSkips: ctx.Bool(flags.AllowSkips.Name), - DefaultTimeout: ctx.Duration(flags.DefaultTimeout.Name), - LogDir: logDir, - Log: log, + TestDir: absTestDir, + ValidatorConfig: absValidatorConfig, + TargetGate: gate, + GoBinary: ctx.String(flags.GoBinary.Name), + RunInterval: runInterval, + RunOnce: runOnce, + AllowSkips: ctx.Bool(flags.AllowSkips.Name), + DefaultTimeout: ctx.Duration(flags.DefaultTimeout.Name), + OutputRealtimeLogs: ctx.Bool(flags.OutputRealtimeLogs.Name), + TestLogLevel: ctx.String(flags.TestLogLevel.Name), + LogDir: logDir, + Log: log, }, nil } diff --git a/op-acceptor/flags/flags.go b/op-acceptor/flags/flags.go index 9a7e1bd7..b1ea9a9f 100644 --- a/op-acceptor/flags/flags.go +++ b/op-acceptor/flags/flags.go @@ -66,6 +66,18 @@ var ( EnvVars: opservice.PrefixEnvVar(EnvVarPrefix, "LOGDIR"), Usage: "Directory to store test logs. Defaults to 'logs' if not specified.", } + TestLogLevel = &cli.StringFlag{ + Name: "test-log-level", + Value: "info", + EnvVars: opservice.PrefixEnvVar(EnvVarPrefix, "TEST_LOG_LEVEL"), + Usage: "Log level to be used for the tests. Defaults to 'info'.", + } + OutputRealtimeLogs = &cli.BoolFlag{ + Name: "output-realtime-logs", + Value: false, + EnvVars: opservice.PrefixEnvVar(EnvVarPrefix, "OUTPUT_REALTIME_LOGS"), + Usage: "If enabled, test logs will be outputted to the console in realtime. Defaults to false.", + } ) var requiredFlags = []cli.Flag{ @@ -80,6 +92,8 @@ var optionalFlags = []cli.Flag{ AllowSkips, DefaultTimeout, LogDir, + TestLogLevel, + OutputRealtimeLogs, } var Flags []cli.Flag diff --git a/op-acceptor/nat.go b/op-acceptor/nat.go index f3fed117..d8950a7f 100644 --- a/op-acceptor/nat.go +++ b/op-acceptor/nat.go @@ -76,14 +76,16 @@ func New(ctx context.Context, config *Config, version string, shutdownCallback f // Create runner with registry testRunner, err := runner.NewTestRunner(runner.Config{ - Registry: reg, - WorkDir: config.TestDir, - Log: config.Log, - TargetGate: config.TargetGate, - GoBinary: config.GoBinary, - AllowSkips: config.AllowSkips, - NetworkName: networkName, - DevnetEnv: env, + Registry: reg, + WorkDir: config.TestDir, + Log: config.Log, + TargetGate: config.TargetGate, + GoBinary: config.GoBinary, + AllowSkips: config.AllowSkips, + OutputRealtimeLogs: config.OutputRealtimeLogs, + TestLogLevel: config.TestLogLevel, + NetworkName: networkName, + DevnetEnv: env, }) if err != nil { return nil, fmt.Errorf("failed to create test runner: %w", err) diff --git a/op-acceptor/runner/logging_test.go b/op-acceptor/runner/logging_test.go index ad07ae52..ee5d9f59 100644 --- a/op-acceptor/runner/logging_test.go +++ b/op-acceptor/runner/logging_test.go @@ -2,9 +2,17 @@ package runner import ( "context" + "fmt" + "log/slog" + "os" + "path/filepath" + "slices" + "strings" "testing" + "time" "github.com/ethereum-optimism/infra/op-acceptor/types" + "github.com/ethereum/go-ethereum/log" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -68,3 +76,312 @@ gates: assert.Contains(t, failingTest.Stdout, "This is some stdout output that should be captured") assert.Contains(t, failingTest.Stdout, "This is a second line of output") } + +// TestLogLevelEnvironment verifies that the TEST_LOG_LEVEL environment variable is correctly set and used +func TestLogLevelEnvironment(t *testing.T) { + ctx := context.Background() + + // Create a simple test file in the work directory + testContent := []byte(` +package main + +import ( + "os" + "testing" +) + +func TestLogLevelEnvironment(t *testing.T) { + // Get log level from environment + logLevel := os.Getenv("TEST_LOG_LEVEL") + if logLevel == "" { + t.Log("TEST_LOG_LEVEL not set") + } else { + t.Log("TEST_LOG_LEVEL set to", logLevel) + } +} +`) + configContent := []byte(` +gates: + - id: logging-gate + description: "Gate with a test that outputs logs" + suites: + logging-suite: + description: "Suite with a test that outputs logs" + tests: + - name: TestLogLevelEnvironment + package: "./main" +`) + + r := setupTestRunner(t, testContent, configContent) + r.testLogLevel = "debug" + err := os.WriteFile(filepath.Join(r.workDir, "main_test.go"), testContent, 0644) + require.NoError(t, err) + + result, err := r.RunTest(ctx, types.ValidatorMetadata{ + ID: "test1", + Gate: "logging-gate", + FuncName: "TestLogLevelEnvironment", + Package: ".", + }) + + require.NoError(t, err) + assert.Equal(t, types.TestStatusPass, result.Status) + assert.Equal(t, "test1", result.Metadata.ID) + assert.Equal(t, "logging-gate", result.Metadata.Gate) + assert.Equal(t, ".", result.Metadata.Package) + assert.False(t, result.Metadata.RunAll) + assert.Contains(t, result.Stdout, "TEST_LOG_LEVEL set to debug") +} + +// testLogger implements the go-ethereum/log.Logger interface +type testLogger struct { + logFn func(msg string) +} + +func (l *testLogger) formatMessage(msg string, ctx ...interface{}) string { + if len(ctx) == 0 { + return msg + } + + // Format key-value pairs + var pairs []string + for i := 0; i < len(ctx); i += 2 { + if i+1 < len(ctx) { + pairs = append(pairs, fmt.Sprintf("%v=%v", ctx[i], ctx[i+1])) + } + } + + if len(pairs) > 0 { + return fmt.Sprintf("%s %s", msg, strings.Join(pairs, " ")) + } + return msg +} + +func (l *testLogger) Crit(msg string, ctx ...interface{}) { + l.logFn(l.formatMessage(msg, ctx...)) +} + +func (l *testLogger) Error(msg string, ctx ...interface{}) { + l.logFn(l.formatMessage(msg, ctx...)) +} + +func (l *testLogger) Warn(msg string, ctx ...interface{}) { + l.logFn(l.formatMessage(msg, ctx...)) +} + +func (l *testLogger) Info(msg string, ctx ...interface{}) { + l.logFn(l.formatMessage(msg, ctx...)) +} + +func (l *testLogger) Debug(msg string, ctx ...interface{}) { + l.logFn(l.formatMessage(msg, ctx...)) +} + +func (l *testLogger) Trace(msg string, ctx ...interface{}) { + l.logFn(l.formatMessage(msg, ctx...)) +} + +func (l *testLogger) New(ctx ...interface{}) log.Logger { + return l +} + +func (l *testLogger) Enabled(ctx context.Context, level slog.Level) bool { + return true // Always enabled for testing +} + +func (l *testLogger) With(ctx ...interface{}) log.Logger { + return l +} + +func (l *testLogger) Handler() slog.Handler { + return nil // Not needed for testing +} + +func (l *testLogger) Log(level slog.Level, msg string, ctx ...interface{}) { + l.logFn(l.formatMessage(msg, ctx...)) +} + +func (l *testLogger) Write(level slog.Level, msg string, attrs ...any) { + l.logFn(l.formatMessage(msg, attrs...)) +} + +// TestOutputRealtimeLogs verifies that test logs are output in real-time when outputRealtimeLogs is enabled +func TestOutputRealtimeLogs(t *testing.T) { + // Create a test file that outputs logs over time + testContent := []byte(` +package feature_test + +import ( + "fmt" + "testing" + "time" +) + +func TestWithRealtimeLogs(t *testing.T) { + fmt.Println("First log message") + time.Sleep(100 * time.Millisecond) + fmt.Println("Second log message") + time.Sleep(100 * time.Millisecond) + fmt.Println("Third log message") + time.Sleep(200 * time.Millisecond) +} +`) + + configContent := []byte(` +gates: + - id: logging-gate + description: "Gate with a test that outputs logs in real-time" + suites: + logging-suite: + description: "Suite with a test that outputs logs in real-time" + tests: + - name: TestWithRealtimeLogs + package: "./feature" +`) + + logChan := make(chan string, 10) + + customLogger := &testLogger{ + logFn: func(msg string) { + logChan <- msg + }, + } + + r := setupTestRunner(t, testContent, configContent) + r.outputRealtimeLogs = true + r.log = customLogger + + // Run the test in a goroutine + done := make(chan struct{}) + go func() { + defer close(done) + result, err := r.RunAllTests(context.Background()) + require.NoError(t, err) + assert.Equal(t, types.TestStatusPass, result.Status) + }() + + expectedLogs := []string{ + "First log message", + "Second log message", + "Third log message", + } + + time.Sleep(10 * time.Millisecond) + + // Track which message we're expecting next + nextExpectedIndex := 0 + timeout := time.After(1000 * time.Millisecond) + + for nextExpectedIndex < len(expectedLogs) { + select { + case msg := <-logChan: + if strings.Contains(msg, expectedLogs[nextExpectedIndex]) { + nextExpectedIndex++ + t.Logf("Received expected message: %s", msg) + } + case <-timeout: + t.Fatalf("Did not receive all messages in order. Got %d/%d messages. Next expected: %s", + nextExpectedIndex, len(expectedLogs), expectedLogs[nextExpectedIndex]) + } + } + + // Wait for the test to complete + select { + case <-done: + case <-time.After(500 * time.Millisecond): + t.Fatal("Test did not complete in time") + } +} + +// TestOutputRealtimeLogsDisabled verifies that test logs are output in real-time when outputRealtimeLogs is disabled +func TestOutputRealtimeLogsDisabled(t *testing.T) { + // Create a test file that outputs logs over time + testContent := []byte(` +package feature_test + +import ( + "fmt" + "testing" + "time" +) + +func TestWithRealtimeLogs(t *testing.T) { + fmt.Println("First log message") + time.Sleep(100 * time.Millisecond) + fmt.Println("Second log message") + time.Sleep(100 * time.Millisecond) + fmt.Println("Third log message") + time.Sleep(200 * time.Millisecond) +} +`) + + configContent := []byte(` +gates: + - id: logging-gate + description: "Gate with a test that outputs logs in real-time" + suites: + logging-suite: + description: "Suite with a test that outputs logs in real-time" + tests: + - name: TestWithRealtimeLogs + package: "./feature" +`) + + logChan := make(chan string, 10) + + customLogger := &testLogger{ + logFn: func(msg string) { + logChan <- msg + }, + } + + r := setupTestRunner(t, testContent, configContent) + r.outputRealtimeLogs = false + r.log = customLogger + + // Run the test in a goroutine + done := make(chan struct{}) + go func() { + defer close(done) + result, err := r.RunAllTests(context.Background()) + require.NoError(t, err) + assert.Equal(t, types.TestStatusPass, result.Status) + }() + + time.Sleep(10 * time.Millisecond) + + // With outputRealtimeLogs disabled, we should not receive any messages in real-time + // Wait for the running message to be logged + // go test ./feature -run ^TestWithRealtimeLogs$ + timeout := time.After(1000 * time.Millisecond) + found := false + for !found { + select { + case msg := <-logChan: + if strings.Contains(msg, "go test ./feature -run ^TestWithRealtimeLogs$") { + found = true + } else { + t.Logf("Received unexpected message: %s", msg) + } + case <-timeout: + t.Fatalf("Did not receive running message in time") + } + } + + testLogs := []string{ + "First log message", + "Second log message", + "Third log message", + } + + // Wait for the test to complete + select { + case <-done: + case msg := <-logChan: + if slices.Contains(testLogs, msg) { + t.Fatalf("Received unexpected log message: %s", msg) + } + case <-time.After(1000 * time.Millisecond): + t.Fatal("Test did not complete in time") + } +} diff --git a/op-acceptor/runner/runner.go b/op-acceptor/runner/runner.go index d10a896f..e08808e1 100644 --- a/op-acceptor/runner/runner.go +++ b/op-acceptor/runner/runner.go @@ -5,9 +5,11 @@ import ( "context" "encoding/json" "fmt" + "io" "net/url" "os" "os/exec" + "path/filepath" "strings" "time" @@ -92,30 +94,34 @@ 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 - fileLogger *logging.FileLogger // Logger for storing test results - networkName string // Name of the network being tested - env *env.DevnetEnv - tracer trace.Tracer + 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 } // 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 - FileLogger *logging.FileLogger // Logger for storing test results - NetworkName string // Name of the network being tested - DevnetEnv *env.DevnetEnv + 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 } // NewTestRunner creates a new test runner instance @@ -155,16 +161,18 @@ func NewTestRunner(cfg Config) (TestRunner, error) { "allowSkips", cfg.AllowSkips, "goBinary", cfg.GoBinary, "networkName", networkName) return &runner{ - registry: cfg.Registry, - validators: validators, - workDir: cfg.WorkDir, - log: cfg.Log, - goBinary: cfg.GoBinary, - allowSkips: cfg.AllowSkips, - fileLogger: cfg.FileLogger, - networkName: networkName, - env: cfg.DevnetEnv, - tracer: otel.Tracer("test 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"), }, nil } @@ -351,6 +359,10 @@ func (r *runner) getTestKey(validator types.ValidatorMetadata) string { return validator.FuncName } +func isLocalPath(pkg string) bool { + return strings.HasPrefix(pkg, "./") || strings.HasPrefix(pkg, "/") || strings.HasPrefix(pkg, "../") +} + // RunTest implements the TestRunner interface func (r *runner) RunTest(ctx context.Context, metadata types.ValidatorMetadata) (*types.TestResult, error) { // Use defer and recover to catch panics and convert them to errors @@ -379,7 +391,21 @@ func (r *runner) RunTest(ctx context.Context, metadata types.ValidatorMetadata) } }() + // Check if the path is available locally + if isLocalPath(metadata.Package) { + fullPath := filepath.Join(r.workDir, metadata.Package) + if _, statErr := os.Stat(fullPath); os.IsNotExist(statErr) { + r.log.Error("Local package path does not exist, failing test", "validator", metadata.ID, "package", metadata.Package, "fullPath", fullPath) + return &types.TestResult{ + Metadata: metadata, + Status: types.TestStatusFail, + Error: fmt.Errorf("local package path does not exist: %s", fullPath), + }, nil + } + } + r.log.Info("Running validator", "validator", metadata.ID) + start := time.Now() if metadata.RunAll { result, err = r.runAllTestsInPackage(ctx, metadata) @@ -516,8 +542,20 @@ func (r *runner) runSingleTest(ctx context.Context, metadata types.ValidatorMeta defer cleanup() var stdout, stderr bytes.Buffer - cmd.Stdout = &stdout - cmd.Stderr = &stderr + 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) + }} + + cmd.Stdout = io.MultiWriter(&stdout, stdoutLogger) + cmd.Stderr = io.MultiWriter(&stderr, stderrLogger) + } else { + cmd.Stdout = &stdout + cmd.Stderr = &stderr + } r.log.Info("Running test", "test", metadata.FuncName) r.log.Debug("Running test command", @@ -563,10 +601,12 @@ func (r *runner) runSingleTest(ctx context.Context, metadata types.ValidatorMeta // If we couldn't parse the output for some reason, create a minimal failing result if parsedResult == nil { + r.log.Error("test exited with non-zero exit code", "exitCode", cmd.ProcessState.ExitCode()) parsedResult = &types.TestResult{ Metadata: metadata, Status: types.TestStatusFail, Error: fmt.Errorf("failed to parse test output"), + Stdout: stdout.String(), } } @@ -652,7 +692,9 @@ func (r *runner) parseTestOutput(output []byte, metadata types.ValidatorMetadata "status", result.Status, "subtests", len(result.SubTests), "hasAnyValidEvent", hasAnyValidEvent, - "hasError", result.Error != nil) + "hasError", result.Error != nil, + "error", result.Error, + ) return result } @@ -1144,7 +1186,11 @@ func (r *runner) testCommandContext(ctx context.Context, name string, arg ...str cmd := exec.CommandContext(ctx, name, arg...) cmd.Dir = r.workDir + // Always set the TEST_LOG_LEVEL environment variable + runEnv := append([]string{fmt.Sprintf("TEST_LOG_LEVEL=%s", r.testLogLevel)}, os.Environ()...) + if r.env == nil { + cmd.Env = telemetry.InstrumentEnvironment(ctx, runEnv) return cmd, func() {} } @@ -1161,8 +1207,7 @@ func (r *runner) testCommandContext(ctx context.Context, name string, arg ...str r.log.Error("Failed to write env to temp file", "error", err) } - env := append( - os.Environ(), + runEnv = append(runEnv, // override the env URL with the one from the temp file fmt.Sprintf("%s=%s", env.EnvURLVar, envFile.Name()), // override the control resolution scheme with the original one @@ -1170,7 +1215,7 @@ func (r *runner) testCommandContext(ctx context.Context, name string, arg ...str // Set DEVNET_EXPECT_PRECONDITIONS_MET=true to make tests fail instead of skip when preconditions are not met "DEVNET_EXPECT_PRECONDITIONS_MET=true", ) - cmd.Env = telemetry.InstrumentEnvironment(ctx, env) + cmd.Env = telemetry.InstrumentEnvironment(ctx, runEnv) } cleanup := func() { if envFile != nil { @@ -1184,3 +1229,31 @@ func (r *runner) testCommandContext(ctx context.Context, name string, arg ...str // Make sure the runner type implements both interfaces var _ TestRunner = &runner{} var _ TestRunnerWithFileLogger = &runner{} + +type logWriter struct { + logFn func(msg string) + buf []byte +} + +func (w *logWriter) Write(p []byte) (n int, err error) { + w.buf = append(w.buf, p...) + for { + idx := bytes.IndexByte(w.buf, '\n') + if idx == -1 { + break + } + line := w.buf[:idx] + w.buf = w.buf[idx+1:] + + // 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) + } else { + // If not a valid test event or not an output action, use the raw line + w.logFn(string(line)) + } + } + return len(p), nil +} diff --git a/op-acceptor/runner/runner_test.go b/op-acceptor/runner/runner_test.go index 76e92181..289b4464 100644 --- a/op-acceptor/runner/runner_test.go +++ b/op-acceptor/runner/runner_test.go @@ -1583,3 +1583,39 @@ gates: validators := reg.GetValidators() require.NotEmpty(t, validators, "Registry should have validators") } + +func TestRunTest_PackagePath_Local(t *testing.T) { + r := setupDefaultTestRunner(t) + + origPath := os.Getenv("PATH") + defer os.Setenv("PATH", origPath) + + testCases := []struct { + name string + packagePath string + expectStatus types.TestStatus + expectErrMsg string + }{ + { + name: "Local path does not exist", + packagePath: "./does-not-exist", + expectStatus: types.TestStatusFail, + expectErrMsg: "local package path does not exist", + }, + } + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + result, err := r.RunTest(context.Background(), types.ValidatorMetadata{ + ID: "test", + Gate: "test-gate", + FuncName: "TestFunc", + Package: tc.packagePath, + }) + require.NoError(t, err) + assert.Equal(t, tc.expectStatus, result.Status) + assert.Error(t, result.Error) + assert.Contains(t, result.Error.Error(), tc.expectErrMsg) + }) + } +}