feat(op-acceptor): better error logging for failing tests. (#254)

Author: scharissis

op-acceptor/nat.go

@@ -45,13 +45,6 @@ func New(ctx context.Context, config *Config, version string, shutdownCallback f
 		return nil, errors.New("config is required")
 	}
 
-	config.Log.Debug("Creating NAT with config",
-		"testDir", config.TestDir,
-		"validatorConfig", config.ValidatorConfig,
-		"runInterval", config.RunInterval,
-		"runOnce", config.RunOnce,
-		"allowSkips", config.AllowSkips)
-
 	reg, err := registry.NewRegistry(registry.Config{
 		Log:                 config.Log,
 		ValidatorConfigFile: config.ValidatorConfig,
@@ -72,7 +65,16 @@ func New(ctx context.Context, config *Config, version string, shutdownCallback f
 	if err != nil {
 		return nil, fmt.Errorf("failed to create test runner: %w", err)
 	}
-	config.Log.Info("nat.New: created registry and test runner")
+
+	config.Log.Debug("Created NAT with config",
+		"testDir", config.TestDir,
+		"validatorConfig", config.ValidatorConfig,
+		"targetGate", config.TargetGate,
+		"runInterval", config.RunInterval,
+		"runOnce", config.RunOnce,
+		"allowSkips", config.AllowSkips,
+		"goBinary", config.GoBinary,
+	)
 
 	return &nat{
 		ctx:              ctx,
@@ -124,9 +126,8 @@ func (n *nat) Start(ctx context.Context) error {
 
 		// Check if any tests failed and return appropriate exit code
 		if n.result != nil && n.result.Status == types.TestStatusFail {
-			n.config.Log.Warn("Run-once test run completed with failures, returning exit code 1")
-			// Return exit code 1 for test failures (assertions failed)
-			return NewTestFailureError(n.result.String())
+			n.config.Log.Warn("Run-once test run completed with failures")
+			return NewTestFailureError("Run-once test run completed with failures")
 		}
 
 		// Only need to call this when we're in run-once mode and all tests passed
@@ -260,6 +261,7 @@ func (n *nat) printResultsTable(runID string) {
 			gate.Stats.Skipped,
 			getResultString(gate.Status),
 			"",
+			"", // No stdout for gates
 		})
 
 		// Print suites in this gate
@@ -274,6 +276,7 @@ func (n *nat) printResultsTable(runID string) {
 				suite.Stats.Skipped,
 				getResultString(suite.Status),
 				"",
+				"", // No stdout for suites
 			})
 
 			// Print tests in this suite
@@ -297,7 +300,7 @@ func (n *nat) printResultsTable(runID string) {
 					boolToInt(test.Status == types.TestStatusFail),
 					boolToInt(test.Status == types.TestStatusSkip),
 					getResultString(test.Status),
-					test.Error,
+					getErrorMessage(test.Status, test.Error),
 				})
 
 				// Display individual sub-tests if present (for package tests)
@@ -318,7 +321,7 @@ func (n *nat) printResultsTable(runID string) {
 							boolToInt(subTest.Status == types.TestStatusFail),
 							boolToInt(subTest.Status == types.TestStatusSkip),
 							getResultString(subTest.Status),
-							subTest.Error,
+							getErrorMessage(subTest.Status, subTest.Error),
 						})
 						j++
 					}
@@ -349,7 +352,7 @@ func (n *nat) printResultsTable(runID string) {
 				boolToInt(test.Status == types.TestStatusFail),
 				boolToInt(test.Status == types.TestStatusSkip),
 				getResultString(test.Status),
-				test.Error,
+				getErrorMessage(test.Status, test.Error),
 			})
 
 			// Display individual sub-tests if present (for package tests)
@@ -370,12 +373,11 @@ func (n *nat) printResultsTable(runID string) {
 						boolToInt(subTest.Status == types.TestStatusFail),
 						boolToInt(subTest.Status == types.TestStatusSkip),
 						getResultString(subTest.Status),
-						subTest.Error,
+						getErrorMessage(subTest.Status, subTest.Error),
 					})
 					j++
 				}
 			}
-
 			i++
 		}
 
@@ -443,6 +445,14 @@ func formatDuration(d time.Duration) string {
 	return fmt.Sprintf("%.1fs", d.Seconds())
 }
 
+// getErrorMessage returns the error message if test failed, empty string otherwise
+func getErrorMessage(status types.TestStatus, err error) string {
+	if status == types.TestStatusFail && err != nil {
+		return err.Error()
+	}
+	return ""
+}
+
 // WaitForShutdown blocks until all goroutines have terminated.
 // This is useful in tests to ensure complete cleanup before moving to the next test.
 func (n *nat) WaitForShutdown(ctx context.Context) error {

op-acceptor/runner/logging_test.go

@@ -0,0 +1,69 @@
+package runner
+
+import (
+	"testing"
+
+	"github.com/ethereum-optimism/infra/op-acceptor/types"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+)
+
+// TestFailingTestStdoutLogging verifies that stdout is captured when tests fail
+func TestFailingTestStdoutLogging(t *testing.T) {
+	// Setup test with a failing test that outputs to stdout
+	testContent := []byte(`
+package feature_test
+
+import (
+	"fmt"
+	"testing"
+)
+
+func TestWithStdout(t *testing.T) {
+	fmt.Println("This is some stdout output that should be captured")
+	fmt.Println("This is a second line of output")
+	t.Error("This test deliberately fails")
+}
+`)
+
+	configContent := []byte(`
+gates:
+  - id: logging-gate
+    description: "Gate with a test that outputs to stdout"
+    suites:
+      logging-suite:
+        description: "Suite with a failing test that outputs to stdout"
+        tests:
+          - name: TestWithStdout
+            package: "./feature"
+`)
+
+	// Setup the test runner
+	r := setupTestRunner(t, testContent, configContent)
+
+	// Run the test
+	result, err := r.RunAllTests()
+	require.NoError(t, err)
+	assert.Equal(t, types.TestStatusFail, result.Status)
+
+	// Verify the structure
+	require.Contains(t, result.Gates, "logging-gate")
+	gate := result.Gates["logging-gate"]
+	require.Contains(t, gate.Suites, "logging-suite")
+	suite := gate.Suites["logging-suite"]
+
+	// Get the failing test
+	var failingTest *types.TestResult
+	for _, test := range suite.Tests {
+		failingTest = test
+		break
+	}
+	require.NotNil(t, failingTest)
+
+	// Verify the test failed and has stdout captured
+	assert.Equal(t, types.TestStatusFail, failingTest.Status)
+	assert.NotNil(t, failingTest.Error)
+	assert.NotEmpty(t, failingTest.Stdout)
+	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")
+}