Merge pull request #5515 from ethereum-optimism/aj/fpp-logs

op-program: Improve logging

op-e2e/system_fpp_test.go

@@ -9,7 +9,7 @@ import (
 	"github.com/ethereum-optimism/optimism/op-node/client"
 	"github.com/ethereum-optimism/optimism/op-node/sources"
 	"github.com/ethereum-optimism/optimism/op-node/testlog"
-	oppcl "github.com/ethereum-optimism/optimism/op-program/client"
+	"github.com/ethereum-optimism/optimism/op-program/client/driver"
 	opp "github.com/ethereum-optimism/optimism/op-program/host"
 	oppconf "github.com/ethereum-optimism/optimism/op-program/host/config"
 	"github.com/ethereum/go-ethereum/accounts/abi/bind"
@@ -119,7 +119,7 @@ func TestVerifyL2OutputRoot(t *testing.T) {
 	t.Log("Running fault proof with invalid claim")
 	fppConfig.L2Claim = common.Hash{0xaa}
 	err = opp.FaultProofProgram(log, fppConfig)
-	require.ErrorIs(t, err, oppcl.ErrClaimNotValid)
+	require.ErrorIs(t, err, driver.ErrClaimNotValid)
 }
 
 func waitForSafeHead(ctx context.Context, safeBlockNum uint64, rollupClient *sources.RollupClient) error {

op-program/client/driver/driver.go

@@ -13,6 +13,10 @@ import (
 	"github.com/ethereum/go-ethereum/log"
 )
 
+var (
+	ErrClaimNotValid = errors.New("invalid claim")
+)
+
 type Derivation interface {
 	Step(ctx context.Context) error
 	SafeL2Head() eth.L2BlockRef
@@ -47,11 +51,12 @@ func NewDriver(logger log.Logger, cfg *rollup.Config, l1Source derive.L1Fetcher,
 // Returns a non-EOF error if the derivation failed
 func (d *Driver) Step(ctx context.Context) error {
 	if err := d.pipeline.Step(ctx); errors.Is(err, io.EOF) {
+		d.logger.Info("Derivation complete: reached L1 head", "head", d.pipeline.SafeL2Head())
 		return io.EOF
 	} else if errors.Is(err, derive.NotEnoughData) {
 		head := d.pipeline.SafeL2Head()
 		if head.Number >= d.targetBlockNum {
-			d.logger.Info("Target L2 block reached", "head", head)
+			d.logger.Info("Derivation complete: reached L2 block", "head", head)
 			return io.EOF
 		}
 		d.logger.Debug("Data is lacking")
@@ -66,12 +71,14 @@ func (d *Driver) SafeHead() eth.L2BlockRef {
 	return d.pipeline.SafeL2Head()
 }
 
-func (d *Driver) ValidateClaim(claimedOutputRoot eth.Bytes32) bool {
+func (d *Driver) ValidateClaim(claimedOutputRoot eth.Bytes32) error {
 	outputRoot, err := d.l2OutputRoot()
 	if err != nil {
-		d.logger.Info("Failed to calculate L2 output root", "err", err)
-		return false
+		return fmt.Errorf("calculate L2 output root: %w", err)
 	}
-	d.logger.Info("Derivation complete", "head", d.SafeHead(), "output", outputRoot, "claim", claimedOutputRoot)
-	return claimedOutputRoot == outputRoot
+	d.logger.Info("Validating claim", "head", d.SafeHead(), "output", outputRoot, "claim", claimedOutputRoot)
+	if claimedOutputRoot != outputRoot {
+		return fmt.Errorf("%w: claim: %v actual: %v", ErrClaimNotValid, claimedOutputRoot, outputRoot)
+	}
+	return nil
 }

op-program/client/driver/driver_test.go

@@ -76,8 +76,8 @@ func TestValidateClaim(t *testing.T) {
 		driver.l2OutputRoot = func() (eth.Bytes32, error) {
 			return expected, nil
 		}
-		valid := driver.ValidateClaim(expected)
-		require.True(t, valid)
+		err := driver.ValidateClaim(expected)
+		require.NoError(t, err)
 	})
 
 	t.Run("Invalid", func(t *testing.T) {
@@ -85,17 +85,18 @@ func TestValidateClaim(t *testing.T) {
 		driver.l2OutputRoot = func() (eth.Bytes32, error) {
 			return eth.Bytes32{0x22}, nil
 		}
-		valid := driver.ValidateClaim(eth.Bytes32{0x11})
-		require.False(t, valid)
+		err := driver.ValidateClaim(eth.Bytes32{0x11})
+		require.ErrorIs(t, err, ErrClaimNotValid)
 	})
 
 	t.Run("Error", func(t *testing.T) {
 		driver := createDriver(t, io.EOF)
+		expectedErr := errors.New("boom")
 		driver.l2OutputRoot = func() (eth.Bytes32, error) {
-			return eth.Bytes32{}, errors.New("boom")
+			return eth.Bytes32{}, expectedErr
 		}
-		valid := driver.ValidateClaim(eth.Bytes32{0x11})
-		require.False(t, valid)
+		err := driver.ValidateClaim(eth.Bytes32{0x11})
+		require.ErrorIs(t, err, expectedErr)
 	})
 }
 

op-program/client/program.go

@@ -18,10 +18,6 @@ import (
 	"github.com/ethereum-optimism/optimism/op-program/preimage"
 )
 
-var (
-	ErrClaimNotValid = errors.New("invalid claim")
-)
-
 // ClientProgram executes the Program, while attached to an IO based pre-image oracle, to be served by a host.
 func ClientProgram(
 	logger log.Logger,
@@ -59,9 +55,5 @@ func Program(logger log.Logger, cfg *rollup.Config, l2Cfg *params.ChainConfig, l
 			return err
 		}
 	}
-	if !d.ValidateClaim(eth.Bytes32(l2Claim)) {
-		return ErrClaimNotValid
-	}
-	logger.Info("Derivation complete", "head", d.SafeHead())
-	return nil
+	return d.ValidateClaim(eth.Bytes32(l2Claim))
 }

op-program/host/cmd/main.go

 package main
 
 import (
+	"errors"
 	"fmt"
 	"os"
 
+	"github.com/ethereum-optimism/optimism/op-program/client/driver"
 	"github.com/ethereum-optimism/optimism/op-program/host"
 	"github.com/ethereum-optimism/optimism/op-program/host/config"
 	"github.com/ethereum-optimism/optimism/op-program/host/flags"
@@ -35,9 +37,10 @@ var VersionWithMeta = func() string {
 
 func main() {
 	args := os.Args
-	err := run(args, host.FaultProofProgram)
-	if err != nil {
-		log.Crit("Application failed", "message", err)
+	if err := run(args, host.FaultProofProgram); errors.Is(err, driver.ErrClaimNotValid) {
+		log.Crit("Claim is invalid", "err", err)
+	} else if err != nil {
+		log.Crit("Application failed", "err", err)
 	} else {
 		log.Info("Claim successfully verified")
 	}

op-program/host/host.go

@@ -131,7 +131,7 @@ func routeHints(logger log.Logger, hintReader *preimage.HintReader, hinter func(
 		for {
 			if err := hintReader.NextHint(hinter); err != nil {
 				if err == io.EOF || errors.Is(err, io.ErrClosedPipe) {
-					logger.Info("closing pre-image hint handler")
+					logger.Debug("closing pre-image hint handler")
 					return
 				}
 				logger.Error("pre-image hint router error", "err", err)
@@ -146,7 +146,7 @@ func launchOracleServer(logger log.Logger, server *preimage.OracleServer, getter
 		for {
 			if err := server.NextPreimageRequest(getter); err != nil {
 				if err == io.EOF || errors.Is(err, io.ErrClosedPipe) {
-					logger.Info("closing pre-image server")
+					logger.Debug("closing pre-image server")
 					return
 				}
 				logger.Error("pre-image server error", "error", err)

op-program/host/prefetcher/prefetcher.go

@@ -49,11 +49,13 @@ func NewPrefetcher(logger log.Logger, l1Fetcher L1Source, l2Fetcher L2Source, kv
 }
 
 func (p *Prefetcher) Hint(hint string) error {
+	p.logger.Trace("Received hint", "hint", hint)
 	p.lastHint = hint
 	return nil
 }
 
 func (p *Prefetcher) GetPreimage(ctx context.Context, key common.Hash) ([]byte, error) {
+	p.logger.Trace("Pre-image requested", "key", key)
 	pre, err := p.kvStore.Get(key)
 	if errors.Is(err, kvstore.ErrNotFound) && p.lastHint != "" {
 		hint := p.lastHint