feat(tx_pool): check if trace log level is set before using trace log (…

…#1545)

* feat(tx_pool): check if trace log level is set before using trace log

* fix: tests

eth/ethconfig/config_zkevm.go

@@ -5,6 +5,7 @@ import (
 
 	"github.com/c2h5oh/datasize"
 	"github.com/ledgerwatch/erigon-lib/common"
+	"github.com/ledgerwatch/erigon/zk/utils"
 )
 
 type Zk struct {
@@ -98,6 +99,7 @@ type Zk struct {
 	WitnessCacheEnabled            bool
 	WitnessCacheLimit              uint64
 	WitnessContractInclusion       []common.Address
+	LogLevel                       utils.LogLevel
 }
 
 var DefaultZkConfig = &Zk{}

eth/stagedsync/stage_execute_zkevm.go

@@ -85,7 +85,7 @@ func SpawnExecuteBlocksStageZk(s *StageState, u Unwinder, tx kv.RwTx, toBlock ui
 		batch.Close()
 	}()
 
-	if err := utils.UpdateZkEVMBlockCfg(cfg.chainConfig, hermezDb, s.LogPrefix()); err != nil {
+	if err := utils.UpdateZkEVMBlockCfg(cfg.chainConfig, hermezDb, s.LogPrefix(), cfg.zk.LogLevel.IsTraceLogLevelSet()); err != nil {
 		return fmt.Errorf("UpdateZkEVMBlockCfg: %w", err)
 	}
 

turbo/cli/flags_zkevm.go

@@ -3,6 +3,7 @@ package cli
 import (
 	"fmt"
 	"math"
+	"os"
 	"strconv"
 	"strings"
 	"time"
@@ -155,6 +156,8 @@ func ApplyFlagsForZkConfig(ctx *cli.Context, cfg *ethconfig.Config) {
 		witnessInclusion = append(witnessInclusion, libcommon.HexToAddress(s))
 	}
 
+	logLevel := os.Getenv("LOG_LEVEL")
+
 	cfg.Zk = &ethconfig.Zk{
 		L2ChainId:                              ctx.Uint64(utils.L2ChainIdFlag.Name),
 		L2RpcUrl:                               ctx.String(utils.L2RpcUrlFlag.Name),
@@ -237,6 +240,7 @@ func ApplyFlagsForZkConfig(ctx *cli.Context, cfg *ethconfig.Config) {
 		MockWitnessGeneration:                  ctx.Bool(utils.MockWitnessGeneration.Name),
 		WitnessCacheLimit:                      witnessCacheLimit,
 		WitnessContractInclusion:               witnessInclusion,
+		LogLevel:                               utils2.LogLevel(logLevel),
 	}
 
 	utils2.EnableTimer(cfg.DebugTimers)

turbo/jsonrpc/eth_api.go

@@ -131,6 +131,7 @@ type BaseAPI struct {
 	dirs           datadir.Dirs
 	l2RpcUrl       string
 	gasless        bool
+	logLevel       utils.LogLevel
 }
 
 func NewBaseApi(f *rpchelper.Filters, stateCache kvcache.Cache, blockReader services.FullBlockReader, agg *libstate.Aggregator, singleNodeMode bool, evmCallTimeout time.Duration, engine consensus.EngineReader, dirs datadir.Dirs) *BaseAPI {
@@ -171,7 +172,7 @@ func (api *BaseAPI) chainConfig(ctx context.Context, tx kv.Tx) (*chain.Config, e
 
 	//[zkevm] get dynamic fork config
 	hermezDb := hermez_db.NewHermezDbReader(tx)
-	if err := utils.UpdateZkEVMBlockCfg(cfg, hermezDb, ""); err != nil {
+	if err := utils.UpdateZkEVMBlockCfg(cfg, hermezDb, "", api.logLevel.IsTraceLogLevelSet()); err != nil {
 		return cfg, err
 	}
 
@@ -375,6 +376,7 @@ type APIImpl struct {
 	SubscribeLogsChannelSize    int
 	logger                      log.Logger
 	VirtualCountersSmtReduction float64
+	logLevel                    utils.LogLevel
 }
 
 // NewEthAPI returns APIImpl instance
@@ -383,6 +385,8 @@ func NewEthAPI(base *BaseAPI, db kv.RoDB, eth rpchelper.ApiBackend, txPool txpoo
 		gascap = uint64(math.MaxUint64 / 2)
 	}
 
+	base.logLevel = ethCfg.LogLevel
+
 	return &APIImpl{
 		BaseAPI:                     base,
 		db:                          db,

zk/stages/stage_sequence_execute.go

@@ -167,7 +167,7 @@ func sequencingBatchStep(
 		return err
 	}
 
-	if err := utils.UpdateZkEVMBlockCfg(cfg.chainConfig, sdb.hermezDb, logPrefix); err != nil {
+	if err := utils.UpdateZkEVMBlockCfg(cfg.chainConfig, sdb.hermezDb, logPrefix, cfg.zk.LogLevel.IsTraceLogLevelSet()); err != nil {
 		return err
 	}
 

zk/txpool/pool.go

@@ -40,6 +40,7 @@ import (
 	"github.com/holiman/uint256"
 	"github.com/ledgerwatch/erigon-lib/txpool/txpoolcfg"
 	"github.com/ledgerwatch/erigon/eth/ethconfig"
+	"github.com/ledgerwatch/erigon/zk/utils"
 	"github.com/ledgerwatch/log/v3"
 	"github.com/status-im/keycard-go/hexutils"
 
@@ -335,6 +336,8 @@ type TxPool struct {
 
 	// limbo specific fields where bad batch transactions identified by the executor go
 	limbo *Limbo
+
+	logLevel utils.LogLevel
 }
 
 func CreateTxPoolBuckets(tx kv.RwTx) error {
@@ -365,6 +368,11 @@ func New(newTxs chan types.Announcements, coreDB kv.RoDB, cfg txpoolcfg.Config,
 		tracedSenders[common.BytesToAddress([]byte(sender))] = struct{}{}
 	}
 
+	logLevel := utils.LogLevel("")
+	if ethCfg.Zk != nil {
+		logLevel = ethCfg.Zk.LogLevel
+	}
+
 	return &TxPool{
 		lock:                    &sync.Mutex{},
 		byHash:                  map[string]*metaTx{},
@@ -389,6 +397,7 @@ func New(newTxs chan types.Announcements, coreDB kv.RoDB, cfg txpoolcfg.Config,
 		flushMtx:                &sync.Mutex{},
 		aclDB:                   aclDB,
 		limbo:                   newLimbo(),
+		logLevel:                logLevel,
 	}, nil
 }
 

zk/txpool/pool_zk.go

@@ -31,6 +31,12 @@ func calcProtocolBaseFee(baseFee uint64) uint64 {
 	return 0
 }
 
+func (p *TxPool) Trace(msg string, ctx ...interface{}) {
+	if p.logLevel.IsTraceLogLevelSet() {
+		log.Trace(msg, ctx...)
+	}
+}
+
 // onSenderStateChange is the function that recalculates ephemeral fields of transactions and determines
 // which sub pool they will need to go to. Sice this depends on other transactions from the same sender by with lower
 // nonces, and also affect other transactions from the same sender with higher nonce, it loops through all transactions
@@ -154,13 +160,13 @@ func (p *TxPool) best(n uint16, txs *types.TxsRlp, tx kv.Tx, onTopOf, availableG
 	defer p.lock.Unlock()
 
 	if p.isDeniedYieldingTransactions() {
-		log.Trace("Denied yielding transactions, cannot proceed")
+		p.Trace("Denied yielding transactions, cannot proceed")
 		return false, 0, nil
 	}
 
 	// First wait for the corresponding block to arrive
 	if p.lastSeenBlock.Load() < onTopOf {
-		log.Trace("Block not yet arrived, too early to process", "lastSeenBlock", p.lastSeenBlock.Load(), "requiredBlock", onTopOf)
+		p.Trace("Block not yet arrived, too early to process", "lastSeenBlock", p.lastSeenBlock.Load(), "requiredBlock", onTopOf)
 		return false, 0, nil
 	}
 
@@ -182,42 +188,42 @@ func (p *TxPool) best(n uint16, txs *types.TxsRlp, tx kv.Tx, onTopOf, availableG
 		}
 
 		mt := best.ms[i]
-		log.Trace("Processing transaction", "txID", mt.Tx.IDHash)
+		p.Trace("Processing transaction", "txID", mt.Tx.IDHash)
 
 		if toSkip.Contains(mt.Tx.IDHash) {
-			log.Trace("Skipping transaction, already in toSkip", "txID", mt.Tx.IDHash)
+			p.Trace("Skipping transaction, already in toSkip", "txID", mt.Tx.IDHash)
 			continue
 		}
 
 		if !isLondon && mt.Tx.Type == 0x2 {
 			// remove ldn txs when not in london
 			toRemove = append(toRemove, mt)
 			toSkip.Add(mt.Tx.IDHash)
-			log.Trace("Removing London transaction in non-London environment", "txID", mt.Tx.IDHash)
+			p.Trace("Removing London transaction in non-London environment", "txID", mt.Tx.IDHash)
 			continue
 		}
 
 		if mt.Tx.Gas > transactionGasLimit {
 			// Skip transactions with very large gas limit, these shouldn't enter the pool at all
 			log.Debug("found a transaction in the pending pool with too high gas for tx - clear the tx pool")
-			log.Trace("Skipping transaction with too high gas", "txID", mt.Tx.IDHash, "gas", mt.Tx.Gas)
+			p.Trace("Skipping transaction with too high gas", "txID", mt.Tx.IDHash, "gas", mt.Tx.Gas)
 			continue
 		}
 		rlpTx, sender, isLocal, err := p.getRlpLocked(tx, mt.Tx.IDHash[:])
 		if err != nil {
-			log.Trace("Error getting RLP of transaction", "txID", mt.Tx.IDHash, "error", err)
+			p.Trace("Error getting RLP of transaction", "txID", mt.Tx.IDHash, "error", err)
 			return false, count, err
 		}
 		if len(rlpTx) == 0 {
 			toRemove = append(toRemove, mt)
-			log.Trace("Removing transaction with empty RLP", "txID", mt.Tx.IDHash)
+			p.Trace("Removing transaction with empty RLP", "txID", mt.Tx.IDHash)
 			continue
 		}
 
 		// Skip transactions that require more blob gas than is available
 		blobCount := uint64(len(mt.Tx.BlobHashes))
 		if blobCount*fixedgas.BlobGasPerBlob > availableBlobGas {
-			log.Trace("Skipping transaction due to insufficient blob gas", "txID", mt.Tx.IDHash, "requiredBlobGas", blobCount*fixedgas.BlobGasPerBlob, "availableBlobGas", availableBlobGas)
+			p.Trace("Skipping transaction due to insufficient blob gas", "txID", mt.Tx.IDHash, "requiredBlobGas", blobCount*fixedgas.BlobGasPerBlob, "availableBlobGas", availableBlobGas)
 			continue
 		}
 		availableBlobGas -= blobCount * fixedgas.BlobGasPerBlob
@@ -228,15 +234,15 @@ func (p *TxPool) best(n uint16, txs *types.TxsRlp, tx kv.Tx, onTopOf, availableG
 		intrinsicGas, _ := CalcIntrinsicGas(uint64(mt.Tx.DataLen), uint64(mt.Tx.DataNonZeroLen), nil, mt.Tx.Creation, true, true, isShanghai)
 		if intrinsicGas > availableGas {
 			// we might find another TX with a low enough intrinsic gas to include so carry on
-			log.Trace("Skipping transaction due to insufficient gas", "txID", mt.Tx.IDHash, "intrinsicGas", intrinsicGas, "availableGas", availableGas)
+			p.Trace("Skipping transaction due to insufficient gas", "txID", mt.Tx.IDHash, "intrinsicGas", intrinsicGas, "availableGas", availableGas)
 			continue
 		}
 
 		if intrinsicGas <= availableGas { // check for potential underflow
 			availableGas -= intrinsicGas
 		}
 
-		log.Trace("Including transaction", "txID", mt.Tx.IDHash)
+		p.Trace("Including transaction", "txID", mt.Tx.IDHash)
 		txs.Txs[count] = rlpTx
 		txs.TxIds[count] = mt.Tx.IDHash
 		copy(txs.Senders.At(count), sender.Bytes())
@@ -249,7 +255,7 @@ func (p *TxPool) best(n uint16, txs *types.TxsRlp, tx kv.Tx, onTopOf, availableG
 	if len(toRemove) > 0 {
 		for _, mt := range toRemove {
 			p.pending.Remove(mt)
-			log.Trace("Removed transaction from pending pool", "txID", mt.Tx.IDHash)
+			p.Trace("Removed transaction from pending pool", "txID", mt.Tx.IDHash)
 		}
 	}
 	return true, count, nil

zk/utils/utils.go

@@ -3,6 +3,7 @@ package utils
 import (
 	"errors"
 	"fmt"
+	"strings"
 
 	"github.com/ledgerwatch/erigon-lib/chain"
 	libcommon "github.com/ledgerwatch/erigon-lib/common"
@@ -87,7 +88,7 @@ type DbReader interface {
 	GetHighestBlockInBatch(batchNo uint64) (uint64, bool, error)
 }
 
-func UpdateZkEVMBlockCfg(cfg ForkConfigWriter, hermezDb ForkReader, logPrefix string) error {
+func UpdateZkEVMBlockCfg(cfg ForkConfigWriter, hermezDb ForkReader, logPrefix string, shouldPrintTrace bool) error {
 	var lastSetBlockNum uint64 = 0
 	var foundAny bool = false
 
@@ -101,10 +102,14 @@ func UpdateZkEVMBlockCfg(cfg ForkConfigWriter, hermezDb ForkReader, logPrefix st
 			lastSetBlockNum = blockNum
 			foundAny = true
 		} else if !foundAny {
-			log.Trace(fmt.Sprintf("[%s] No block number found for fork id %v and no previous block number set", logPrefix, forkId))
+			if shouldPrintTrace {
+				log.Trace(fmt.Sprintf("[%s] No block number found for fork id %v and no previous block number set", logPrefix, forkId))
+			}
 			continue
 		} else {
-			log.Trace(fmt.Sprintf("[%s] No block number found for fork id %v, using last set block number: %v", logPrefix, forkId, lastSetBlockNum))
+			if shouldPrintTrace {
+				log.Trace(fmt.Sprintf("[%s] No block number found for fork id %v, using last set block number: %v", logPrefix, forkId, lastSetBlockNum))
+			}
 		}
 
 		if err := cfg.SetForkIdBlock(forkId, lastSetBlockNum); err != nil {
@@ -227,3 +232,13 @@ func CalculateBatchData(batchBlockData []BatchBlockData) (batchL2Data []byte, er
 
 	return batchL2Data, err
 }
+
+type LogLevel string
+
+// function to check if log level is trace
+func (ll *LogLevel) IsTraceLogLevelSet() bool {
+	if ll == nil {
+		return false
+	}
+	return strings.ToLower(string(*ll)) == "trace"
+}

zk/utils/utils_test.go

@@ -85,7 +85,7 @@ func TestUpdateZkEVMBlockCfg(t *testing.T) {
 			cfg := NewTestConfig()
 			reader := &SimpleForkReader{BlockForks: scenario.blockForks}
 
-			err := UpdateZkEVMBlockCfg(cfg, reader, "TestPrefix")
+			err := UpdateZkEVMBlockCfg(cfg, reader, "TestPrefix", false)
 			assert.NoError(t, err, "should not return an error")
 
 			assert.Equal(t, scenario.expectedCalls, cfg.setCalls, "SetForkIdBlock calls mismatch")