op-challenger: Log StdOut and StdErr output when executing cannon.

op-challenger/fault/cannon/executor.go

@@ -11,6 +11,7 @@ import (
 	"strconv"
 
 	"github.com/ethereum-optimism/optimism/op-challenger/config"
+	oplog "github.com/ethereum-optimism/optimism/op-service/log"
 	"github.com/ethereum/go-ethereum/log"
 )
 
@@ -22,7 +23,7 @@ const (
 var snapshotNameRegexp = regexp.MustCompile(`^[0-9]+\.json$`)
 
 type snapshotSelect func(logger log.Logger, dir string, absolutePreState string, i uint64) (string, error)
-type cmdExecutor func(ctx context.Context, binary string, args ...string) error
+type cmdExecutor func(ctx context.Context, l log.Logger, binary string, args ...string) error
 
 type Executor struct {
 	logger           log.Logger
@@ -72,15 +73,14 @@ func (e *Executor) GenerateProof(ctx context.Context, dir string, i uint64) erro
 		// TODO(CLI-4240): Pass local game inputs (l1.head, l2.head, l2.claim etc)
 	}
 
-	e.logger.Info("Generating trace", "idx", i, "cmd", e.cannon, "args", args)
-	return e.cmdExecutor(ctx, e.cannon, args...)
+	e.logger.Info("Generating trace", "proof", i, "cmd", e.cannon, "args", args)
+	return e.cmdExecutor(ctx, e.logger.New("proof", i), e.cannon, args...)
 }
 
-func runCmd(ctx context.Context, binary string, args ...string) error {
+func runCmd(ctx context.Context, l log.Logger, binary string, args ...string) error {
 	cmd := exec.CommandContext(ctx, binary, args...)
-	// TODO(CLI-4242): Provide context about what the generation is for in logs
-	cmd.Stdout = os.Stdout
-	cmd.Stderr = os.Stderr
+	cmd.Stdout = oplog.NewWriter(l, log.LvlInfo)
+	cmd.Stderr = oplog.NewWriter(l, log.LvlError)
 	return cmd.Run()
 }
 

op-challenger/fault/cannon/executor_test.go

@@ -6,6 +6,7 @@ import (
 	"os"
 	"path/filepath"
 	"testing"
+	"time"
 
 	"github.com/ethereum-optimism/optimism/op-challenger/config"
 	"github.com/ethereum-optimism/optimism/op-node/testlog"
@@ -32,7 +33,7 @@ func TestGenerateProof(t *testing.T) {
 	}
 	var binary string
 	args := make(map[string]string)
-	executor.cmdExecutor = func(ctx context.Context, b string, a ...string) error {
+	executor.cmdExecutor = func(ctx context.Context, l log.Logger, b string, a ...string) error {
 		binary = b
 		for i := 0; i < len(a); i += 2 {
 			args[a[i]] = a[i+1]
@@ -53,6 +54,20 @@ func TestGenerateProof(t *testing.T) {
 	require.Contains(t, args, "--snapshot-fmt", filepath.Join(cfg.CannonDatadir, snapsDir, "%d.json"))
 }
 
+func TestRunCmdLogsOutput(t *testing.T) {
+	bin := "/bin/echo"
+	if _, err := os.Stat(bin); err != nil {
+		t.Skip(bin, " not available", err)
+	}
+	ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
+	defer cancel()
+	logger := testlog.Logger(t, log.LvlInfo)
+	logs := testlog.Capture(logger)
+	err := runCmd(ctx, logger, bin, "Hello World")
+	require.NoError(t, err)
+	require.NotNil(t, logs.FindLog(log.LvlInfo, "Hello World"))
+}
+
 func TestFindStartingSnapshot(t *testing.T) {
 	logger := testlog.Logger(t, log.LvlInfo)
 

op-node/testlog/capturing.go

@@ -11,6 +11,14 @@ type CapturingHandler struct {
 	Logs     []*log.Record
 }
 
+func Capture(l log.Logger) *CapturingHandler {
+	handler := &CapturingHandler{
+		Delegate: l.GetHandler(),
+	}
+	l.SetHandler(handler)
+	return handler
+}
+
 func (c *CapturingHandler) Log(r *log.Record) error {
 	c.Logs = append(c.Logs, r)
 	if c.Delegate != nil {

op-service/log/writer.go

+package log
+
+import (
+	"sync"
+
+	"github.com/ethereum/go-ethereum/log"
+)
+
+type Writer struct {
+	log     func(str string, ctx ...interface{})
+	lock    sync.Mutex
+	pending []byte
+}
+
+func NewWriter(l log.Logger, lvl log.Lvl) *Writer {
+	var logMethod func(str string, ctx ...interface{})
+	switch lvl {
+	case log.LvlTrace:
+		logMethod = l.Trace
+	case log.LvlDebug:
+		logMethod = l.Debug
+	case log.LvlInfo:
+		logMethod = l.Info
+	case log.LvlWarn:
+		logMethod = l.Warn
+	case log.LvlError:
+		logMethod = l.Error
+	case log.LvlCrit:
+		logMethod = l.Crit
+	default:
+		// Cast lvl to int to avoid trying to convert it to a string which will fail for unknown types
+		l.Error("Unknown log level. Using Error", "lvl", int(lvl))
+		logMethod = l.Error
+	}
+	return &Writer{
+		log: logMethod,
+	}
+}
+
+func (w *Writer) Write(b []byte) (int, error) {
+	w.lock.Lock()
+	defer w.lock.Unlock()
+	for _, c := range b {
+		if c == '\n' {
+			w.log(string(w.pending))
+			w.pending = nil
+			continue
+		}
+		w.pending = append(w.pending, c)
+	}
+	return len(b), nil
+}

op-service/log/writer_test.go

+package log
+
+import (
+	"io"
+	"testing"
+
+	"github.com/ethereum-optimism/optimism/op-node/testlog"
+	"github.com/ethereum/go-ethereum/log"
+	"github.com/stretchr/testify/require"
+)
+
+var _ io.Writer = (*Writer)(nil)
+
+func TestLogWriter(t *testing.T) {
+	setup := func(t *testing.T, lvl log.Lvl) (*Writer, *testlog.CapturingHandler) {
+		logger := testlog.Logger(t, lvl)
+		logs := testlog.Capture(logger)
+		writer := NewWriter(logger, lvl)
+		return writer, logs
+	}
+
+	t.Run("LogSingleLine", func(t *testing.T) {
+		writer, logs := setup(t, log.LvlInfo)
+		line := []byte("Test line\n")
+		count, err := writer.Write(line)
+		require.NoError(t, err)
+		require.Equal(t, len(line), count)
+		require.NotNil(t, logs.FindLog(log.LvlInfo, "Test line"))
+	})
+
+	t.Run("LogMultipleLines", func(t *testing.T) {
+		writer, logs := setup(t, log.LvlInfo)
+		line := []byte("Line 1\nLine 2\n")
+		count, err := writer.Write(line)
+		require.NoError(t, err)
+		require.Equal(t, len(line), count)
+		require.NotNil(t, logs.FindLog(log.LvlInfo, "Line 1"))
+		require.NotNil(t, logs.FindLog(log.LvlInfo, "Line 2"))
+	})
+
+	t.Run("LogLineAcrossMultipleCalls", func(t *testing.T) {
+		writer, logs := setup(t, log.LvlInfo)
+		line := []byte("First line\nSplit ")
+		count, err := writer.Write(line)
+		require.NoError(t, err)
+		require.Equal(t, len(line), count)
+		require.NotNil(t, logs.FindLog(log.LvlInfo, "First line"))
+
+		line = []byte("Line\nLast Line\n")
+		count, err = writer.Write(line)
+		require.NoError(t, err)
+		require.Equal(t, len(line), count)
+		require.NotNil(t, logs.FindLog(log.LvlInfo, "Split Line"))
+		require.NotNil(t, logs.FindLog(log.LvlInfo, "Last Line"))
+	})
+
+	// Can't test LvlCrit or it will call os.Exit
+	for _, lvl := range []log.Lvl{log.LvlTrace, log.LvlDebug, log.LvlInfo, log.LvlWarn, log.LvlError} {
+		lvl := lvl
+		t.Run("LogLvl_"+lvl.String(), func(t *testing.T) {
+			writer, logs := setup(t, lvl)
+			line := []byte("Log line\n")
+			count, err := writer.Write(line)
+			require.NoError(t, err)
+			require.Equal(t, len(line), count)
+			require.NotNil(t, logs.FindLog(lvl, "Log line"))
+		})
+	}
+
+	t.Run("UseErrorForUnknownLevels", func(t *testing.T) {
+		logger := testlog.Logger(t, log.LvlInfo)
+		logs := testlog.Capture(logger)
+		writer := NewWriter(logger, 60027)
+		line := []byte("Log line\n")
+		count, err := writer.Write(line)
+		require.NoError(t, err)
+		require.Equal(t, len(line), count)
+		require.NotNil(t, logs.FindLog(log.LvlError, "Unknown log level. Using Error"))
+		require.NotNil(t, logs.FindLog(log.LvlError, "Log line"))
+	})
+}