chg : commit tx logs from info to debug (#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"
@@ -952,12 +953,14 @@ func (w *worker) commitTransactions(env *environment, txs *types.TransactionsByP
 	var breakCause string
 
 	defer func() {
-		log.Warn("commitTransactions-stats",
-			"initialTxsCount", initialTxs,
-			"initialGasLimit", initialGasLimit,
-			"resultTxsCount", txs.GetTxs(),
-			"resultGapPool", env.gasPool.Gas(),
-			"exitCause", breakCause)
+		log.OnDebug(func(lg log.Logging) {
+			lg("commitTransactions-stats",
+				"initialTxsCount", initialTxs,
+				"initialGasLimit", initialGasLimit,
+				"resultTxsCount", txs.GetTxs(),
+				"resultGapPool", env.gasPool.Gas(),
+				"exitCause", breakCause)
+		})
 	}()
 
 	for {
@@ -1012,7 +1015,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)
 
@@ -1037,7 +1044,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
@@ -1136,7 +1146,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.