diff --git a/core/services/ocr2/plugins/ccip/execution_plugin.go b/core/services/ocr2/plugins/ccip/execution_plugin.go index 2d00333d93..95426bdd40 100644 --- a/core/services/ocr2/plugins/ccip/execution_plugin.go +++ b/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, diff --git a/core/services/ocr2/plugins/ccip/execution_reporting_plugin.go b/core/services/ocr2/plugins/ccip/execution_reporting_plugin.go index 805366217e..01472c6a0c 100644 --- a/core/services/ocr2/plugins/ccip/execution_reporting_plugin.go +++ b/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 diff --git a/core/services/ocr2/plugins/ccip/internal/ccipdata/logpoller.go b/core/services/ocr2/plugins/ccip/internal/ccipdata/logpoller.go index 8a14dc450f..5bc3a305bc 100644 --- a/core/services/ocr2/plugins/ccip/internal/ccipdata/logpoller.go +++ b/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 } } diff --git a/core/services/ocr2/plugins/ccip/internal/ccipdata/logpoller_test.go b/core/services/ocr2/plugins/ccip/internal/ccipdata/logpoller_test.go index 56f5ff1db2..48e10c87e1 100644 --- a/core/services/ocr2/plugins/ccip/internal/ccipdata/logpoller_test.go +++ b/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) diff --git a/core/services/ocr2/plugins/ccip/tokendata/usdc/usdc.go b/core/services/ocr2/plugins/ccip/tokendata/usdc/usdc.go index 3b1f1b6177..1b1745b325 100644 --- a/core/services/ocr2/plugins/ccip/tokendata/usdc/usdc.go +++ b/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,12 +84,14 @@ 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 ") } @@ -94,7 +99,7 @@ func (s *TokenDataReader) getUpdatedAttestation(ctx context.Context, msg interna 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 diff --git a/core/services/ocr2/plugins/ccip/tokendata/usdc/usdc_blackbox_test.go b/core/services/ocr2/plugins/ccip/tokendata/usdc/usdc_blackbox_test.go index 6e61be5ed3..bcc1ca5aae 100644 --- a/core/services/ocr2/plugins/ccip/tokendata/usdc/usdc_blackbox_test.go +++ b/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, diff --git a/core/services/ocr2/plugins/ccip/tokendata/usdc/usdc_test.go b/core/services/ocr2/plugins/ccip/tokendata/usdc/usdc_test.go index d61ef530d5..42940c9135 100644 --- a/core/services/ocr2/plugins/ccip/tokendata/usdc/usdc_test.go +++ b/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)