Re-enable info-level OCR logging for LLO (#16122)

* Re-enable info-level OCR logging for LLO * Changeset * log poller optimization * Add additional info to LLO OCR logging * Fixes test --------- Co-authored-by: vyzaldysanchez <[email protected]>
smartcontractkit · Jan 30, 2025 · 9b1fdce · 9b1fdce
1 parent ddce630
commit 9b1fdce
Show file tree

Hide file tree

Showing 7 changed files with 69 additions and 39 deletions.
diff --git a/.changeset/serious-suns-flow.md b/.changeset/serious-suns-flow.md
@@ -0,0 +1,5 @@
+---
+"chainlink": patch
+---
+
+Only show OCR info-level logs with VerboseLogging #internal
diff --git a/core/services/llo/delegate.go b/core/services/llo/delegate.go
@@ -135,7 +135,7 @@ func (d *delegate) Start(ctx context.Context) error {
 			case 1:
 				lggr = logger.With(lggr, "instanceType", "Green")
 			}
-			ocrLogger := logger.NewOCRWrapper(NewSuppressedLogger(lggr, d.cfg.ReportingPluginConfig.VerboseLogging), d.cfg.TraceLogging, func(msg string) {
+			ocrLogger := logger.NewOCRWrapper(NewSuppressedLogger(lggr, d.cfg.TraceLogging, d.cfg.ReportingPluginConfig.VerboseLogging), d.cfg.TraceLogging, func(msg string) {
 				// NOTE: Some OCR loggers include a DB-persist here
 				// We do not DB persist errors in LLO, since they could be quite voluminous and ought to be present in logs anyway.
 				// This is a performance optimization

diff --git a/core/services/llo/suppressed_logger.go b/core/services/llo/suppressed_logger.go
@@ -2,50 +2,52 @@ package llo
 
 import "github.com/smartcontractkit/chainlink-common/pkg/logger"
 
-// Suppressed logger swallows debug/info unless the verbose flag is turned on
+// Suppressed logger swallows debug and/or info levels
 // Useful for OCR to calm down its verbosity
 
 var _ logger.Logger = &SuppressedLogger{}
 
-func NewSuppressedLogger(lggr logger.Logger, verbose bool) logger.Logger {
+func NewSuppressedLogger(lggr logger.Logger, debug, info bool) logger.Logger {
 	return &SuppressedLogger{
-		Logger:  lggr,
-		Verbose: verbose,
+		Logger:     lggr,
+		DebugLevel: debug,
+		InfoLevel:  info,
 	}
 }
 
 type SuppressedLogger struct {
 	logger.Logger
-	Verbose bool
+	DebugLevel bool
+	InfoLevel  bool
 }
 
 func (s *SuppressedLogger) Debug(args ...interface{}) {
-	if s.Verbose {
+	if s.DebugLevel {
 		s.Logger.Debug(args...)
 	}
 }
 func (s *SuppressedLogger) Info(args ...interface{}) {
-	if s.Verbose {
+	if s.InfoLevel {
 		s.Logger.Info(args...)
 	}
 }
 func (s *SuppressedLogger) Debugf(format string, values ...interface{}) {
-	if s.Verbose {
+	if s.DebugLevel {
 		s.Logger.Debugf(format, values...)
 	}
 }
 func (s *SuppressedLogger) Infof(format string, values ...interface{}) {
-	if s.Verbose {
+	if s.InfoLevel {
 		s.Logger.Infof(format, values...)
 	}
 }
 func (s *SuppressedLogger) Debugw(msg string, keysAndValues ...interface{}) {
-	if s.Verbose {
+	if s.DebugLevel {
 		s.Logger.Debugw(msg, keysAndValues...)
 	}
 }
 func (s *SuppressedLogger) Infow(msg string, keysAndValues ...interface{}) {
-	if s.Verbose {
+	if s.InfoLevel {
 		s.Logger.Infow(msg, keysAndValues...)
 	}
 }
diff --git a/core/services/ocr2/delegate.go b/core/services/ocr2/delegate.go
@@ -885,7 +885,7 @@ func (d *Delegate) newServicesMercury(
 	lc.ContractConfigTrackerPollInterval = 1 * time.Second // This is the fastest that libocr supports. See: https://github.com/smartcontractkit/offchain-reporting/pull/520
 
 	// Disable OCR debug+info logging for legacy mercury jobs unless tracelogging is enabled, because its simply too verbose (150 jobs => ~50k logs per second)
-	ocrLogger := ocrcommon.NewOCRWrapper(llo.NewSuppressedLogger(lggr, d.cfg.OCR2().TraceLogging()), d.cfg.OCR2().TraceLogging(), func(ctx context.Context, msg string) {
+	ocrLogger := ocrcommon.NewOCRWrapper(llo.NewSuppressedLogger(lggr, d.cfg.OCR2().TraceLogging(), d.cfg.OCR2().TraceLogging()), d.cfg.OCR2().TraceLogging(), func(ctx context.Context, msg string) {
 		lggr.ErrorIf(d.jobORM.RecordError(ctx, jb.ID, msg), "unable to record error")
 	})
 
@@ -946,7 +946,6 @@ func (d *Delegate) newServicesLLO(
 	ocrDB *db,
 	lc ocrtypes.LocalConfig,
 ) ([]job.ServiceCtx, error) {
-	lggr = logger.Sugared(lggr.Named("LLO"))
 	spec := jb.OCR2OracleSpec
 	transmitterID := spec.TransmitterID.String
 	if len(transmitterID) != 64 {
@@ -985,6 +984,7 @@ func (d *Delegate) newServicesLLO(
 	if err = json.Unmarshal(spec.PluginConfig.Bytes(), &pluginCfg); err != nil {
 		return nil, err
 	}
+	lggr = logger.Sugared(lggr.Named("LLO").With("donID", pluginCfg.DonID, "channelDefinitionsContractAddress", pluginCfg.ChannelDefinitionsContractAddress))
 
 	// Handle key bundle IDs explicitly specified in job spec
 	kbm := make(map[llotypes.ReportFormat]llo.Key)

diff --git a/core/services/relay/evm/evm.go b/core/services/relay/evm/evm.go
@@ -209,7 +209,7 @@ func NewRelayer(ctx context.Context, lggr logger.Logger, chain legacyevm.Chain,
 	if err != nil {
 		return nil, fmt.Errorf("cannot create evm relayer: %w", err)
 	}
-	sugared := logger.Sugared(lggr).Named("Relayer")
+	sugared := logger.Sugared(lggr).Named("Relayer").With("evmChainID", chain.ID())
 	mercuryORM := mercury.NewORM(opts.DS)
 	cdcFactory := sync.OnceValues(func() (llo.ChannelDefinitionCacheFactory, error) {
 		chainSelector, err := chainselectors.SelectorFromChainId(chain.ID().Uint64())
@@ -836,7 +836,7 @@ func (r *Relayer) NewConfigProvider(ctx context.Context, args commontypes.RelayA
 		// performance hit no matter how minor.
 		configProvider, err = newLLOConfigProvider(ctx, lggr, r.chain, &llo.NullRetirementReportCache{}, relayOpts)
 	case "ocr3-capability":
-		configProvider, err = newOCR3CapabilityConfigProvider(ctx, r.lggr, r.chain, relayOpts)
+		configProvider, err = newOCR3CapabilityConfigProvider(ctx, lggr, r.chain, relayOpts)
 	default:
 		return nil, fmt.Errorf("unrecognized provider type: %q", args.ProviderType)
 	}

diff --git a/core/services/relay/evm/llo/config_poller.go b/core/services/relay/evm/llo/config_poller.go
@@ -4,10 +4,12 @@ import (
 	"bytes"
 	"context"
 	"database/sql"
+	"encoding/hex"
 	"fmt"
 	"math"
 	"math/big"
 	"strconv"
+	"sync"
 
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/pkg/errors"
@@ -60,7 +62,8 @@ type configPoller struct {
 	donIDTopic  [32]byte
 	filterExprs []query.Expression
 
-	fromBlock uint64
+	fromBlock int64
+	mu        sync.RWMutex
 
 	instanceType InstanceType
 }
@@ -100,7 +103,7 @@ func newConfigPoller(lggr logger.Logger, lp LogPoller, cc ConfigCache, addr comm
 		donIDTopic:   DonIDToBytes32(donID),
 		filterExprs:  exprs,
 		instanceType: instanceType,
-		fromBlock:    fromBlock,
+		fromBlock:    int64(fromBlock),
 	}
 	cp.Service, cp.eng = services.Config{
 		Name: "LLOConfigPoller",
@@ -115,11 +118,32 @@ func (cp *configPoller) Notify() <-chan struct{} {
 
 // LatestConfigDetails returns the latest config details from the logs
 func (cp *configPoller) LatestConfigDetails(ctx context.Context) (changedInBlock uint64, configDigest ocrtypes.ConfigDigest, err error) {
-	latestConfig, log, err := cp.latestConfig(ctx, int64(cp.fromBlock), math.MaxInt64) // #nosec G115
+	latestConfig, log, err := cp.latestConfig(ctx, cp.readFromBlock(), math.MaxInt64)
 	if err != nil {
 		return 0, ocrtypes.ConfigDigest{}, fmt.Errorf("failed to get latest config: %w", err)
 	}
-	return uint64(log.BlockNumber), latestConfig.ConfigDigest, nil
+	// Slight optimization, since we only care about the latest log, we can
+	// avoid re-scanning from the original fromBlock every time by setting
+	// fromBlock to the latest seen log here.
+	//
+	// This should always be safe even if LatestConfigDetails is called
+	// concurrently.
+	cp.setFromBlock(log.BlockNumber)
+	return uint64(log.BlockNumber), latestConfig.ConfigDigest, nil // #nosec G115 // log.BlockNumber will never be negative
+}
+
+func (cp *configPoller) readFromBlock() int64 {
+	cp.mu.RLock()
+	defer cp.mu.RUnlock()
+	return cp.fromBlock
+}
+
+func (cp *configPoller) setFromBlock(fromBlock int64) {
+	cp.mu.Lock()
+	defer cp.mu.Unlock()
+	if fromBlock > cp.fromBlock {
+		cp.fromBlock = fromBlock
+	}
 }
 
 func (cp *configPoller) latestConfig(ctx context.Context, fromBlock, toBlock int64) (latestConfig FullConfigFromLog, latestLog logpoller.Log, err error) {
@@ -150,7 +174,7 @@ func (cp *configPoller) latestConfig(ctx context.Context, fromBlock, toBlock int
 			}
 
 			if err = cp.cc.StoreConfig(ctx, event.ConfigDigest, event.Signers, event.F); err != nil {
-				cp.eng.SugaredLogger.Errorf("failed to store production config: %v", err)
+				cp.eng.Errorf("failed to store production config: %v", err)
 			}
 
 			isProduction := (cp.instanceType != InstanceTypeBlue) == event.IsGreenProduction
@@ -168,7 +192,7 @@ func (cp *configPoller) latestConfig(ctx context.Context, fromBlock, toBlock int
 			}
 
 			if err = cp.cc.StoreConfig(ctx, event.ConfigDigest, event.Signers, event.F); err != nil {
-				cp.eng.SugaredLogger.Errorf("failed to store staging config: %v", err)
+				cp.eng.Errorf("failed to store staging config: %v", err)
 			}
 
 			isProduction := (cp.instanceType != InstanceTypeBlue) == event.IsGreenProduction
@@ -190,10 +214,11 @@ func (cp *configPoller) latestConfig(ctx context.Context, fromBlock, toBlock int
 
 // LatestConfig returns the latest config from the logs starting from a certain block
 func (cp *configPoller) LatestConfig(ctx context.Context, changedInBlock uint64) (ocrtypes.ContractConfig, error) {
-	cfg, _, err := cp.latestConfig(ctx, int64(changedInBlock), math.MaxInt64) // #nosec G115
+	cfg, latestLog, err := cp.latestConfig(ctx, int64(changedInBlock), math.MaxInt64) // #nosec G115
 	if err != nil {
 		return ocrtypes.ContractConfig{}, fmt.Errorf("failed to get latest config: %w", err)
 	}
+	cp.eng.Infow("LatestConfig fetched", "config", cfg.ContractConfig, "txHash", latestLog.TxHash, "blockNumber", latestLog.BlockNumber, "blockHash", latestLog.BlockHash, "logIndex", latestLog.LogIndex, "instanceType", cp.instanceType, "donID", cp.donID, "changedInBlock", changedInBlock)
 	return cfg.ContractConfig, nil
 }
 
@@ -206,7 +231,7 @@ func (cp *configPoller) LatestBlockHeight(ctx context.Context) (blockHeight uint
 		}
 		return 0, err
 	}
-	return uint64(latest.BlockNumber), nil
+	return uint64(latest.BlockNumber), nil // #nosec G115 // latest.BlockNumber will never be negative
 }
 
 func (cp *configPoller) InstanceType() InstanceType {
@@ -220,14 +245,13 @@ type FullConfigFromLog struct {
 }
 
 func FullConfigFromProductionConfigSet(unpacked configurator.ConfiguratorProductionConfigSet) (FullConfigFromLog, error) {
-	var transmitAccounts []ocrtypes.Account
-	for _, addr := range unpacked.OffchainTransmitters {
-		transmitAccounts = append(transmitAccounts, ocrtypes.Account(fmt.Sprintf("%x", addr)))
+	transmitAccounts := make([]ocrtypes.Account, len(unpacked.OffchainTransmitters))
+	for i, addr := range unpacked.OffchainTransmitters {
+		transmitAccounts[i] = ocrtypes.Account(hex.EncodeToString(addr[:]))
 	}
-	var signers []ocrtypes.OnchainPublicKey
-	for _, addr := range unpacked.Signers {
-		addr := addr
-		signers = append(signers, addr)
+	signers := make([]ocrtypes.OnchainPublicKey, len(unpacked.Signers))
+	for i, addr := range unpacked.Signers {
+		signers[i] = addr
 	}
 
 	donIDBig := common.Hash(unpacked.ConfigId).Big()
@@ -252,14 +276,13 @@ func FullConfigFromProductionConfigSet(unpacked configurator.ConfiguratorProduct
 }
 
 func FullConfigFromStagingConfigSet(unpacked configurator.ConfiguratorStagingConfigSet) (FullConfigFromLog, error) {
-	var transmitAccounts []ocrtypes.Account
-	for _, addr := range unpacked.OffchainTransmitters {
-		transmitAccounts = append(transmitAccounts, ocrtypes.Account(fmt.Sprintf("%x", addr)))
+	transmitAccounts := make([]ocrtypes.Account, len(unpacked.OffchainTransmitters))
+	for i, addr := range unpacked.OffchainTransmitters {
+		transmitAccounts[i] = ocrtypes.Account(hex.EncodeToString(addr[:]))
 	}
-	var signers []ocrtypes.OnchainPublicKey
-	for _, addr := range unpacked.Signers {
-		addr := addr
-		signers = append(signers, addr)
+	signers := make([]ocrtypes.OnchainPublicKey, len(unpacked.Signers))
+	for i, addr := range unpacked.Signers {
+		signers[i] = addr
 	}
 
 	donIDBig := common.Hash(unpacked.ConfigId).Big()

diff --git a/core/services/relay/evm/write_target_test.go b/core/services/relay/evm/write_target_test.go
@@ -264,12 +264,12 @@ func TestEvmWrite(t *testing.T) {
 		testChain := evmmocks.NewChain(t)
 		testCfg := configtest.NewGeneralConfig(t, func(c *chainlink.Config, s *chainlink.Secrets) {
 			c.EVM[0].Workflow.FromAddress = nil
-
 			forwarderA := testutils.NewAddress()
 			forwarderAddr, err2 := evmtypes.NewEIP55Address(forwarderA.Hex())
 			require.NoError(t, err2)
 			c.EVM[0].Workflow.ForwarderAddress = &forwarderAddr
 		})
+		testChain.On("ID").Return(big.NewInt(11155111))
 		testChain.On("Config").Return(evmtest.NewChainScopedConfig(t, testCfg))
 		capabilityRegistry := evmcapabilities.NewRegistry(lggr)