better logs (#36)

* miner logs
* builder logs

Author: dvush

builder/builder.go

@@ -92,7 +92,6 @@ func (b *Builder) Stop() error {
 }
 
 func (b *Builder) onSealedBlock(block *types.Block, bundles []types.SimulatedBundle, proposerPubkey boostTypes.PublicKey, proposerFeeRecipient boostTypes.Address, attrs *BuilderPayloadAttributes) error {
-	start := time.Now()
 	executableData := beacon.BlockToExecutableData(block)
 	payload, err := executableDataToExecutionPayload(executableData)
 	if err != nil {
@@ -137,11 +136,9 @@ func (b *Builder) onSealedBlock(block *types.Block, bundles []types.SimulatedBun
 	if err != nil {
 		log.Error("could not submit block", "err", err, "bundles", len(bundles))
 		return err
-	} else {
-		log.Info("could submit block", "bundles", len(bundles))
 	}
 
-	log.Info("submitted block", "header", block.Header(), "bid", blockBidMsg, "time", time.Since(start))
+	log.Info("submitted block", "slot", blockBidMsg.Slot, "value", blockBidMsg.Value.String(), "parent", blockBidMsg.ParentHash, "hash", block.Hash(), "bundles", len(bundles))
 
 	return nil
 }
@@ -172,7 +169,7 @@ func (b *Builder) OnPayloadAttribute(attrs *BuilderPayloadAttributes) error {
 
 	parentBlock := b.eth.GetBlockByHash(attrs.HeadHash)
 	if parentBlock == nil {
-		log.Info("Block hash not found in blocktree", "head block hash", attrs.HeadHash)
+		log.Warn("Block hash not found in blocktree", "head block hash", attrs.HeadHash)
 		return errors.New("parent block not found in blocktree")
 	}
 

miner/algo_common.go

@@ -174,7 +174,7 @@ func (envDiff *environmentDiff) commitTx(tx *types.Transaction, chData chainData
 		default:
 			// Strange error, discard the transaction and get the next in line (note, the
 			// nonce-too-high clause will prevent us from executing in vain).
-			log.Debug("Transaction failed, account skipped", "hash", tx.Hash(), "err", err)
+			log.Trace("Transaction failed, account skipped", "hash", tx.Hash(), "err", err)
 			return nil, shiftTx, err
 		}
 	}
@@ -231,12 +231,12 @@ func (envDiff *environmentDiff) commitBundle(bundle *types.SimulatedBundle, chDa
 		receipt, _, err := tmpEnvDiff.commitTx(tx, chData)
 
 		if err != nil {
-			log.Debug("Bundle tx error", "bundle", bundle.OriginalBundle.Hash, "tx", tx.Hash(), "err", err)
+			log.Trace("Bundle tx error", "bundle", bundle.OriginalBundle.Hash, "tx", tx.Hash(), "err", err)
 			return err
 		}
 
 		if receipt.Status != types.ReceiptStatusSuccessful && !bundle.OriginalBundle.RevertingHash(tx.Hash()) {
-			log.Debug("Bundle tx failed", "bundle", bundle.OriginalBundle.Hash, "tx", tx.Hash(), "err", err)
+			log.Trace("Bundle tx failed", "bundle", bundle.OriginalBundle.Hash, "tx", tx.Hash(), "err", err)
 			return errors.New("bundle tx revert")
 		}
 
@@ -256,7 +256,7 @@ func (envDiff *environmentDiff) commitBundle(bundle *types.SimulatedBundle, chDa
 	bundleSimEffGP.Mul(bundleSimEffGP, big.NewInt(99))
 
 	if bundleSimEffGP.Cmp(bundleActualEffGP) == 1 {
-		log.Debug("Bundle underpays after inclusion", "bundle", bundle.OriginalBundle.Hash)
+		log.Trace("Bundle underpays after inclusion", "bundle", bundle.OriginalBundle.Hash)
 		return errors.New("bundle underpays")
 	}
 

miner/algo_greedy.go

@@ -66,7 +66,7 @@ func (b *greedyBuilder) buildBlock(simBundles []types.SimulatedBundle, transacti
 			}
 
 			if err != nil {
-				log.Info("could not apply tx", "hash", order.Tx.Hash(), "err", err)
+				log.Trace("could not apply tx", "hash", order.Tx.Hash(), "err", err)
 				continue
 			}
 			effGapPrice, err := order.Tx.EffectiveGasTip(env.header.BaseFee)
@@ -79,11 +79,11 @@ func (b *greedyBuilder) buildBlock(simBundles []types.SimulatedBundle, transacti
 			err := envDiff.commitBundle(bundle, b.chainData, b.interrupt)
 			orders.Pop()
 			if err != nil {
-				log.Info("Could not apply bundle", "bundle", bundle.OriginalBundle.Hash, "err", err)
+				log.Trace("Could not apply bundle", "bundle", bundle.OriginalBundle.Hash, "err", err)
 				continue
 			}
 
-			log.Info("Included bundle", "bundleEGP", bundle.MevGasPrice.String(), "gasUsed", bundle.TotalGasUsed, "ethToCoinbase", ethIntToFloat(bundle.TotalEth))
+			log.Trace("Included bundle", "bundleEGP", bundle.MevGasPrice.String(), "gasUsed", bundle.TotalGasUsed, "ethToCoinbase", ethIntToFloat(bundle.TotalEth))
 			usedBundles = append(usedBundles, *bundle)
 		}
 	}

miner/worker.go

@@ -1367,30 +1367,25 @@ func (w *worker) fillTransactions(interrupt *atomic.Int32, env *environment, val
 
 	if validatorCoinbase != nil && w.config.BuilderTxSigningKey != nil {
 		builderCoinbaseBalanceAfter := env.state.GetBalance(w.coinbase)
-		log.Info("Before creating validator profit", "validatorCoinbase", validatorCoinbase.String(), "builderCoinbase", w.coinbase.String(), "builderCoinbaseBalanceBefore", builderCoinbaseBalanceBefore.String(), "builderCoinbaseBalanceAfter", builderCoinbaseBalanceAfter.String())
+		log.Trace("Before creating validator profit", "validatorCoinbase", validatorCoinbase.String(), "builderCoinbase", w.coinbase.String(), "builderCoinbaseBalanceBefore", builderCoinbaseBalanceBefore.String(), "builderCoinbaseBalanceAfter", builderCoinbaseBalanceAfter.String())
 
 		profit := new(big.Int).Sub(builderCoinbaseBalanceAfter, builderCoinbaseBalanceBefore)
 		env.gasPool.AddGas(paymentTxGas)
 		if profit.Sign() == 1 {
 			tx, err := w.createProposerPayoutTx(env, validatorCoinbase, profit)
 			if err != nil {
-				log.Error("Proposer payout create tx failed", "err", err)
 				return fmt.Errorf("proposer payout create tx failed - %v", err), nil
 			}
 			if tx != nil {
-				log.Info("Proposer payout create tx succeeded, proceeding to commit tx")
 				_, err = w.commitTransaction(env, tx)
 				if err != nil {
-					log.Error("Proposer payout commit tx failed", "hash", tx.Hash().String(), "err", err)
 					return fmt.Errorf("proposer payout commit tx failed - %v", err), nil
 				}
-				log.Info("Proposer payout commit tx succeeded", "hash", tx.Hash().String())
 				env.tcount++
 			} else {
 				return errors.New("proposer payout create tx failed due to tx is nil"), nil
 			}
 		} else {
-			log.Warn("Proposer payout create tx failed due to not enough balance", "profit", profit.String())
 			return errors.New("proposer payout create tx failed due to not enough balance"), nil
 		}
 	}
@@ -1437,35 +1432,30 @@ func (w *worker) fillTransactionsAlgoWorker(interrupt *int32, env *environment,
 	start := time.Now()
 	builder := newGreedyBuilder(w.chain, w.chainConfig, w.blockList, env, interrupt)
 	newEnv, blockBundles := builder.buildBlock(bundlesToConsider, pending)
-	log.Debug("Build block", "time", time.Since(start), "gas used", newEnv.header.GasUsed)
+	log.Debug("Build block", "time", time.Since(start), "gasUsed", newEnv.header.GasUsed)
 	*env = *newEnv
 
 	if validatorCoinbase != nil && w.config.BuilderTxSigningKey != nil {
 		builderCoinbaseBalanceAfter := env.state.GetBalance(w.coinbase)
-		log.Info("Before creating validator profit", "validatorCoinbase", validatorCoinbase.String(), "builderCoinbase", w.coinbase.String(), "builderCoinbaseBalanceBefore", builderCoinbaseBalanceBefore.String(), "builderCoinbaseBalanceAfter", builderCoinbaseBalanceAfter.String())
+		log.Trace("Before creating validator profit", "validatorCoinbase", validatorCoinbase.String(), "builderCoinbase", w.coinbase.String(), "builderCoinbaseBalanceBefore", builderCoinbaseBalanceBefore.String(), "builderCoinbaseBalanceAfter", builderCoinbaseBalanceAfter.String())
 
 		profit := new(big.Int).Sub(builderCoinbaseBalanceAfter, builderCoinbaseBalanceBefore)
 		env.gasPool.AddGas(params.TxGas)
 		if profit.Sign() == 1 {
 			tx, err := w.createProposerPayoutTx(env, validatorCoinbase, profit)
 			if err != nil {
-				log.Error("Proposer payout create tx failed", "err", err)
 				return fmt.Errorf("proposer payout create tx failed - %v", err), nil
 			}
 			if tx != nil {
-				log.Info("Proposer payout create tx succeeded, proceeding to commit tx")
 				_, err = w.commitTransaction(env, tx)
 				if err != nil {
-					log.Error("Proposer payout commit tx failed", "hash", tx.Hash().String(), "err", err)
 					return fmt.Errorf("proposer payout commit tx failed - %v", err), nil
 				}
-				log.Info("Proposer payout commit tx succeeded", "hash", tx.Hash().String())
 				env.tcount++
 			} else {
 				return errors.New("proposer payout create tx failed due to tx is nil"), nil
 			}
 		} else {
-			log.Warn("Proposer payout create tx failed due to not enough balance", "profit", profit.String())
 			return errors.New("proposer payout create tx failed due to not enough balance"), nil
 		}
 
@@ -1494,7 +1484,7 @@ func (w *worker) generateWork(params *generateParams) (*types.Block, *big.Int, e
 		if errors.Is(err, errBlockInterruptedByTimeout) {
 			log.Warn("Block building is interrupted", "allowance", common.PrettyDuration(w.newpayloadTimeout))
 		}
-		log.Info("Filled block with transactions", "time", time.Since(start), "gas used", work.header.GasUsed, "txs", work.txs)
+		log.Debug("Filled block with transactions", "time", time.Since(start), "gas used", work.header.GasUsed, "txs", len(work.txs))
 	}
 	block, err := w.engine.FinalizeAndAssemble(w.chain, work.header, work.state, work.txs, work.unclelist(), work.receipts, params.withdrawals)
 	if err != nil {
@@ -1921,7 +1911,7 @@ func (w *worker) createProposerPayoutTx(env *environment, recipient *common.Addr
 	}
 	gasPrice := new(big.Int).Set(env.header.BaseFee)
 	chainId := w.chainConfig.ChainID
-	log.Debug("createProposerPayoutTx", "sender", sender, "chainId", chainId.String(), "nonce", nonce, "amount", amount.String(), "baseFee", env.header.BaseFee.String(), "fee", fee)
+	log.Trace("createProposerPayoutTx", "sender", sender, "chainId", chainId.String(), "nonce", nonce, "amount", amount.String(), "baseFee", env.header.BaseFee.String(), "fee", fee)
 	tx := types.NewTransaction(nonce, *recipient, amount, paymentTxGas, gasPrice, nil)
 	return types.SignTx(tx, types.LatestSignerForChainID(chainId), w.config.BuilderTxSigningKey)
 }