op-challenger: Improve logging (#6394)

Fix handling of transaction failures when resolving the game

Avoid duplicate logging of errors
Reduce expected situations to debug level
Log an error if the game is lost
Consistently start log messages with a capital letter

op-challenger/challenger.go

@@ -31,7 +31,7 @@ func Main(ctx context.Context, logger log.Logger, cfg *config.Config) error {
 		return fmt.Errorf("failed to bind the fault dispute game contract: %w", err)
 	}
 
-	loader := fault.NewLoader(logger, contract)
+	loader := fault.NewLoader(contract)
 	responder, err := fault.NewFaultResponder(logger, txMgr, cfg.GameAddress)
 	if err != nil {
 		return fmt.Errorf("failed to create the responder: %w", err)
@@ -45,14 +45,27 @@ func Main(ctx context.Context, logger log.Logger, cfg *config.Config) error {
 		return fmt.Errorf("failed to bind the fault contract: %w", err)
 	}
 
-	logger.Info("Fault game started")
+	logger.Info("Monitoring fault dispute game", "game", cfg.GameAddress, "agreeWithOutput", cfg.AgreeWithProposedOutput)
 
 	for {
-		logger.Info("Performing action")
-		_ = agent.Act(ctx)
-		status, _ := caller.GetGameStatus(ctx)
-		if status != 0 {
-			caller.LogGameStatus(ctx)
+		logger.Trace("Checking if actions are required", "game", cfg.GameAddress)
+		if err = agent.Act(ctx); err != nil {
+			logger.Error("Error when acting on game", "err", err)
+		}
+		if status, err := caller.GetGameStatus(ctx); err != nil {
+			logger.Warn("Unable to retrieve game status", "err", err)
+		} else if status != 0 {
+			var expectedStatus fault.GameStatus
+			if cfg.AgreeWithProposedOutput {
+				expectedStatus = fault.GameStatusChallengerWon
+			} else {
+				expectedStatus = fault.GameStatusDefenderWon
+			}
+			if expectedStatus == status {
+				logger.Info("Game won", "status", fault.GameStatusString(status))
+			} else {
+				logger.Error("Game lost", "status", fault.GameStatusString(status))
+			}
 			return nil
 		} else {
 			caller.LogGameInfo(ctx)

op-challenger/fault/agent.go

@@ -35,12 +35,11 @@ func (a *Agent) Act(ctx context.Context) error {
 	}
 	game, err := a.newGameFromContracts(ctx)
 	if err != nil {
-		a.log.Error("Failed to create new game", "err", err)
-		return err
+		return fmt.Errorf("create game from contracts: %w", err)
 	}
 	// Create counter claims
 	for _, claim := range game.Claims() {
-		if err := a.move(ctx, claim, game); err != nil {
+		if err := a.move(ctx, claim, game); err != nil && !errors.Is(err, ErrGameDepthReached) {
 			log.Error("Failed to move", "err", err)
 		}
 	}
@@ -57,11 +56,13 @@ func (a *Agent) Act(ctx context.Context) error {
 // and returns true if the game resolves successfully.
 func (a *Agent) tryResolve(ctx context.Context) bool {
 	if a.responder.CanResolve(ctx) {
+		a.log.Info("Resolving game")
 		err := a.responder.Resolve(ctx)
 		if err != nil {
-			return true
+			a.log.Error("Failed to resolve the game", "err", err)
+			return false
 		}
-		a.log.Error("failed to resolve the game", "err", err)
+		return true
 	}
 	return false
 }
@@ -86,8 +87,7 @@ func (a *Agent) newGameFromContracts(ctx context.Context) (Game, error) {
 func (a *Agent) move(ctx context.Context, claim Claim, game Game) error {
 	nextMove, err := a.solver.NextMove(claim, game.AgreeWithClaimLevel(claim))
 	if err != nil {
-		a.log.Warn("Failed to execute the next move", "err", err)
-		return err
+		return fmt.Errorf("execute next move: %w", err)
 	}
 	if nextMove == nil {
 		a.log.Debug("No next move")
@@ -98,7 +98,7 @@ func (a *Agent) move(ctx context.Context, claim Claim, game Game) error {
 		"value", move.Value, "trace_index", move.TraceIndex(a.maxDepth),
 		"parent_value", claim.Value, "parent_trace_index", claim.TraceIndex(a.maxDepth))
 	if game.IsDuplicate(move) {
-		log.Debug("Duplicate move")
+		log.Debug("Skipping duplicate move")
 		return nil
 	}
 	log.Info("Performing move")
@@ -113,20 +113,19 @@ func (a *Agent) step(ctx context.Context, claim Claim, game Game) error {
 
 	agreeWithClaimLevel := game.AgreeWithClaimLevel(claim)
 	if agreeWithClaimLevel {
-		a.log.Warn("Agree with leaf claim, skipping step", "claim_depth", claim.Depth(), "maxDepth", a.maxDepth)
+		a.log.Debug("Agree with leaf claim, skipping step", "claim_depth", claim.Depth(), "maxDepth", a.maxDepth)
 		return nil
 	}
 
 	if claim.Countered {
-		a.log.Info("Claim already stepped on", "claim_depth", claim.Depth(), "maxDepth", a.maxDepth)
+		a.log.Debug("Step already executed against claim", "depth", claim.Depth(), "index_at_depth", claim.IndexAtDepth(), "value", claim.Value)
 		return nil
 	}
 
 	a.log.Info("Attempting step", "claim_depth", claim.Depth(), "maxDepth", a.maxDepth)
 	step, err := a.solver.AttemptStep(claim, agreeWithClaimLevel)
 	if err != nil {
-		a.log.Warn("Failed to get a step", "err", err)
-		return err
+		return fmt.Errorf("attempt step: %w", err)
 	}
 
 	a.log.Info("Performing step", "is_attack", step.IsAttack,

op-challenger/fault/caller.go

@@ -62,17 +62,9 @@ func (fc *FaultCaller) LogGameInfo(ctx context.Context) {
 // 0: In Progress
 // 1: Challenger Won
 // 2: Defender Won
-func (fc *FaultCaller) GetGameStatus(ctx context.Context) (uint8, error) {
-	return fc.Status(&bind.CallOpts{Context: ctx})
-}
-
-func (fc *FaultCaller) LogGameStatus(ctx context.Context) {
-	status, err := fc.GetGameStatus(ctx)
-	if err != nil {
-		fc.log.Error("failed to get game status", "err", err)
-		return
-	}
-	fc.log.Info("Game status", "status", GameStatusString(status))
+func (fc *FaultCaller) GetGameStatus(ctx context.Context) (GameStatus, error) {
+	status, err := fc.Status(&bind.CallOpts{Context: ctx})
+	return GameStatus(status), err
 }
 
 // GetClaimDataLength returns the number of claims in the game.
@@ -90,13 +82,13 @@ func (fc *FaultCaller) LogClaimDataLength(ctx context.Context) {
 }
 
 // GameStatusString returns the current game status as a string.
-func GameStatusString(status uint8) string {
+func GameStatusString(status GameStatus) string {
 	switch status {
-	case 0:
+	case GameStatusInProgress:
 		return "In Progress"
-	case 1:
+	case GameStatusChallengerWon:
 		return "Challenger Won"
-	case 2:
+	case GameStatusDefenderWon:
 		return "Defender Won"
 	default:
 		return "Unknown"

op-challenger/fault/caller_test.go

@@ -42,7 +42,7 @@ func TestFaultCaller_GetGameStatus(t *testing.T) {
 	tests := []struct {
 		name           string
 		caller         FaultDisputeGameCaller
-		expectedStatus uint8
+		expectedStatus GameStatus
 		expectedErr    error
 	}{
 		{
@@ -50,7 +50,7 @@ func TestFaultCaller_GetGameStatus(t *testing.T) {
 			caller: &mockFaultDisputeGameCaller{
 				status: 1,
 			},
-			expectedStatus: 1,
+			expectedStatus: GameStatusChallengerWon,
 			expectedErr:    nil,
 		},
 		{

op-challenger/fault/loader.go

@@ -5,7 +5,6 @@ import (
 	"math/big"
 
 	"github.com/ethereum/go-ethereum/accounts/abi/bind"
-	"github.com/ethereum/go-ethereum/log"
 )
 
 // ClaimFetcher is a minimal interface around [bindings.FaultDisputeGameCaller].
@@ -28,14 +27,12 @@ type Loader interface {
 
 // loader pulls in fault dispute game claim data periodically and over subscriptions.
 type loader struct {
-	log          log.Logger
 	claimFetcher ClaimFetcher
 }
 
 // NewLoader creates a new [loader].
-func NewLoader(log log.Logger, claimFetcher ClaimFetcher) *loader {
+func NewLoader(claimFetcher ClaimFetcher) *loader {
 	return &loader{
-		log:          log,
 		claimFetcher: claimFetcher,
 	}
 }

op-challenger/fault/loader_test.go

@@ -6,9 +6,7 @@ import (
 	"math/big"
 	"testing"
 
-	"github.com/ethereum-optimism/optimism/op-node/testlog"
 	"github.com/ethereum/go-ethereum/accounts/abi/bind"
-	"github.com/ethereum/go-ethereum/log"
 	"github.com/stretchr/testify/require"
 )
 
@@ -91,10 +89,9 @@ func (m *mockClaimFetcher) ClaimDataLen(opts *bind.CallOpts) (*big.Int, error) {
 
 // TestLoader_FetchClaims_Succeeds tests [loader.FetchClaims].
 func TestLoader_FetchClaims_Succeeds(t *testing.T) {
-	log := testlog.Logger(t, log.LvlError)
 	mockClaimFetcher := newMockClaimFetcher()
 	expectedClaims := mockClaimFetcher.returnClaims
-	loader := NewLoader(log, mockClaimFetcher)
+	loader := NewLoader(mockClaimFetcher)
 	claims, err := loader.FetchClaims(context.Background())
 	require.NoError(t, err)
 	require.ElementsMatch(t, []Claim{
@@ -143,10 +140,9 @@ func TestLoader_FetchClaims_Succeeds(t *testing.T) {
 // TestLoader_FetchClaims_ClaimDataErrors tests [loader.FetchClaims]
 // when the claim fetcher [ClaimData] function call errors.
 func TestLoader_FetchClaims_ClaimDataErrors(t *testing.T) {
-	log := testlog.Logger(t, log.LvlError)
 	mockClaimFetcher := newMockClaimFetcher()
 	mockClaimFetcher.claimDataError = true
-	loader := NewLoader(log, mockClaimFetcher)
+	loader := NewLoader(mockClaimFetcher)
 	claims, err := loader.FetchClaims(context.Background())
 	require.ErrorIs(t, err, mockClaimDataError)
 	require.Empty(t, claims)
@@ -155,10 +151,9 @@ func TestLoader_FetchClaims_ClaimDataErrors(t *testing.T) {
 // TestLoader_FetchClaims_ClaimLenErrors tests [loader.FetchClaims]
 // when the claim fetcher [ClaimDataLen] function call errors.
 func TestLoader_FetchClaims_ClaimLenErrors(t *testing.T) {
-	log := testlog.Logger(t, log.LvlError)
 	mockClaimFetcher := newMockClaimFetcher()
 	mockClaimFetcher.claimLenError = true
-	loader := NewLoader(log, mockClaimFetcher)
+	loader := NewLoader(mockClaimFetcher)
 	claims, err := loader.FetchClaims(context.Background())
 	require.ErrorIs(t, err, mockClaimLenError)
 	require.Empty(t, claims)

op-challenger/fault/responder.go

@@ -123,9 +123,9 @@ func (r *faultResponder) sendTxAndWait(ctx context.Context, txData []byte) error
 		return err
 	}
 	if receipt.Status == types.ReceiptStatusFailed {
-		r.log.Error("responder tx successfully published but reverted", "tx_hash", receipt.TxHash)
+		r.log.Error("Responder tx successfully published but reverted", "tx_hash", receipt.TxHash)
 	} else {
-		r.log.Info("responder tx successfully published", "tx_hash", receipt.TxHash)
+		r.log.Debug("Responder tx successfully published", "tx_hash", receipt.TxHash)
 	}
 	return nil
 }

op-challenger/fault/solver.go

@@ -2,10 +2,15 @@ package fault
 
 import (
 	"errors"
+	"fmt"
 
 	"github.com/ethereum/go-ethereum/common"
 )
 
+var (
+	ErrGameDepthReached = errors.New("game depth reached")
+)
+
 // Solver uses a [TraceProvider] to determine the moves to make in a dispute game.
 type Solver struct {
 	TraceProvider
@@ -54,7 +59,7 @@ func (s *Solver) handleMiddle(claim Claim) (*Claim, error) {
 		return nil, err
 	}
 	if claim.Depth() == s.gameDepth {
-		return nil, errors.New("game depth reached")
+		return nil, ErrGameDepthReached
 	}
 	if claimCorrect {
 		return s.defend(claim)
@@ -113,7 +118,7 @@ func (s *Solver) attack(claim Claim) (*Claim, error) {
 	position := claim.Attack()
 	value, err := s.traceAtPosition(position)
 	if err != nil {
-		return nil, err
+		return nil, fmt.Errorf("attack claim: %w", err)
 	}
 	return &Claim{
 		ClaimData:           ClaimData{Value: value, Position: position},
@@ -127,7 +132,7 @@ func (s *Solver) defend(claim Claim) (*Claim, error) {
 	position := claim.Defend()
 	value, err := s.traceAtPosition(position)
 	if err != nil {
-		return nil, err
+		return nil, fmt.Errorf("defend claim: %w", err)
 	}
 	return &Claim{
 		ClaimData:           ClaimData{Value: value, Position: position},

op-challenger/fault/types.go

@@ -11,6 +11,14 @@ var (
 	ErrIndexTooLarge = errors.New("index is larger than the maximum index")
 )
 
+type GameStatus uint8
+
+const (
+	GameStatusInProgress GameStatus = iota
+	GameStatusChallengerWon
+	GameStatusDefenderWon
+)
+
 // StepCallData encapsulates the data needed to perform a step.
 type StepCallData struct {
 	ClaimIndex uint64

op-service/txmgr/txmgr.go

@@ -209,7 +209,7 @@ func (m *SimpleTxManager) craftTx(ctx context.Context, candidate TxCandidate) (*
 		Data:      candidate.TxData,
 	}
 
-	m.l.Info("creating tx", "to", rawTx.To, "from", m.cfg.From)
+	m.l.Info("Creating tx", "to", rawTx.To, "from", m.cfg.From)
 
 	// If the gas limit is set, we can use that as the gas
 	if candidate.GasLimit != 0 {
@@ -333,7 +333,7 @@ func (m *SimpleTxManager) sendTx(ctx context.Context, tx *types.Transaction) (*t
 // for the transaction.
 func (m *SimpleTxManager) publishAndWaitForTx(ctx context.Context, tx *types.Transaction, sendState *SendState, receiptChan chan *types.Receipt) {
 	log := m.l.New("hash", tx.Hash(), "nonce", tx.Nonce(), "gasTipCap", tx.GasTipCap(), "gasFeeCap", tx.GasFeeCap())
-	log.Info("publishing transaction")
+	log.Info("Publishing transaction")
 
 	cCtx, cancel := context.WithTimeout(ctx, m.cfg.NetworkTimeout)
 	defer cancel()