add usdc logging (#155)

core/services/ocr2/plugins/ccip/execution_plugin.go

@@ -190,6 +190,7 @@ func getTokenDataProviders(lggr logger.Logger, pluginConfig ccipconfig.Execution
 
 		tokenDataProviders[pluginConfig.USDCConfig.SourceTokenAddress] = tokendata.NewCachedReader(
 			usdc.NewUSDCTokenDataReader(
+				lggr,
 				sourceChainEventClient,
 				pluginConfig.USDCConfig.SourceTokenAddress,
 				pluginConfig.USDCConfig.SourceMessageTransmitterAddress,

core/services/ocr2/plugins/ccip/execution_reporting_plugin.go

@@ -645,12 +645,13 @@ func getTokenData(ctx context.Context, lggr logger.Logger, msg internal.EVM2EVMO
 		tknData, err2 := offchainTokenDataProvider.ReadTokenData(ctx, msg)
 		if err2 != nil {
 			if errors.Is(err2, tokendata.ErrNotReady) {
-				lggr.Infof("Token data not ready yet for token %s", token.Token.Hex())
+				lggr.Infow("Token data not ready yet", "token", token.Token.Hex())
 				return [][]byte{}, false, nil
 			}
 			return [][]byte{}, false, err2
 		}
 
+		lggr.Infow("Token data retrieved", "token", token.Token.Hex())
 		tokenData = append(tokenData, tknData)
 	}
 	return tokenData, true, nil

core/services/ocr2/plugins/ccip/internal/ccipdata/logpoller.go

@@ -230,6 +230,7 @@ func (c *LogPollerReader) GetLastUSDCMessagePriorToLogIndexInTx(ctx context.Cont
 	for i := range logs {
 		current := logs[len(logs)-i-1]
 		if current.LogIndex < logIndex {
+			c.lggr.Infow("Found USDC message", "logIndex", current.LogIndex, "txHash", current.TxHash.Hex(), "log", current)
 			return current.Data, nil
 		}
 	}

core/services/ocr2/plugins/ccip/internal/ccipdata/logpoller_test.go

@@ -153,7 +153,7 @@ func TestLogPollerClient_GetLastUSDCMessagePriorToLogIndexInTx(t *testing.T) {
 			{LogIndex: ccipLogIndex + 1, Data: []byte("1")},
 		}, nil)
 
-		c := &LogPollerReader{lp: lp}
+		c := &LogPollerReader{lp: lp, lggr: logger.TestLogger(t)}
 		usdcMessageData, err := c.GetLastUSDCMessagePriorToLogIndexInTx(context.Background(), ccipLogIndex, txHash)
 		assert.NoError(t, err)
 		assert.Equal(t, expectedData, usdcMessageData)

core/services/ocr2/plugins/ccip/tokendata/usdc/usdc.go

@@ -14,6 +14,7 @@ import (
 	"github.com/pkg/errors"
 
 	"github.com/smartcontractkit/chainlink/v2/core/chains/evm/logpoller"
+	"github.com/smartcontractkit/chainlink/v2/core/logger"
 	"github.com/smartcontractkit/chainlink/v2/core/services/ocr2/plugins/ccip/abihelpers"
 	"github.com/smartcontractkit/chainlink/v2/core/services/ocr2/plugins/ccip/internal"
 	"github.com/smartcontractkit/chainlink/v2/core/services/ocr2/plugins/ccip/internal/ccipdata"
@@ -22,6 +23,7 @@ import (
 )
 
 type TokenDataReader struct {
+	lggr               logger.Logger
 	sourceChainEvents  ccipdata.Reader
 	attestationApi     *url.URL
 	messageTransmitter common.Address
@@ -53,8 +55,9 @@ const (
 
 var _ tokendata.Reader = &TokenDataReader{}
 
-func NewUSDCTokenDataReader(sourceChainEvents ccipdata.Reader, usdcTokenAddress, usdcMessageTransmitterAddress, onRampAddress common.Address, usdcAttestationApi *url.URL) *TokenDataReader {
+func NewUSDCTokenDataReader(lggr logger.Logger, sourceChainEvents ccipdata.Reader, usdcTokenAddress, usdcMessageTransmitterAddress, onRampAddress common.Address, usdcAttestationApi *url.URL) *TokenDataReader {
 	return &TokenDataReader{
+		lggr:                 lggr.With("tokenDataProvider", "usdc"),
 		sourceChainEvents:    sourceChainEvents,
 		attestationApi:       usdcAttestationApi,
 		messageTransmitter:   usdcMessageTransmitterAddress,
@@ -81,20 +84,22 @@ func (s *TokenDataReader) ReadTokenData(ctx context.Context, msg internal.EVM2EV
 }
 
 func (s *TokenDataReader) getUpdatedAttestation(ctx context.Context, msg internal.EVM2EVMOnRampCCIPSendRequestedWithMeta) (attestationResponse, error) {
-	messageBody, err := s.getUSDCMessageBody(ctx, msg)
+	messageBodyHash, err := s.getUSDCMessageBodyHash(ctx, msg)
 	if err != nil {
 		return attestationResponse{}, errors.Wrap(err, "failed getting the USDC message body")
 	}
 
-	response, err := s.callAttestationApi(ctx, messageBody)
+	s.lggr.Infow("Calling attestation API", "messageBody", messageBodyHash, "messageID", msg.MessageId)
+
+	response, err := s.callAttestationApi(ctx, messageBodyHash)
 	if err != nil {
 		return attestationResponse{}, errors.Wrap(err, "failed calling usdc attestation API ")
 	}
 
 	return response, nil
 }
 
-func (s *TokenDataReader) getUSDCMessageBody(ctx context.Context, msg internal.EVM2EVMOnRampCCIPSendRequestedWithMeta) ([32]byte, error) {
+func (s *TokenDataReader) getUSDCMessageBodyHash(ctx context.Context, msg internal.EVM2EVMOnRampCCIPSendRequestedWithMeta) ([32]byte, error) {
 	s.usdcMessageHashCacheMutex.Lock()
 	defer s.usdcMessageHashCacheMutex.Unlock()
 
@@ -107,6 +112,8 @@ func (s *TokenDataReader) getUSDCMessageBody(ctx context.Context, msg internal.E
 		return [32]byte{}, err
 	}
 
+	s.lggr.Infow("Got USDC message body", "messageBody", usdcMessageBody, "messageID", msg.MessageId)
+
 	msgBodyHash := utils.Keccak256Fixed(usdcMessageBody)
 
 	// Save the attempt in the cache in case the external call fails

core/services/ocr2/plugins/ccip/tokendata/usdc/usdc_blackbox_test.go

@@ -16,6 +16,7 @@ import (
 
 	"github.com/smartcontractkit/chainlink/v2/core/gethwrappers/ccip/generated/evm_2_evm_offramp"
 	"github.com/smartcontractkit/chainlink/v2/core/gethwrappers/ccip/generated/evm_2_evm_onramp"
+	"github.com/smartcontractkit/chainlink/v2/core/logger"
 	"github.com/smartcontractkit/chainlink/v2/core/services/ocr2/plugins/ccip/internal"
 	"github.com/smartcontractkit/chainlink/v2/core/services/ocr2/plugins/ccip/internal/ccipdata"
 	"github.com/smartcontractkit/chainlink/v2/core/services/ocr2/plugins/ccip/tokendata/usdc"
@@ -82,7 +83,7 @@ func TestUSDCReader_ReadTokenData(t *testing.T) {
 	attestationURI, err := url.ParseRequestURI(ts.URL)
 	require.NoError(t, err)
 
-	usdcService := usdc.NewUSDCTokenDataReader(&eventsClient, mockUSDCTokenAddress, mockMsgTransmitter, mockOnRampAddress, attestationURI)
+	usdcService := usdc.NewUSDCTokenDataReader(logger.TestLogger(t), &eventsClient, mockUSDCTokenAddress, mockMsgTransmitter, mockOnRampAddress, attestationURI)
 	attestation, err := usdcService.ReadTokenData(context.Background(), internal.EVM2EVMOnRampCCIPSendRequestedWithMeta{
 		InternalEVM2EVMMessage: evm_2_evm_offramp.InternalEVM2EVMMessage{
 			SequenceNumber: seqNum,

core/services/ocr2/plugins/ccip/tokendata/usdc/usdc_test.go

@@ -9,10 +9,12 @@ import (
 	"testing"
 
 	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/common/hexutil"
 	"github.com/stretchr/testify/mock"
 	"github.com/stretchr/testify/require"
 
 	"github.com/smartcontractkit/chainlink/v2/core/chains/evm/logpoller"
+	"github.com/smartcontractkit/chainlink/v2/core/logger"
 	"github.com/smartcontractkit/chainlink/v2/core/services/ocr2/plugins/ccip/internal"
 	"github.com/smartcontractkit/chainlink/v2/core/services/ocr2/plugins/ccip/internal/ccipdata"
 	"github.com/smartcontractkit/chainlink/v2/core/utils"
@@ -29,7 +31,7 @@ func TestUSDCReader_callAttestationApi(t *testing.T) {
 	usdcMessageHash := "912f22a13e9ccb979b621500f6952b2afd6e75be7eadaed93fc2625fe11c52a2"
 	attestationURI, err := url.ParseRequestURI("https://iris-api-sandbox.circle.com")
 	require.NoError(t, err)
-	usdcService := NewUSDCTokenDataReader(nil, mockUSDCTokenAddress, mockMsgTransmitter, mockOnRampAddress, attestationURI)
+	usdcService := NewUSDCTokenDataReader(logger.TestLogger(t), nil, mockUSDCTokenAddress, mockMsgTransmitter, mockOnRampAddress, attestationURI)
 
 	attestation, err := usdcService.callAttestationApi(context.Background(), [32]byte(common.FromHex(usdcMessageHash)))
 	require.NoError(t, err)
@@ -49,7 +51,7 @@ func TestUSDCReader_callAttestationApiMock(t *testing.T) {
 	attestationURI, err := url.ParseRequestURI(ts.URL)
 	require.NoError(t, err)
 
-	usdcService := NewUSDCTokenDataReader(nil, mockUSDCTokenAddress, mockMsgTransmitter, mockOnRampAddress, attestationURI)
+	usdcService := NewUSDCTokenDataReader(logger.TestLogger(t), nil, mockUSDCTokenAddress, mockMsgTransmitter, mockOnRampAddress, attestationURI)
 	attestation, err := usdcService.callAttestationApi(context.Background(), utils.RandomBytes32())
 	require.NoError(t, err)
 
@@ -65,7 +67,7 @@ func TestUSDCReader_callAttestationApiMockError(t *testing.T) {
 	attestationURI, err := url.ParseRequestURI(ts.URL)
 	require.NoError(t, err)
 
-	usdcService := NewUSDCTokenDataReader(nil, mockUSDCTokenAddress, mockMsgTransmitter, mockOnRampAddress, attestationURI)
+	usdcService := NewUSDCTokenDataReader(logger.TestLogger(t), nil, mockUSDCTokenAddress, mockMsgTransmitter, mockOnRampAddress, attestationURI)
 	_, err = usdcService.callAttestationApi(context.Background(), utils.RandomBytes32())
 	require.Error(t, err)
 }
@@ -82,7 +84,7 @@ func getMockUSDCEndpoint(t *testing.T, response attestationResponse) *httptest.S
 
 // Asserts the hard coded event signature matches Keccak256("MessageSent(bytes)")
 func TestGetUSDCReaderSourceLPFilters(t *testing.T) {
-	usdcService := NewUSDCTokenDataReader(nil, mockUSDCTokenAddress, mockMsgTransmitter, mockOnRampAddress, nil)
+	usdcService := NewUSDCTokenDataReader(logger.TestLogger(t), nil, mockUSDCTokenAddress, mockMsgTransmitter, mockOnRampAddress, nil)
 
 	filters := usdcService.GetSourceLogPollerFilters()
 
@@ -96,23 +98,24 @@ func TestGetUSDCReaderSourceLPFilters(t *testing.T) {
 }
 
 func TestGetUSDCMessageBody(t *testing.T) {
-	expectedBody := []byte("TestGetUSDCMessageBody")
+	expectedBody, err := hexutil.Decode("0x0000000000000001000000020000000000048D71000000000000000000000000EB08F243E5D3FCFF26A9E38AE5520A669F4019D000000000000000000000000023A04D5935ED8BC8E3EB78DB3541F0ABFB001C6E0000000000000000000000006CB3ED9B441EB674B58495C8B3324B59FAFF5243000000000000000000000000000000005425890298AED601595A70AB815C96711A31BC65000000000000000000000000AB4F961939BFE6A93567CC57C59EED7084CE2131000000000000000000000000000000000000000000000000000000000000271000000000000000000000000035E08285CFED1EF159236728F843286C55FC0861")
+	require.NoError(t, err)
 	expectedBodyHash := utils.Keccak256Fixed(expectedBody)
 
 	sourceChainEventsMock := ccipdata.MockReader{}
 	sourceChainEventsMock.On("GetLastUSDCMessagePriorToLogIndexInTx", mock.Anything, mock.Anything, mock.Anything).Return(expectedBody, nil)
 
-	usdcService := NewUSDCTokenDataReader(&sourceChainEventsMock, mockUSDCTokenAddress, mockMsgTransmitter, mockOnRampAddress, nil)
+	usdcService := NewUSDCTokenDataReader(logger.TestLogger(t), &sourceChainEventsMock, mockUSDCTokenAddress, mockMsgTransmitter, mockOnRampAddress, nil)
 
 	// Make the first call and assert the underlying function is called
-	body, err := usdcService.getUSDCMessageBody(context.Background(), internal.EVM2EVMOnRampCCIPSendRequestedWithMeta{})
+	body, err := usdcService.getUSDCMessageBodyHash(context.Background(), internal.EVM2EVMOnRampCCIPSendRequestedWithMeta{})
 	require.NoError(t, err)
 	require.Equal(t, body, expectedBodyHash)
 
 	sourceChainEventsMock.AssertNumberOfCalls(t, "GetLastUSDCMessagePriorToLogIndexInTx", 1)
 
 	// Make another call and assert that the cache is used
-	body, err = usdcService.getUSDCMessageBody(context.Background(), internal.EVM2EVMOnRampCCIPSendRequestedWithMeta{})
+	body, err = usdcService.getUSDCMessageBodyHash(context.Background(), internal.EVM2EVMOnRampCCIPSendRequestedWithMeta{})
 	require.NoError(t, err)
 	require.Equal(t, body, expectedBodyHash)
 	sourceChainEventsMock.AssertNumberOfCalls(t, "GetLastUSDCMessagePriorToLogIndexInTx", 1)