Fix issues (ethereum-optimism#147)

* feat(op-monitorism): enhance error handling and logging in withdrawal processes

- Added additional logging details in the monitor for enriched withdrawal events, including L1 block range.
- Improved error messages in L2 proxy and withdrawal validator to include context about failed backup clients.
- Updated the GethBackupClientsDictionary function to return a map of bad clients for better diagnostics.
- Enhanced the GetProvenWithdrawalsEventsIterator function to clarify block range in error messages.

* fix(monitor): update L2 Geth backup URLs logging format

- Changed the logging of L2 Geth backup URLs to join keys into a comma-separated string for improved readability.
- This enhancement ensures better clarity in the monitor's output regarding backup client configurations.

* refactor(env): remove deprecated L2 OP node URL and add backup Geth URLs

- Removed the L2 OP node URL from example environment files for clarity.
- Introduced a new configuration for L2 OP Geth backup URLs to enhance redundancy in monitoring setups.

* enhance(test): improve test command functionality in Makefile

- Updated the test target to allow for specific package testing by filtering based on command-line arguments.
- Added a placeholder rule to enable passing additional arguments to the test target, enhancing flexibility in test execution.

* docs(Makefile): update test command help message for clarity

- Modified the help output for the test command to specify that it can run tests for a specific module, enhancing user understanding of its functionality.

* feat(monitor): enhance block search algorithm and add unit tests

- Refactored the binary search method for finding blocks at approximate timestamps, improving logging and error handling.
- Introduced a new acceptable time difference constant for better clarity in block selection.
- Added unit tests for state management and event handling in faultproof withdrawals, ensuring robustness of the new features.

Author: raffaele-oplabs

op-monitorism/Makefile

@@ -42,7 +42,15 @@ clean:
 .PHONY: test
 test:
 	@echo "Running tests..."
-	$(GOTEST) ./... -v
+	@if [ "$(filter-out $@,$(MAKECMDGOALS))" != "" ]; then \
+		$(GOTEST) -v -count=1 ./$(filter-out $@,$(MAKECMDGOALS))/...; \
+	else \
+		$(GOTEST) ./... -v; \
+	fi
+
+# This allows passing arguments to the test target
+%:
+	@:
 
 #include tests that require live resources
 #these resources are meant to be real and not mocked
@@ -64,7 +72,7 @@ help:
 	@echo "  make build"
 	@echo "  make run"
 	@echo "  make clean"
-	@echo "  make test"
+	@echo "  make test [module]    # Run all tests or tests for a specific module (e.g. make test faultproof_withdrawals)"
 	@echo "  make test-live"
 	@echo "  make tidy"
 	@echo "  make help"

op-monitorism/faultproof_withdrawals/.env.op.mainnet.example

@@ -1,9 +1,9 @@
 FAULTPROOF_WITHDRAWAL_MON_L1_GETH_URL="<geth-url>"
-FAULTPROOF_WITHDRAWAL_MON_L2_OP_NODE_URL="<op-geth-node>"
 FAULTPROOF_WITHDRAWAL_MON_L2_OP_GETH_URL="<op-geth-url>"
 FAULTPROOF_WITHDRAWAL_MON_OPTIMISM_PORTAL="0xbEb5Fc579115071764c7423A4f12eDde41f106Ed" # This is the address of the Optimism portal contract, this should be for the chain you are monitoring
 FAULTPROOF_WITHDRAWAL_MON_START_BLOCK_HEIGHT=20872390 # This is the block height from which the monitoring will start, decide at which block height you want to start monitoring
 FAULTPROOF_WITHDRAWAL_MON_EVENT_BLOCK_RANGE=1000 # This is the range of blocks to be monitored
 MONITORISM_LOOP_INTERVAL_MSEC=100 # This is the interval in milliseconds for the monitoring loop
 MONITORISM_METRICS_PORT=7300 # This is the port on which the metrics server will run 
 MONITORISM_METRICS_ENABLED=true # This is the flag to enable/disable the metrics server
+FAULTPROOF_WITHDRAWAL_MON_L2_OP_GETH_BACKUP_URLS="alchemy=<alchemy-op-geth-url>,infura=<infura-op-geth-url>"

op-monitorism/faultproof_withdrawals/.env.op.sepolia.example

@@ -1,9 +1,9 @@
 FAULTPROOF_WITHDRAWAL_MON_L1_GETH_URL="<geth-url>"
-FAULTPROOF_WITHDRAWAL_MON_L2_OP_NODE_URL="<op-geth-node>"
 FAULTPROOF_WITHDRAWAL_MON_L2_OP_GETH_URL="<op-geth-url>"
 FAULTPROOF_WITHDRAWAL_MON_OPTIMISM_PORTAL="0x16Fc5058F25648194471939df75CF27A2fdC48BC" # This is the address of the Optimism portal contract, this should be for the chain you are monitoring
 FAULTPROOF_WITHDRAWAL_MON_START_BLOCK_HEIGHT=5914813 # This is the block height from which the monitoring will start, decide at which block height you want to start monitoring
 FAULTPROOF_WITHDRAWAL_MON_EVENT_BLOCK_RANGE=1000 # This is the range of blocks to be monitored
 MONITORISM_LOOP_INTERVAL_MSEC=100 # This is the interval in milliseconds for the monitoring loop
 MONITORISM_METRICS_PORT=7300 # This is the port on which the metrics server will run 
 MONITORISM_METRICS_ENABLED=true # This is the flag to enable/disable the metrics server
+FAULTPROOF_WITHDRAWAL_MON_L2_OP_GETH_BACKUP_URLS="alchemy=<alchemy-op-geth-url>,infura=<infura-op-geth-url>"

op-monitorism/faultproof_withdrawals/monitor.go

@@ -3,6 +3,7 @@ package faultproof_withdrawals
 import (
 	"context"
 	"fmt"
+	"math"
 	"math/big"
 	"strings"
 	"time"
@@ -11,13 +12,16 @@ import (
 	"github.com/ethereum-optimism/optimism/op-service/metrics"
 
 	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/core/types"
 	"github.com/ethereum/go-ethereum/ethclient"
 	"github.com/ethereum/go-ethereum/log"
+	"golang.org/x/exp/maps"
 )
 
 const (
 	MetricsNamespace                 = "faultproof_withdrawals"
 	DefaultHoursInThePastToStartFrom = 14 * 24 //14 days
+	acceptableDiffSec                = 3600    // 1h
 )
 
 // Monitor monitors the state and events related to withdrawal forgery.
@@ -163,100 +167,114 @@ func NewMonitor(ctx context.Context, log log.Logger, m metrics.Factory, cfg CLIC
 		"startingL1Height", startingL1BlockHeight,
 		"latestL1Height", latestL1Height,
 		"latestL2Height", latestL2Height,
-		"maxBlockRange", cfg.EventBlockRange)
+		"maxBlockRange", cfg.EventBlockRange,
+		"l1GethURL", cfg.L1GethURL,
+		"l2GethURL", cfg.L2OpGethURL,
+		"optimismPortalAddress", cfg.OptimismPortalAddress,
+		"l2GethBackupURLs", strings.Join(maps.Keys(mapL2GethBackupURLs), ","),
+		"hoursInThePastToStartFrom", hoursInThePastToStartFrom,
+		"startingL1BlockHeight", cfg.StartingL1BlockHeight,
+		"eventBlockRange", cfg.EventBlockRange,
+	)
 
 	return ret, nil
 }
 
 // getBlockAtApproximateTimeBinarySearch finds the block number corresponding to the timestamp from two weeks ago using a binary search approach.
-func (m *Monitor) getBlockAtApproximateTimeBinarySearch(ctx context.Context, client *ethclient.Client, latestBlockNumber *big.Int, hoursInThePast *big.Int) (*big.Int, error) {
-
-	secondsInThePast := hoursInThePast.Mul(hoursInThePast, big.NewInt(60*60))
-	m.log.Info("Looking for a block at approximate time of hours back",
-		"secondsInThePast", fmt.Sprintf("%v", secondsInThePast),
-		"time", fmt.Sprintf("%v", time.Now().Format("2006-01-02 15:04:05 MST")),
-		"latestBlockNumber", fmt.Sprintf("%v", latestBlockNumber))
-	// Calculate the total seconds in two weeks
-	targetTime := big.NewInt(time.Now().Unix())
-	targetTime.Sub(targetTime, secondsInThePast)
-
-	// Initialize the search range
-	left := big.NewInt(0)
-	right := new(big.Int).Set(latestBlockNumber)
-
-	var mid *big.Int
-	acceptablediff := big.NewInt(60 * 60) //60 minutes
+func (m *Monitor) getBlockAtApproximateTimeBinarySearch(
+	ctx context.Context,
+	client *ethclient.Client,
+	latest *big.Int,
+	hoursAgo *big.Int,
+) (*big.Int, error) {
+	m.log.Info("Starting binary search for block",
+		"hoursAgo", hoursAgo,
+		"latestBlock", fmt.Sprintf("%d", latest),
+		"acceptableDiffSec", acceptableDiffSec)
+
+	secondsAgo := new(big.Int).Mul(hoursAgo, big.NewInt(3600))
+	targetTs := big.NewInt(time.Now().Unix()).Sub(big.NewInt(time.Now().Unix()), secondsAgo)
+
+	m.log.Debug("Search parameters",
+		"secondsAgo", secondsAgo,
+		"targetTimestamp", time.Unix(targetTs.Int64(), 0).UTC().Format("2006-01-02 15:04:05 UTC"))
 
-	m.log.Debug("Starting binary search",
-		"targetTime", time.Unix(targetTime.Int64(), 0).Format("2006-01-02 15:04:05 MST"),
-		"leftBound", left.String(),
-		"rightBound", right.String(),
-		"acceptableDiffSeconds", acceptablediff.String())
+	left := big.NewInt(0)
+	right := new(big.Int).Set(latest)
+	best := new(big.Int)
+	var bestHdr *types.Header
+	bestDiffAbs := new(big.Int).SetUint64(math.MaxUint64)
+	iterations := 0
 
-	// Perform binary search
 	for left.Cmp(right) <= 0 {
-		//interrupt in case of context cancellation
-		select {
-		case <-ctx.Done():
-			return nil, fmt.Errorf("context cancelled")
-		default:
-		}
-
-		// Calculate the midpoint
-		mid = new(big.Int).Add(left, right)
+		iterations++
+		mid := new(big.Int).Add(left, right)
 		mid.Div(mid, big.NewInt(2))
 
 		m.log.Debug("Binary search iteration",
-			"left", left.String(),
-			"right", right.String(),
-			"mid", mid.String())
+			"iteration", iterations,
+			"left", left,
+			"right", right,
+			"mid", mid)
 
-		// Get the block at mid
-		block, err := client.BlockByNumber(context.Background(), mid)
+		hdr, err := client.HeaderByNumber(ctx, mid)
 		if err != nil {
-			m.log.Error("Failed to get block", "blockNumber", mid.String(), "error", err)
+			m.log.Error("Failed to get block header", "block", mid, "error", err)
 			return nil, err
 		}
 
-		// Check the block's timestamp
-		blockTime := big.NewInt(int64(block.Time()))
-		blockTimeFormatted := time.Unix(blockTime.Int64(), 0).Format("2006-01-02 15:04:05 MST")
-
-		//calculate the difference between the block time and the target time
-		diff := new(big.Int).Sub(blockTime, targetTime)
-		diffHours := new(big.Int).Div(diff, big.NewInt(3600))
+		blockTs := big.NewInt(int64(hdr.Time))
+		diffAbs := new(big.Int).Abs(new(big.Int).Sub(blockTs, targetTs))
+		diffHours := new(big.Int).Div(diffAbs, big.NewInt(3600))
 
 		m.log.Debug("Block time comparison",
-			"blockNumber", mid.String(),
-			"blockTime", blockTimeFormatted,
-			"timeDiffHours", diffHours.String(),
-			"timeDiffSeconds", diff.String())
-
-		// If block time is less than or equal to target time, check if we need to search to the right
-		if blockTime.Cmp(targetTime) <= 0 {
-			left.Set(mid) // Move left boundary up to mid
-			m.log.Debug("Moving left boundary up", "newLeft", left.String())
-		} else {
-			right.Sub(mid, big.NewInt(1)) // Move right boundary down
-			m.log.Debug("Moving right boundary down", "newRight", right.String())
+			"block", fmt.Sprintf("%d", mid),
+			"blockTime", time.Unix(int64(hdr.Time), 0).UTC().Format("2006-01-02 15:04:05 UTC"),
+			"timeDiffHours", diffHours,
+			"timeDiffSeconds", diffAbs)
+
+		if diffAbs.Cmp(bestDiffAbs) < 0 {
+			best.Set(mid)
+			bestHdr = hdr
+			bestDiffAbs.Set(diffAbs)
+			m.log.Debug("New best block found",
+				"block", fmt.Sprintf("%d", mid),
+				"timeDiff", diffAbs)
+			if bestDiffAbs.Cmp(big.NewInt(acceptableDiffSec)) <= 0 {
+				m.log.Debug("Found block within acceptable time difference", "diffSeconds", bestDiffAbs)
+				break
+			}
 		}
-		if new(big.Int).Abs(diff).Cmp(acceptablediff) <= 0 {
-			//if the difference is less than or equal to 1 hour, we can consider this block as the block closest to the target time
-			m.log.Debug("Found acceptable block",
-				"blockNumber", mid.String(),
-				"blockTime", blockTimeFormatted,
-				"timeDiffHours", diffHours.String())
-			break
+
+		if blockTs.Cmp(targetTs) < 0 {
+			left.Set(mid)
+			m.log.Debug("Moving left boundary", "newLeft", left)
+		} else {
+			right.Sub(mid, big.NewInt(1))
+			m.log.Debug("Moving right boundary", "newRight", right)
 		}
 	}
 
-	// log the block number closest to the target time and the time
 	m.log.Info("Found block closest to target time",
-		"block", left.String(),
-		"time", time.Unix(targetTime.Int64(), 0).Format("2006-01-02 15:04:05 MST"),
-		"blockTime", time.Unix(targetTime.Int64(), 0).Format("2006-01-02 15:04:05 MST"))
-	// After exiting the loop, left should be the block number closest to the target time
-	return left, nil
+		"block", fmt.Sprintf("%d", best),
+		"blockTs", time.Unix(int64(bestHdr.Time), 0).UTC().Format("2006-01-02 15:04:05 UTC"),
+		"targetTs", time.Unix(targetTs.Int64(), 0).UTC().Format("2006-01-02 15:04:05 UTC"),
+		"timeDiffHours", new(big.Int).Div(bestDiffAbs, big.NewInt(3600)),
+		"timeDiffSeconds", bestDiffAbs,
+		"iterations", iterations)
+
+	maxAllowedDiffSeconds := big.NewInt(30 * 60) // 30 minutes
+	// Validate that the found block is within a few minutes of the target time
+	if bestDiffAbs.Cmp(maxAllowedDiffSeconds) > 0 {
+		m.log.Error("Found block is too far from target time",
+			"block", fmt.Sprintf("%d", best),
+			"blockTime", time.Unix(int64(bestHdr.Time), 0).UTC().Format("2006-01-02 15:04:05 UTC"),
+			"targetTime", time.Unix(targetTs.Int64(), 0).UTC().Format("2006-01-02 15:04:05 UTC"),
+			"timeDiffSeconds", bestDiffAbs,
+			"maxAllowedDiffSeconds", maxAllowedDiffSeconds)
+	}
+
+	return best, nil
 }
 
 // GetLatestBlock retrieves the latest block number from the L1 Geth client.
@@ -324,24 +342,26 @@ func (m *Monitor) Run(ctx context.Context) {
 
 	// get new events
 	m.log.Info("Getting enriched withdrawal events",
-		"start", start,
-		"stop", stop,
-		"range", stop-start)
+		"l1BlockStart", fmt.Sprintf("%d", start),
+		"l1BlockStop", fmt.Sprintf("%d", stop),
+		"l1BlockRange", fmt.Sprintf("%d", stop-start))
 	newEvents, err := m.withdrawalValidator.GetEnrichedWithdrawalsEventsMap(start, &stop)
 
 	if err != nil {
 		if start >= stop {
 			m.log.Info("No new events to process", "start", start, "stop", stop)
 		} else if stop-start <= 1 {
 			m.log.Info("Failed to get enriched withdrawal events, range too small",
-				"error", err,
-				"start", start,
-				"stop", stop)
+				"l1BlockStart", fmt.Sprintf("%d", start),
+				"l1BlockStop", fmt.Sprintf("%d", stop),
+				"l1BlockRange", fmt.Sprintf("%d", stop-start),
+				"error", err)
 		} else {
 			m.log.Error("Failed to get enriched withdrawal events",
-				"error", err,
-				"start", start,
-				"stop", stop)
+				"l1BlockStart", fmt.Sprintf("%d", start),
+				"l1BlockStop", fmt.Sprintf("%d", stop),
+				"l1BlockRange", fmt.Sprintf("%d", stop-start),
+				"error", err)
 		}
 		return
 	}

op-monitorism/faultproof_withdrawals/state_test.go

@@ -0,0 +1,92 @@
+package faultproof_withdrawals
+
+import (
+	"testing"
+
+	"github.com/ethereum-optimism/monitorism/op-monitorism/faultproof_withdrawals/validator"
+	"github.com/ethereum/go-ethereum/common"
+	oplog "github.com/ethereum/go-ethereum/log"
+	lru "github.com/hashicorp/golang-lru"
+	"github.com/stretchr/testify/require"
+)
+
+// newTestState creates a minimal State instance with the internal maps / cache
+// initialised so that the increment-helpers can run without panicking.
+func newTestState() *State {
+	cache, _ := lru.New(10)
+
+	return &State{
+		logger:                                oplog.New(),
+		potentialAttackOnDefenderWinsGames:    make(map[common.Hash]*validator.EnrichedProvenWithdrawalEvent),
+		potentialAttackOnInProgressGames:      make(map[common.Hash]*validator.EnrichedProvenWithdrawalEvent),
+		suspiciousEventsOnChallengerWinsGames: cache,
+	}
+}
+
+// newTestEvent builds a synthetic EnrichedProvenWithdrawalEvent whose
+// TxHash is derived from the supplied hex string.
+func newTestEvent(txHashHex string) *validator.EnrichedProvenWithdrawalEvent {
+	txHash := common.HexToHash(txHashHex)
+	withdrawalEvent := &validator.WithdrawalProvenExtension1Event{
+		Raw: validator.Raw{
+			BlockNumber: 1,
+			TxHash:      txHash,
+		},
+	}
+
+	return &validator.EnrichedProvenWithdrawalEvent{
+		Event: withdrawalEvent,
+	}
+}
+
+func TestIncrementWithdrawalsValidated(t *testing.T) {
+	st := newTestState()
+	evt := newTestEvent("0x1")
+
+	st.IncrementWithdrawalsValidated(evt)
+
+	require.Equal(t, uint64(1), st.withdrawalsProcessed)
+	require.NotZero(t, evt.ProcessedTimeStamp)
+}
+
+func TestIncrementPotentialAttackOnDefenderWinsGames(t *testing.T) {
+	st := newTestState()
+	evt := newTestEvent("0x2")
+
+	st.IncrementPotentialAttackOnDefenderWinsGames(evt)
+
+	require.Equal(t, uint64(1), st.numberOfPotentialAttacksOnDefenderWinsGames)
+	require.Equal(t, 1, len(st.potentialAttackOnDefenderWinsGames))
+	require.Equal(t, uint64(1), st.withdrawalsProcessed)
+	require.NotZero(t, evt.ProcessedTimeStamp)
+}
+
+func TestIncrementPotentialAttackOnInProgressGames(t *testing.T) {
+	st := newTestState()
+	evt := newTestEvent("0x3")
+
+	st.IncrementPotentialAttackOnInProgressGames(evt)
+
+	require.Equal(t, uint64(1), st.numberOfPotentialAttackOnInProgressGames)
+	require.Equal(t, 1, len(st.potentialAttackOnInProgressGames))
+	require.Equal(t, uint64(0), st.withdrawalsProcessed)
+	require.NotZero(t, evt.ProcessedTimeStamp)
+}
+
+func TestIncrementSuspiciousEventsOnChallengerWinsGames(t *testing.T) {
+	st := newTestState()
+	evt := newTestEvent("0x4")
+
+	// First mark the event as in-progress to exercise the removal path.
+	st.IncrementPotentialAttackOnInProgressGames(evt)
+
+	require.Equal(t, uint64(1), st.numberOfPotentialAttackOnInProgressGames, "setup failed: expected 1 in-progress event")
+
+	st.IncrementSuspiciousEventsOnChallengerWinsGames(evt)
+
+	require.Equal(t, uint64(1), st.numberOfSuspiciousEventsOnChallengerWinsGames)
+	require.Equal(t, 1, st.suspiciousEventsOnChallengerWinsGames.Len())
+	require.Equal(t, uint64(0), st.numberOfPotentialAttackOnInProgressGames, "expected 0 after removal")
+	require.Equal(t, uint64(1), st.withdrawalsProcessed)
+	require.NotZero(t, evt.ProcessedTimeStamp)
+}