chg : commit tx logs from info to debug (maticnetwork#673)

* chg : commit tx logs from info to debug

* fix : minor changes

* chg : miner : commitTransactions-stats moved from info to debug

* lint : fix linters

* refactor logging

* miner : chg : UnauthorizedSignerError to debug

* lint : fix lint

* fix : log.Logger interface compatibility

---------

Co-authored-by: Evgeny Danienko <6655321@bk.ru>

internal/testlog/testlog.go

@@ -148,3 +148,35 @@ func (l *logger) flush() {
 	}
 	l.h.buf = nil
 }
+
+func (l *logger) OnTrace(fn func(l log.Logging)) {
+	if l.GetHandler().Level() >= log.LvlTrace {
+		fn(l.Trace)
+	}
+}
+
+func (l *logger) OnDebug(fn func(l log.Logging)) {
+	if l.GetHandler().Level() >= log.LvlDebug {
+		fn(l.Debug)
+	}
+}
+func (l *logger) OnInfo(fn func(l log.Logging)) {
+	if l.GetHandler().Level() >= log.LvlInfo {
+		fn(l.Info)
+	}
+}
+func (l *logger) OnWarn(fn func(l log.Logging)) {
+	if l.GetHandler().Level() >= log.LvlWarn {
+		fn(l.Warn)
+	}
+}
+func (l *logger) OnError(fn func(l log.Logging)) {
+	if l.GetHandler().Level() >= log.LvlError {
+		fn(l.Error)
+	}
+}
+func (l *logger) OnCrit(fn func(l log.Logging)) {
+	if l.GetHandler().Level() >= log.LvlCrit {
+		fn(l.Crit)
+	}
+}

log/logger.go

@@ -106,6 +106,8 @@ type RecordKeyNames struct {
 	Ctx  string
 }
 
+type Logging func(msg string, ctx ...interface{})
+
 // A Logger writes key/value pairs to a Handler
 type Logger interface {
 	// New returns a new Logger that has this logger's context plus the given context
@@ -124,6 +126,13 @@ type Logger interface {
 	Warn(msg string, ctx ...interface{})
 	Error(msg string, ctx ...interface{})
 	Crit(msg string, ctx ...interface{})
+
+	OnTrace(func(l Logging))
+	OnDebug(func(l Logging))
+	OnInfo(func(l Logging))
+	OnWarn(func(l Logging))
+	OnError(func(l Logging))
+	OnCrit(func(l Logging))
 }
 
 type logger struct {
@@ -198,6 +207,38 @@ func (l *logger) SetHandler(h Handler) {
 	l.h.Swap(h)
 }
 
+func (l *logger) OnTrace(fn func(l Logging)) {
+	if l.GetHandler().Level() >= LvlTrace {
+		fn(l.Trace)
+	}
+}
+
+func (l *logger) OnDebug(fn func(l Logging)) {
+	if l.GetHandler().Level() >= LvlDebug {
+		fn(l.Debug)
+	}
+}
+func (l *logger) OnInfo(fn func(l Logging)) {
+	if l.GetHandler().Level() >= LvlInfo {
+		fn(l.Info)
+	}
+}
+func (l *logger) OnWarn(fn func(l Logging)) {
+	if l.GetHandler().Level() >= LvlWarn {
+		fn(l.Warn)
+	}
+}
+func (l *logger) OnError(fn func(l Logging)) {
+	if l.GetHandler().Level() >= LvlError {
+		fn(l.Error)
+	}
+}
+func (l *logger) OnCrit(fn func(l Logging)) {
+	if l.GetHandler().Level() >= LvlCrit {
+		fn(l.Crit)
+	}
+}
+
 func normalize(ctx []interface{}) []interface{} {
 	// if the caller passed a Ctx object, then expand it
 	if len(ctx) == 1 {

log/root.go

@@ -60,6 +60,38 @@ func Crit(msg string, ctx ...interface{}) {
 	os.Exit(1)
 }
 
+func OnTrace(fn func(l Logging)) {
+	if root.GetHandler().Level() >= LvlTrace {
+		fn(root.Trace)
+	}
+}
+
+func OnDebug(fn func(l Logging)) {
+	if root.GetHandler().Level() >= LvlDebug {
+		fn(root.Debug)
+	}
+}
+func OnInfo(fn func(l Logging)) {
+	if root.GetHandler().Level() >= LvlInfo {
+		fn(root.Info)
+	}
+}
+func OnWarn(fn func(l Logging)) {
+	if root.GetHandler().Level() >= LvlWarn {
+		fn(root.Warn)
+	}
+}
+func OnError(fn func(l Logging)) {
+	if root.GetHandler().Level() >= LvlError {
+		fn(root.Error)
+	}
+}
+func OnCrit(fn func(l Logging)) {
+	if root.GetHandler().Level() >= LvlCrit {
+		fn(root.Crit)
+	}
+}
+
 // Output is a convenient alias for write, allowing for the modification of
 // the calldepth (number of stack frames to skip).
 // calldepth influences the reported line number of the log message.

miner/worker.go

@@ -39,6 +39,7 @@ import (
 	cmath "github.com/ethereum/go-ethereum/common/math"
 	"github.com/ethereum/go-ethereum/common/tracing"
 	"github.com/ethereum/go-ethereum/consensus"
+	"github.com/ethereum/go-ethereum/consensus/bor"
 	"github.com/ethereum/go-ethereum/consensus/misc"
 	"github.com/ethereum/go-ethereum/core"
 	"github.com/ethereum/go-ethereum/core/state"
@@ -946,6 +947,22 @@ func (w *worker) commitTransactions(env *environment, txs *types.TransactionsByP
 	}
 	var coalescedLogs []*types.Log
 
+	initialGasLimit := env.gasPool.Gas()
+	initialTxs := txs.GetTxs()
+
+	var breakCause string
+
+	defer func() {
+		log.OnDebug(func(lg log.Logging) {
+			lg("commitTransactions-stats",
+				"initialTxsCount", initialTxs,
+				"initialGasLimit", initialGasLimit,
+				"resultTxsCount", txs.GetTxs(),
+				"resultGapPool", env.gasPool.Gas(),
+				"exitCause", breakCause)
+		})
+	}()
+
 	for {
 		// In the following three cases, we will interrupt the execution of the transaction.
 		// (1) new head block event arrival, the interrupt signal is 1
@@ -993,7 +1010,11 @@ func (w *worker) commitTransactions(env *environment, txs *types.TransactionsByP
 		// Start executing the transaction
 		env.state.Prepare(tx.Hash(), env.tcount)
 
-		start := time.Now()
+		var start time.Time
+
+		log.OnDebug(func(log.Logging) {
+			start = time.Now()
+		})
 
 		logs, err := w.commitTransaction(env, tx)
 
@@ -1018,7 +1039,10 @@ func (w *worker) commitTransactions(env *environment, txs *types.TransactionsByP
 			coalescedLogs = append(coalescedLogs, logs...)
 			env.tcount++
 			txs.Shift()
-			log.Info("Committed new tx", "tx hash", tx.Hash(), "from", from, "to", tx.To(), "nonce", tx.Nonce(), "gas", tx.Gas(), "gasPrice", tx.GasPrice(), "value", tx.Value(), "time spent", time.Since(start))
+
+			log.OnDebug(func(lg log.Logging) {
+				lg("Committed new tx", "tx hash", tx.Hash(), "from", from, "to", tx.To(), "nonce", tx.Nonce(), "gas", tx.Gas(), "gasPrice", tx.GasPrice(), "value", tx.Value(), "time spent", time.Since(start))
+			})
 
 		case errors.Is(err, core.ErrTxTypeNotSupported):
 			// Pop the unsupported transaction without shifting in the next from the account
@@ -1117,7 +1141,12 @@ func (w *worker) prepareWork(genParams *generateParams) (*environment, error) {
 	}
 	// Run the consensus preparation with the default or customized consensus engine.
 	if err := w.engine.Prepare(w.chain, header); err != nil {
-		log.Error("Failed to prepare header for sealing", "err", err)
+		switch err.(type) {
+		case *bor.UnauthorizedSignerError:
+			log.Debug("Failed to prepare header for sealing", "err", err)
+		default:
+			log.Error("Failed to prepare header for sealing", "err", err)
+		}
 		return nil, err
 	}
 	// Could potentially happen if starting to mine in an odd state.