chore(lib/log): add InfoErr and DebugErr (#2569)

Adds:
- `log.InfoErr(ctx, "message", err)` to log errors at Info level. Same
for `log.DebugErr`.
 - Improve linter to check for invalid logging usage.
 - Fix invalid usages. 

issue: none

e2e/app/rpc.go

@@ -107,7 +107,7 @@ func waitForNode(ctx context.Context, node *e2e.Node, height int64, timeout time
 	defer timer.Stop()
 
 	var lastHeight int64
-	var lastErr error
+	lastErr := errors.New("no last error")
 	lastChanged := time.Now()
 
 	for {
@@ -116,7 +116,7 @@ func waitForNode(ctx context.Context, node *e2e.Node, height int64, timeout time
 			return nil, errors.Wrap(ctx.Err(), "context canceled")
 		case <-timer.C:
 			if time.Since(lastChanged) > timeout {
-				return nil, errors.New("timed out waiting for height", "name", node.Name, "height", height, "last_err", lastErr, "last_height", lastHeight)
+				return nil, errors.Wrap(lastErr, "timed out waiting for height", "name", node.Name, "height", height, "last_height", lastHeight)
 			}
 
 			status, err := client.Status(ctx)

e2e/app/test.go

@@ -5,6 +5,7 @@ import (
 	"encoding/json"
 	"os"
 	"path/filepath"
+	"strings"
 
 	"github.com/omni-network/omni/lib/errors"
 	"github.com/omni-network/omni/lib/log"
@@ -74,11 +75,11 @@ func Test(ctx context.Context, def Definition, verbose bool) error {
 	}
 
 	log.Debug(ctx, "Env files",
-		EnvE2EManifest, manifestFile,
-		EnvInfraType, infd.Provider,
-		EnvInfraFile, infd.Path,
-		EnvE2EDeployInfo, deployInfoFile,
-		EnvE2ERPCEndpoints, endpointsFile,
+		strings.ToLower(EnvE2EManifest), manifestFile,
+		strings.ToLower(EnvInfraType), infd.Provider,
+		strings.ToLower(EnvInfraFile), infd.Path,
+		strings.ToLower(EnvE2EDeployInfo), deployInfoFile,
+		strings.ToLower(EnvE2ERPCEndpoints), endpointsFile,
 	)
 
 	args := []string{"go", "test", "-timeout", "60s", "-count", "1"}

halo/attest/keeper/keeper.go

@@ -198,7 +198,7 @@ func (k *Keeper) addOne(ctx context.Context, agg *types.AggVote, valSetID uint64
 	} else if err != nil {
 		return errors.Wrap(err, "by att unique key")
 	} else if existing.GetFinalizedAttId() != 0 {
-		log.Debug(ctx, "Ignoring vote for attestation with finalized override", nil,
+		log.Debug(ctx, "Ignoring vote for attestation with finalized override",
 			"agg_id", attID,
 			"chain", k.namer(header.XChainVersion()),
 			"attest_offset", header.AttestOffset,

halo/evmstaking2/keeper/keeper.go

@@ -177,7 +177,7 @@ func (k Keeper) processBufferedEvent(ctx context.Context, elog *evmenginetypes.E
 	if err := catch(func() error { //nolint:contextcheck // False positive wrt ctx
 		return k.parseAndDeliver(branchCtx, elog)
 	}); err != nil {
-		log.Info(ctx, "Delivering EVM log event failed", "error", err,
+		log.InfoErr(ctx, "Delivering EVM log event failed", err,
 			"name", k.Name(),
 			"height", branchCtx.BlockHeight(),
 		)

lib/contracts/feeoraclev1/feeparams.go

@@ -106,7 +106,7 @@ func conversionRate(ctx context.Context, pricer tokens.Pricer, from, to tokens.T
 
 	prices, err := pricer.Price(ctx, from, to)
 	if err != nil {
-		return 0, errors.Wrap(err, "get price", "ids", "from", from, "to", to)
+		return 0, errors.Wrap(err, "get price", "from", from, "to", to)
 	}
 
 	has := func(t tokens.Token) bool {

lib/contracts/feeoraclev2/feeparams.go

@@ -105,7 +105,7 @@ func conversionRate(ctx context.Context, pricer tokens.Pricer, from, to tokens.T
 
 	prices, err := pricer.Price(ctx, from, to)
 	if err != nil {
-		return 0, errors.Wrap(err, "get price", "ids", "from", from, "to", to)
+		return 0, errors.Wrap(err, "get price", "from", from, "to", to)
 	}
 
 	has := func(t tokens.Token) bool {

lib/log/log.go

@@ -32,11 +32,33 @@ func Debug(ctx context.Context, msg string, attrs ...any) {
 	log(ctx, slog.LevelDebug, msg, mergeAttrs(ctx, attrs)...)
 }
 
+// DebugErr logs the message and error and attributes at debug level.
+// If err is nil, it will not be logged, but rather use Debug in that case.
+func DebugErr(ctx context.Context, msg string, err error, attrs ...any) {
+	if err != nil {
+		attrs = append(attrs, slog.String("err", err.Error()))
+		attrs = append(attrs, errAttrs(err)...)
+	}
+
+	log(ctx, slog.LevelDebug, msg, mergeAttrs(ctx, attrs)...)
+}
+
 // Info logs the message and attributes at info level.
 func Info(ctx context.Context, msg string, attrs ...any) {
 	log(ctx, slog.LevelInfo, msg, mergeAttrs(ctx, attrs)...)
 }
 
+// InfoErr logs the message and error and attributes at info level.
+// If err is nil, it will not be logged, but rather use Info in that case.
+func InfoErr(ctx context.Context, msg string, err error, attrs ...any) {
+	if err != nil {
+		attrs = append(attrs, slog.String("err", err.Error()))
+		attrs = append(attrs, errAttrs(err)...)
+	}
+
+	log(ctx, slog.LevelInfo, msg, mergeAttrs(ctx, attrs)...)
+}
+
 // Warn logs the message and error and attributes at warning level.
 // If err is nil, it will not be logged.
 func Warn(ctx context.Context, msg string, err error, attrs ...any) {

lib/log/log_test.go

@@ -46,6 +46,11 @@ func TestSimpleLogs(t *testing.T) {
 			err = pkgerrors.Wrap(err, "pkg wrap")
 			log.Warn(ctx, "Pkg wrapped error", err)
 		}
+		{ // InfoErr/DebugErr
+			err := errors.New("new", "new", "new")
+			log.DebugErr(ctx, "debug with error", err, "1", 1, "2", "two")
+			log.InfoErr(ctx, "info with error", err, "3", 3, "4", "four")
+		}
 	})
 }
 

lib/log/testdata/TestSimpleLogs_cli.golden

@@ -7,3 +7,5 @@ err2
 ctx debug message                                                                          ctx_key1=ctx_value1 debug_key1=debug_value1
 ctx info message                                                                           ctx_key1=ctx_value1 ctx_key2=ctx_value2 info_key2=info_value2
 Pkg wrapped error                                                                          err="pkg wrap: omni wrap: new" wrap=wrap new=new
+debug with error                                                                           1=1 2=two err=new new=new
+info with error                                                                            3=3 4=four err=new new=new

lib/log/testdata/TestSimpleLogs_console.golden

@@ -7,3 +7,5 @@
 00-00-00 00:00:00 DEBU ctx debug message                        ctx_key1=ctx_value1 debug_key1=debug_value1
 00-00-00 00:00:00 INFO ctx info message                         ctx_key1=ctx_value1 ctx_key2=ctx_value2 info_key2=info_value2
 00-00-00 00:00:00 WARN Pkg wrapped error                        err="pkg wrap: omni wrap: new" wrap=wrap new=new stacktrace=<stacktrace>
+00-00-00 00:00:00 DEBU debug with error                         1=1 2=two err=new new=new stacktrace=<stacktrace>
+00-00-00 00:00:00 INFO info with error                          3=3 4=four err=new new=new stacktrace=<stacktrace>

lib/log/testdata/TestSimpleLogs_json.golden

@@ -7,3 +7,5 @@
 {"time":"00-00-00 00:00:00","level":"DEBUG","source":"<source>","msg":"ctx debug message","ctx_key1":"ctx_value1","debug_key1":"debug_value1"}
 {"time":"00-00-00 00:00:00","level":"INFO","source":"<source>","msg":"ctx info message","ctx_key1":"ctx_value1","ctx_key2":"ctx_value2","info_key2":"info_value2"}
 {"time":"00-00-00 00:00:00","level":"WARN","source":"<source>","msg":"Pkg wrapped error","err":"pkg wrap: omni wrap: new","wrap":"wrap","new":"new","source":"<stacktrace>"}
+{"time":"00-00-00 00:00:00","level":"DEBUG","source":"<source>","msg":"debug with error","1":1,"2":"two","err":"new","new":"new","source":"<stacktrace>"}
+{"time":"00-00-00 00:00:00","level":"INFO","source":"<source>","msg":"info with error","3":3,"4":"four","err":"new","new":"new","source":"<stacktrace>"}

lib/log/testdata/TestSimpleLogs_logfmt.golden

@@ -7,3 +7,5 @@ time="00-00-00 00:00:00" level=ERROR source=<source> msg=err2 err="second: first
 time="00-00-00 00:00:00" level=DEBUG source=<source> msg="ctx debug message" ctx_key1=ctx_value1 debug_key1=debug_value1
 time="00-00-00 00:00:00" level=INFO source=<source> msg="ctx info message" ctx_key1=ctx_value1 ctx_key2=ctx_value2 info_key2=info_value2
 time="00-00-00 00:00:00" level=WARN source=<source> msg="Pkg wrapped error" err="pkg wrap: omni wrap: new" wrap=wrap new=new source=<stacktrace>
+time="00-00-00 00:00:00" level=DEBUG source=<source> msg="debug with error" 1=1 2=two err=new new=new source=<stacktrace>
+time="00-00-00 00:00:00" level=INFO source=<source> msg="info with error" 3=3 4=four err=new new=new source=<stacktrace>

lib/netconf/provider.go

@@ -50,7 +50,7 @@ func AwaitOnExecutionChain(ctx context.Context, netID ID, portalRegistry *bindin
 		}
 
 		if !containsAll(network, expected) {
-			log.Info(ctx, "Execution registry doesn't contain all expected chains (will retry)", ""+
+			log.Info(ctx, "Execution registry doesn't contain all expected chains (will retry)",
 				"expected", expected, "actual", network.ChainNamesByIDs())
 			backoff()
 
@@ -101,7 +101,7 @@ func AwaitOnConsensusChain(ctx context.Context, netID ID, cprov cchain.Provider,
 		}
 
 		if !containsAll(network, expected) {
-			log.Info(ctx, "Consensus registry doesn't contain all expected chains (will retry)", ""+
+			log.Info(ctx, "Consensus registry doesn't contain all expected chains (will retry)",
 				"expected", expected, "actual", network.ChainNamesByIDs())
 			backoff()
 

lib/p2putil/disc_test.go

@@ -66,7 +66,7 @@ func TestDiscv4(t *testing.T) {
 			}
 		}
 
-		log.Info("discovered nodes", "count", len(ips), "ips", ips)
+		t.Log("discovered nodes", "count", len(ips), "ips", ips)
 		time.Sleep(time.Second * 2)
 	}
 }

lib/txmgr/config.go

@@ -83,7 +83,7 @@ func (m CLIConfig) Check() error {
 	}
 	if m.MinBaseFeeGwei < m.MinTipCapGwei {
 		return errors.New("minBaseFee smaller than minTipCap",
-			m.MinBaseFeeGwei, m.MinTipCapGwei)
+			"base", m.MinBaseFeeGwei, "min", m.MinTipCapGwei)
 	}
 	if m.ResubmissionTimeout == 0 {
 		return errors.New("must provide ResubmissionTimeout")
@@ -231,7 +231,7 @@ func NewConfig(cfg CLIConfig, privateKey *ecdsa.PrivateKey, client ethclient.Cli
 
 func newConfig(cfg CLIConfig, signer SignerFn, from common.Address, client ethclient.Client) (Config, error) {
 	if err := cfg.Check(); err != nil {
-		return Config{}, errors.New("invalid config", err)
+		return Config{}, errors.Wrap(err, "invalid config")
 	}
 
 	feeLimitThreshold, err := GweiToWei(cfg.FeeLimitThresholdGwei)
@@ -283,7 +283,7 @@ func (m Config) Check() error {
 	}
 	if m.MinBaseFee != nil && m.MinTipCap != nil && m.MinBaseFee.Cmp(m.MinTipCap) == -1 {
 		return errors.New("minBaseFee smaller than minTipCap",
-			m.MinBaseFee, m.MinTipCap)
+			"base", m.MinBaseFee, "min", m.MinTipCap)
 	}
 	if m.ResubmissionTimeout == 0 {
 		return errors.New("must provide ResubmissionTimeout")

lib/txmgr/ether.go

@@ -13,7 +13,7 @@ import (
 // GweiToWei converts a float64 GWei value into a big.Int Wei value.
 func GweiToWei(gwei float64) (*big.Int, error) {
 	if math.IsNaN(gwei) || math.IsInf(gwei, 0) {
-		return nil, errors.New("invalid gwei value", gwei)
+		return nil, errors.New("invalid gwei value", "value", gwei)
 	}
 
 	// convert float GWei value into integer Wei value

lib/txmgr/txmgr.go

@@ -353,7 +353,7 @@ func (m *simple) publishTx(ctx context.Context, tx *types.Transaction, sendState
 		if bumpFeesImmediately {
 			newTx, err := m.increaseGasPrice(ctx, tx)
 			if err != nil {
-				log.Info(ctx, "Unable to increase gas", err)
+				log.Warn(ctx, "Unable to increase gas", err)
 				return tx, false
 			}
 			tx = newTx
@@ -630,7 +630,7 @@ func (m *simple) checkLimits(tip, baseFee, bumpedTip, bumpedFee *big.Int) error
 		}
 		// if the value is over the max, add an error message
 		if v.Cmp(max) > 0 {
-			errs = errors.New("bumped cap is over multiple of the suggested value", name, v, limit)
+			errs = errors.New("bumped cap is over multiple of the suggested value", name, v, "limit", limit)
 		}
 	}
 	check(bumpedTip, maxTip, "tip")

monitor/app/public_rpc.go

@@ -24,8 +24,6 @@ func monitorPublicRPCForever(
 		return
 	}
 
-	log.Info(ctx, "Setting up monitoring of a public RPC for %v", network.ID)
-
 	publicRPC, err := publicRPCEndpoint(network, omniChain, ethClients)
 	if err != nil {
 		log.Error(ctx, "Failed to dial into public RPC", err)
@@ -34,6 +32,8 @@ func monitorPublicRPCForever(
 
 	omniNodeRPC := ethClients[omniChain.ID]
 
+	log.Info(ctx, "Monitoring public RPC", "public", publicRPC, "local", omniNodeRPC)
+
 	ticker := time.NewTicker(time.Second * 30)
 	defer ticker.Stop()
 

monitor/routerecon/recon_internal_test.go

@@ -112,7 +112,7 @@ func TestBasicHistorical(t *testing.T) {
 		log.Info(ctx, "Max routescan offset", "stream", streamName, "offset", maxOffset, "src_timestamp", fmtTime(maxCrossTx.SrcTimestamp), "dst_timestamp", fmtTime(maxCrossTx.DstTimestamp))
 
 		sub, ok, err := conn.XProvider.GetSubmittedCursor(ctx, xchain.LatestRef, streamID)
-		log.Info(ctx, "Max onchain offset", "stream", streamName, "offset", sub.MsgOffset, "ok", ok, "err", err)
+		log.InfoErr(ctx, "Max onchain offset", err, "stream", streamName, "offset", sub.MsgOffset, "ok", ok)
 		log.Info(ctx, "Missing routescan offsets", "stream", streamName, "indexed", len(offsets), "indexed_gaps", gaps, "unindexed", umath.SubtractOrZero(sub.MsgOffset, maxOffset))
 	}
 }

relayer/app/worker.go

@@ -65,7 +65,7 @@ func (w *Worker) Run(ctx context.Context) {
 		if ctx.Err() != nil {
 			return
 		} else if errors.Is(err, chaos.ErrChaos) {
-			log.Info(ctx, "Worker failed due to chaos testing, resetting", err)
+			log.InfoErr(ctx, "Worker failed due to chaos testing, resetting", err)
 		} else {
 			log.Warn(ctx, "Worker failed, resetting", err)
 		}