From 0191a22636fcba8113a0592192dd4636796ef832 Mon Sep 17 00:00:00 2001 From: "mergify[bot]" <37929162+mergify[bot]@users.noreply.github.com> Date: Wed, 24 Feb 2021 09:50:46 -0500 Subject: [PATCH] state executor: groom logs (bp #6152) (#6172) --- consensus/state.go | 2 +- state/execution.go | 59 +++++++++++++++++++++++++--------------------- 2 files changed, 33 insertions(+), 28 deletions(-) diff --git a/consensus/state.go b/consensus/state.go index 5090ed4d8..77eb500ae 100644 --- a/consensus/state.go +++ b/consensus/state.go @@ -1967,7 +1967,7 @@ func (cs *State) tryAddVote(vote *types.Vote, peerID p2p.ID) (bool, error) { // 2) not a bad peer? this can also err sometimes with "Unexpected step" OR // 3) tmkms use with multiple validators connecting to a single tmkms instance // (https://github.com/tendermint/tendermint/issues/3839). - cs.Logger.Error("failed attempting to add vote", "err", err) + cs.Logger.Info("failed attempting to add vote", "err", err) return added, ErrAddingVote } } diff --git a/state/execution.go b/state/execution.go index 41fb248bd..433444d5f 100644 --- a/state/execution.go +++ b/state/execution.go @@ -137,8 +137,9 @@ func (blockExec *BlockExecutor) ApplyBlock( } startTime := time.Now().UnixNano() - abciResponses, err := execBlockOnProxyApp(blockExec.logger, blockExec.proxyApp, block, - blockExec.store, state.InitialHeight) + abciResponses, err := execBlockOnProxyApp( + blockExec.logger, blockExec.proxyApp, block, blockExec.store, state.InitialHeight, + ) endTime := time.Now().UnixNano() blockExec.metrics.BlockProcessingTime.Observe(float64(endTime-startTime) / 1000000) if err != nil { @@ -160,12 +161,13 @@ func (blockExec *BlockExecutor) ApplyBlock( if err != nil { return state, 0, fmt.Errorf("error in validator updates: %v", err) } + validatorUpdates, err := types.PB2TM.ValidatorUpdates(abciValUpdates) if err != nil { return state, 0, err } if len(validatorUpdates) > 0 { - blockExec.logger.Info("Updates to validators", "updates", types.ValidatorListString(validatorUpdates)) + blockExec.logger.Info("updates to validators", "updates", types.ValidatorListString(validatorUpdates)) } // Update the state with the block and responses. @@ -218,26 +220,23 @@ func (blockExec *BlockExecutor) Commit( // in the ABCI app before Commit. err := blockExec.mempool.FlushAppConn() if err != nil { - blockExec.logger.Error("Client error during mempool.FlushAppConn", "err", err) + blockExec.logger.Error("client error during mempool.FlushAppConn", "err", err) return nil, 0, err } // Commit block, get hash back res, err := blockExec.proxyApp.CommitSync() if err != nil { - blockExec.logger.Error( - "Client error during proxyAppConn.CommitSync", - "err", err, - ) + blockExec.logger.Error("client error during proxyAppConn.CommitSync", "err", err) return nil, 0, err } - // ResponseCommit has no error code - just data + // ResponseCommit has no error code - just data blockExec.logger.Info( - "Committed state", + "committed state", "height", block.Height, - "txs", len(block.Txs), - "appHash", res.Data, + "num_txs", len(block.Txs), + "app_hash", fmt.Sprintf("%X", res.Data), ) // Update mempool. @@ -281,9 +280,10 @@ func execBlockOnProxyApp( if txRes.Code == abci.CodeTypeOK { validTxs++ } else { - logger.Debug("Invalid tx", "code", txRes.Code, "log", txRes.Log) + logger.Debug("invalid tx", "code", txRes.Code, "log", txRes.Log) invalidTxs++ } + abciResponses.DeliverTxs[txIndex] = txRes txIndex++ } @@ -303,6 +303,7 @@ func execBlockOnProxyApp( if pbh == nil { return nil, errors.New("nil header") } + abciResponses.BeginBlock, err = proxyAppConn.BeginBlockSync(abci.RequestBeginBlock{ Hash: block.Hash(), Header: *pbh, @@ -310,11 +311,11 @@ func execBlockOnProxyApp( ByzantineValidators: byzVals, }) if err != nil { - logger.Error("Error in proxyAppConn.BeginBlock", "err", err) + logger.Error("error in proxyAppConn.BeginBlock", "err", err) return nil, err } - // Run txs of block. + // run txs of block for _, tx := range block.Txs { proxyAppConn.DeliverTxAsync(abci.RequestDeliverTx{Tx: tx}) if err := proxyAppConn.Error(); err != nil { @@ -325,12 +326,11 @@ func execBlockOnProxyApp( // End block. abciResponses.EndBlock, err = proxyAppConn.EndBlockSync(abci.RequestEndBlock{Height: block.Height}) if err != nil { - logger.Error("Error in proxyAppConn.EndBlock", "err", err) + logger.Error("error in proxyAppConn.EndBlock", "err", err) return nil, err } - logger.Info("Executed block", "height", block.Height, "validTxs", validTxs, "invalidTxs", invalidTxs) - + logger.Info("executed block", "height", block.Height, "num_valid_txs", validTxs, "num_invalid_txs", invalidTxs) return abciResponses, nil } @@ -353,8 +353,10 @@ func getBeginBlockValidatorInfo(block *types.Block, store Store, valSetLen = len(lastValSet.Validators) ) if commitSize != valSetLen { - panic(fmt.Sprintf("commit size (%d) doesn't match valset length (%d) at height %d\n\n%v\n\n%v", - commitSize, valSetLen, block.Height, block.LastCommit.Signatures, lastValSet.Validators)) + panic(fmt.Sprintf( + "commit size (%d) doesn't match valset length (%d) at height %d\n\n%v\n\n%v", + commitSize, valSetLen, block.Height, block.LastCommit.Signatures, lastValSet.Validators, + )) } for i, val := range lastValSet.Validators { @@ -478,15 +480,16 @@ func fireEvents( ResultBeginBlock: *abciResponses.BeginBlock, ResultEndBlock: *abciResponses.EndBlock, }); err != nil { - logger.Error("Error publishing new block", "err", err) + logger.Error("failed publishing new block", "err", err) } + if err := eventBus.PublishEventNewBlockHeader(types.EventDataNewBlockHeader{ Header: block.Header, NumTxs: int64(len(block.Txs)), ResultBeginBlock: *abciResponses.BeginBlock, ResultEndBlock: *abciResponses.EndBlock, }); err != nil { - logger.Error("Error publishing new block header", "err", err) + logger.Error("failed publishing new block header", "err", err) } if len(block.Evidence.Evidence) != 0 { @@ -495,7 +498,7 @@ func fireEvents( Evidence: ev, Height: block.Height, }); err != nil { - logger.Error("Error publishing new evidence", "err", err) + logger.Error("failed publishing new evidence", "err", err) } } } @@ -507,14 +510,14 @@ func fireEvents( Tx: tx, Result: *(abciResponses.DeliverTxs[i]), }}); err != nil { - logger.Error("Error publishing event TX", "err", err) + logger.Error("failed publishing event TX", "err", err) } } if len(validatorUpdates) > 0 { if err := eventBus.PublishEventValidatorSetUpdates( types.EventDataValidatorSetUpdates{ValidatorUpdates: validatorUpdates}); err != nil { - logger.Error("Error publishing event", "err", err) + logger.Error("failed publishing event", "err", err) } } } @@ -533,15 +536,17 @@ func ExecCommitBlock( ) ([]byte, error) { _, err := execBlockOnProxyApp(logger, appConnConsensus, block, store, initialHeight) if err != nil { - logger.Error("Error executing block on proxy app", "height", block.Height, "err", err) + logger.Error("failed executing block on proxy app", "height", block.Height, "err", err) return nil, err } + // Commit block, get hash back res, err := appConnConsensus.CommitSync() if err != nil { - logger.Error("Client error during proxyAppConn.CommitSync", "err", res) + logger.Error("client error during proxyAppConn.CommitSync", "err", res) return nil, err } + // ResponseCommit has no error or log, just data return res.Data, nil }