Add debug logs for config polling and discovery

pkg/chainaccessor/config_processors.go

@@ -54,8 +54,7 @@ func processConfigResults(
 }
 
 // processSourceChainConfigResults extracts and processes source chain config results from the batch
-func processSourceChainConfigResults(
-	lggr logger.Logger,
+func (l *DefaultAccessor) processSourceChainConfigResults(
 	batchResult types.BatchGetLatestValuesResult,
 	standardOffRampRequestCount int,
 	filteredSourceChains []cciptypes.ChainSelector,
@@ -69,7 +68,8 @@ func processSourceChainConfigResults(
 			sourceChainResults := results[standardOffRampRequestCount:]
 
 			if len(sourceChainResults) != len(filteredSourceChains) {
-				lggr.Warnw("Source chain result count mismatch",
+				l.lggr.Warnw("Source chain result count mismatch",
+					"accessorSelector", l.chainSelector,
 					"expected", len(filteredSourceChains),
 					"got", len(sourceChainResults))
 			} else {
@@ -81,16 +81,17 @@ func processSourceChainConfigResults(
 
 					v, err := sourceChainResults[i].GetResult()
 					if err != nil {
-						lggr.Errorw("Failed to get source chain config from result",
-							"chain", chain,
+						l.lggr.Errorw("Failed to get source chain config from result",
+							"accessorSelector", l.chainSelector,
+							"sourceChain", chain,
 							"error", err)
 						continue
 					}
 
 					cfg, ok := v.(*cciptypes.SourceChainConfig)
 					if !ok {
-						lggr.Errorw("Invalid result type from GetSourceChainConfig",
-							"chain", chain,
+						l.lggr.Errorw("Invalid result type from GetSourceChainConfig",
+							"sourceChain", chain,
 							"type", fmt.Sprintf("%T", v))
 						continue
 					}

pkg/chainaccessor/default_accessor.go

@@ -58,7 +58,7 @@
 func (l *DefaultAccessor) GetContractAddress(contractName string) ([]byte, error) {
 	bindings := l.contractReader.GetBindings(contractName)
 	if len(bindings) != 1 {
-		return nil, fmt.Errorf("expected one binding for the %s contract, got %d", contractName, len(bindings))
+		return nil, fmt.Errorf("expected one binding for the %s contract, got %d, for accessor on chain %d", contractName, len(bindings), l.chainSelector)
 	}
 
 	addressBytes, err := l.addrCodec.AddressStringToBytes(bindings[0].Binding.Address, l.chainSelector)
@@ -83,12 +83,12 @@
 	var configRequests contractreader.ExtendedBatchGetLatestValuesRequest
 	var standardOffRampRequestCount int
 	if l.chainSelector == destChainSelector {
-		lggr.Debugw("getting ChainConfigSnapshot and and OffRamp SourceChainConfigs for destination chain",
-			"chainSelector", l.chainSelector)
+		lggr.Debugw("getting ChainConfigSnapshot and OffRamp SourceChainConfigs for destination chain",
+			"accessorSelector", l.chainSelector)
 		configRequests, standardOffRampRequestCount = prepareDestChainRequest(sourceChainSelectors)
 	} else {
 		lggr.Debugw("getting ChainConfigSnapshot for a source chain",
-			"chainSelector", l.chainSelector)
+			"accessorSelector", l.chainSelector)
 		configRequests = prepareSourceChainRequest(destChainSelector)
 	}
 
@@ -99,25 +99,35 @@
 	}
 
 	if len(skipped) > 0 {
-		lggr.Warnw("chain reader skipped some config requests", "skipped", skipped)
+		lggr.Warnw("chain reader skipped some config requests",
+			"skipped", skipped, "accessorSelector", l.chainSelector, "destChainSelector", destChainSelector,
+			"sourceChainSelectors", sourceChainSelectors)
 	}
 
 	// Process standard results (ChainConfigSnapshot)
 	standardResultsCopy := extractStandardChainConfigResults(batchResult, standardOffRampRequestCount)
 	standardConfigs, err := processConfigResults(lggr, l.chainSelector, destChainSelector, standardResultsCopy)
 	if err != nil {
 		// Log error but don't return yet and attempt to process source chain configs
-		lggr.Errorw("failed to process standard chain config results", "err", err)
+		lggr.Errorw("failed to process standard chain config results", "accessorSelector", l.chainSelector,
+			"destChainSelector", destChainSelector, "sourceChainSelectors", sourceChainSelectors, "err", err)
 		standardConfigs = cciptypes.ChainConfigSnapshot{}
 	}
 
 	// Process source chain config results
-	sourceChainConfigs := processSourceChainConfigResults(
-		lggr,
+	sourceChainConfigs := l.processSourceChainConfigResults(
 		batchResult,
 		standardOffRampRequestCount,
 		sourceChainSelectors,
 	)
+	l.lggr.Debugw("processed all chain config results",
+		"accessorSelector", l.chainSelector,
+		"destChainSelector", destChainSelector,
+		"sourceChainSelectors", sourceChainSelectors,
+		"numSourceChainConfigs", len(sourceChainConfigs),
+		"standardConfigs", standardConfigs,
+		"sourceChainConfigs", sourceChainConfigs,
+	)
 	return standardConfigs, sourceChainConfigs, nil
 }
 
@@ -823,7 +833,7 @@
 	)
 
 	if err != nil {
-		lggr.Errorw("failed to batch get chain fee price updates", "err", err)
+		lggr.Errorw("failed to batch get chain fee price updates", "accessorSelector", l.chainSelector, "err", err)
 		return make(map[cciptypes.ChainSelector]cciptypes.TimestampedUnixBig), nil // Return a new empty map
 	}
 
@@ -834,12 +844,13 @@
 		if contract.Name == consts.ContractNameFeeQuoter {
 			feeQuoterResults = results
 			found = true
+			lggr.Debugw("found fee quoter results")
 			break // Found the results, exit loop
 		}
 	}
 
 	if !found {
-		lggr.Errorw("FeeQuoter results missing from batch response")
+		lggr.Errorw("FeeQuoter results missing from batch response", "accessorSelector", l.chainSelector)
 		return make(map[cciptypes.ChainSelector]cciptypes.TimestampedUnixBig), nil // Return a new empty map
 	}
 
@@ -867,6 +878,7 @@
 		if i >= len(results) {
 			// Log error if we have fewer results than requested selectors
 			lggr.Errorw("Skipping selector due to missing result",
+				"accessorSelector", l.chainSelector,
 				"selectorIndex", i,
 				"chain", chain,
 				"lenFeeQuoterResults", len(results))
@@ -877,6 +889,7 @@
 		val, err := readResult.GetResult()
 		if err != nil {
 			lggr.Warnw("failed to get chain fee price update from batch result",
+				"accessorSelector", l.chainSelector,
 				"chain", chain,
 				"err", err)
 			continue
@@ -886,6 +899,7 @@
 		update, ok := val.(*cciptypes.TimestampedUnixBig)
 		if !ok || update == nil {
 			lggr.Warnw("Invalid type or nil value received for chain fee price update",
+				"accessorSelector", l.chainSelector,
 				"chain", chain,
 				"type", fmt.Sprintf("%T", val),
 				"ok", ok)
@@ -895,6 +909,7 @@
 		// Check if the update is empty
 		if update.Timestamp == 0 || update.Value == nil {
 			lggr.Debugw("chain fee price update is empty",
+				"accessorSelector", l.chainSelector,
 				"chain", chain,
 				"update", update)
 			continue
@@ -918,7 +933,7 @@
 		&latestSeqNr,
 	)
 	if err != nil {
-		return 0, fmt.Errorf("get latest price sequence number: %w", err)
+		return 0, fmt.Errorf("get latest price sequence number for accessor %d: %w", l.chainSelector, err)
 	}
 	return cciptypes.SeqNum(latestSeqNr), nil
 }

pkg/reader/ccip.go

@@ -445,11 +445,12 @@
 	ctx context.Context,
 	selectors []cciptypes.ChainSelector,
 ) map[cciptypes.ChainSelector]cciptypes.BigInt {
 	lggr := logutil.WithContextValues(ctx, r.lggr)
 	// 1. Call chain's router to get native token address https://github.com/smartcontractkit/chainlink/blob/60e8b1181dd74b66903cf5b9a8427557b85357ec/contracts/src/v0.8/ccip/Router.sol#L189:L191
 	// 2. Call chain's FeeQuoter to get native tokens price  https://github.com/smartcontractkit/chainlink/blob/60e8b1181dd74b66903cf5b9a8427557b85357ec/contracts/src/v0.8/ccip/FeeQuoter.sol#L229-L229
 	//
 	//nolint:lll
+	lggr = logger.With(r.lggr, "method", "GetWrappedNativeTokenPriceUSD", "destChain", r.destChain, "selectors", selectors)
 	prices := make(map[cciptypes.ChainSelector]cciptypes.BigInt)
 
 	var wg sync.WaitGroup
@@ -474,15 +475,19 @@
 				lggr.Warnw("failed to get chain config for native token address", "chain", chain, "err", err)
 				return
 			}
+
+			lggr.Debugw("fetched chain config for native token address", "chain", chain, "config", config)
 			nativeTokenAddress := config.Router.WrappedNativeAddress
+			lggr.Debugw("casted native token address", "chain", chain, "address", nativeTokenAddress.String(), "hex", hex.EncodeToString(nativeTokenAddress))
 
 			if cciptypes.UnknownAddress(nativeTokenAddress).IsZeroOrEmpty() {
 				lggr.Warnw("Native token address is zero or empty. Ignore for disabled chains otherwise "+
-					"check for router misconfiguration", "chain", chain, "address", nativeTokenAddress.String())
+					"check for router misconfiguration", "chain", chain, "address", cciptypes.UnknownAddress(nativeTokenAddress), "hexCast", hex.EncodeToString(cciptypes.UnknownAddress(nativeTokenAddress)))
 				return
 			}
 
 			price, err := chainAccessor.GetTokenPriceUSD(ctx, cciptypes.UnknownAddress(nativeTokenAddress))
+			lggr.Debugw("fetched native token price", "chain", chain, "address", nativeTokenAddress.String(), "price", price)
 			if err != nil {
 				lggr.Errorw("failed to get native token price", "chain", chain, "address", nativeTokenAddress.String(), "err", err)
 				return
@@ -498,6 +503,7 @@
 			}
 
 			mu.Lock()
+			lggr.Debugw("setting native token price", "chain", chain, "price", price.Value, "timestamp", price.Timestamp)
 			prices[chain] = cciptypes.NewBigInt(price.Value)
 			mu.Unlock()
 		}()
@@ -635,19 +641,26 @@
 	lggr logger.Logger,
 	chains []cciptypes.ChainSelector,
 ) (ContractAddresses, error) {
+	lggr = logger.With(lggr, "function", "discoverOffRampContracts",
+		"destChain", r.destChain, "offRamp", r.offrampAddress, "chains", chains)
+
 	// Get from cache
+	lggr.Debugw("fetching offramp dest chain config")
 	config, err := r.configPoller.GetChainConfig(ctx, r.destChain)
 	if err != nil {
 		return nil, fmt.Errorf("unable to lookup RMN remote address (RMN proxy): %w", err)
 	}
 
+	lggr.Debugw("fetched offramp dest chain config from cache", "config", config)
+
 	resp := make(ContractAddresses)
 
 	// OnRamps are in the offRamp SourceChainConfig.
 	{
+		lggr.Debugw("fetching offramp source chain configs")
 		sourceConfigs, err := r.getOffRampSourceChainsConfig(ctx, lggr, chains, false)
-
 		if err != nil {
+			lggr.Debugw("unable to get SourceChainsConfig", "err", err)
 			return nil, fmt.Errorf("unable to get SourceChainsConfig: %w", err)
 		}
 
@@ -660,12 +673,13 @@
 			// The local router is located in each source sourceChain config. Add it once.
 			if len(resp[consts.ContractNameRouter][r.destChain]) == 0 {
 				resp = resp.Append(consts.ContractNameRouter, r.destChain, cfg.Router)
-				lggr.Infow("appending router contract address", "address", cfg.Router)
+				lggr.Infow("appending router contract address", "address", cfg.Router, "sourceChain", sourceChain)
 			}
 		}
 	}
 
 	// Add static config contracts
+	lggr.Debugw("checking offramp static config contracts")
 	if len(config.Offramp.StaticConfig.RmnRemote) > 0 {
 		lggr.Infow("appending RMN remote contract address",
 			"address", hex.EncodeToString(config.Offramp.StaticConfig.RmnRemote),
@@ -674,6 +688,9 @@
 	}
 
 	if len(config.Offramp.StaticConfig.NonceManager) > 0 {
+		lggr.Infow("appending nonce manager contract address",
+			"address", hex.EncodeToString(config.Offramp.StaticConfig.NonceManager),
+			"chain", r.destChain)
 		resp = resp.Append(consts.ContractNameNonceManager, r.destChain, config.Offramp.StaticConfig.NonceManager)
 	}
 
@@ -685,6 +702,7 @@
 		resp = resp.Append(consts.ContractNameFeeQuoter, r.destChain, config.Offramp.DynamicConfig.FeeQuoter)
 	}
 
+	lggr.Debugw("returning discovered contracts", "contracts", resp)
 	return resp, nil
 }
 
@@ -694,14 +712,21 @@
 	var resp ContractAddresses
 	var err error
 	lggr := logutil.WithContextValues(ctx, r.lggr)
+	lggr = logger.With(lggr, "function", "DiscoverContracts",
+		"destChain", r.destChain, "offRamp", r.offrampAddress,
+		"supportedChains", supportedChains, "allChains", allChains)
 
 	if slices.Contains(supportedChains, r.destChain) {
+		lggr.Debugw("dest chain is supported, calling discoverOffRampContracts")
 		resp, err = r.discoverOffRampContracts(ctx, lggr, allChains)
 		// Can't continue with discovery if the destination chain is not available.
 		// We read source chains OnRamps from there, and onRamps are essential for feeQuoter and Router discovery.
 		if err != nil {
+			lggr.Debugw("failed to discover destination contracts", "err", err)
 			return nil, fmt.Errorf("discover destination contracts: %w", err)
 		}
+	} else {
+		lggr.Debugw("dest chain is not supported, skipping discoverOffRampContracts")
 	}
 
 	// The following calls are on dynamically configured chains which may not
@@ -739,32 +764,46 @@
 					"err", err)
 				return
 			}
+			lggr.Debugw("got chain config for chainSel", "chainSel", chainSel, "config", config)
 
 			// Use mutex to safely update the shared resp
 			mu.Lock()
 			defer mu.Unlock()
 
 			// Add FeeQuoter from dynamic config
 			if !cciptypes.UnknownAddress(config.OnRamp.DynamicConfig.DynamicConfig.FeeQuoter).IsZeroOrEmpty() {
+				lggr.Debugw("appending fee quoter contract address",
+					"address", hex.EncodeToString(config.OnRamp.DynamicConfig.DynamicConfig.FeeQuoter))
 				resp = resp.Append(
 					consts.ContractNameFeeQuoter,
 					chainSel,
 					config.OnRamp.DynamicConfig.DynamicConfig.FeeQuoter)
+			} else {
+				lggr.Warnw("FeeQuoter address is zero or empty. Ignore for disabled chains otherwise "+
+					"check for onRamp misconfiguration", "chain", chainSel,
+					"address", hex.EncodeToString(config.OnRamp.DynamicConfig.DynamicConfig.FeeQuoter))
 			}
 
 			// Add Router from dest chain config
 			if !cciptypes.UnknownAddress(config.OnRamp.DestChainConfig.Router).IsZeroOrEmpty() {
+				lggr.Debugw("appending router contract address",
+					"address", hex.EncodeToString(config.OnRamp.DestChainConfig.Router))
 				resp = resp.Append(
 					consts.ContractNameRouter,
 					chainSel,
 					config.OnRamp.DestChainConfig.Router)
+			} else {
+				lggr.Warnw("Router address is zero or empty. Ignore for disabled chains otherwise "+
+					"check for onRamp misconfiguration", "chain", chainSel,
+					"address", hex.EncodeToString(config.OnRamp.DestChainConfig.Router))
 			}
 		}(chainCopy)
 	}
 
 	// Wait for all goroutines to complete
 	wg.Wait()
 
+	lggr.Debugw("returning discovered contracts", "contracts", resp)
 	return resp, nil
 }
 
@@ -932,6 +971,8 @@
 		return nil, fmt.Errorf("get source chain configs: %w", err)
 	}
 
+	lggr.Debugw("fetched offramp source chain configs from config poller", "count", len(configs), "configs", configs)
+
 	// Filter out disabled chains if needed
 	if !includeDisabled {
 		for chain, cfg := range configs {
@@ -949,6 +990,7 @@
 		}
 	}
 
+	lggr.Debugw("returning offramp source chain configs", "count", len(configs))
 	return configs, nil
 }
 
@@ -1091,21 +1133,32 @@
 	ctx context.Context,
 	chain cciptypes.ChainSelector,
 	rmnRemoteProxyAddress []byte) ([]byte, error) {
+	lggr := logger.With(r.lggr,
+		"function", "getRMNRemoteAddress",
+		"chain", chain,
+		"rmnRemoteProxyAddress", hex.EncodeToString(rmnRemoteProxyAddress),
+		"destChain", r.destChain)
+
 	chainAccessor, err := getChainAccessor(r.accessors, chain)
 	if err != nil {
+		lggr.Debugw("failed to get chain accessor", "err", err)
 		return nil, fmt.Errorf("unable to getChainAccessor: %w", err)
 	}
 	err = chainAccessor.Sync(ctx, consts.ContractNameRMNProxy, rmnRemoteProxyAddress)
 	if err != nil {
+		lggr.Debugw("failed to sync RMN proxy contract", "err", err)
 		return nil, fmt.Errorf("sync RMN proxy contract: %w", err)
 	}
 
 	// Get the address from cache instead of making a contract call
 	config, err := r.configPoller.GetChainConfig(ctx, chain)
 	if err != nil {
+		lggr.Debugw("failed to get chain config from cache", "err", err)
 		return nil, fmt.Errorf("get chain config: %w", err)
 	}
 
+	lggr.Debugw("got chain config snapshot from cache", "config", config)
+
 	return config.RMNProxy.RemoteAddress, nil
 }