fix: remove duplicate logs (#261)

There are two fixes to the logging done in `saexec/execution.go`:
1. When encountering a FATAL error, there would be two log entries. One
logged by the `execute` function and one by the `processQueue` function.
Now only the `processQueue` function reports errors.
2. Inside `execute`, we overwrote `logger` with `logger = logger.With(`
for every tx iteration. This causes O(n^2) memory allocations.

Related (but non-functional) changes:
- `logger` was renamed to `log` to align with the rest of the codebase.
- `log := log.With(` was replaced with `blockLog := log.With(` in
`sae/block_builder.go` to avoid any potential future O(n^2) memory
allocations (and to align with the `txLog` and `opLog` that is performed
in the rest of the function).

Author: StephenButtolph

sae/block_builder.go

@@ -193,19 +193,19 @@ func (b *blockBuilderG[T]) buildWithTxs(
 
 	unsettled := blocks.Range(lastSettled, parent)
 	for _, block := range unsettled {
-		log := log.With(
+		blockLog := log.With(
 			zap.Uint64("block_height", block.Height()),
 			zap.Stringer("block_hash", block.Hash()),
 		)
 		if err := state.StartBlock(block.Header()); err != nil {
-			log.Warn("Could not start historical worst-case calculation",
+			blockLog.Warn("Could not start historical worst-case calculation",
 				zap.Error(err),
 			)
 			return nil, fmt.Errorf("starting worst-case state for block %d: %v", block.Height(), err)
 		}
 		for i, tx := range block.Transactions() {
 			if err := state.ApplyTx(tx); err != nil {
-				log.Warn("Could not apply tx during historical worst-case calculation",
+				blockLog.Warn("Could not apply tx during historical worst-case calculation",
 					zap.Int("tx_index", i),
 					zap.Stringer("tx_hash", tx.Hash()),
 					zap.Error(err),
@@ -215,14 +215,14 @@ func (b *blockBuilderG[T]) buildWithTxs(
 		}
 		ops, err := b.hooks.EndOfBlockOps(block.EthBlock())
 		if err != nil {
-			log.Warn("Could not extract ops during historical worst-case calculation",
+			blockLog.Warn("Could not extract ops during historical worst-case calculation",
 				zap.Error(err),
 			)
 			return nil, fmt.Errorf("extracting ops of block %d to worst-case state: %v", block.Height(), err)
 		}
 		for i, op := range ops {
 			if err := state.Apply(op); err != nil {
-				log.Warn("Could not apply op during historical worst-case calculation",
+				blockLog.Warn("Could not apply op during historical worst-case calculation",
 					zap.Int("op_index", i),
 					zap.Stringer("op_id", op.ID),
 					zap.Error(err),
@@ -231,7 +231,7 @@ func (b *blockBuilderG[T]) buildWithTxs(
 			}
 		}
 		if _, err := state.FinishBlock(); err != nil {
-			log.Warn("Could not finish historical worst-case calculation",
+			blockLog.Warn("Could not finish historical worst-case calculation",
 				zap.Error(err),
 			)
 			return nil, fmt.Errorf("finishing worst-case state for block %d: %v", block.Height(), err)

saexec/execution.go

@@ -51,7 +51,7 @@ func (e *Executor) Enqueue(ctx context.Context, block *blocks.Block) error {
 	}
 }
 
-var emergencyPlaybookLink = zap.String("playbook", "https://github.com/ava-labs/strevm/issues/28")
+const emergencyPlaybookLink = "https://github.com/ava-labs/strevm/issues/28"
 
 func (e *Executor) processQueue() {
 	defer close(e.done)
@@ -62,27 +62,39 @@ func (e *Executor) processQueue() {
 			return
 
 		case block := <-e.queue:
-			logger := e.log.With(
+			log := e.log.With(
 				zap.Uint64("block_height", block.Height()),
 				zap.Uint64("block_time", block.BuildTime()),
 				zap.Stringer("block_hash", block.Hash()),
 				zap.Int("tx_count", len(block.Transactions())),
 			)
 
-			if err := e.execute(block, logger); err != nil {
-				logger.Fatal(
-					"Block execution failed; see emergency playbook",
-					emergencyPlaybookLink,
+			err := e.execute(block, log)
+			switch {
+			case errors.Is(err, errFatal):
+				log.Fatal( //nolint:gocritic // False positive, will not terminate the process
+					"Block execution failed",
+					zap.String("playbook", emergencyPlaybookLink),
 					zap.Error(err),
 				)
+			case err != nil:
+				log.Error(
+					"Error of unknown severity in block execution",
+					zap.String("if_escalation_required", emergencyPlaybookLink),
+					zap.Error(err),
+				)
+			}
+			if err != nil {
 				return
 			}
 		}
 	}
 }
 
-func (e *Executor) execute(b *blocks.Block, logger logging.Logger) error {
-	logger.Debug("Executing block")
+var errFatal = errors.New("fatal execution error")
+
+func (e *Executor) execute(b *blocks.Block, log logging.Logger) error {
+	log.Debug("Executing block")
 
 	// Since `b` hasn't been executed, it definitely hasn't been settled, so we
 	// are guaranteed to have a non-nil parent available.
@@ -122,11 +134,6 @@ func (e *Executor) execute(b *blocks.Block, logger logging.Logger) error {
 		stateDB.SetTxContext(tx.Hash(), ti)
 		b.CheckSenderBalanceBound(stateDB, signer, tx)
 
-		logger = logger.With(
-			zap.Int("tx_index", ti),
-			zap.Stringer("tx_hash", tx.Hash()),
-		)
-
 		receipt, err := core.ApplyTransaction(
 			e.chainConfig,
 			e.chainContext,
@@ -139,12 +146,7 @@ func (e *Executor) execute(b *blocks.Block, logger logging.Logger) error {
 			vm.Config{},
 		)
 		if err != nil {
-			logger.Fatal(
-				"Transaction execution errored (not reverted); see emergency playbook",
-				emergencyPlaybookLink,
-				zap.Error(err),
-			)
-			return err
+			return fmt.Errorf("%w: transaction execution errored (not reverted) [%d](%#x): %v", errFatal, ti, tx.Hash(), err)
 		}
 
 		perTxClock.Tick(gas.Gas(receipt.GasUsed))
@@ -180,12 +182,7 @@ func (e *Executor) execute(b *blocks.Block, logger logging.Logger) error {
 	numTxs := len(b.Transactions())
 	ops, err := e.hooks.EndOfBlockOps(b.EthBlock())
 	if err != nil {
-		logger.Fatal(
-			"Unable to extract extra block operations; see emergency playbook",
-			emergencyPlaybookLink,
-			zap.Error(err),
-		)
-		return err
+		return fmt.Errorf("%w: %T.EndOfBlockOps(%#x): %v", errFatal, e.hooks, b.Hash(), err)
 	}
 	for i, o := range ops {
 		b.CheckOpBurnerBalanceBounds(stateDB, numTxs+i, o)
@@ -194,14 +191,7 @@ func (e *Executor) execute(b *blocks.Block, logger logging.Logger) error {
 		b.SetInterimExecutionTime(perTxClock)
 
 		if err := o.ApplyTo(stateDB); err != nil {
-			logger.Fatal(
-				"Extra block operation errored; see emergency playbook",
-				zap.Int("op_index", i),
-				zap.Stringer("op_id", o.ID),
-				emergencyPlaybookLink,
-				zap.Error(err),
-			)
-			return err
+			return fmt.Errorf("%w: applying end-of-block operation [%d](%v): %v", errFatal, i, o.ID, err)
 		}
 	}
 
@@ -211,7 +201,7 @@ func (e *Executor) execute(b *blocks.Block, logger logging.Logger) error {
 		return fmt.Errorf("after-block gas time update: %w", err)
 	}
 
-	logger.Debug(
+	log.Debug(
 		"Block execution complete",
 		zap.Uint64("gas_consumed", uint64(blockGasConsumed)),
 		zap.Time("gas_time", gasClock.AsTime()),