Add verbose logging to the transactions execution (#195)

* Implement fmt.Stringer in the Header and Transaction

* Log block transactions when executing a block

* Log genesis configuration on debug level

* Changes in the FSM logs

* Address comments

* Remove unused param from test

* Lint fix

* Minor change

* Address comment

blockchain/blockchain_test.go

@@ -569,7 +569,6 @@ func TestBlockchainWriteBody(t *testing.T) {
 	newChain := func(
 		t *testing.T,
 		txFromByTxHash map[types.Hash]types.Address,
-		path string,
 	) *Blockchain {
 		t.Helper()
 
@@ -604,7 +603,7 @@ func TestBlockchainWriteBody(t *testing.T) {
 
 		txFromByTxHash := map[types.Hash]types.Address{}
 
-		chain := newChain(t, txFromByTxHash, "t1")
+		chain := newChain(t, txFromByTxHash)
 		defer chain.db.Close()
 		batchWriter := chain.db.NewWriter()
 
@@ -633,7 +632,7 @@ func TestBlockchainWriteBody(t *testing.T) {
 
 		txFromByTxHash := map[types.Hash]types.Address{}
 
-		chain := newChain(t, txFromByTxHash, "t2")
+		chain := newChain(t, txFromByTxHash)
 		defer chain.db.Close()
 		batchWriter := chain.db.NewWriter()
 
@@ -665,7 +664,7 @@ func TestBlockchainWriteBody(t *testing.T) {
 			tx.Hash(): addr,
 		}
 
-		chain := newChain(t, txFromByTxHash, "t3")
+		chain := newChain(t, txFromByTxHash)
 		defer chain.db.Close()
 		batchWriter := chain.db.NewWriter()
 

chain/params.go

@@ -2,6 +2,7 @@ package chain
 
 import (
 	"errors"
+	"fmt"
 	"sort"
 
 	"github.com/0xPolygon/polygon-edge/forkmanager"
@@ -190,6 +191,17 @@ type ForksInTime struct {
 	EIP3607 bool
 }
 
+func (f ForksInTime) String() string {
+	return fmt.Sprintf("EIP150: %t, EIP158: %t, EIP155: %t, "+
+		"Homestead: %t, Byzantium: %t, Constantinople: %t, "+
+		"Petersburg: %t, Istanbul: %t, Berlin: %t, London: %t"+
+		"Governance: %t, EIP3855: %t, EIP3607: %t",
+		f.EIP150, f.EIP158, f.EIP155,
+		f.Homestead, f.Byzantium, f.Constantinople, f.Petersburg,
+		f.Istanbul, f.Berlin, f.London,
+		f.Governance, f.EIP3855, f.EIP3607)
+}
+
 // AllForksEnabled should contain all supported forks by current edge version
 var AllForksEnabled = &Forks{
 	Homestead:      NewFork(0),

consensus/polybft/block_builder.go

@@ -1,6 +1,7 @@
 package polybft
 
 import (
+	"bytes"
 	"fmt"
 	"time"
 
@@ -157,6 +158,8 @@ func (b *BlockBuilder) WriteTx(tx *types.Transaction) error {
 
 // Fill fills the block with transactions from the txpool
 func (b *BlockBuilder) Fill() {
+	var buf bytes.Buffer
+
 	blockTimer := time.NewTimer(b.params.BlockTime)
 
 	b.params.TxPool.Prepare()
@@ -168,6 +171,10 @@ write:
 		default:
 			tx := b.params.TxPool.Peek()
 
+			if b.params.Logger.IsDebug() && tx != nil {
+				_, _ = buf.WriteString(tx.String())
+			}
+
 			// execute transactions one by one
 			finished, err := b.writeTxPoolTransaction(tx)
 			if err != nil {
@@ -180,6 +187,10 @@ write:
 		}
 	}
 
+	if b.params.Logger.IsDebug() {
+		b.params.Logger.Debug("[BlockBuilder.Fill]", "block number", b.header.Number, "block txs", buf.String())
+	}
+
 	//	wait for the timer to expire
 	<-blockTimer.C
 }

consensus/polybft/blockchain_wrapper.go

@@ -1,6 +1,7 @@
 package polybft
 
 import (
+	"bytes"
 	"errors"
 	"fmt"
 	"math/big"
@@ -71,6 +72,7 @@ type blockchainBackend interface {
 var _ blockchainBackend = &blockchainWrapper{}
 
 type blockchainWrapper struct {
+	logger     hclog.Logger
 	executor   *state.Executor
 	blockchain *blockchain.Blockchain
 }
@@ -87,6 +89,10 @@ func (p *blockchainWrapper) CommitBlock(block *types.FullBlock) error {
 
 // ProcessBlock builds a final block from given 'block' on top of 'parent'
 func (p *blockchainWrapper) ProcessBlock(parent *types.Header, block *types.Block) (*types.FullBlock, error) {
+	p.logger.Debug("[BlockchainWrapper.ProcessBlock]",
+		"block number", block.Number(), "block hash", block.Hash(),
+		"parent state root", parent.StateRoot, "block state root", block.Header.StateRoot)
+
 	header := block.Header.Copy()
 	start := time.Now().UTC()
 
@@ -95,13 +101,32 @@ func (p *blockchainWrapper) ProcessBlock(parent *types.Header, block *types.Bloc
 		return nil, err
 	}
 
-	// apply transactions from block
-	for _, tx := range block.Transactions {
-		if err = transition.Write(tx); err != nil {
-			return nil, fmt.Errorf("process block tx error, tx = %v, err = %w", tx.Hash(), err)
+	var buf bytes.Buffer
+
+	for i, t := range block.Transactions {
+		if err := transition.Write(t); err != nil {
+			p.logger.Error("failed to write transaction to the block", "tx", t, "err", err)
+
+			return nil, fmt.Errorf("failed to write transaction %s to the block: %w", t.Hash(), err)
+		}
+
+		if p.logger.GetLevel() <= hclog.Debug {
+			if p.logger.IsTrace() {
+				_, _ = buf.WriteString(t.String())
+			}
+
+			if p.logger.IsDebug() {
+				_, _ = buf.WriteString(t.Hash().String())
+			}
+
+			if i != len(block.Transactions)-1 {
+				_, _ = buf.WriteString("\n")
+			}
 		}
 	}
 
+	p.logger.Debug("[BlockchainWrapper.ProcessBlock]", "txs count", len(block.Transactions), "txs", buf.String())
+
 	_, root, err := transition.Commit()
 	if err != nil {
 		return nil, fmt.Errorf("failed to commit the state changes: %w", err)

consensus/polybft/fsm.go

@@ -10,7 +10,7 @@ import (
 	"github.com/0xPolygon/go-ibft/messages"
 	"github.com/0xPolygon/go-ibft/messages/proto"
 	"github.com/armon/go-metrics"
-	hcf "github.com/hashicorp/go-hclog"
+	"github.com/hashicorp/go-hclog"
 
 	"github.com/0xPolygon/polygon-edge/bls"
 	"github.com/0xPolygon/polygon-edge/chain"
@@ -101,7 +101,7 @@ type fsm struct {
 	proposerCommitmentToRegister *CommitmentMessageSigned
 
 	// logger instance
-	logger hcf.Logger
+	logger hclog.Logger
 
 	// target is the block being computed
 	target *types.FullBlock
@@ -192,7 +192,7 @@ func (f *fsm) BuildProposal(currentRound uint64) ([]byte, error) {
 		EventRoot:             f.exitEventRootHash,
 	}
 
-	f.logger.Debug("[Build Proposal]", "Current validators hash", currentValidatorsHash,
+	f.logger.Trace("[FSM.BuildProposal]", "Current validators hash", currentValidatorsHash,
 		"Next validators hash", nextValidatorsHash)
 
 	stateBlock, err := f.blockBuilder.Build(func(h *types.Header) {
@@ -204,17 +204,33 @@ func (f *fsm) BuildProposal(currentRound uint64) ([]byte, error) {
 		return nil, err
 	}
 
-	if f.logger.IsDebug() {
+	if f.logger.GetLevel() <= hclog.Debug {
 		checkpointHash, err := extra.Checkpoint.Hash(f.backend.GetChainID(), f.Height(), stateBlock.Block.Hash())
 		if err != nil {
 			return nil, fmt.Errorf("failed to calculate proposal hash: %w", err)
 		}
 
-		f.logger.Debug("[FSM Build Proposal]",
-			"block", stateBlock.Block.Number(),
+		var buf bytes.Buffer
+
+		for i, tx := range stateBlock.Block.Transactions {
+			if f.logger.IsDebug() {
+				buf.WriteString(tx.Hash().String())
+			} else if f.logger.IsTrace() {
+				buf.WriteString(tx.String())
+			}
+
+			if i != len(stateBlock.Block.Transactions)-1 {
+				buf.WriteString("\n")
+			}
+		}
+
+		f.logger.Debug("[FSM.BuildProposal]",
+			"block num", stateBlock.Block.Number(),
 			"round", currentRound,
-			"txs", len(stateBlock.Block.Transactions),
-			"proposal hash", checkpointHash.String())
+			"state root", stateBlock.Block.Header.StateRoot,
+			"proposal hash", checkpointHash.String(),
+			"txs count", len(stateBlock.Block.Transactions),
+			"txs", buf.String())
 	}
 
 	f.target = stateBlock
@@ -380,7 +396,7 @@ func (f *fsm) Validate(proposal []byte) error {
 			return fmt.Errorf("failed to retrieve validators:%w", err)
 		}
 
-		f.logger.Trace("[FSM Validate]", "Block", block.Number(), "parent validators", validators)
+		f.logger.Trace("[FSM.Validate]", "block num", block.Number(), "parent validators", validators)
 	}
 
 	stateBlock, err := f.backend.ProcessBlock(f.parent, &block)
@@ -394,10 +410,10 @@ func (f *fsm) Validate(proposal []byte) error {
 			return fmt.Errorf("failed to calculate proposal hash: %w", err)
 		}
 
-		f.logger.Debug("[FSM Validate] Finish",
+		f.logger.Debug("[FSM.Validate]",
 			"block num", block.Number(),
+			"state root", block.Header.StateRoot,
 			"proposer", types.BytesToHash(block.Header.Miner),
-			"txs", len(block.Transactions),
 			"proposal hash", checkpointHash)
 	}
 

consensus/polybft/polybft.go

@@ -462,6 +462,7 @@ func (p *Polybft) Initialize() error {
 
 	// set blockchain backend
 	p.blockchain = &blockchainWrapper{
+		logger:     p.logger.Named("blockchain_wrapper"),
 		blockchain: p.config.Blockchain,
 		executor:   p.config.Executor,
 	}

server/server.go

@@ -147,13 +147,22 @@ func NewServer(config *Config) (*Server, error) {
 		restoreProgression: progress.NewProgressionWrapper(progress.ChainSyncRestore),
 	}
 
-	m.logger.Info("Data dir", "path", config.DataDir)
-	m.logger.Info("Version metadata",
+	m.logger.Info("data dir", "path", config.DataDir)
+	m.logger.Info("version metadata",
 		"version", versioning.Version,
 		"commit", versioning.Commit,
 		"branch", versioning.Branch,
 		"build time", versioning.BuildTime)
 
+	if m.logger.IsDebug() {
+		chainConfigJSON, err := json.MarshalIndent(config.Chain, "", "\t")
+		if err != nil {
+			return nil, fmt.Errorf("failed to marshal chain config to JSON: %w", err)
+		}
+
+		m.logger.Debug(fmt.Sprintf("chain configuration %s", string(chainConfigJSON)))
+	}
+
 	var dirPaths = []string{
 		"blockchain",
 		"trie",
@@ -209,7 +218,7 @@ func NewServer(config *Config) (*Server, error) {
 	st := itrie.NewState(stateStorage)
 	m.state = st
 
-	m.executor = state.NewExecutor(config.Chain.Params, st, logger)
+	m.executor = state.NewExecutor(config.Chain.Params, st, logger.Named("executor"))
 
 	// custom write genesis hook per consensus engine
 	engineName := m.config.Chain.Params.GetEngine()

state/executor.go

@@ -1,6 +1,7 @@
 package state
 
 import (
+	"bytes"
 	"errors"
 	"fmt"
 	"math"
@@ -133,19 +134,45 @@ func (e *Executor) ProcessBlock(
 	block *types.Block,
 	blockCreator types.Address,
 ) (*Transition, error) {
+	e.logger.Debug("[BlockchainWrapper.ProcessBlock]",
+		"block number", block.Number(), "block hash", block.Hash(),
+		"parent state root", parentRoot, "block state root", block.Header.StateRoot)
+
 	txn, err := e.BeginTxn(parentRoot, block.Header, blockCreator)
 	if err != nil {
 		return nil, err
 	}
 
-	for _, t := range block.Transactions {
+	var buf bytes.Buffer
+
+	for i, t := range block.Transactions {
 		if t.Gas() > block.Header.GasLimit {
 			continue
 		}
 
 		if err = txn.Write(t); err != nil {
+			e.logger.Error("failed to write transaction to the block", "tx", t, "err", err)
+
 			return nil, err
 		}
+
+		if e.logger.GetLevel() <= hclog.Debug {
+			if e.logger.IsTrace() {
+				_, _ = buf.WriteString(t.String())
+			}
+
+			if e.logger.IsDebug() {
+				_, _ = buf.WriteString(t.Hash().String())
+			}
+
+			if i != len(block.Transactions)-1 {
+				_, _ = buf.WriteString("\n")
+			}
+		}
+	}
+
+	if e.logger.IsDebug() {
+		e.logger.Debug("[Executor.ProcessBlock]", "txs count", len(block.Transactions), "txs", buf.String())
 	}
 
 	return txn, nil
@@ -337,6 +364,7 @@ func (t *Transition) Write(txn *types.Transaction) error {
 		}
 
 		txn.SetFrom(from)
+		t.logger.Debug("[Transition.Write]", "recovered sender", from)
 	}
 
 	// Make a local copy and apply the transaction

types/access_list_tx.go

@@ -1,6 +1,7 @@
 package types
 
 import (
+	"bytes"
 	"fmt"
 	"math/big"
 
@@ -165,6 +166,24 @@ func (t *TxAccessList) unmarshalJSON(v *fastjson.Value) error {
 	return nil
 }
 
+func (t *TxAccessList) String() string {
+	var buf bytes.Buffer
+
+	for _, accessEntry := range *t {
+		_, _ = buf.WriteString(fmt.Sprintf("address=%s", accessEntry.Address))
+
+		for i, storageKey := range accessEntry.StorageKeys {
+			if i == 0 {
+				_, _ = buf.WriteString("\n")
+			}
+
+			_, _ = buf.WriteString(fmt.Sprintf("\tstorage key=%s", storageKey))
+		}
+	}
+
+	return buf.String()
+}
+
 type AccessListTxn struct {
 	*BaseTx
 	GasPrice *big.Int