From 5a58f0ed8622b0e57ffd649bb1b9187bdb0009b2 Mon Sep 17 00:00:00 2001 From: Michael Gu Date: Wed, 3 Oct 2018 16:16:46 -0400 Subject: [PATCH 1/4] added print statements to tx_pool.go and worker.go to log the mining process --- core/tx_pool.go | 29 +++++++++++++++++++++++++++++ miner/worker.go | 27 +++++++++++++++++++++++++++ 2 files changed, 56 insertions(+) diff --git a/core/tx_pool.go b/core/tx_pool.go index f6da5da2a7..d3ee87bbd8 100644 --- a/core/tx_pool.go +++ b/core/tx_pool.go @@ -33,6 +33,10 @@ import ( "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/metrics" "github.com/ethereum/go-ethereum/params" + + "github.com/jimlawless/whereami" + "github.com/natefinch/lumberjack" + l "log" ) const ( @@ -215,6 +219,14 @@ type TxPool struct { // NewTxPool creates a new transaction pool to gather, sort and filter inbound // transactions from the network. func NewTxPool(config TxPoolConfig, chainconfig *params.ChainConfig, chain blockChain) *TxPool { + l.SetOutput(&lumberjack.Logger{ + Filename: "../miner.log", + MaxSize: 500, + MaxBackups: 3, + MaxAge: 28, + Compress: true, + }) + // Sanitize the input to ensure no vulnerable gas prices are set config = (&config).sanitize() @@ -566,15 +578,19 @@ func (pool *TxPool) local() map[common.Address]types.Transactions { // validateTx checks whether a transaction is valid according to the consensus // rules and adheres to some heuristic limits of the local node (price and size). func (pool *TxPool) validateTx(tx *types.Transaction, local bool) error { + l.Printf("Pool beginning standard validation using local heuristics @ %s\n\n", whereami.WhereAmI()) + // Heuristic limit, reject transactions over 32KB to prevent DOS attacks if tx.Size() > 32*1024 { return ErrOversizedData } + l.Println("Txn passed size limit of 32KB\n") // Transactions can't be negative. This may never happen using RLP decoded // transactions but may occur if you create a transaction using the RPC. if tx.Value().Sign() < 0 { return ErrNegativeValue } + l.Println("Txn passed non-negative check\n") // Ensure the transaction doesn't exceed the current block limit gas. if pool.currentMaxGas < tx.Gas() { return ErrGasLimit @@ -584,20 +600,24 @@ func (pool *TxPool) validateTx(tx *types.Transaction, local bool) error { if err != nil { return ErrInvalidSender } + l.Println("Txn signed properly\n") // Drop non-local transactions under our own minimal accepted gas price local = local || pool.locals.contains(from) // account may be local even if the transaction arrived from the network if !local && pool.gasPrice.Cmp(tx.GasPrice()) > 0 { return ErrUnderpriced } + l.Printf("Txn gas price of %v is above our pool's acceptable gas price of %v\n\n", tx.GasPrice(), pool.gasPrice) // Ensure the transaction adheres to nonce ordering if pool.currentState.GetNonce(from) > tx.Nonce() { return ErrNonceTooLow } + l.Println("Txn correctly ordered by nonce\n") // Transactor should have enough funds to cover the costs // cost == V + GP * GL if pool.currentState.GetBalance(from).Cmp(tx.Cost()) < 0 { return ErrInsufficientFunds } + l.Printf("Sender has sufficient balance of %v to cover txn cost of %v\n\n", pool.currentState.GetBalance(from), tx.Cost()) intrGas, err := IntrinsicGas(tx.Data(), tx.To() == nil, pool.homestead) if err != nil { return err @@ -605,6 +625,7 @@ func (pool *TxPool) validateTx(tx *types.Transaction, local bool) error { if tx.Gas() < intrGas { return ErrIntrinsicGas } + l.Printf("Txn gas used (%v) is under max intrinsic gas threshold of %v\n\n", tx.Gas(), intrGas) return nil } @@ -624,11 +645,13 @@ func (pool *TxPool) add(tx *types.Transaction, local bool) (bool, error) { return false, fmt.Errorf("known transaction: %x", hash) } // If the transaction fails basic validation, discard it + l.Printf("Pool found incoming txn, queueing new txn with hash: %x @ %s\n\n", hash, whereami.WhereAmI()) if err := pool.validateTx(tx, local); err != nil { log.Trace("Discarding invalid transaction", "hash", hash, "err", err) invalidTxCounter.Inc(1) return false, err } + l.Printf("New txn passed all basic standard validation heuristics @ %s\n\n", whereami.WhereAmI()) // If the transaction pool is full, discard underpriced transactions if uint64(pool.all.Count()) >= pool.config.GlobalSlots+pool.config.GlobalQueue { // If the new transaction is underpriced, don't accept it @@ -937,12 +960,15 @@ func (pool *TxPool) promoteExecutables(accounts []common.Address) { continue // Just in case someone calls with a non existing account } // Drop all transactions that are deemed too old (low nonce) + l.Println("Pool dropping old queued txns\n") for _, tx := range list.Forward(pool.currentState.GetNonce(addr)) { hash := tx.Hash() log.Trace("Removed old queued transaction", "hash", hash) pool.all.Remove(hash) pool.priced.Removed() + l.Printf("Pool dropped old txn with hash: %x\n\n", hash) } + l.Println("Pool dropping unpayabe txns (low balance/no gas)\n") // Drop all transactions that are too costly (low balance or out of gas) drops, _ := list.Filter(pool.currentState.GetBalance(addr), pool.currentMaxGas) for _, tx := range drops { @@ -951,12 +977,15 @@ func (pool *TxPool) promoteExecutables(accounts []common.Address) { pool.all.Remove(hash) pool.priced.Removed() queuedNofundsCounter.Inc(1) + l.Printf("Pool dropped unpayable txn with hash: %x\n\n", hash) } // Gather all executable transactions and promote them + l.Println("Pool promoting txns ready for execution\n") for _, tx := range list.Ready(pool.pendingState.GetNonce(addr)) { hash := tx.Hash() if pool.promoteTx(addr, hash, tx) { log.Trace("Promoting queued transaction", "hash", hash) + l.Printf("Pool promoting queued txn with hash: %x\n\n", hash) promoted = append(promoted, tx) } } diff --git a/miner/worker.go b/miner/worker.go index 8579c5c84b..51bf65e68a 100644 --- a/miner/worker.go +++ b/miner/worker.go @@ -35,6 +35,10 @@ import ( "github.com/ethereum/go-ethereum/event" "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/params" + + "github.com/jimlawless/whereami" + "github.com/natefinch/lumberjack" + l "log" ) const ( @@ -180,6 +184,14 @@ type worker struct { } func newWorker(config *params.ChainConfig, engine consensus.Engine, eth Backend, mux *event.TypeMux, recommit time.Duration, gasFloor, gasCeil uint64, isLocalBlock func(*types.Block) bool) *worker { + l.SetOutput(&lumberjack.Logger{ + Filename: "../miner.log", + MaxSize: 500, + MaxBackups: 3, + MaxAge: 28, + Compress: true, + }) + worker := &worker{ config: config, engine: engine, @@ -693,6 +705,8 @@ func (w *worker) commitTransaction(tx *types.Transaction, coinbase common.Addres snap := w.current.state.Snapshot() receipt, _, err := core.ApplyTransaction(w.config, w.chain, &coinbase, w.current.gasPool, w.current.state, w.current.header, tx, &w.current.header.GasUsed, vm.Config{}) + + l.Printf("Txn (%x) executed with receipt: %v @ %s\n\n", tx.Hash(), receipt, whereami.WhereAmI()) if err != nil { w.current.state.RevertToSnapshot(snap) return nil, err @@ -741,11 +755,15 @@ func (w *worker) commitTransactions(txs *types.TransactionsByPriceAndNonce, coin log.Trace("Not enough gas for further transactions", "have", w.current.gasPool, "want", params.TxGas) break } + l.Printf("Worker has access to sufficient gas pool of %v\n\n", w.current.gasPool.Gas()) // Retrieve the next transaction and abort if all done tx := txs.Peek() if tx == nil { + l.Println("Worker found no more txns\n") break } + + l.Printf("Next txn to commit: %x\n\n", tx.Hash()) // Error may be ignored here. The error has already been checked // during transaction acceptance is the transaction pool. // @@ -761,6 +779,7 @@ func (w *worker) commitTransactions(txs *types.TransactionsByPriceAndNonce, coin } // Start executing the transaction w.current.state.Prepare(tx.Hash(), common.Hash{}, w.current.tcount) + l.Printf("Executing txn: %x\n\n", tx.Hash()) logs, err := w.commitTransaction(tx, coinbase) switch err { @@ -911,6 +930,8 @@ func (w *worker) commitNewWork(interrupt *int32, noempty bool, timestamp int64) // Fill the block with all available pending transactions. pending, err := w.eth.TxPool().Pending() + l.Printf("Worker found (%v) pending txns from pool: %v @ %s\n\n", len(pending), pending, whereami.WhereAmI()) + if err != nil { log.Error("Failed to fetch pending transactions", "err", err) return @@ -929,14 +950,20 @@ func (w *worker) commitNewWork(interrupt *int32, noempty bool, timestamp int64) } } if len(localTxs) > 0 { + l.Printf("Worker found (%v) local transactions: %v @ %s\n\n", len(localTxs), localTxs, whereami.WhereAmI()) txs := types.NewTransactionsByPriceAndNonce(w.current.signer, localTxs) + l.Printf("Worker sorted local txns by price and nonce: %v @ %s\n\n", txs, whereami.WhereAmI()) if w.commitTransactions(txs, w.coinbase, interrupt) { + l.Printf("Worker committing local txns: %s", whereami.WhereAmI()) return } } if len(remoteTxs) > 0 { + l.Printf("Worker found (%v) remote transactions: %v @ %s\n\n", len(remoteTxs), remoteTxs, whereami.WhereAmI()) txs := types.NewTransactionsByPriceAndNonce(w.current.signer, remoteTxs) + l.Printf("Worker sorted remote txns by price and nonce: %v @ %s\n\n", txs, whereami.WhereAmI()) if w.commitTransactions(txs, w.coinbase, interrupt) { + l.Printf("Worker comitting remote local txns: %s", whereami.WhereAmI()) return } } From d9fae5ae7ea309b7edd979cdbf637cc2ecf3973d Mon Sep 17 00:00:00 2001 From: Michael Gu Date: Fri, 5 Oct 2018 10:27:17 -0400 Subject: [PATCH 2/4] using geth logging module --- core/tx_pool.go | 42 ++++++++++++++++-------------------------- miner/worker.go | 34 ++++++++++++---------------------- 2 files changed, 28 insertions(+), 48 deletions(-) diff --git a/core/tx_pool.go b/core/tx_pool.go index d3ee87bbd8..63f602691e 100644 --- a/core/tx_pool.go +++ b/core/tx_pool.go @@ -35,8 +35,6 @@ import ( "github.com/ethereum/go-ethereum/params" "github.com/jimlawless/whereami" - "github.com/natefinch/lumberjack" - l "log" ) const ( @@ -219,14 +217,6 @@ type TxPool struct { // NewTxPool creates a new transaction pool to gather, sort and filter inbound // transactions from the network. func NewTxPool(config TxPoolConfig, chainconfig *params.ChainConfig, chain blockChain) *TxPool { - l.SetOutput(&lumberjack.Logger{ - Filename: "../miner.log", - MaxSize: 500, - MaxBackups: 3, - MaxAge: 28, - Compress: true, - }) - // Sanitize the input to ensure no vulnerable gas prices are set config = (&config).sanitize() @@ -578,19 +568,19 @@ func (pool *TxPool) local() map[common.Address]types.Transactions { // validateTx checks whether a transaction is valid according to the consensus // rules and adheres to some heuristic limits of the local node (price and size). func (pool *TxPool) validateTx(tx *types.Transaction, local bool) error { - l.Printf("Pool beginning standard validation using local heuristics @ %s\n\n", whereami.WhereAmI()) + log.Info("Pool beginning standard validation using local heuristics", "location", whereami.WhereAmI()) // Heuristic limit, reject transactions over 32KB to prevent DOS attacks if tx.Size() > 32*1024 { return ErrOversizedData } - l.Println("Txn passed size limit of 32KB\n") + log.Info("Txn passed size limit of 32KB") // Transactions can't be negative. This may never happen using RLP decoded // transactions but may occur if you create a transaction using the RPC. if tx.Value().Sign() < 0 { return ErrNegativeValue } - l.Println("Txn passed non-negative check\n") + log.Info("Txn passed non-negative check") // Ensure the transaction doesn't exceed the current block limit gas. if pool.currentMaxGas < tx.Gas() { return ErrGasLimit @@ -600,24 +590,24 @@ func (pool *TxPool) validateTx(tx *types.Transaction, local bool) error { if err != nil { return ErrInvalidSender } - l.Println("Txn signed properly\n") + log.Info("Txn signed properly") // Drop non-local transactions under our own minimal accepted gas price local = local || pool.locals.contains(from) // account may be local even if the transaction arrived from the network if !local && pool.gasPrice.Cmp(tx.GasPrice()) > 0 { return ErrUnderpriced } - l.Printf("Txn gas price of %v is above our pool's acceptable gas price of %v\n\n", tx.GasPrice(), pool.gasPrice) + log.Info("Txn gas price is above our pool's acceptable gas price", "tx_gasprice", tx.GasPrice(), "pool_gasprice", pool.gasPrice) // Ensure the transaction adheres to nonce ordering if pool.currentState.GetNonce(from) > tx.Nonce() { return ErrNonceTooLow } - l.Println("Txn correctly ordered by nonce\n") + log.Info("Txn correctly ordered by nonce") // Transactor should have enough funds to cover the costs // cost == V + GP * GL if pool.currentState.GetBalance(from).Cmp(tx.Cost()) < 0 { return ErrInsufficientFunds } - l.Printf("Sender has sufficient balance of %v to cover txn cost of %v\n\n", pool.currentState.GetBalance(from), tx.Cost()) + log.Info("Sender has sufficient balance to cover txn cost", "sender_balance", pool.currentState.GetBalance(from), "txn_cost", tx.Cost()) intrGas, err := IntrinsicGas(tx.Data(), tx.To() == nil, pool.homestead) if err != nil { return err @@ -625,7 +615,7 @@ func (pool *TxPool) validateTx(tx *types.Transaction, local bool) error { if tx.Gas() < intrGas { return ErrIntrinsicGas } - l.Printf("Txn gas used (%v) is under max intrinsic gas threshold of %v\n\n", tx.Gas(), intrGas) + log.Info("Txn gas used is under max intrinsic gas threshold", "txn_gas", tx.Gas(), "intrinsic_gas", intrGas) return nil } @@ -645,13 +635,13 @@ func (pool *TxPool) add(tx *types.Transaction, local bool) (bool, error) { return false, fmt.Errorf("known transaction: %x", hash) } // If the transaction fails basic validation, discard it - l.Printf("Pool found incoming txn, queueing new txn with hash: %x @ %s\n\n", hash, whereami.WhereAmI()) + log.Info("Pool found incoming txn, queueing new txn", "hash", hash, "location", whereami.WhereAmI()) if err := pool.validateTx(tx, local); err != nil { log.Trace("Discarding invalid transaction", "hash", hash, "err", err) invalidTxCounter.Inc(1) return false, err } - l.Printf("New txn passed all basic standard validation heuristics @ %s\n\n", whereami.WhereAmI()) + log.Info("New txn passed all basic standard validation heuristics", "location", whereami.WhereAmI()) // If the transaction pool is full, discard underpriced transactions if uint64(pool.all.Count()) >= pool.config.GlobalSlots+pool.config.GlobalQueue { // If the new transaction is underpriced, don't accept it @@ -960,15 +950,15 @@ func (pool *TxPool) promoteExecutables(accounts []common.Address) { continue // Just in case someone calls with a non existing account } // Drop all transactions that are deemed too old (low nonce) - l.Println("Pool dropping old queued txns\n") + log.Info("Pool dropping old queued txns") for _, tx := range list.Forward(pool.currentState.GetNonce(addr)) { hash := tx.Hash() log.Trace("Removed old queued transaction", "hash", hash) pool.all.Remove(hash) pool.priced.Removed() - l.Printf("Pool dropped old txn with hash: %x\n\n", hash) + log.Info("Pool dropped old txn", "hash", hash) } - l.Println("Pool dropping unpayabe txns (low balance/no gas)\n") + log.Info("Pool dropping unpayabe txns (low balance/no gas)") // Drop all transactions that are too costly (low balance or out of gas) drops, _ := list.Filter(pool.currentState.GetBalance(addr), pool.currentMaxGas) for _, tx := range drops { @@ -977,15 +967,15 @@ func (pool *TxPool) promoteExecutables(accounts []common.Address) { pool.all.Remove(hash) pool.priced.Removed() queuedNofundsCounter.Inc(1) - l.Printf("Pool dropped unpayable txn with hash: %x\n\n", hash) + log.Info("Pool dropped unpayable txn", "hash", hash) } // Gather all executable transactions and promote them - l.Println("Pool promoting txns ready for execution\n") + log.Info("Pool promoting txns ready for execution") for _, tx := range list.Ready(pool.pendingState.GetNonce(addr)) { hash := tx.Hash() if pool.promoteTx(addr, hash, tx) { log.Trace("Promoting queued transaction", "hash", hash) - l.Printf("Pool promoting queued txn with hash: %x\n\n", hash) + log.Info("Pool promoting queued txn", "hash", hash) promoted = append(promoted, tx) } } diff --git a/miner/worker.go b/miner/worker.go index 51bf65e68a..2cf666dca0 100644 --- a/miner/worker.go +++ b/miner/worker.go @@ -37,8 +37,6 @@ import ( "github.com/ethereum/go-ethereum/params" "github.com/jimlawless/whereami" - "github.com/natefinch/lumberjack" - l "log" ) const ( @@ -184,14 +182,6 @@ type worker struct { } func newWorker(config *params.ChainConfig, engine consensus.Engine, eth Backend, mux *event.TypeMux, recommit time.Duration, gasFloor, gasCeil uint64, isLocalBlock func(*types.Block) bool) *worker { - l.SetOutput(&lumberjack.Logger{ - Filename: "../miner.log", - MaxSize: 500, - MaxBackups: 3, - MaxAge: 28, - Compress: true, - }) - worker := &worker{ config: config, engine: engine, @@ -706,7 +696,7 @@ func (w *worker) commitTransaction(tx *types.Transaction, coinbase common.Addres receipt, _, err := core.ApplyTransaction(w.config, w.chain, &coinbase, w.current.gasPool, w.current.state, w.current.header, tx, &w.current.header.GasUsed, vm.Config{}) - l.Printf("Txn (%x) executed with receipt: %v @ %s\n\n", tx.Hash(), receipt, whereami.WhereAmI()) + log.Info("Txn executed", "receipt", tx.Hash(), "location", whereami.WhereAmI()) if err != nil { w.current.state.RevertToSnapshot(snap) return nil, err @@ -755,15 +745,15 @@ func (w *worker) commitTransactions(txs *types.TransactionsByPriceAndNonce, coin log.Trace("Not enough gas for further transactions", "have", w.current.gasPool, "want", params.TxGas) break } - l.Printf("Worker has access to sufficient gas pool of %v\n\n", w.current.gasPool.Gas()) + log.Info("Worker has access to sufficient gas pool", "gasPool", w.current.gasPool.Gas()) // Retrieve the next transaction and abort if all done tx := txs.Peek() if tx == nil { - l.Println("Worker found no more txns\n") + log.Info("Worker found no more txns") break } - l.Printf("Next txn to commit: %x\n\n", tx.Hash()) + log.Info("Next txn to commit", "hash", tx.Hash()) // Error may be ignored here. The error has already been checked // during transaction acceptance is the transaction pool. // @@ -779,7 +769,7 @@ func (w *worker) commitTransactions(txs *types.TransactionsByPriceAndNonce, coin } // Start executing the transaction w.current.state.Prepare(tx.Hash(), common.Hash{}, w.current.tcount) - l.Printf("Executing txn: %x\n\n", tx.Hash()) + log.Info("Executing txn", "hash", tx.Hash()) logs, err := w.commitTransaction(tx, coinbase) switch err { @@ -930,7 +920,7 @@ func (w *worker) commitNewWork(interrupt *int32, noempty bool, timestamp int64) // Fill the block with all available pending transactions. pending, err := w.eth.TxPool().Pending() - l.Printf("Worker found (%v) pending txns from pool: %v @ %s\n\n", len(pending), pending, whereami.WhereAmI()) + log.Info("Worker found new pending txns from pool", "num_txns", len(pending), "txns", pending, "location", whereami.WhereAmI()) if err != nil { log.Error("Failed to fetch pending transactions", "err", err) @@ -950,20 +940,20 @@ func (w *worker) commitNewWork(interrupt *int32, noempty bool, timestamp int64) } } if len(localTxs) > 0 { - l.Printf("Worker found (%v) local transactions: %v @ %s\n\n", len(localTxs), localTxs, whereami.WhereAmI()) + log.Info("Worker found local transactions", "num_txns", len(localTxs), "txns", localTxs, "location", whereami.WhereAmI()) txs := types.NewTransactionsByPriceAndNonce(w.current.signer, localTxs) - l.Printf("Worker sorted local txns by price and nonce: %v @ %s\n\n", txs, whereami.WhereAmI()) + log.Info("Worker sorted local txns by price and nonce", "txns", txs, "location", whereami.WhereAmI()) if w.commitTransactions(txs, w.coinbase, interrupt) { - l.Printf("Worker committing local txns: %s", whereami.WhereAmI()) + log.Info("Worker committing local txns", "location", whereami.WhereAmI()) return } } if len(remoteTxs) > 0 { - l.Printf("Worker found (%v) remote transactions: %v @ %s\n\n", len(remoteTxs), remoteTxs, whereami.WhereAmI()) + log.Info("Worker found remote transactions", "num_txns", len(remoteTxs), "txns", remoteTxs, "location", whereami.WhereAmI()) txs := types.NewTransactionsByPriceAndNonce(w.current.signer, remoteTxs) - l.Printf("Worker sorted remote txns by price and nonce: %v @ %s\n\n", txs, whereami.WhereAmI()) + log.Info("Worker sorted remote txns by price and nonce", "txns", txs, "location", whereami.WhereAmI()) if w.commitTransactions(txs, w.coinbase, interrupt) { - l.Printf("Worker comitting remote local txns: %s", whereami.WhereAmI()) + log.Info("Worker comitting remote local txns", "location", whereami.WhereAmI()) return } } From 5b6e854eb32425803553dc10c47787f1b9dfe43a Mon Sep 17 00:00:00 2001 From: Michael Gu Date: Fri, 5 Oct 2018 10:29:42 -0400 Subject: [PATCH 3/4] remove extranneous spaces --- miner/worker.go | 2 -- 1 file changed, 2 deletions(-) diff --git a/miner/worker.go b/miner/worker.go index 2cf666dca0..04a709655e 100644 --- a/miner/worker.go +++ b/miner/worker.go @@ -695,7 +695,6 @@ func (w *worker) commitTransaction(tx *types.Transaction, coinbase common.Addres snap := w.current.state.Snapshot() receipt, _, err := core.ApplyTransaction(w.config, w.chain, &coinbase, w.current.gasPool, w.current.state, w.current.header, tx, &w.current.header.GasUsed, vm.Config{}) - log.Info("Txn executed", "receipt", tx.Hash(), "location", whereami.WhereAmI()) if err != nil { w.current.state.RevertToSnapshot(snap) @@ -752,7 +751,6 @@ func (w *worker) commitTransactions(txs *types.TransactionsByPriceAndNonce, coin log.Info("Worker found no more txns") break } - log.Info("Next txn to commit", "hash", tx.Hash()) // Error may be ignored here. The error has already been checked // during transaction acceptance is the transaction pool. From 5df21a1e6fc85f54cccf723e00a3f5a0f51a5243 Mon Sep 17 00:00:00 2001 From: Michael Gu Date: Mon, 8 Oct 2018 13:37:19 -0400 Subject: [PATCH 4/4] logging logic in tx pool when 1) nonce gap occurs and 2) txns originate from different accounts --- core/tx_list.go | 1 + core/tx_pool.go | 14 ++++++++++++++ core/types/transaction.go | 4 ++++ miner/worker.go | 2 +- 4 files changed, 20 insertions(+), 1 deletion(-) diff --git a/core/tx_list.go b/core/tx_list.go index 57abc51486..4e1e66f173 100644 --- a/core/tx_list.go +++ b/core/tx_list.go @@ -186,6 +186,7 @@ func (m *txSortedMap) Ready(start uint64) types.Transactions { ready = append(ready, m.items[next]) delete(m.items, next) heap.Pop(m.index) + log.Info("=====> Txn List adding txn with sequentially valid nonce that is greater than current pool nonce", "txn", m.items[next]) } m.cache = nil diff --git a/core/tx_pool.go b/core/tx_pool.go index 63f602691e..535b4ffc17 100644 --- a/core/tx_pool.go +++ b/core/tx_pool.go @@ -661,14 +661,17 @@ func (pool *TxPool) add(tx *types.Transaction, local bool) (bool, error) { // If the transaction is replacing an already pending one, do directly from, _ := types.Sender(pool.signer, tx) // already validated if list := pool.pending[from]; list != nil && list.Overlaps(tx) { + log.Info("======> Pool detected txn nonce already in txn list", "nonce", tx.Nonce()) // Nonce already pending, check if required price bump is met inserted, old := list.Add(tx, pool.config.PriceBump) if !inserted { + log.Info("======> Older txn with shared nonce has higher gas price, accepted over new txn", "oldHash", old.Hash(), "oldGasPrice", old.GasPrice(), "txnGasPrice", tx.GasPrice()) pendingDiscardCounter.Inc(1) return false, ErrReplaceUnderpriced } // New transaction is better, replace old one if old != nil { + log.Info("======> New txn with shared nonce has higher gas price, overwriting old txn", "oldHash", old.Hash()) pool.all.Remove(old.Hash()) pool.priced.Removed() pendingReplaceCounter.Inc(1) @@ -750,9 +753,11 @@ func (pool *TxPool) promoteTx(addr common.Address, hash common.Hash, tx *types.T // Try to insert the transaction into the pending queue if pool.pending[addr] == nil { pool.pending[addr] = newTxList(true) + log.Info("======> Pool intitializing new txn list in pending queue under address", "address", addr) } list := pool.pending[addr] + log.Info("=====> Pool attempting to promote txn with hash", "hash", hash) inserted, old := list.Add(tx, pool.config.PriceBump) if !inserted { // An older transaction was better, discard this @@ -777,6 +782,7 @@ func (pool *TxPool) promoteTx(addr common.Address, hash common.Hash, tx *types.T // Set the potentially new pending nonce and notify any subsystems of the new tx pool.beats[addr] = time.Now() pool.pendingState.SetNonce(addr, tx.Nonce()+1) + log.Info("======> Pool promoted next txn for execution, incrementing nonce at address", "addr", addr, "nonce", pool.pendingState.GetNonce(addr)) return true } @@ -971,7 +977,9 @@ func (pool *TxPool) promoteExecutables(accounts []common.Address) { } // Gather all executable transactions and promote them log.Info("Pool promoting txns ready for execution") + log.Info("=====> Pool calling list.Ready() to grab all txns with nonce greater than current pool state under this address", "address", addr) for _, tx := range list.Ready(pool.pendingState.GetNonce(addr)) { + log.Info("=====> Pool retrieved txns with nonce greater than currentState.nonce, sorted in sequentially increasing order", "list", list.Ready(pool.pendingState.GetNonce(addr), "current nonce", pool.pendingState.GetNonce(addr))) hash := tx.Hash() if pool.promoteTx(addr, hash, tx) { log.Trace("Promoting queued transaction", "hash", hash) @@ -996,6 +1004,7 @@ func (pool *TxPool) promoteExecutables(accounts []common.Address) { } // Notify subsystem for new promoted transactions. if len(promoted) > 0 { + log.Info("======> New promoted txns", "promoted", promoted) go pool.txFeed.Send(NewTxsEvent{promoted}) } // If the pending limit is overflown, start equalizing allowances @@ -1004,6 +1013,7 @@ func (pool *TxPool) promoteExecutables(accounts []common.Address) { pending += uint64(list.Len()) } if pending > pool.config.GlobalSlots { + log.Info("======> Pending exceeds pool size limit", "pending", pending, "limit", pool.config.GlobalSlots) pendingBeforeCap := pending // Assemble a spam order to penalize large transactors first spammers := prque.New(nil) @@ -1015,6 +1025,7 @@ func (pool *TxPool) promoteExecutables(accounts []common.Address) { } // Gradually drop transactions from offenders offenders := []common.Address{} + log.Info("======> Found accounts with too many transactions, dropping their transactions", "spammers", spammers) for pending > pool.config.GlobalSlots && !spammers.Empty() { // Retrieve the next offender if not local address offender, _ := spammers.Pop() @@ -1031,6 +1042,7 @@ func (pool *TxPool) promoteExecutables(accounts []common.Address) { list := pool.pending[offenders[i]] for _, tx := range list.Cap(list.Len() - 1) { // Drop the transaction from the global pools too + log.Info("=======> Dropping transaction from pool", "hash", tx.Hash(), "offender", offenders[i]) hash := tx.Hash() pool.all.Remove(hash) pool.priced.Removed() @@ -1038,6 +1050,7 @@ func (pool *TxPool) promoteExecutables(accounts []common.Address) { // Update the account nonce to the dropped transaction if nonce := tx.Nonce(); pool.pendingState.GetNonce(offenders[i]) > nonce { pool.pendingState.SetNonce(offenders[i], nonce) + log.Info("=======> Setting offender's nonce to the pool's nonce state", "nonce", nonce) } log.Trace("Removed fairness-exceeding pending transaction", "hash", hash) } @@ -1060,6 +1073,7 @@ func (pool *TxPool) promoteExecutables(accounts []common.Address) { // Update the account nonce to the dropped transaction if nonce := tx.Nonce(); pool.pendingState.GetNonce(addr) > nonce { pool.pendingState.SetNonce(addr, nonce) + log.Info("=======> Setting offender's nonce to the pool's nonce state", "nonce", nonce) } log.Trace("Removed fairness-exceeding pending transaction", "hash", hash) } diff --git a/core/types/transaction.go b/core/types/transaction.go index 7b53cac2c6..b839dcf68b 100644 --- a/core/types/transaction.go +++ b/core/types/transaction.go @@ -26,6 +26,7 @@ import ( "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/common/hexutil" "github.com/ethereum/go-ethereum/crypto" + "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/rlp" ) @@ -335,7 +336,9 @@ type TransactionsByPriceAndNonce struct { func NewTransactionsByPriceAndNonce(signer Signer, txs map[common.Address]Transactions) *TransactionsByPriceAndNonce { // Initialize a price based heap with the head transactions heads := make(TxByPrice, 0, len(txs)) + log.Info("======> Sorting the txns from pool by initializing a heap and iteratively deleting from heap, causing next best txn price to bubble up") for from, accTxs := range txs { + log.Info("======> Txn with next best price/nonce", "nextBestTxn", accTxs[0]) heads = append(heads, accTxs[0]) // Ensure the sender address is from the signer acc, _ := Sender(signer, accTxs[0]) @@ -345,6 +348,7 @@ func NewTransactionsByPriceAndNonce(signer Signer, txs map[common.Address]Transa } } heap.Init(&heads) + log.Info("======> Returning sorted txn heap", "heap", heads) // Assemble and return the transaction set return &TransactionsByPriceAndNonce{ diff --git a/miner/worker.go b/miner/worker.go index 04a709655e..6b87edab7b 100644 --- a/miner/worker.go +++ b/miner/worker.go @@ -918,7 +918,7 @@ func (w *worker) commitNewWork(interrupt *int32, noempty bool, timestamp int64) // Fill the block with all available pending transactions. pending, err := w.eth.TxPool().Pending() - log.Info("Worker found new pending txns from pool", "num_txns", len(pending), "txns", pending, "location", whereami.WhereAmI()) + log.Info("Worker found new pending txns from pending queue set by tx pool", "num_txns", len(pending), "txns", pending, "location", whereami.WhereAmI()) if err != nil { log.Error("Failed to fetch pending transactions", "err", err)