diff --git a/blockchain/blockchain_test.go b/blockchain/blockchain_test.go index 7f4cabdd9b..e80a6838fc 100644 --- a/blockchain/blockchain_test.go +++ b/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() diff --git a/chain/params.go b/chain/params.go index 1847a0d1b2..63fc19a45f 100644 --- a/chain/params.go +++ b/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), diff --git a/consensus/polybft/block_builder.go b/consensus/polybft/block_builder.go index 1849faa1db..d98efb0da4 100644 --- a/consensus/polybft/block_builder.go +++ b/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 } diff --git a/consensus/polybft/blockchain_wrapper.go b/consensus/polybft/blockchain_wrapper.go index dd23b9b437..4cac1b626a 100644 --- a/consensus/polybft/blockchain_wrapper.go +++ b/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) diff --git a/consensus/polybft/fsm.go b/consensus/polybft/fsm.go index 262882d2f7..fa9075b6c8 100644 --- a/consensus/polybft/fsm.go +++ b/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) } diff --git a/consensus/polybft/polybft.go b/consensus/polybft/polybft.go index f1d8561569..3de2f1404d 100644 --- a/consensus/polybft/polybft.go +++ b/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, } diff --git a/server/server.go b/server/server.go index a02e81d549..e908cdd224 100644 --- a/server/server.go +++ b/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() diff --git a/state/executor.go b/state/executor.go index 5274549368..54db8f45b2 100644 --- a/state/executor.go +++ b/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 diff --git a/types/access_list_tx.go b/types/access_list_tx.go index 257001cde7..55080431e1 100644 --- a/types/access_list_tx.go +++ b/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 diff --git a/types/header.go b/types/header.go index d3367741eb..21fddeed97 100644 --- a/types/header.go +++ b/types/header.go @@ -51,6 +51,17 @@ func (h *Header) IsGenesis() bool { return h.Hash != ZeroHash && h.Number == 0 } +func (h *Header) String() string { + return fmt.Sprintf("[Header#%d] ParentHash: %s, Hash: %s, BaseFee: %d, "+ + "Miner: %s, StateRoot: %s, TxRoot: %s, ReceiptsRoot: %s, "+ + "LogsBloom: %s, Difficulty: %d, GasLimit: %d, GasUsed: %d, "+ + "Timestamp: %d, ExtraData: %x, MixHash: %s, Nonce: %s, Sha3Uncles: %s", + h.Number, h.ParentHash, h.Hash, h.BaseFee, + BytesToAddress(h.Miner), h.StateRoot, h.TxRoot, + h.ReceiptsRoot, h.LogsBloom, h.Difficulty, h.GasLimit, + h.GasUsed, h.Timestamp, h.ExtraData, h.MixHash, h.Nonce, h.Sha3Uncles) +} + type Nonce [8]byte func (n Nonce) String() string { diff --git a/types/transaction.go b/types/transaction.go index a37e83f1be..332780d128 100644 --- a/types/transaction.go +++ b/types/transaction.go @@ -123,6 +123,16 @@ type TxData interface { copy() TxData } +func (tx *Transaction) String() string { + v, r, s := tx.RawSignatureValues() + + return fmt.Sprintf("[%s] Nonce: %d, GasPrice: %d, GasTipCap: %d, GasFeeCap: %d, "+ + "Gas: %d, To: %s, Value: %d, Input: %x, V: %d, R: %d, S: %s, Hash: %s, From: %s, AccessList: %s", + tx.Type(), tx.Nonce(), tx.GasPrice(), tx.GasTipCap(), tx.GasFeeCap(), + tx.Gas(), tx.To(), tx.Value(), tx.Input(), + v, r, s, tx.Hash(), tx.From(), tx.AccessList()) +} + func (t *Transaction) Type() TxType { return t.Inner.transactionType() }