From c74ef487ef281f0dff77fd8dd309f754831ee63b Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Tue, 29 Aug 2023 20:22:44 +0000 Subject: [PATCH 01/49] add json database --- database/database.go | 8 ++ database/json_file_storage.go | 153 ++++++++++++++++++++++++++++++++++ 2 files changed, 161 insertions(+) create mode 100644 database/database.go create mode 100644 database/json_file_storage.go diff --git a/database/database.go b/database/database.go new file mode 100644 index 00000000..f86166d6 --- /dev/null +++ b/database/database.go @@ -0,0 +1,8 @@ +package database + +import "github.com/ava-labs/avalanchego/ids" + +type RelayerDatabase interface { + Get(chainID ids.ID, key []byte) ([]byte, error) + Put(chainID ids.ID, key []byte, value []byte) error +} diff --git a/database/json_file_storage.go b/database/json_file_storage.go new file mode 100644 index 00000000..94ceec0d --- /dev/null +++ b/database/json_file_storage.go @@ -0,0 +1,153 @@ +package database + +import ( + "encoding/json" + "os" + "path/filepath" + "sync" + + "github.com/ava-labs/avalanchego/ids" + "github.com/ava-labs/avalanchego/utils/logging" + "github.com/pkg/errors" + "go.uber.org/zap" +) + +var _ RelayerDatabase = &JsonFileStorage{} + +type chainState map[string]string + +// JsonFileStorage implements RelayerDatabase +type JsonFileStorage struct { + // the directory where the json files are stored + dir string + + // one mutex per network + // we predefined the network when creating the storage + // also we don't allow adding new network after the storage is created + // so we don't need to lock the map + mutexes map[string]*sync.RWMutex + logger logging.Logger +} + +// NewJSONFileStorage creates a new JsonFileStorage instance +// with predefined networks. e.g "ethereum", "avalanche" +func NewJSONFileStorage(logger logging.Logger, dir string, networks []string) (*JsonFileStorage, error) { + storage := &JsonFileStorage{ + dir: filepath.Clean(dir), + mutexes: make(map[string]*sync.RWMutex), + logger: logger, + } + + for _, network := range networks { + storage.mutexes[network] = &sync.RWMutex{} + } + + _, err := os.Stat(dir) + if err == nil { + // dir already exist + // return the existing storage + return storage, nil + } + + // 0755: The owner can read, write, execute. + // Everyone else can read and execute but not modify the file. + err = os.MkdirAll(dir, 0755) + if err != nil { + storage.logger.Error("failed to create dir", + zap.Error(err)) + return nil, err + } + + return storage, nil +} + +// Get the latest chain state from the json database, and retrieve the value from the key +func (s *JsonFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { + var currentState chainState + err := s.read(chainID.String(), ¤tState) + if err != nil { + return nil, err + } + + return []byte(currentState[string(key)]), nil +} + +// Put the value into the json database. Read the current chain state and overwrite the key, if it exists +func (s *JsonFileStorage) Put(chainID ids.ID, key []byte, value []byte) error { + currentState := make(chainState) + var currentStateData []byte + err := s.read(chainID.String(), ¤tStateData) + if err == nil { + err = json.Unmarshal(currentStateData, ¤tState) + if err != nil { + return err + } + } + + currentState[string(key)] = string(value) + + return s.write(chainID.String(), currentState) +} + +// write value into the file +func (s *JsonFileStorage) write(network string, v interface{}) error { + mutex, ok := s.mutexes[network] + if !ok { + return errors.New("network does not exist") + } + + mutex.Lock() + defer mutex.Unlock() + + fnlPath := filepath.Join(s.dir, network+".json") + tmpPath := fnlPath + ".tmp" + + b, err := json.MarshalIndent(v, "", "\t") + if err != nil { + return err + } + + // write marshaled data to the temp file + // if write failed, the original file is not affected + // 0644 Only the owner can read and write. + // Everyone else can only read. No one can execute the file. + if err := os.WriteFile(tmpPath, b, 0644); err != nil { + return errors.Wrap(err, "failed to write file") + } + + // move final file into place + if err := os.Rename(tmpPath, fnlPath); err != nil { + return errors.Wrap(err, "failed to rename file") + } + + return nil +} + +// Read from disk and unmarshal into v +func (s *JsonFileStorage) read(network string, v interface{}) error { + mutex, ok := s.mutexes[network] + if !ok { + return errors.New("network does not exist") + } + + mutex.RLock() + defer mutex.RUnlock() + + path := filepath.Join(s.dir, network+".json") + _, err := os.Stat(path) + if err != nil { + return err + } + + b, err := os.ReadFile(path) + if err != nil { + return errors.Wrap(err, "failed to read file") + } + + // unmarshal data + if err = json.Unmarshal(b, &v); err != nil { + return errors.Wrap(err, "failed to unmarshal json file") + } + + return nil +} From 1280b4a31862950af1a9c7f2406c2c7362e83656 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Tue, 29 Aug 2023 20:59:28 +0000 Subject: [PATCH 02/49] initialize subscriber from stored block height --- config/config.go | 18 +++++ database/database.go | 4 ++ database/json_file_storage.go | 20 +++--- main/main.go | 17 ++++- relayer/relayer.go | 17 ++++- vms/evm/subscriber.go | 127 ++++++++++++++++++++++++++++------ vms/subscriber.go | 11 ++- 7 files changed, 179 insertions(+), 35 deletions(-) diff --git a/config/config.go b/config/config.go index 41a07cea..5bc04613 100644 --- a/config/config.go +++ b/config/config.go @@ -42,6 +42,7 @@ type SourceSubnet struct { APINodeHost string `mapstructure:"api-node-host" json:"api-node-host"` APINodePort uint32 `mapstructure:"api-node-port" json:"api-node-port"` EncryptConnection bool `mapstructure:"encrypt-connection" json:"encrypt-connection"` + RPCEndpoint string `mapstructure:"rpc-endpoint" json:"rpc-endpoint"` WSEndpoint string `mapstructure:"ws-endpoint" json:"ws-endpoint"` MessageContracts map[string]MessageProtocolConfig `mapstructure:"message-contracts" json:"message-contracts"` } @@ -295,6 +296,23 @@ func (s *DestinationSubnet) GetNodeRPCEndpoint() string { return fmt.Sprintf("%s/ext/bc/%s/rpc", baseUrl, chainID) } +// Constructs an RPC endpoint for the subnet. +// If the RPCEndpoint field is set in the configuration, returns that directly. +// Otherwise, constructs the endpoint from the APINodeHost, APINodePort, and EncryptConnection fields, +// following the /ext/bc/{chainID}/rpc format. +func (s *SourceSubnet) GetNodeRPCEndpoint() string { + if s.RPCEndpoint != "" { + return s.RPCEndpoint + } + baseUrl := constructURL("http", s.APINodeHost, s.APINodePort, s.EncryptConnection) + chainID := s.ChainID + subnetID, _ := ids.FromString(s.SubnetID) // already validated in Validate() + if subnetID == constants.PrimaryNetworkID { + chainID = cChainIdentifierString + } + return fmt.Sprintf("%s/ext/bc/%s/rpc", baseUrl, chainID) +} + // Constructs a WS endpoint for the subnet. // If the WSEndpoint field is set in the configuration, returns that directly. // Otherwise, constructs the endpoint from the APINodeHost, APINodePort, and EncryptConnection fields, diff --git a/database/database.go b/database/database.go index f86166d6..f0dbf8b9 100644 --- a/database/database.go +++ b/database/database.go @@ -2,6 +2,10 @@ package database import "github.com/ava-labs/avalanchego/ids" +const ( + LatestBlockHeightKey = "latestBlockHeight" +) + type RelayerDatabase interface { Get(chainID ids.ID, key []byte) ([]byte, error) Put(chainID ids.ID, key []byte, value []byte) error diff --git a/database/json_file_storage.go b/database/json_file_storage.go index 94ceec0d..127adaf4 100644 --- a/database/json_file_storage.go +++ b/database/json_file_storage.go @@ -25,16 +25,16 @@ type JsonFileStorage struct { // we predefined the network when creating the storage // also we don't allow adding new network after the storage is created // so we don't need to lock the map - mutexes map[string]*sync.RWMutex + mutexes map[ids.ID]*sync.RWMutex logger logging.Logger } // NewJSONFileStorage creates a new JsonFileStorage instance // with predefined networks. e.g "ethereum", "avalanche" -func NewJSONFileStorage(logger logging.Logger, dir string, networks []string) (*JsonFileStorage, error) { +func NewJSONFileStorage(logger logging.Logger, dir string, networks []ids.ID) (*JsonFileStorage, error) { storage := &JsonFileStorage{ dir: filepath.Clean(dir), - mutexes: make(map[string]*sync.RWMutex), + mutexes: make(map[ids.ID]*sync.RWMutex), logger: logger, } @@ -64,7 +64,7 @@ func NewJSONFileStorage(logger logging.Logger, dir string, networks []string) (* // Get the latest chain state from the json database, and retrieve the value from the key func (s *JsonFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { var currentState chainState - err := s.read(chainID.String(), ¤tState) + err := s.read(chainID, ¤tState) if err != nil { return nil, err } @@ -76,7 +76,7 @@ func (s *JsonFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { func (s *JsonFileStorage) Put(chainID ids.ID, key []byte, value []byte) error { currentState := make(chainState) var currentStateData []byte - err := s.read(chainID.String(), ¤tStateData) + err := s.read(chainID, ¤tStateData) if err == nil { err = json.Unmarshal(currentStateData, ¤tState) if err != nil { @@ -86,11 +86,11 @@ func (s *JsonFileStorage) Put(chainID ids.ID, key []byte, value []byte) error { currentState[string(key)] = string(value) - return s.write(chainID.String(), currentState) + return s.write(chainID, currentState) } // write value into the file -func (s *JsonFileStorage) write(network string, v interface{}) error { +func (s *JsonFileStorage) write(network ids.ID, v interface{}) error { mutex, ok := s.mutexes[network] if !ok { return errors.New("network does not exist") @@ -99,7 +99,7 @@ func (s *JsonFileStorage) write(network string, v interface{}) error { mutex.Lock() defer mutex.Unlock() - fnlPath := filepath.Join(s.dir, network+".json") + fnlPath := filepath.Join(s.dir, network.String()+".json") tmpPath := fnlPath + ".tmp" b, err := json.MarshalIndent(v, "", "\t") @@ -124,7 +124,7 @@ func (s *JsonFileStorage) write(network string, v interface{}) error { } // Read from disk and unmarshal into v -func (s *JsonFileStorage) read(network string, v interface{}) error { +func (s *JsonFileStorage) read(network ids.ID, v interface{}) error { mutex, ok := s.mutexes[network] if !ok { return errors.New("network does not exist") @@ -133,7 +133,7 @@ func (s *JsonFileStorage) read(network string, v interface{}) error { mutex.RLock() defer mutex.RUnlock() - path := filepath.Join(s.dir, network+".json") + path := filepath.Join(s.dir, network.String()+".json") _, err := os.Stat(path) if err != nil { return err diff --git a/main/main.go b/main/main.go index 2fe475df..40dc87cf 100644 --- a/main/main.go +++ b/main/main.go @@ -21,6 +21,7 @@ import ( "github.com/ava-labs/avalanchego/utils/logging" "github.com/ava-labs/avalanchego/vms/platformvm" "github.com/ava-labs/awm-relayer/config" + "github.com/ava-labs/awm-relayer/database" "github.com/ava-labs/awm-relayer/peers" "github.com/ava-labs/awm-relayer/relayer" "github.com/ava-labs/awm-relayer/vms" @@ -33,6 +34,8 @@ const ( defaultErrorChanSize = 1000 defaultApiPort = 8080 defaultMetricsPort = 9090 + + defaultStorageLocation = "~/.awm-relayer" ) func main() { @@ -149,6 +152,16 @@ func main() { return } + // Initialize the database + db, err := database.NewJSONFileStorage(logger, defaultStorageLocation, sourceChainIDs) + if err != nil { + logger.Error( + "Failed to create database", + zap.Error(err), + ) + return + } + // Create relayers for each of the subnets configured as a source var wg sync.WaitGroup for _, s := range cfg.SourceSubnets { @@ -167,7 +180,7 @@ func main() { wg.Done() healthy.Store(false) }() - runRelayer(logger, metrics, subnetInfo, pChainClient, network, responseChans[chainID], destinationClients, messageCreator) + runRelayer(logger, metrics, db, subnetInfo, pChainClient, network, responseChans[chainID], destinationClients, messageCreator) logger.Info( "Relayer exiting.", zap.String("chainID", chainID.String()), @@ -180,6 +193,7 @@ func main() { // runRelayer creates a relayer instance for a subnet. It listens for warp messages on that subnet, and handles delivery to the destination func runRelayer(logger logging.Logger, metrics *relayer.MessageRelayerMetrics, + db database.RelayerDatabase, sourceSubnetInfo config.SourceSubnet, pChainClient platformvm.Client, network *peers.AppRequestNetwork, @@ -195,6 +209,7 @@ func runRelayer(logger logging.Logger, relayer, subscriber, err := relayer.NewRelayer( logger, + db, sourceSubnetInfo, errorChan, pChainClient, diff --git a/relayer/relayer.go b/relayer/relayer.go index fb22b030..57b227a8 100644 --- a/relayer/relayer.go +++ b/relayer/relayer.go @@ -12,6 +12,7 @@ import ( "github.com/ava-labs/avalanchego/utils/logging" "github.com/ava-labs/avalanchego/vms/platformvm" "github.com/ava-labs/awm-relayer/config" + "github.com/ava-labs/awm-relayer/database" "github.com/ava-labs/awm-relayer/messages" "github.com/ava-labs/awm-relayer/peers" vms "github.com/ava-labs/awm-relayer/vms" @@ -39,6 +40,7 @@ type Relayer struct { func NewRelayer( logger logging.Logger, + db database.RelayerDatabase, sourceSubnetInfo config.SourceSubnet, errorChan chan error, pChainClient platformvm.Client, @@ -47,7 +49,7 @@ func NewRelayer( destinationClients map[ids.ID]vms.DestinationClient, ) (*Relayer, vms.Subscriber, error) { - sub := vms.NewSubscriber(logger, sourceSubnetInfo) + sub := vms.NewSubscriber(logger, sourceSubnetInfo, db) subnetID, err := ids.FromString(sourceSubnetInfo.SubnetID) if err != nil { @@ -105,9 +107,20 @@ func NewRelayer( logger: logger, } - // Start the message router. We must do this before Subscribing for the first time, otherwise we may miss an incoming message + // Start the message router. We must do this before Subscribing or Initializing for the first time, otherwise we may miss an incoming message go r.RouteToMessageChannel() + // Initialize the subscriber. This will poll the node for any logs that match the filter query from the stored block height, + // and process the contained warp messages + err = sub.Initialize() + if err != nil { + logger.Error( + "Failed to initialize subscriber", + zap.Error(err), + ) + return nil, nil, err + } + err = sub.Subscribe() if err != nil { logger.Error( diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index 2e003bd2..4f862c97 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -7,11 +7,14 @@ import ( "context" "errors" "fmt" + "math/big" + "strconv" "time" "github.com/ava-labs/avalanchego/ids" "github.com/ava-labs/avalanchego/utils/logging" "github.com/ava-labs/awm-relayer/config" + "github.com/ava-labs/awm-relayer/database" "github.com/ava-labs/awm-relayer/vms/vmtypes" "github.com/ava-labs/subnet-evm/core/types" "github.com/ava-labs/subnet-evm/ethclient" @@ -33,21 +36,50 @@ var ( ErrInvalidLog = errors.New("invalid warp message log") ) +var warpFilterQuery = interfaces.FilterQuery{ + Topics: [][]common.Hash{ + {warp.WarpABI.Events["SendWarpMessage"].ID}, + {}, + {}, + }, + Addresses: []common.Address{ + warp.ContractAddress, + }, +} + // subscriber implements Subscriber type subscriber struct { - nodeURL string - log chan vmtypes.WarpLogInfo - evmLog <-chan types.Log - sub interfaces.Subscription + nodeWSURL string + nodeRPCURL string + chainID ids.ID + log chan vmtypes.WarpLogInfo + evmLog <-chan types.Log + sub interfaces.Subscription logger logging.Logger + db database.RelayerDatabase } // NewSubscriber returns a subscriber -func NewSubscriber(logger logging.Logger, subnetInfo config.SourceSubnet) *subscriber { +func NewSubscriber(logger logging.Logger, subnetInfo config.SourceSubnet, db database.RelayerDatabase) *subscriber { + chainID, err := ids.FromString(subnetInfo.ChainID) + if err != nil { + logger.Error( + "Invalid chainID provided to subscriber", + zap.Error(err), + ) + return nil + } + + logs := make(chan vmtypes.WarpLogInfo, maxClientSubscriptionBuffer) + return &subscriber{ - nodeURL: subnetInfo.GetNodeWSEndpoint(), - logger: logger, + nodeWSURL: subnetInfo.GetNodeWSEndpoint(), + nodeRPCURL: subnetInfo.GetNodeRPCEndpoint(), + chainID: chainID, + logger: logger, + db: db, + log: logs, } } @@ -84,9 +116,75 @@ func (s *subscriber) forwardLogs() { continue } s.log <- *messageInfo + + // Update the database with the latest block height + // TODO: This should also be done in a separate goroutine, rather than waiting for warp messages to be processed + err = s.db.Put(s.chainID, []byte(database.LatestBlockHeightKey), []byte(strconv.FormatUint(msgLog.BlockNumber, 10))) + if err != nil { + s.logger.Error(fmt.Sprintf("failed to put %s into database", database.LatestBlockHeightKey), zap.Error(err)) + } } } +func (s *subscriber) Initialize() error { + ethClient, err := ethclient.Dial(s.nodeRPCURL) + if err != nil { + return err + } + + heightData, err := s.db.Get(s.chainID, []byte(database.LatestBlockHeightKey)) + if err != nil { + s.logger.Error("failed to get latestBlockHeight from database", zap.Error(err)) + return err + } + latestBlockHeight, success := new(big.Int).SetString(string(heightData), 10) + if !success { + s.logger.Error("failed to convert latestBlockHeight to big.Int", zap.Error(err)) + return err + } + + // Grab the latest block before filtering logs so we don't miss any before updating the db + latestBlock, err := ethClient.BlockNumber(context.Background()) + if err != nil { + s.logger.Error( + "Failed to get latest block", + zap.Error(err), + ) + return err + } + + var initializationFilterQuery = warpFilterQuery + initializationFilterQuery.FromBlock = latestBlockHeight + logs, err := ethClient.FilterLogs(context.Background(), initializationFilterQuery) + if err != nil { + s.logger.Error( + "Failed to get logs on initialization", + zap.Error(err), + ) + return err + } + + for _, log := range logs { + messageInfo, err := NewWarpLogInfo(log) + if err != nil { + s.logger.Info( + "Invalid log on initialization. Continuing.", + zap.Error(err), + ) + continue + } + s.log <- *messageInfo + } + + // Update the database with the latest block height + err = s.db.Put(s.chainID, []byte(database.LatestBlockHeightKey), []byte(strconv.FormatUint(latestBlock, 10))) + if err != nil { + s.logger.Error(fmt.Sprintf("failed to put %s into database", database.LatestBlockHeightKey), zap.Error(err)) + return err + } + return nil +} + func (s *subscriber) Subscribe() error { // Retry subscribing until successful. Attempt to resubscribe maxResubscribeAttempts times for attempt := 0; attempt < maxResubscribeAttempts; attempt++ { @@ -118,23 +216,13 @@ func (s *subscriber) Subscribe() error { func (s *subscriber) dialAndSubscribe() error { // Dial the configured destination chain endpoint // This needs to be a websocket - ethClient, err := ethclient.Dial(s.nodeURL) + ethClient, err := ethclient.Dial(s.nodeWSURL) if err != nil { return err } - filterQuery := interfaces.FilterQuery{ - Topics: [][]common.Hash{ - {warp.WarpABI.Events["SendWarpMessage"].ID}, - {}, - {}, - }, - Addresses: []common.Address{ - warp.ContractAddress, - }, - } + filterQuery := warpFilterQuery evmLogs := make(chan types.Log, maxClientSubscriptionBuffer) - logs := make(chan vmtypes.WarpLogInfo, maxClientSubscriptionBuffer) sub, err := ethClient.SubscribeFilterLogs(context.Background(), filterQuery, evmLogs) if err != nil { s.logger.Error( @@ -143,7 +231,6 @@ func (s *subscriber) dialAndSubscribe() error { ) return err } - s.log = logs s.evmLog = evmLogs s.sub = sub diff --git a/vms/subscriber.go b/vms/subscriber.go index 45c4345b..a7f2ea0f 100644 --- a/vms/subscriber.go +++ b/vms/subscriber.go @@ -6,30 +6,37 @@ package vms import ( "github.com/ava-labs/avalanchego/utils/logging" "github.com/ava-labs/awm-relayer/config" + "github.com/ava-labs/awm-relayer/database" "github.com/ava-labs/awm-relayer/vms/evm" "github.com/ava-labs/awm-relayer/vms/vmtypes" ) // Subscriber subscribes to VM events containing Warp message data type Subscriber interface { + // Inialize the subscriber by processing any pending events + Initialize() error + // Subscribe registers a subscription. After Subscribe is called, // log events that match [filter] are written to the channel returned // by Logs Subscribe() error + // Logs returns the channel that the subscription writes events to Logs() <-chan vmtypes.WarpLogInfo + // Err returns the channel that the subscription writes errors to // If an error is sent to this channel, the subscription should be closed Err() <-chan error + // Cancel cancels the subscription Cancel() } // NewSubscriber returns a concrete Subscriber according to the VM specified by [subnetInfo] -func NewSubscriber(logger logging.Logger, subnetInfo config.SourceSubnet) Subscriber { +func NewSubscriber(logger logging.Logger, subnetInfo config.SourceSubnet, db database.RelayerDatabase) Subscriber { switch config.ParseVM(subnetInfo.VM) { case config.EVM: - return evm.NewSubscriber(logger, subnetInfo) + return evm.NewSubscriber(logger, subnetInfo, db) default: return nil } From 551b90e0f81ab466602a209f64fa3cbd6df79b2b Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Tue, 29 Aug 2023 21:12:05 +0000 Subject: [PATCH 03/49] subscriber initialization failure is non fatal --- relayer/relayer.go | 7 +++---- vms/evm/subscriber.go | 5 +++-- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/relayer/relayer.go b/relayer/relayer.go index 57b227a8..31fcf647 100644 --- a/relayer/relayer.go +++ b/relayer/relayer.go @@ -111,14 +111,13 @@ func NewRelayer( go r.RouteToMessageChannel() // Initialize the subscriber. This will poll the node for any logs that match the filter query from the stored block height, - // and process the contained warp messages + // and process the contained warp messages. If initialization fails, continue with normal relayer operation, but log the error. err = sub.Initialize() if err != nil { - logger.Error( - "Failed to initialize subscriber", + logger.Warn( + "Encountered an error when initializing subscriber. Skipping initialization.", zap.Error(err), ) - return nil, nil, err } err = sub.Subscribe() diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index 4f862c97..7955f9df 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -132,14 +132,15 @@ func (s *subscriber) Initialize() error { return err } + // Get the latest processed block height from the database. heightData, err := s.db.Get(s.chainID, []byte(database.LatestBlockHeightKey)) if err != nil { - s.logger.Error("failed to get latestBlockHeight from database", zap.Error(err)) + s.logger.Warn("failed to get latest block from database", zap.Error(err)) return err } latestBlockHeight, success := new(big.Int).SetString(string(heightData), 10) if !success { - s.logger.Error("failed to convert latestBlockHeight to big.Int", zap.Error(err)) + s.logger.Error("failed to convert latest block to big.Int", zap.Error(err)) return err } From ba3f2fb6c794b05c33c9a46b83966fa03faa12ec Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Tue, 29 Aug 2023 21:49:20 +0000 Subject: [PATCH 04/49] add storage location cfg option --- config/config.go | 2 ++ config/keys.go | 1 + main/main.go | 4 +--- 3 files changed, 4 insertions(+), 3 deletions(-) diff --git a/config/config.go b/config/config.go index 5bc04613..84e6729b 100644 --- a/config/config.go +++ b/config/config.go @@ -63,6 +63,7 @@ type Config struct { NetworkID uint32 `mapstructure:"network-id" json:"network-id"` PChainAPIURL string `mapstructure:"p-chain-api-url" json:"p-chain-api-url"` EncryptConnection bool `mapstructure:"encrypt-connection" json:"encrypt-connection"` + StorageLocation string `mapstructure:"storage-location" json:"storage-location"` SourceSubnets []SourceSubnet `mapstructure:"source-subnets" json:"source-subnets"` DestinationSubnets []DestinationSubnet `mapstructure:"destination-subnets" json:"destination-subnets"` } @@ -72,6 +73,7 @@ func SetDefaultConfigValues(v *viper.Viper) { v.SetDefault(NetworkIDKey, constants.MainnetID) v.SetDefault(PChainAPIURLKey, "https://api.avax.network") v.SetDefault(EncryptConnectionKey, true) + v.SetDefault(StorageLocationKey, "./awm-relayer-storage") } // BuildConfig constructs the relayer config using Viper. diff --git a/config/keys.go b/config/keys.go index a9beb607..d872a0e1 100644 --- a/config/keys.go +++ b/config/keys.go @@ -13,4 +13,5 @@ const ( DestinationSubnetsKey = "destination-subnets" EncryptConnectionKey = "encrypt-connection" AccountPrivateKeyKey = "account-private-key" + StorageLocationKey = "storage-location" ) diff --git a/main/main.go b/main/main.go index 40dc87cf..9661fc7b 100644 --- a/main/main.go +++ b/main/main.go @@ -34,8 +34,6 @@ const ( defaultErrorChanSize = 1000 defaultApiPort = 8080 defaultMetricsPort = 9090 - - defaultStorageLocation = "~/.awm-relayer" ) func main() { @@ -153,7 +151,7 @@ func main() { } // Initialize the database - db, err := database.NewJSONFileStorage(logger, defaultStorageLocation, sourceChainIDs) + db, err := database.NewJSONFileStorage(logger, cfg.StorageLocation, sourceChainIDs) if err != nil { logger.Error( "Failed to create database", From 39fdc21ffbe6f94bd8e96d131c785cf7ed28d069 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Wed, 30 Aug 2023 13:46:30 +0000 Subject: [PATCH 05/49] better read error handling --- database/json_file_storage.go | 56 +++++++++++++++++++++++++---------- 1 file changed, 40 insertions(+), 16 deletions(-) diff --git a/database/json_file_storage.go b/database/json_file_storage.go index 127adaf4..4574ae61 100644 --- a/database/json_file_storage.go +++ b/database/json_file_storage.go @@ -14,6 +14,10 @@ import ( var _ RelayerDatabase = &JsonFileStorage{} +var ( + fileDoesNotExistErr = errors.New("JSON database file does not exist") +) + type chainState map[string]string // JsonFileStorage implements RelayerDatabase @@ -21,16 +25,14 @@ type JsonFileStorage struct { // the directory where the json files are stored dir string - // one mutex per network - // we predefined the network when creating the storage - // also we don't allow adding new network after the storage is created - // so we don't need to lock the map + // Each network has its own mutex + // The chainIDs used to index the JsonFileStorage are created at initialization + // and are not modified afterwards, so we don't need to lock the map itself. mutexes map[ids.ID]*sync.RWMutex logger logging.Logger } // NewJSONFileStorage creates a new JsonFileStorage instance -// with predefined networks. e.g "ethereum", "avalanche" func NewJSONFileStorage(logger logging.Logger, dir string, networks []ids.ID) (*JsonFileStorage, error) { storage := &JsonFileStorage{ dir: filepath.Clean(dir), @@ -64,10 +66,13 @@ func NewJSONFileStorage(logger logging.Logger, dir string, networks []ids.ID) (* // Get the latest chain state from the json database, and retrieve the value from the key func (s *JsonFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { var currentState chainState - err := s.read(chainID, ¤tState) + fileExists, err := s.read(chainID, ¤tState) if err != nil { return nil, err } + if !fileExists { + return nil, fileDoesNotExistErr + } return []byte(currentState[string(key)]), nil } @@ -76,8 +81,17 @@ func (s *JsonFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { func (s *JsonFileStorage) Put(chainID ids.ID, key []byte, value []byte) error { currentState := make(chainState) var currentStateData []byte - err := s.read(chainID, ¤tStateData) - if err == nil { + fileExists, err := s.read(chainID, ¤tStateData) + if err != nil { + s.logger.Error( + "failed to read file", + zap.Error(err), + ) + return err + } + // If the file exists, unmarshal the data into currentState + // Otherwise, we write the value to the empty currentState, and overwrite the file + if fileExists { err = json.Unmarshal(currentStateData, ¤tState) if err != nil { return err @@ -124,30 +138,40 @@ func (s *JsonFileStorage) write(network ids.ID, v interface{}) error { } // Read from disk and unmarshal into v -func (s *JsonFileStorage) read(network ids.ID, v interface{}) error { +// Returns a bool indicating whether the file exists, and an error. +// If an error is returned, the bool should be ignored. +func (s *JsonFileStorage) read(network ids.ID, v interface{}) (bool, error) { mutex, ok := s.mutexes[network] if !ok { - return errors.New("network does not exist") + return false, errors.New("network does not exist") } mutex.RLock() defer mutex.RUnlock() path := filepath.Join(s.dir, network.String()+".json") - _, err := os.Stat(path) - if err != nil { - return err + + // If the file does not exist, return false, but do not return an error as this + // is an expected case + if _, err := os.Stat(path); errors.Is(err, os.ErrNotExist) { + s.logger.Debug( + "file does not exist", + zap.String("path", path), + zap.Error(err), + ) + return false, nil } b, err := os.ReadFile(path) if err != nil { - return errors.Wrap(err, "failed to read file") + return false, errors.Wrap(err, "failed to read file") } // unmarshal data if err = json.Unmarshal(b, &v); err != nil { - return errors.Wrap(err, "failed to unmarshal json file") + return false, errors.Wrap(err, "failed to unmarshal json file") } - return nil + // Return true to indicate that the file exists and we read from it successfully + return true, nil } From a1aab005114453eacdf414af9ad58d9ed185ae50 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Wed, 30 Aug 2023 13:46:39 +0000 Subject: [PATCH 06/49] add comments --- database/database.go | 1 + vms/evm/subscriber.go | 13 +++++++++++-- 2 files changed, 12 insertions(+), 2 deletions(-) diff --git a/database/database.go b/database/database.go index f0dbf8b9..df03471c 100644 --- a/database/database.go +++ b/database/database.go @@ -6,6 +6,7 @@ const ( LatestBlockHeightKey = "latestBlockHeight" ) +// RelayerDatabase is a key-value store for relayer state, with each chainID maintaining its own state type RelayerDatabase interface { Get(chainID ids.ID, key []byte) ([]byte, error) Put(chainID ids.ID, key []byte, value []byte) error diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index 7955f9df..5eb93fd7 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -36,6 +36,7 @@ var ( ErrInvalidLog = errors.New("invalid warp message log") ) +// The filter query used to match logs emitted by the Warp precompile var warpFilterQuery = interfaces.FilterQuery{ Topics: [][]common.Hash{ {warp.WarpABI.Events["SendWarpMessage"].ID}, @@ -119,6 +120,7 @@ func (s *subscriber) forwardLogs() { // Update the database with the latest block height // TODO: This should also be done in a separate goroutine, rather than waiting for warp messages to be processed + // TODO: Rather than updating the db when logs are received, we may want to consider updating the db when messages are successfully relayed err = s.db.Put(s.chainID, []byte(database.LatestBlockHeightKey), []byte(strconv.FormatUint(msgLog.BlockNumber, 10))) if err != nil { s.logger.Error(fmt.Sprintf("failed to put %s into database", database.LatestBlockHeightKey), zap.Error(err)) @@ -154,8 +156,14 @@ func (s *subscriber) Initialize() error { return err } - var initializationFilterQuery = warpFilterQuery - initializationFilterQuery.FromBlock = latestBlockHeight + // Filter logs from the latest processed block to the latest block + // Since initializationFilterQuery does not modify existing fields of warpFilterQuery, + // we can safely reuse warpFilterQuery with only a shallow copy + initializationFilterQuery := interfaces.FilterQuery{ + Topics: warpFilterQuery.Topics, + Addresses: warpFilterQuery.Addresses, + FromBlock: latestBlockHeight, + } logs, err := ethClient.FilterLogs(context.Background(), initializationFilterQuery) if err != nil { s.logger.Error( @@ -165,6 +173,7 @@ func (s *subscriber) Initialize() error { return err } + // Queue each of the logs to be processed for _, log := range logs { messageInfo, err := NewWarpLogInfo(log) if err != nil { From 6913fb9f1dc1888b639e7d62dd02b357ff6c238b Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Wed, 30 Aug 2023 14:05:51 +0000 Subject: [PATCH 07/49] properly set default storage location --- config/config.go | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/config/config.go b/config/config.go index 84e6729b..db079455 100644 --- a/config/config.go +++ b/config/config.go @@ -73,7 +73,7 @@ func SetDefaultConfigValues(v *viper.Viper) { v.SetDefault(NetworkIDKey, constants.MainnetID) v.SetDefault(PChainAPIURLKey, "https://api.avax.network") v.SetDefault(EncryptConnectionKey, true) - v.SetDefault(StorageLocationKey, "./awm-relayer-storage") + v.SetDefault(StorageLocationKey, "./.awm-relayer-storage") } // BuildConfig constructs the relayer config using Viper. @@ -102,6 +102,7 @@ func BuildConfig(v *viper.Viper) (Config, bool, error) { cfg.NetworkID = v.GetUint32(NetworkIDKey) cfg.PChainAPIURL = v.GetString(PChainAPIURLKey) cfg.EncryptConnection = v.GetBool(EncryptConnectionKey) + cfg.StorageLocation = v.GetString(StorageLocationKey) if err := v.UnmarshalKey(DestinationSubnetsKey, &cfg.DestinationSubnets); err != nil { return Config{}, false, fmt.Errorf("failed to unmarshal destination subnets: %v", err) } From 505b33706c5dca131796d3d892dc8d63d23be861 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Wed, 30 Aug 2023 14:36:10 +0000 Subject: [PATCH 08/49] fix update json db vals bug --- database/json_file_storage.go | 17 ++++++----------- 1 file changed, 6 insertions(+), 11 deletions(-) diff --git a/database/json_file_storage.go b/database/json_file_storage.go index 4574ae61..27d2ec69 100644 --- a/database/json_file_storage.go +++ b/database/json_file_storage.go @@ -65,9 +65,13 @@ func NewJSONFileStorage(logger logging.Logger, dir string, networks []ids.ID) (* // Get the latest chain state from the json database, and retrieve the value from the key func (s *JsonFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { - var currentState chainState + currentState := make(chainState) fileExists, err := s.read(chainID, ¤tState) if err != nil { + s.logger.Error( + "failed to read file", + zap.Error(err), + ) return nil, err } if !fileExists { @@ -80,8 +84,7 @@ func (s *JsonFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { // Put the value into the json database. Read the current chain state and overwrite the key, if it exists func (s *JsonFileStorage) Put(chainID ids.ID, key []byte, value []byte) error { currentState := make(chainState) - var currentStateData []byte - fileExists, err := s.read(chainID, ¤tStateData) + _, err := s.read(chainID, ¤tState) if err != nil { s.logger.Error( "failed to read file", @@ -89,14 +92,6 @@ func (s *JsonFileStorage) Put(chainID ids.ID, key []byte, value []byte) error { ) return err } - // If the file exists, unmarshal the data into currentState - // Otherwise, we write the value to the empty currentState, and overwrite the file - if fileExists { - err = json.Unmarshal(currentStateData, ¤tState) - if err != nil { - return err - } - } currentState[string(key)] = string(value) From de7a347c7fefd34116133d718727040cb170c151 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Wed, 30 Aug 2023 14:38:05 +0000 Subject: [PATCH 09/49] add initialization log message --- vms/evm/subscriber.go | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index 5eb93fd7..8c7482f5 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -174,6 +174,11 @@ func (s *subscriber) Initialize() error { } // Queue each of the logs to be processed + s.logger.Info( + "Processing logs on initialization", + zap.String("fromBlockHeight", latestBlockHeight.String()), + zap.String("toBlockHeight", strconv.Itoa(int(latestBlock))), + ) for _, log := range logs { messageInfo, err := NewWarpLogInfo(log) if err != nil { From 349ac1ece5b235c5ec0be7475ec675ed3f1a0382 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Wed, 30 Aug 2023 14:41:18 +0000 Subject: [PATCH 10/49] typo --- vms/subscriber.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/vms/subscriber.go b/vms/subscriber.go index a7f2ea0f..d60cb4ef 100644 --- a/vms/subscriber.go +++ b/vms/subscriber.go @@ -13,7 +13,7 @@ import ( // Subscriber subscribes to VM events containing Warp message data type Subscriber interface { - // Inialize the subscriber by processing any pending events + // Initialize the subscriber by processing any pending events Initialize() error // Subscribe registers a subscription. After Subscribe is called, From 162ca0dcb3f8920f0d1da8117774927dee2f6198 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Wed, 30 Aug 2023 18:47:04 +0000 Subject: [PATCH 11/49] validate rpc endpoint in config --- config/config.go | 3 +++ config/config_test.go | 29 ++++++++++++++++++----------- 2 files changed, 21 insertions(+), 11 deletions(-) diff --git a/config/config.go b/config/config.go index db079455..c323d1d2 100644 --- a/config/config.go +++ b/config/config.go @@ -219,6 +219,9 @@ func (s *SourceSubnet) Validate() error { if _, err := url.ParseRequestURI(s.GetNodeWSEndpoint()); err != nil { return fmt.Errorf("invalid relayer subscribe URL in source subnet configuration: %v", err) } + if _, err := url.ParseRequestURI(s.GetNodeRPCEndpoint()); err != nil { + return fmt.Errorf("invalid relayer RPC URL in source subnet configuration: %v", err) + } // Validate the VM specific settings switch ParseVM(s.VM) { diff --git a/config/config_test.go b/config/config_test.go index 5c99b1d5..f48f0c9e 100644 --- a/config/config_test.go +++ b/config/config_test.go @@ -124,10 +124,11 @@ func TestGetDestinationRPCEndpoint(t *testing.T) { } } -func TestGetSourceSubnetWSEndpoint(t *testing.T) { +func TestGetSourceSubnetEndpoints(t *testing.T) { testCases := []struct { - s SourceSubnet - expectedResult string + s SourceSubnet + expectedWsResult string + expectedRpcResult string }{ { s: SourceSubnet{ @@ -137,7 +138,8 @@ func TestGetSourceSubnetWSEndpoint(t *testing.T) { ChainID: testChainID, SubnetID: testSubnetID, }, - expectedResult: fmt.Sprintf("ws://127.0.0.1:9650/ext/bc/%s/ws", testChainID), + expectedWsResult: fmt.Sprintf("ws://127.0.0.1:9650/ext/bc/%s/ws", testChainID), + expectedRpcResult: fmt.Sprintf("http://127.0.0.1:9650/ext/bc/%s/rpc", testChainID), }, { s: SourceSubnet{ @@ -147,7 +149,8 @@ func TestGetSourceSubnetWSEndpoint(t *testing.T) { ChainID: testChainID, SubnetID: testSubnetID, }, - expectedResult: fmt.Sprintf("wss://127.0.0.1:9650/ext/bc/%s/ws", testChainID), + expectedWsResult: fmt.Sprintf("wss://127.0.0.1:9650/ext/bc/%s/ws", testChainID), + expectedRpcResult: fmt.Sprintf("https://127.0.0.1:9650/ext/bc/%s/rpc", testChainID), }, { s: SourceSubnet{ @@ -157,7 +160,8 @@ func TestGetSourceSubnetWSEndpoint(t *testing.T) { ChainID: testChainID, SubnetID: testSubnetID, }, - expectedResult: fmt.Sprintf("ws://api.avax.network/ext/bc/%s/ws", testChainID), + expectedWsResult: fmt.Sprintf("ws://api.avax.network/ext/bc/%s/ws", testChainID), + expectedRpcResult: fmt.Sprintf("http://api.avax.network/ext/bc/%s/rpc", testChainID), }, { s: SourceSubnet{ @@ -167,7 +171,8 @@ func TestGetSourceSubnetWSEndpoint(t *testing.T) { ChainID: testChainID, SubnetID: primarySubnetID, }, - expectedResult: "ws://127.0.0.1:9650/ext/bc/C/ws", + expectedWsResult: "ws://127.0.0.1:9650/ext/bc/C/ws", + expectedRpcResult: "http://127.0.0.1:9650/ext/bc/C/rpc", }, { s: SourceSubnet{ @@ -176,15 +181,17 @@ func TestGetSourceSubnetWSEndpoint(t *testing.T) { APINodePort: 9650, ChainID: testChainID, SubnetID: testSubnetID, - WSEndpoint: "wss://subnets.avax.network/mysubnet/ws", // overrides all other settings used to construct the endpoint + WSEndpoint: "wss://subnets.avax.network/mysubnet/ws", // overrides all other settings used to construct the endpoint + RPCEndpoint: "https://subnets.avax.network/mysubnet/rpc", // overrides all other settings used to construct the endpoint }, - expectedResult: "wss://subnets.avax.network/mysubnet/ws", + expectedWsResult: "wss://subnets.avax.network/mysubnet/ws", + expectedRpcResult: "https://subnets.avax.network/mysubnet/rpc", }, } for i, testCase := range testCases { - res := testCase.s.GetNodeWSEndpoint() - assert.Equal(t, testCase.expectedResult, res, fmt.Sprintf("test case %d failed", i)) + assert.Equal(t, testCase.expectedWsResult, testCase.s.GetNodeWSEndpoint(), fmt.Sprintf("test case %d failed", i)) + assert.Equal(t, testCase.expectedRpcResult, testCase.s.GetNodeRPCEndpoint(), fmt.Sprintf("test case %d failed", i)) } } From 7d07d82c7c106415d5528e0ddc4ae9aede9df8b3 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Wed, 30 Aug 2023 18:47:21 +0000 Subject: [PATCH 12/49] create subscription before processing back events --- database/database.go | 2 +- relayer/relayer.go | 37 ++++++++++++++++++++++++++++--------- vms/evm/subscriber.go | 27 +++++++-------------------- vms/subscriber.go | 6 ++++-- 4 files changed, 40 insertions(+), 32 deletions(-) diff --git a/database/database.go b/database/database.go index df03471c..d192274c 100644 --- a/database/database.go +++ b/database/database.go @@ -3,7 +3,7 @@ package database import "github.com/ava-labs/avalanchego/ids" const ( - LatestBlockHeightKey = "latestBlockHeight" + LatestProcessedBlockKey = "latestProcessedBlock" ) // RelayerDatabase is a key-value store for relayer state, with each chainID maintaining its own state diff --git a/relayer/relayer.go b/relayer/relayer.go index 31fcf647..92f9057e 100644 --- a/relayer/relayer.go +++ b/relayer/relayer.go @@ -4,6 +4,7 @@ package relayer import ( + "math/big" "math/rand" "sync" @@ -36,6 +37,7 @@ type Relayer struct { contractMessage vms.ContractMessage messageManagers map[common.Hash]messages.MessageManager logger logging.Logger + db database.RelayerDatabase } func NewRelayer( @@ -105,29 +107,46 @@ func NewRelayer( contractMessage: vms.NewContractMessage(logger, sourceSubnetInfo), messageManagers: messageManagers, logger: logger, + db: db, } // Start the message router. We must do this before Subscribing or Initializing for the first time, otherwise we may miss an incoming message go r.RouteToMessageChannel() - // Initialize the subscriber. This will poll the node for any logs that match the filter query from the stored block height, - // and process the contained warp messages. If initialization fails, continue with normal relayer operation, but log the error. - err = sub.Initialize() + // Open the subscription. We must do this before processing any missed messages, otherwise we may miss an incoming message + // in between fetching the latest block and subscribing. + err = sub.Subscribe() if err != nil { - logger.Warn( - "Encountered an error when initializing subscriber. Skipping initialization.", + logger.Error( + "Failed to subscribe to node", zap.Error(err), ) + return nil, nil, err } - err = sub.Subscribe() + // Get the latest processed block height from the database. + latestProcessedBlockData, err := r.db.Get(r.sourceChainID, []byte(database.LatestProcessedBlockKey)) if err != nil { - logger.Error( - "Failed to subscribe to node", + r.logger.Warn("failed to get latest block from database", zap.Error(err)) + return nil, nil, err + } + latestProcessedBlock, success := new(big.Int).SetString(string(latestProcessedBlockData), 10) + if !success { + r.logger.Error("failed to convert latest block to big.Int", zap.Error(err)) + return nil, nil, err + } + + // Back-process all warp messages from the latest processed block to the latest block + // This will query the node for any logs that match the filter query from the stored block height, + // and process the contained warp messages. If initialization fails, continue with normal relayer operation, but log the error. + err = sub.ProcessFromHeight(latestProcessedBlock) + if err != nil { + logger.Warn( + "Encountered an error when processing historical blocks. Continuing to normal relaying operation.", zap.Error(err), ) - return nil, nil, err } + return &r, sub, nil } diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index 8c7482f5..ba88ab35 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -119,33 +119,20 @@ func (s *subscriber) forwardLogs() { s.log <- *messageInfo // Update the database with the latest block height - // TODO: This should also be done in a separate goroutine, rather than waiting for warp messages to be processed // TODO: Rather than updating the db when logs are received, we may want to consider updating the db when messages are successfully relayed - err = s.db.Put(s.chainID, []byte(database.LatestBlockHeightKey), []byte(strconv.FormatUint(msgLog.BlockNumber, 10))) + err = s.db.Put(s.chainID, []byte(database.LatestProcessedBlockKey), []byte(strconv.FormatUint(msgLog.BlockNumber, 10))) if err != nil { - s.logger.Error(fmt.Sprintf("failed to put %s into database", database.LatestBlockHeightKey), zap.Error(err)) + s.logger.Error(fmt.Sprintf("failed to put %s into database", database.LatestProcessedBlockKey), zap.Error(err)) } } } -func (s *subscriber) Initialize() error { +func (s *subscriber) ProcessFromHeight(height *big.Int) error { ethClient, err := ethclient.Dial(s.nodeRPCURL) if err != nil { return err } - // Get the latest processed block height from the database. - heightData, err := s.db.Get(s.chainID, []byte(database.LatestBlockHeightKey)) - if err != nil { - s.logger.Warn("failed to get latest block from database", zap.Error(err)) - return err - } - latestBlockHeight, success := new(big.Int).SetString(string(heightData), 10) - if !success { - s.logger.Error("failed to convert latest block to big.Int", zap.Error(err)) - return err - } - // Grab the latest block before filtering logs so we don't miss any before updating the db latestBlock, err := ethClient.BlockNumber(context.Background()) if err != nil { @@ -162,7 +149,7 @@ func (s *subscriber) Initialize() error { initializationFilterQuery := interfaces.FilterQuery{ Topics: warpFilterQuery.Topics, Addresses: warpFilterQuery.Addresses, - FromBlock: latestBlockHeight, + FromBlock: height, } logs, err := ethClient.FilterLogs(context.Background(), initializationFilterQuery) if err != nil { @@ -176,7 +163,7 @@ func (s *subscriber) Initialize() error { // Queue each of the logs to be processed s.logger.Info( "Processing logs on initialization", - zap.String("fromBlockHeight", latestBlockHeight.String()), + zap.String("fromBlockHeight", height.String()), zap.String("toBlockHeight", strconv.Itoa(int(latestBlock))), ) for _, log := range logs { @@ -192,9 +179,9 @@ func (s *subscriber) Initialize() error { } // Update the database with the latest block height - err = s.db.Put(s.chainID, []byte(database.LatestBlockHeightKey), []byte(strconv.FormatUint(latestBlock, 10))) + err = s.db.Put(s.chainID, []byte(database.LatestProcessedBlockKey), []byte(strconv.FormatUint(latestBlock, 10))) if err != nil { - s.logger.Error(fmt.Sprintf("failed to put %s into database", database.LatestBlockHeightKey), zap.Error(err)) + s.logger.Error(fmt.Sprintf("failed to put %s into database", database.LatestProcessedBlockKey), zap.Error(err)) return err } return nil diff --git a/vms/subscriber.go b/vms/subscriber.go index d60cb4ef..bb79dc39 100644 --- a/vms/subscriber.go +++ b/vms/subscriber.go @@ -4,6 +4,8 @@ package vms import ( + "math/big" + "github.com/ava-labs/avalanchego/utils/logging" "github.com/ava-labs/awm-relayer/config" "github.com/ava-labs/awm-relayer/database" @@ -13,8 +15,8 @@ import ( // Subscriber subscribes to VM events containing Warp message data type Subscriber interface { - // Initialize the subscriber by processing any pending events - Initialize() error + // ProcessFromHeight processes events from {height} to the latest block + ProcessFromHeight(height *big.Int) error // Subscribe registers a subscription. After Subscribe is called, // log events that match [filter] are written to the channel returned From 9a0baa09b455d916c9a04cb555c4552e38f0b886 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Wed, 30 Aug 2023 18:50:27 +0000 Subject: [PATCH 13/49] rename type --- database/json_file_storage.go | 22 +++++++++++----------- 1 file changed, 11 insertions(+), 11 deletions(-) diff --git a/database/json_file_storage.go b/database/json_file_storage.go index 27d2ec69..36849ca1 100644 --- a/database/json_file_storage.go +++ b/database/json_file_storage.go @@ -12,7 +12,7 @@ import ( "go.uber.org/zap" ) -var _ RelayerDatabase = &JsonFileStorage{} +var _ RelayerDatabase = &JSONFileStorage{} var ( fileDoesNotExistErr = errors.New("JSON database file does not exist") @@ -20,21 +20,21 @@ var ( type chainState map[string]string -// JsonFileStorage implements RelayerDatabase -type JsonFileStorage struct { +// JSONFileStorage implements RelayerDatabase +type JSONFileStorage struct { // the directory where the json files are stored dir string // Each network has its own mutex - // The chainIDs used to index the JsonFileStorage are created at initialization + // The chainIDs used to index the JSONFileStorage are created at initialization // and are not modified afterwards, so we don't need to lock the map itself. mutexes map[ids.ID]*sync.RWMutex logger logging.Logger } -// NewJSONFileStorage creates a new JsonFileStorage instance -func NewJSONFileStorage(logger logging.Logger, dir string, networks []ids.ID) (*JsonFileStorage, error) { - storage := &JsonFileStorage{ +// NewJSONFileStorage creates a new JSONFileStorage instance +func NewJSONFileStorage(logger logging.Logger, dir string, networks []ids.ID) (*JSONFileStorage, error) { + storage := &JSONFileStorage{ dir: filepath.Clean(dir), mutexes: make(map[ids.ID]*sync.RWMutex), logger: logger, @@ -64,7 +64,7 @@ func NewJSONFileStorage(logger logging.Logger, dir string, networks []ids.ID) (* } // Get the latest chain state from the json database, and retrieve the value from the key -func (s *JsonFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { +func (s *JSONFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { currentState := make(chainState) fileExists, err := s.read(chainID, ¤tState) if err != nil { @@ -82,7 +82,7 @@ func (s *JsonFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { } // Put the value into the json database. Read the current chain state and overwrite the key, if it exists -func (s *JsonFileStorage) Put(chainID ids.ID, key []byte, value []byte) error { +func (s *JSONFileStorage) Put(chainID ids.ID, key []byte, value []byte) error { currentState := make(chainState) _, err := s.read(chainID, ¤tState) if err != nil { @@ -99,7 +99,7 @@ func (s *JsonFileStorage) Put(chainID ids.ID, key []byte, value []byte) error { } // write value into the file -func (s *JsonFileStorage) write(network ids.ID, v interface{}) error { +func (s *JSONFileStorage) write(network ids.ID, v interface{}) error { mutex, ok := s.mutexes[network] if !ok { return errors.New("network does not exist") @@ -135,7 +135,7 @@ func (s *JsonFileStorage) write(network ids.ID, v interface{}) error { // Read from disk and unmarshal into v // Returns a bool indicating whether the file exists, and an error. // If an error is returned, the bool should be ignored. -func (s *JsonFileStorage) read(network ids.ID, v interface{}) (bool, error) { +func (s *JSONFileStorage) read(network ids.ID, v interface{}) (bool, error) { mutex, ok := s.mutexes[network] if !ok { return false, errors.New("network does not exist") From dc7ae3c040b55add020fcfe9af499c7655362319 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Wed, 30 Aug 2023 19:53:10 +0000 Subject: [PATCH 14/49] rename latestSeenBlock --- database/database.go | 2 +- relayer/relayer.go | 8 ++++---- vms/evm/subscriber.go | 13 ++++++------- 3 files changed, 11 insertions(+), 12 deletions(-) diff --git a/database/database.go b/database/database.go index d192274c..0fa886ea 100644 --- a/database/database.go +++ b/database/database.go @@ -3,7 +3,7 @@ package database import "github.com/ava-labs/avalanchego/ids" const ( - LatestProcessedBlockKey = "latestProcessedBlock" + LatestSeenBlockKey = "latestSeenBlock" ) // RelayerDatabase is a key-value store for relayer state, with each chainID maintaining its own state diff --git a/relayer/relayer.go b/relayer/relayer.go index 92f9057e..31449d5d 100644 --- a/relayer/relayer.go +++ b/relayer/relayer.go @@ -125,21 +125,21 @@ func NewRelayer( } // Get the latest processed block height from the database. - latestProcessedBlockData, err := r.db.Get(r.sourceChainID, []byte(database.LatestProcessedBlockKey)) + latestSeenBlockData, err := r.db.Get(r.sourceChainID, []byte(database.LatestSeenBlockKey)) if err != nil { r.logger.Warn("failed to get latest block from database", zap.Error(err)) return nil, nil, err } - latestProcessedBlock, success := new(big.Int).SetString(string(latestProcessedBlockData), 10) + latestSeenBlock, success := new(big.Int).SetString(string(latestSeenBlockData), 10) if !success { r.logger.Error("failed to convert latest block to big.Int", zap.Error(err)) return nil, nil, err } - // Back-process all warp messages from the latest processed block to the latest block + // Back-process all warp messages from the latest seen block to the latest block // This will query the node for any logs that match the filter query from the stored block height, // and process the contained warp messages. If initialization fails, continue with normal relayer operation, but log the error. - err = sub.ProcessFromHeight(latestProcessedBlock) + err = sub.ProcessFromHeight(latestSeenBlock) if err != nil { logger.Warn( "Encountered an error when processing historical blocks. Continuing to normal relaying operation.", diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index ba88ab35..a10a9122 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -118,11 +118,10 @@ func (s *subscriber) forwardLogs() { } s.log <- *messageInfo - // Update the database with the latest block height - // TODO: Rather than updating the db when logs are received, we may want to consider updating the db when messages are successfully relayed - err = s.db.Put(s.chainID, []byte(database.LatestProcessedBlockKey), []byte(strconv.FormatUint(msgLog.BlockNumber, 10))) + // Update the database with the latest seen block height + err = s.db.Put(s.chainID, []byte(database.LatestSeenBlockKey), []byte(strconv.FormatUint(msgLog.BlockNumber, 10))) if err != nil { - s.logger.Error(fmt.Sprintf("failed to put %s into database", database.LatestProcessedBlockKey), zap.Error(err)) + s.logger.Error(fmt.Sprintf("failed to put %s into database", database.LatestSeenBlockKey), zap.Error(err)) } } } @@ -178,10 +177,10 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { s.log <- *messageInfo } - // Update the database with the latest block height - err = s.db.Put(s.chainID, []byte(database.LatestProcessedBlockKey), []byte(strconv.FormatUint(latestBlock, 10))) + // Update the database with the latest seen block height + err = s.db.Put(s.chainID, []byte(database.LatestSeenBlockKey), []byte(strconv.FormatUint(latestBlock, 10))) if err != nil { - s.logger.Error(fmt.Sprintf("failed to put %s into database", database.LatestProcessedBlockKey), zap.Error(err)) + s.logger.Error(fmt.Sprintf("failed to put %s into database", database.LatestSeenBlockKey), zap.Error(err)) return err } return nil From 860f595f3b825505368d5a4a644c6c981b7c360c Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Wed, 30 Aug 2023 20:33:07 +0000 Subject: [PATCH 15/49] json storage unit tests --- database/json_file_storage_test.go | 75 ++++++++++++++++++++++++++++++ 1 file changed, 75 insertions(+) create mode 100644 database/json_file_storage_test.go diff --git a/database/json_file_storage_test.go b/database/json_file_storage_test.go new file mode 100644 index 00000000..bd562c80 --- /dev/null +++ b/database/json_file_storage_test.go @@ -0,0 +1,75 @@ +package database + +import ( + "fmt" + "math/big" + "os" + "strconv" + "sync" + "testing" + + "github.com/ava-labs/avalanchego/ids" + "github.com/ava-labs/avalanchego/utils/logging" + "github.com/stretchr/testify/assert" +) + +func TestConcurrentWriteRead(t *testing.T) { + networks := []ids.ID{ + ids.GenerateTestID(), + ids.GenerateTestID(), + ids.GenerateTestID(), + } + jsonStorage := setupJsonStorage(t, networks) + + // Test writing to the JSON database concurrently. + wg := sync.WaitGroup{} + for i := 0; i < 3; i++ { + wg.Add(1) + go func() { + defer wg.Done() + testWrite(jsonStorage, networks[0], uint64(0)) + testWrite(jsonStorage, networks[1], uint64(1)) + testWrite(jsonStorage, networks[2], uint64(2)) + }() + } + wg.Wait() + + for i, id := range networks { + latestSeenBlockData, err := jsonStorage.Get(id, []byte(LatestSeenBlockKey)) + if err != nil { + t.Fatal(fmt.Sprintf("failed to retrieve from JSON storage. networkID: %d err: %v", i, err)) + } + latestSeenBlock, success := new(big.Int).SetString(string(latestSeenBlockData), 10) + if !success { + t.Fatal(fmt.Sprintf("failed to convert latest block to big.Int. err: %v", err)) + } + assert.Equal(t, uint64(i), latestSeenBlock.Uint64(), fmt.Sprintf("latest seen block height is not correct. networkID: %d", i)) + } +} + +func setupJsonStorage(t *testing.T, networks []ids.ID) *JSONFileStorage { + logger := logging.NewLogger( + "awm-relayer-test", + logging.NewWrappedCore( + logging.Info, + os.Stdout, + logging.JSON.ConsoleEncoder(), + ), + ) + storageDir := t.TempDir() + + jsonStorage, err := NewJSONFileStorage(logger, storageDir, networks) + if err != nil { + t.Fatal(err) + } + return jsonStorage +} + +func testWrite(storage *JSONFileStorage, chainID ids.ID, height uint64) { + fmt.Println(chainID, height) + err := storage.Put(chainID, []byte(LatestSeenBlockKey), []byte(strconv.FormatUint(height, 10))) + if err != nil { + fmt.Printf("failed to put data: %v", err) + return + } +} From aa8dd8b874bec524b8af45debb5e67985ff69695 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Wed, 30 Aug 2023 22:46:57 +0000 Subject: [PATCH 16/49] correct comment --- vms/evm/subscriber.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index a10a9122..397e5878 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -215,7 +215,7 @@ func (s *subscriber) Subscribe() error { } func (s *subscriber) dialAndSubscribe() error { - // Dial the configured destination chain endpoint + // Dial the configured source chain endpoint // This needs to be a websocket ethClient, err := ethclient.Dial(s.nodeWSURL) if err != nil { From ac5d57d14c885c7cfcd60a3c205095959ae1abb4 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Wed, 30 Aug 2023 22:47:10 +0000 Subject: [PATCH 17/49] better error messages --- database/json_file_storage.go | 17 ++++++++++------- 1 file changed, 10 insertions(+), 7 deletions(-) diff --git a/database/json_file_storage.go b/database/json_file_storage.go index 36849ca1..bae810cd 100644 --- a/database/json_file_storage.go +++ b/database/json_file_storage.go @@ -14,10 +14,6 @@ import ( var _ RelayerDatabase = &JSONFileStorage{} -var ( - fileDoesNotExistErr = errors.New("JSON database file does not exist") -) - type chainState map[string]string // JSONFileStorage implements RelayerDatabase @@ -55,7 +51,8 @@ func NewJSONFileStorage(logger logging.Logger, dir string, networks []ids.ID) (* // Everyone else can read and execute but not modify the file. err = os.MkdirAll(dir, 0755) if err != nil { - storage.logger.Error("failed to create dir", + storage.logger.Error("failed to create directory", + zap.String("dir", dir), zap.Error(err)) return nil, err } @@ -70,12 +67,17 @@ func (s *JSONFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { if err != nil { s.logger.Error( "failed to read file", + zap.String("chainID", chainID.String()), zap.Error(err), ) return nil, err } if !fileExists { - return nil, fileDoesNotExistErr + return nil, errors.Errorf("file does not exist. chainID: %s", chainID) + } + + if _, ok := currentState[string(key)]; !ok { + return nil, errors.Errorf("key does not exist. chainID: %s key: %s", chainID, key) } return []byte(currentState[string(key)]), nil @@ -88,6 +90,7 @@ func (s *JSONFileStorage) Put(chainID ids.ID, key []byte, value []byte) error { if err != nil { s.logger.Error( "failed to read file", + zap.String("chainID", chainID.String()), zap.Error(err), ) return err @@ -102,7 +105,7 @@ func (s *JSONFileStorage) Put(chainID ids.ID, key []byte, value []byte) error { func (s *JSONFileStorage) write(network ids.ID, v interface{}) error { mutex, ok := s.mutexes[network] if !ok { - return errors.New("network does not exist") + return errors.Errorf("network does not exist. chainID: %s", network.String()) } mutex.Lock() From 9a5172786ebcff3f5364059f5f4bc558bc80973f Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Thu, 31 Aug 2023 14:29:14 +0000 Subject: [PATCH 18/49] more unit tests --- database/json_file_storage_test.go | 50 +++++++++++++++++++++++++++--- 1 file changed, 45 insertions(+), 5 deletions(-) diff --git a/database/json_file_storage_test.go b/database/json_file_storage_test.go index bd562c80..1658dd17 100644 --- a/database/json_file_storage_test.go +++ b/database/json_file_storage_test.go @@ -13,7 +13,42 @@ import ( "github.com/stretchr/testify/assert" ) -func TestConcurrentWriteRead(t *testing.T) { +// Test that the JSON database can write and read to a single chain concurrently. +func TestConcurrentWriteReadSingleChain(t *testing.T) { + networks := []ids.ID{ + ids.GenerateTestID(), + } + jsonStorage := setupJsonStorage(t, networks) + + // Test writing to the JSON database concurrently. + wg := sync.WaitGroup{} + for i := 0; i < 10; i++ { + wg.Add(1) + go func() { + defer wg.Done() + testWrite(jsonStorage, networks[0], uint64(i)) + }() + } + wg.Wait() + + // Write one final time to ensure that concurrent writes don't cause any issues. + finalTargetValue := uint64(11) + testWrite(jsonStorage, networks[0], finalTargetValue) + + latestSeenBlockData, err := jsonStorage.Get(networks[0], []byte(LatestSeenBlockKey)) + if err != nil { + t.Fatal(fmt.Sprintf("failed to retrieve from JSON storage. err: %v", err)) + } + latestSeenBlock, success := new(big.Int).SetString(string(latestSeenBlockData), 10) + if !success { + t.Fatal(fmt.Sprintf("failed to convert latest block to big.Int. err: %v", err)) + } + assert.Equal(t, finalTargetValue, latestSeenBlock.Uint64(), "latest seen block height is not correct.") + +} + +// Test that the JSON database can write and read from multiple chains concurrently. Write to any given chain are not concurrent. +func TestConcurrentWriteReadMultipleChains(t *testing.T) { networks := []ids.ID{ ids.GenerateTestID(), ids.GenerateTestID(), @@ -25,15 +60,20 @@ func TestConcurrentWriteRead(t *testing.T) { wg := sync.WaitGroup{} for i := 0; i < 3; i++ { wg.Add(1) + index := i go func() { defer wg.Done() - testWrite(jsonStorage, networks[0], uint64(0)) - testWrite(jsonStorage, networks[1], uint64(1)) - testWrite(jsonStorage, networks[2], uint64(2)) + testWrite(jsonStorage, networks[index], uint64(index)) }() } wg.Wait() + // Write one final time to ensure that concurrent writes don't cause any issues. + finalTargetValue := uint64(3) + for _, network := range networks { + testWrite(jsonStorage, network, finalTargetValue) + } + for i, id := range networks { latestSeenBlockData, err := jsonStorage.Get(id, []byte(LatestSeenBlockKey)) if err != nil { @@ -43,7 +83,7 @@ func TestConcurrentWriteRead(t *testing.T) { if !success { t.Fatal(fmt.Sprintf("failed to convert latest block to big.Int. err: %v", err)) } - assert.Equal(t, uint64(i), latestSeenBlock.Uint64(), fmt.Sprintf("latest seen block height is not correct. networkID: %d", i)) + assert.Equal(t, finalTargetValue, latestSeenBlock.Uint64(), fmt.Sprintf("latest seen block height is not correct. networkID: %d", i)) } } From 16af742920ee732323bf3c1430f86d44538a7951 Mon Sep 17 00:00:00 2001 From: Cameron Schultz Date: Fri, 1 Sep 2023 09:09:29 -0400 Subject: [PATCH 19/49] error on invalid log --- vms/evm/subscriber.go | 25 +++++++++++++++++++------ 1 file changed, 19 insertions(+), 6 deletions(-) diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index 397e5878..e601d3fe 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -84,15 +84,28 @@ func NewSubscriber(logger logging.Logger, subnetInfo config.SourceSubnet, db dat } } -func NewWarpLogInfo(log types.Log) (*vmtypes.WarpLogInfo, error) { +func (s *subscriber) NewWarpLogInfo(log types.Log) (*vmtypes.WarpLogInfo, error) { if len(log.Topics) != 4 { + s.logger.Error( + "Log did not have the correct number of topics", + zap.Int("numTopics", len(log.Topics)), + ) return nil, ErrInvalidLog } if log.Topics[0] != warp.WarpABI.Events["SendWarpMessage"].ID { + s.logger.Error( + "Log topic does not match the SendWarpMessage event type", + zap.String("topic", log.Topics[0].String()), + zap.String("expectedTopic", warp.WarpABI.Events["SendWarpMessage"].ID.String()), + ) return nil, ErrInvalidLog } destinationChainID, err := ids.ToID(log.Topics[1].Bytes()) if err != nil { + s.logger.Error( + "Failed to decode destination chain ID", + zap.Error(err), + ) return nil, ErrInvalidLog } @@ -108,9 +121,9 @@ func NewWarpLogInfo(log types.Log) (*vmtypes.WarpLogInfo, error) { // forward logs from the concrete log channel to the interface channel func (s *subscriber) forwardLogs() { for msgLog := range s.evmLog { - messageInfo, err := NewWarpLogInfo(msgLog) + messageInfo, err := s.NewWarpLogInfo(msgLog) if err != nil { - s.logger.Info( + s.logger.Error( "Invalid log. Continuing.", zap.Error(err), ) @@ -166,10 +179,10 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { zap.String("toBlockHeight", strconv.Itoa(int(latestBlock))), ) for _, log := range logs { - messageInfo, err := NewWarpLogInfo(log) + messageInfo, err := s.NewWarpLogInfo(log) if err != nil { - s.logger.Info( - "Invalid log on initialization. Continuing.", + s.logger.Error( + "Invalid log when processing from height. Continuing.", zap.Error(err), ) continue From 2bb9605cee6755f4de1dd1f591c75d7f8b202ff7 Mon Sep 17 00:00:00 2001 From: Cameron Schultz Date: Fri, 1 Sep 2023 11:50:27 -0400 Subject: [PATCH 20/49] save constructed urls --- config/config.go | 12 +++++++++--- 1 file changed, 9 insertions(+), 3 deletions(-) diff --git a/config/config.go b/config/config.go index c323d1d2..08f12b82 100644 --- a/config/config.go +++ b/config/config.go @@ -299,7 +299,9 @@ func (s *DestinationSubnet) GetNodeRPCEndpoint() string { if subnetID == constants.PrimaryNetworkID { chainID = cChainIdentifierString } - return fmt.Sprintf("%s/ext/bc/%s/rpc", baseUrl, chainID) + // Save this result for future use + s.RPCEndpoint = fmt.Sprintf("%s/ext/bc/%s/rpc", baseUrl, chainID) + return s.RPCEndpoint } // Constructs an RPC endpoint for the subnet. @@ -316,7 +318,9 @@ func (s *SourceSubnet) GetNodeRPCEndpoint() string { if subnetID == constants.PrimaryNetworkID { chainID = cChainIdentifierString } - return fmt.Sprintf("%s/ext/bc/%s/rpc", baseUrl, chainID) + // Save this result for future use + s.RPCEndpoint = fmt.Sprintf("%s/ext/bc/%s/rpc", baseUrl, chainID) + return s.RPCEndpoint } // Constructs a WS endpoint for the subnet. @@ -333,7 +337,9 @@ func (s *SourceSubnet) GetNodeWSEndpoint() string { if subnetID == constants.PrimaryNetworkID { chainID = cChainIdentifierString } - return fmt.Sprintf("%s/ext/bc/%s/ws", baseUrl, chainID) + // Save this result for future use + s.WSEndpoint = fmt.Sprintf("%s/ext/bc/%s/ws", baseUrl, chainID) + return s.WSEndpoint } // Get the private key and derive the wallet address from a relayer's configured private key for a given destination subnet. From 1727f90701fb412af560cf3d6f3e384e030f7171 Mon Sep 17 00:00:00 2001 From: Cameron Schultz Date: Fri, 1 Sep 2023 12:15:25 -0400 Subject: [PATCH 21/49] make json db writes atomic --- database/json_file_storage.go | 40 +++++++++++++++++------------------ 1 file changed, 20 insertions(+), 20 deletions(-) diff --git a/database/json_file_storage.go b/database/json_file_storage.go index bae810cd..f4b27c4a 100644 --- a/database/json_file_storage.go +++ b/database/json_file_storage.go @@ -62,6 +62,13 @@ func NewJSONFileStorage(logger logging.Logger, dir string, networks []ids.ID) (* // Get the latest chain state from the json database, and retrieve the value from the key func (s *JSONFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { + mutex, ok := s.mutexes[chainID] + if !ok { + return nil, errors.New("network does not exist") + } + + mutex.RLock() + defer mutex.RUnlock() currentState := make(chainState) fileExists, err := s.read(chainID, ¤tState) if err != nil { @@ -76,15 +83,23 @@ func (s *JSONFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { return nil, errors.Errorf("file does not exist. chainID: %s", chainID) } - if _, ok := currentState[string(key)]; !ok { - return nil, errors.Errorf("key does not exist. chainID: %s key: %s", chainID, key) + if val, ok := currentState[string(key)]; ok { + return []byte(val), nil } - return []byte(currentState[string(key)]), nil + return nil, errors.Errorf("key does not exist. chainID: %s key: %s", chainID, key) } // Put the value into the json database. Read the current chain state and overwrite the key, if it exists func (s *JSONFileStorage) Put(chainID ids.ID, key []byte, value []byte) error { + mutex, ok := s.mutexes[chainID] + if !ok { + return errors.Errorf("network does not exist. chainID: %s", chainID.String()) + } + + mutex.Lock() + defer mutex.Unlock() + currentState := make(chainState) _, err := s.read(chainID, ¤tState) if err != nil { @@ -101,16 +116,8 @@ func (s *JSONFileStorage) Put(chainID ids.ID, key []byte, value []byte) error { return s.write(chainID, currentState) } -// write value into the file +// Write the value to the file. The caller is responsible for ensuring proper synchronization func (s *JSONFileStorage) write(network ids.ID, v interface{}) error { - mutex, ok := s.mutexes[network] - if !ok { - return errors.Errorf("network does not exist. chainID: %s", network.String()) - } - - mutex.Lock() - defer mutex.Unlock() - fnlPath := filepath.Join(s.dir, network.String()+".json") tmpPath := fnlPath + ".tmp" @@ -138,15 +145,8 @@ func (s *JSONFileStorage) write(network ids.ID, v interface{}) error { // Read from disk and unmarshal into v // Returns a bool indicating whether the file exists, and an error. // If an error is returned, the bool should be ignored. +// The caller is responsible for ensuring proper synchronization func (s *JSONFileStorage) read(network ids.ID, v interface{}) (bool, error) { - mutex, ok := s.mutexes[network] - if !ok { - return false, errors.New("network does not exist") - } - - mutex.RLock() - defer mutex.RUnlock() - path := filepath.Join(s.dir, network.String()+".json") // If the file does not exist, return false, but do not return an error as this From e49395b539262ba273e454afc46dd8209c26d6ae Mon Sep 17 00:00:00 2001 From: Cameron Schultz Date: Fri, 1 Sep 2023 14:12:02 -0400 Subject: [PATCH 22/49] add license header --- database/database.go | 3 +++ database/json_file_storage.go | 3 +++ database/json_file_storage_test.go | 3 +++ 3 files changed, 9 insertions(+) diff --git a/database/database.go b/database/database.go index 0fa886ea..b1410179 100644 --- a/database/database.go +++ b/database/database.go @@ -1,3 +1,6 @@ +// Copyright (C) 2023, Ava Labs, Inc. All rights reserved. +// See the file LICENSE for licensing terms. + package database import "github.com/ava-labs/avalanchego/ids" diff --git a/database/json_file_storage.go b/database/json_file_storage.go index f4b27c4a..63e5c6bb 100644 --- a/database/json_file_storage.go +++ b/database/json_file_storage.go @@ -1,3 +1,6 @@ +// Copyright (C) 2023, Ava Labs, Inc. All rights reserved. +// See the file LICENSE for licensing terms. + package database import ( diff --git a/database/json_file_storage_test.go b/database/json_file_storage_test.go index 1658dd17..ed2f6e3b 100644 --- a/database/json_file_storage_test.go +++ b/database/json_file_storage_test.go @@ -1,3 +1,6 @@ +// Copyright (C) 2023, Ava Labs, Inc. All rights reserved. +// See the file LICENSE for licensing terms. + package database import ( From ebdfc79b11989200d5936d4bcaea22025b4d12e4 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Tue, 5 Sep 2023 15:12:01 +0000 Subject: [PATCH 23/49] properly handle json file missing case --- database/database.go | 10 +++++++++- database/json_file_storage.go | 6 +++--- relayer/relayer.go | 11 ++++++++++- 3 files changed, 22 insertions(+), 5 deletions(-) diff --git a/database/database.go b/database/database.go index b1410179..d432b469 100644 --- a/database/database.go +++ b/database/database.go @@ -3,12 +3,20 @@ package database -import "github.com/ava-labs/avalanchego/ids" +import ( + "github.com/ava-labs/avalanchego/ids" + "github.com/pkg/errors" +) const ( LatestSeenBlockKey = "latestSeenBlock" ) +var ( + ErrKeyNotFound = errors.New("key not found") + ErrChainNotFound = errors.New("no database for chain") +) + // RelayerDatabase is a key-value store for relayer state, with each chainID maintaining its own state type RelayerDatabase interface { Get(chainID ids.ID, key []byte) ([]byte, error) diff --git a/database/json_file_storage.go b/database/json_file_storage.go index 63e5c6bb..73197208 100644 --- a/database/json_file_storage.go +++ b/database/json_file_storage.go @@ -67,7 +67,7 @@ func NewJSONFileStorage(logger logging.Logger, dir string, networks []ids.ID) (* func (s *JSONFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { mutex, ok := s.mutexes[chainID] if !ok { - return nil, errors.New("network does not exist") + return nil, errors.New("database not configured for chain") } mutex.RLock() @@ -83,14 +83,14 @@ func (s *JSONFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { return nil, err } if !fileExists { - return nil, errors.Errorf("file does not exist. chainID: %s", chainID) + return nil, ErrChainNotFound } if val, ok := currentState[string(key)]; ok { return []byte(val), nil } - return nil, errors.Errorf("key does not exist. chainID: %s key: %s", chainID, key) + return nil, ErrKeyNotFound } // Put the value into the json database. Read the current chain state and overwrite the key, if it exists diff --git a/relayer/relayer.go b/relayer/relayer.go index 31449d5d..4be40273 100644 --- a/relayer/relayer.go +++ b/relayer/relayer.go @@ -4,6 +4,7 @@ package relayer import ( + "errors" "math/big" "math/rand" "sync" @@ -124,8 +125,16 @@ func NewRelayer( return nil, nil, err } - // Get the latest processed block height from the database. + // Get the latest processed block height from the database. If the database doesn't have a value for the latest block height, + // for this chain, return here without an error. This will cause the subscriber to begin processing new incoming warp messages. latestSeenBlockData, err := r.db.Get(r.sourceChainID, []byte(database.LatestSeenBlockKey)) + if errors.Is(err, database.ErrChainNotFound) { + logger.Info( + "Latest seen block not found in database. Starting from latest block.", + zap.String("chainID", r.sourceChainID.String()), + ) + return &r, sub, nil + } if err != nil { r.logger.Warn("failed to get latest block from database", zap.Error(err)) return nil, nil, err From 532094cf43d98aacb239fa7522223d270ae2f08c Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Tue, 5 Sep 2023 18:33:24 +0000 Subject: [PATCH 24/49] cleanup --- database/database.go | 5 +++-- database/json_file_storage.go | 18 +++++++++++++----- vms/evm/subscriber.go | 3 +-- 3 files changed, 17 insertions(+), 9 deletions(-) diff --git a/database/database.go b/database/database.go index d432b469..152acb3d 100644 --- a/database/database.go +++ b/database/database.go @@ -13,8 +13,9 @@ const ( ) var ( - ErrKeyNotFound = errors.New("key not found") - ErrChainNotFound = errors.New("no database for chain") + ErrKeyNotFound = errors.New("key not found") + ErrChainNotFound = errors.New("no database for chain") + ErrDatabaseMisconfiguration = errors.New("database misconfiguration") ) // RelayerDatabase is a key-value store for relayer state, with each chainID maintaining its own state diff --git a/database/json_file_storage.go b/database/json_file_storage.go index 73197208..a967224b 100644 --- a/database/json_file_storage.go +++ b/database/json_file_storage.go @@ -5,6 +5,7 @@ package database import ( "encoding/json" + "fmt" "os" "path/filepath" "sync" @@ -67,7 +68,10 @@ func NewJSONFileStorage(logger logging.Logger, dir string, networks []ids.ID) (* func (s *JSONFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { mutex, ok := s.mutexes[chainID] if !ok { - return nil, errors.New("database not configured for chain") + return nil, errors.Wrap( + ErrDatabaseMisconfiguration, + fmt.Sprintf("database not configured for chain %s", chainID.String()), + ) } mutex.RLock() @@ -86,18 +90,22 @@ func (s *JSONFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { return nil, ErrChainNotFound } - if val, ok := currentState[string(key)]; ok { - return []byte(val), nil + var val string + if val, ok = currentState[string(key)]; !ok { + return nil, ErrKeyNotFound } - return nil, ErrKeyNotFound + return []byte(val), nil } // Put the value into the json database. Read the current chain state and overwrite the key, if it exists func (s *JSONFileStorage) Put(chainID ids.ID, key []byte, value []byte) error { mutex, ok := s.mutexes[chainID] if !ok { - return errors.Errorf("network does not exist. chainID: %s", chainID.String()) + return errors.Wrap( + ErrDatabaseMisconfiguration, + fmt.Sprintf("database not configured for chain %s", chainID.String()), + ) } mutex.Lock() diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index e601d3fe..2f7bb505 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -235,9 +235,8 @@ func (s *subscriber) dialAndSubscribe() error { return err } - filterQuery := warpFilterQuery evmLogs := make(chan types.Log, maxClientSubscriptionBuffer) - sub, err := ethClient.SubscribeFilterLogs(context.Background(), filterQuery, evmLogs) + sub, err := ethClient.SubscribeFilterLogs(context.Background(), warpFilterQuery, evmLogs) if err != nil { s.logger.Error( "Failed to subscribe to logs", From f4d2c8304af093365f44f66f3221fab3cedd7950 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Tue, 5 Sep 2023 19:02:55 +0000 Subject: [PATCH 25/49] write latest block to db on initialization --- relayer/relayer.go | 43 ++++++++++++++++++----------- vms/evm/subscriber.go | 63 ++++++++++++++++++++++++------------------- 2 files changed, 63 insertions(+), 43 deletions(-) diff --git a/relayer/relayer.go b/relayer/relayer.go index 4be40273..f965db78 100644 --- a/relayer/relayer.go +++ b/relayer/relayer.go @@ -125,29 +125,42 @@ func NewRelayer( return nil, nil, err } - // Get the latest processed block height from the database. If the database doesn't have a value for the latest block height, - // for this chain, return here without an error. This will cause the subscriber to begin processing new incoming warp messages. - latestSeenBlockData, err := r.db.Get(r.sourceChainID, []byte(database.LatestSeenBlockKey)) - if errors.Is(err, database.ErrChainNotFound) { + // Get the latest processed block height from the database. + var ( + latestSeenBlockData []byte + latestSeenBlock *big.Int // initialized to nil + ) + latestSeenBlockData, err = r.db.Get(r.sourceChainID, []byte(database.LatestSeenBlockKey)) + + // The following cases are treated as successful: + // 1) The database contains the latest seen block data for the chain + // - In this case, we parse the block height and process warp logs from that height to the current block + // 2) The database has been configured for the chain, but does not contain the latest seen block data + // - In this case, we save the current block height in the database, but do not process any historical warp logs + if err == nil { + // If the database contains the latest seen block data, then back-process all warp messages from the + // latest seen block to the latest block + // This will query the node for any logs that match the filter query from the stored block height, + r.logger.Info("latest processed block", zap.String("block", string(latestSeenBlockData))) + var success bool + latestSeenBlock, success = new(big.Int).SetString(string(latestSeenBlockData), 10) + if !success { + r.logger.Error("failed to convert latest block to big.Int", zap.Error(err)) + return nil, nil, err + } + } else if errors.Is(err, database.ErrChainNotFound) || errors.Is(err, database.ErrKeyNotFound) { + // Otherwise, latestSeenBlock is nil, so the call to ProcessFromHeight will simply update the database with the + // latest block height logger.Info( "Latest seen block not found in database. Starting from latest block.", zap.String("chainID", r.sourceChainID.String()), ) - return &r, sub, nil - } - if err != nil { + } else { r.logger.Warn("failed to get latest block from database", zap.Error(err)) return nil, nil, err } - latestSeenBlock, success := new(big.Int).SetString(string(latestSeenBlockData), 10) - if !success { - r.logger.Error("failed to convert latest block to big.Int", zap.Error(err)) - return nil, nil, err - } - // Back-process all warp messages from the latest seen block to the latest block - // This will query the node for any logs that match the filter query from the stored block height, - // and process the contained warp messages. If initialization fails, continue with normal relayer operation, but log the error. + // Process historical logs. If this fails for any reason, continue with normal relayer operation, but log the error. err = sub.ProcessFromHeight(latestSeenBlock) if err != nil { logger.Warn( diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index 2f7bb505..f6304f12 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -139,6 +139,9 @@ func (s *subscriber) forwardLogs() { } } +// Process logs from the given block height to the latest block +// If height is nil, then simply store the latest block height in the database, +// but do not process any logs func (s *subscriber) ProcessFromHeight(height *big.Int) error { ethClient, err := ethclient.Dial(s.nodeRPCURL) if err != nil { @@ -155,39 +158,43 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { return err } - // Filter logs from the latest processed block to the latest block - // Since initializationFilterQuery does not modify existing fields of warpFilterQuery, - // we can safely reuse warpFilterQuery with only a shallow copy - initializationFilterQuery := interfaces.FilterQuery{ - Topics: warpFilterQuery.Topics, - Addresses: warpFilterQuery.Addresses, - FromBlock: height, - } - logs, err := ethClient.FilterLogs(context.Background(), initializationFilterQuery) - if err != nil { - s.logger.Error( - "Failed to get logs on initialization", - zap.Error(err), - ) - return err - } - - // Queue each of the logs to be processed - s.logger.Info( - "Processing logs on initialization", - zap.String("fromBlockHeight", height.String()), - zap.String("toBlockHeight", strconv.Itoa(int(latestBlock))), - ) - for _, log := range logs { - messageInfo, err := s.NewWarpLogInfo(log) + // Only process logs if the provided height is not nil. Otherwise, simply update the database with + // the latest block height + if height != nil { + // Filter logs from the latest processed block to the latest block + // Since initializationFilterQuery does not modify existing fields of warpFilterQuery, + // we can safely reuse warpFilterQuery with only a shallow copy + initializationFilterQuery := interfaces.FilterQuery{ + Topics: warpFilterQuery.Topics, + Addresses: warpFilterQuery.Addresses, + FromBlock: height, + } + logs, err := ethClient.FilterLogs(context.Background(), initializationFilterQuery) if err != nil { s.logger.Error( - "Invalid log when processing from height. Continuing.", + "Failed to get logs on initialization", zap.Error(err), ) - continue + return err + } + + // Queue each of the logs to be processed + s.logger.Info( + "Processing logs on initialization", + zap.String("fromBlockHeight", height.String()), + zap.String("toBlockHeight", strconv.Itoa(int(latestBlock))), + ) + for _, log := range logs { + messageInfo, err := s.NewWarpLogInfo(log) + if err != nil { + s.logger.Error( + "Invalid log when processing from height. Continuing.", + zap.Error(err), + ) + continue + } + s.log <- *messageInfo } - s.log <- *messageInfo } // Update the database with the latest seen block height From 4e5419d72aac50e33a6e5db51c35f83aefef55c3 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Tue, 5 Sep 2023 21:46:53 +0000 Subject: [PATCH 26/49] consolidate endpoint methods --- config/config.go | 62 ++++++++++++++++++++++++++++++------------------ 1 file changed, 39 insertions(+), 23 deletions(-) diff --git a/config/config.go b/config/config.go index 08f12b82..d0b22057 100644 --- a/config/config.go +++ b/config/config.go @@ -274,7 +274,13 @@ func (s *DestinationSubnet) Validate() error { return nil } -func constructURL(protocol string, host string, port uint32, encrypt bool) string { +func constructURL(protocol string, host string, port uint32, encrypt bool, chainIDStr string, subnetIDStr string) string { + var protocolPathMap = map[string]string{ + "http": "rpc", + "ws": "ws", + } + path := protocolPathMap[protocol] + if encrypt { protocol = protocol + "s" } @@ -282,7 +288,11 @@ func constructURL(protocol string, host string, port uint32, encrypt bool) strin if port != 0 { portStr = fmt.Sprintf(":%d", port) } - return fmt.Sprintf("%s://%s%s", protocol, host, portStr) + subnetID, _ := ids.FromString(subnetIDStr) // already validated in Validate() + if subnetID == constants.PrimaryNetworkID { + chainIDStr = cChainIdentifierString + } + return fmt.Sprintf("%s://%s%s/ext/bc/%s/%s", protocol, host, portStr, chainIDStr, path) } // Constructs an RPC endpoint for the subnet. @@ -293,14 +303,16 @@ func (s *DestinationSubnet) GetNodeRPCEndpoint() string { if s.RPCEndpoint != "" { return s.RPCEndpoint } - baseUrl := constructURL("http", s.APINodeHost, s.APINodePort, s.EncryptConnection) - chainID := s.ChainID - subnetID, _ := ids.FromString(s.SubnetID) // already validated in Validate() - if subnetID == constants.PrimaryNetworkID { - chainID = cChainIdentifierString - } + // Save this result for future use - s.RPCEndpoint = fmt.Sprintf("%s/ext/bc/%s/rpc", baseUrl, chainID) + s.RPCEndpoint = constructURL( + "http", + s.APINodeHost, + s.APINodePort, + s.EncryptConnection, + s.ChainID, + s.SubnetID, + ) return s.RPCEndpoint } @@ -312,14 +324,16 @@ func (s *SourceSubnet) GetNodeRPCEndpoint() string { if s.RPCEndpoint != "" { return s.RPCEndpoint } - baseUrl := constructURL("http", s.APINodeHost, s.APINodePort, s.EncryptConnection) - chainID := s.ChainID - subnetID, _ := ids.FromString(s.SubnetID) // already validated in Validate() - if subnetID == constants.PrimaryNetworkID { - chainID = cChainIdentifierString - } + // Save this result for future use - s.RPCEndpoint = fmt.Sprintf("%s/ext/bc/%s/rpc", baseUrl, chainID) + s.RPCEndpoint = constructURL( + "http", + s.APINodeHost, + s.APINodePort, + s.EncryptConnection, + s.ChainID, + s.SubnetID, + ) return s.RPCEndpoint } @@ -331,14 +345,16 @@ func (s *SourceSubnet) GetNodeWSEndpoint() string { if s.WSEndpoint != "" { return s.WSEndpoint } - baseUrl := constructURL("ws", s.APINodeHost, s.APINodePort, s.EncryptConnection) - chainID := s.ChainID - subnetID, _ := ids.FromString(s.SubnetID) // already validated in Validate() - if subnetID == constants.PrimaryNetworkID { - chainID = cChainIdentifierString - } + // Save this result for future use - s.WSEndpoint = fmt.Sprintf("%s/ext/bc/%s/ws", baseUrl, chainID) + s.WSEndpoint = constructURL( + "ws", + s.APINodeHost, + s.APINodePort, + s.EncryptConnection, + s.ChainID, + s.SubnetID, + ) return s.WSEndpoint } From cf9a0e78ad9d3fb40d631a79cfc1d9c9e5a05f0a Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Tue, 5 Sep 2023 21:47:26 +0000 Subject: [PATCH 27/49] clean up comments --- database/json_file_storage.go | 18 +++++++++--------- relayer/relayer.go | 4 ++-- 2 files changed, 11 insertions(+), 11 deletions(-) diff --git a/database/json_file_storage.go b/database/json_file_storage.go index a967224b..5969b8d4 100644 --- a/database/json_file_storage.go +++ b/database/json_file_storage.go @@ -46,8 +46,8 @@ func NewJSONFileStorage(logger logging.Logger, dir string, networks []ids.ID) (* _, err := os.Stat(dir) if err == nil { - // dir already exist - // return the existing storage + // Directory already exists. + // Return the existing storage. return storage, nil } @@ -64,7 +64,7 @@ func NewJSONFileStorage(logger logging.Logger, dir string, networks []ids.ID) (* return storage, nil } -// Get the latest chain state from the json database, and retrieve the value from the key +// Get the latest chain state from the JSON database, and retrieve the value from the key func (s *JSONFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { mutex, ok := s.mutexes[chainID] if !ok { @@ -98,7 +98,7 @@ func (s *JSONFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { return []byte(val), nil } -// Put the value into the json database. Read the current chain state and overwrite the key, if it exists +// Put the value into the JSON database. Read the current chain state and overwrite the key, if it exists func (s *JSONFileStorage) Put(chainID ids.ID, key []byte, value []byte) error { mutex, ok := s.mutexes[chainID] if !ok { @@ -137,15 +137,15 @@ func (s *JSONFileStorage) write(network ids.ID, v interface{}) error { return err } - // write marshaled data to the temp file - // if write failed, the original file is not affected - // 0644 Only the owner can read and write. + // Write marshaled data to the temp file. + // If the write fails, the original file is not affected. + // Set file permissiones to 0644 so only the owner can read and write. // Everyone else can only read. No one can execute the file. if err := os.WriteFile(tmpPath, b, 0644); err != nil { return errors.Wrap(err, "failed to write file") } - // move final file into place + // Move final file into place if err := os.Rename(tmpPath, fnlPath); err != nil { return errors.Wrap(err, "failed to rename file") } @@ -176,7 +176,7 @@ func (s *JSONFileStorage) read(network ids.ID, v interface{}) (bool, error) { return false, errors.Wrap(err, "failed to read file") } - // unmarshal data + // Unmarshal data if err = json.Unmarshal(b, &v); err != nil { return false, errors.Wrap(err, "failed to unmarshal json file") } diff --git a/relayer/relayer.go b/relayer/relayer.go index f965db78..52835bb5 100644 --- a/relayer/relayer.go +++ b/relayer/relayer.go @@ -125,7 +125,7 @@ func NewRelayer( return nil, nil, err } - // Get the latest processed block height from the database. + // Get the latest seen block height from the database. var ( latestSeenBlockData []byte latestSeenBlock *big.Int // initialized to nil @@ -141,7 +141,7 @@ func NewRelayer( // If the database contains the latest seen block data, then back-process all warp messages from the // latest seen block to the latest block // This will query the node for any logs that match the filter query from the stored block height, - r.logger.Info("latest processed block", zap.String("block", string(latestSeenBlockData))) + r.logger.Info("latest seen block", zap.String("block", string(latestSeenBlockData))) var success bool latestSeenBlock, success = new(big.Int).SetString(string(latestSeenBlockData), 10) if !success { From 9fdd275538c3a1d61ff3f52467699680ff6c7a88 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Tue, 5 Sep 2023 21:47:32 +0000 Subject: [PATCH 28/49] rename var --- vms/evm/subscriber.go | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index f6304f12..52db2c08 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -53,7 +53,7 @@ type subscriber struct { nodeWSURL string nodeRPCURL string chainID ids.ID - log chan vmtypes.WarpLogInfo + logsChan chan vmtypes.WarpLogInfo evmLog <-chan types.Log sub interfaces.Subscription @@ -80,7 +80,7 @@ func NewSubscriber(logger logging.Logger, subnetInfo config.SourceSubnet, db dat chainID: chainID, logger: logger, db: db, - log: logs, + logsChan: logs, } } @@ -129,7 +129,7 @@ func (s *subscriber) forwardLogs() { ) continue } - s.log <- *messageInfo + s.logsChan <- *messageInfo // Update the database with the latest seen block height err = s.db.Put(s.chainID, []byte(database.LatestSeenBlockKey), []byte(strconv.FormatUint(msgLog.BlockNumber, 10))) @@ -161,7 +161,7 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { // Only process logs if the provided height is not nil. Otherwise, simply update the database with // the latest block height if height != nil { - // Filter logs from the latest processed block to the latest block + // Filter logs from the latest seen block to the latest block // Since initializationFilterQuery does not modify existing fields of warpFilterQuery, // we can safely reuse warpFilterQuery with only a shallow copy initializationFilterQuery := interfaces.FilterQuery{ @@ -193,7 +193,7 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { ) continue } - s.log <- *messageInfo + s.logsChan <- *messageInfo } } @@ -260,7 +260,7 @@ func (s *subscriber) dialAndSubscribe() error { } func (s *subscriber) Logs() <-chan vmtypes.WarpLogInfo { - return s.log + return s.logsChan } func (s *subscriber) Err() <-chan error { From 32146a487e42380464534e3107da8dd8586f9dc5 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Tue, 5 Sep 2023 22:05:24 +0000 Subject: [PATCH 29/49] cap the number of blocks to process on startup --- vms/evm/subscriber.go | 17 ++++++++++++++++- 1 file changed, 16 insertions(+), 1 deletion(-) diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index 52db2c08..038ebac6 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -29,6 +29,7 @@ const ( maxClientSubscriptionBuffer = 20000 subscribeRetryTimeout = 1 * time.Second maxResubscribeAttempts = 10 + MaxBlocksToProcess = 200 ) var ( @@ -142,6 +143,8 @@ func (s *subscriber) forwardLogs() { // Process logs from the given block height to the latest block // If height is nil, then simply store the latest block height in the database, // but do not process any logs +// Cap the number of blocks requested from the client to MaxBlocksToProcess, +// counting back from the current block. func (s *subscriber) ProcessFromHeight(height *big.Int) error { ethClient, err := ethclient.Dial(s.nodeRPCURL) if err != nil { @@ -161,6 +164,17 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { // Only process logs if the provided height is not nil. Otherwise, simply update the database with // the latest block height if height != nil { + // Cap the number of blocks to process to MaxBlocksToProcess + toBlock := big.NewInt(0).SetUint64(latestBlock) + if height.Cmp(big.NewInt(0).Add(toBlock, big.NewInt(-MaxBlocksToProcess))) < 0 { + s.logger.Warn( + fmt.Sprintf("Requested to process too many blocks. Processing only the most recent %s blocks", MaxBlocksToProcess), + zap.String("requestedBlockHeight", height.String()), + zap.String("latestBlockHeight", toBlock.String()), + ) + height = big.NewInt(0).Add(toBlock, big.NewInt(-MaxBlocksToProcess)) + } + // Filter logs from the latest seen block to the latest block // Since initializationFilterQuery does not modify existing fields of warpFilterQuery, // we can safely reuse warpFilterQuery with only a shallow copy @@ -168,6 +182,7 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { Topics: warpFilterQuery.Topics, Addresses: warpFilterQuery.Addresses, FromBlock: height, + ToBlock: toBlock, } logs, err := ethClient.FilterLogs(context.Background(), initializationFilterQuery) if err != nil { @@ -182,7 +197,7 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { s.logger.Info( "Processing logs on initialization", zap.String("fromBlockHeight", height.String()), - zap.String("toBlockHeight", strconv.Itoa(int(latestBlock))), + zap.String("toBlockHeight", toBlock.String()), ) for _, log := range logs { messageInfo, err := s.NewWarpLogInfo(log) From ce66b8227aea3f89ad2ba2a065edb726d922ae3d Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Tue, 5 Sep 2023 22:24:34 +0000 Subject: [PATCH 30/49] cleanup --- database/json_file_storage.go | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/database/json_file_storage.go b/database/json_file_storage.go index 5969b8d4..62b525a0 100644 --- a/database/json_file_storage.go +++ b/database/json_file_storage.go @@ -99,6 +99,7 @@ func (s *JSONFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { } // Put the value into the JSON database. Read the current chain state and overwrite the key, if it exists +// If the file corresponding to {chainID} does not exist, then it will be created func (s *JSONFileStorage) Put(chainID ids.ID, key []byte, value []byte) error { mutex, ok := s.mutexes[chainID] if !ok { @@ -128,8 +129,8 @@ func (s *JSONFileStorage) Put(chainID ids.ID, key []byte, value []byte) error { } // Write the value to the file. The caller is responsible for ensuring proper synchronization -func (s *JSONFileStorage) write(network ids.ID, v interface{}) error { - fnlPath := filepath.Join(s.dir, network.String()+".json") +func (s *JSONFileStorage) write(chainID ids.ID, v interface{}) error { + fnlPath := filepath.Join(s.dir, chainID.String()+".json") tmpPath := fnlPath + ".tmp" b, err := json.MarshalIndent(v, "", "\t") @@ -157,8 +158,8 @@ func (s *JSONFileStorage) write(network ids.ID, v interface{}) error { // Returns a bool indicating whether the file exists, and an error. // If an error is returned, the bool should be ignored. // The caller is responsible for ensuring proper synchronization -func (s *JSONFileStorage) read(network ids.ID, v interface{}) (bool, error) { - path := filepath.Join(s.dir, network.String()+".json") +func (s *JSONFileStorage) read(chainID ids.ID, v interface{}) (bool, error) { + path := filepath.Join(s.dir, chainID.String()+".json") // If the file does not exist, return false, but do not return an error as this // is an expected case From e012c4ebcdab1e822f058f2ee5b5a523fe07bf6d Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Tue, 5 Sep 2023 22:24:44 +0000 Subject: [PATCH 31/49] refactor subscriber interface --- relayer/relayer.go | 44 ++++++++++------- vms/evm/subscriber.go | 109 +++++++++++++++++++++++++----------------- vms/subscriber.go | 3 ++ 3 files changed, 94 insertions(+), 62 deletions(-) diff --git a/relayer/relayer.go b/relayer/relayer.go index 52835bb5..7bd38059 100644 --- a/relayer/relayer.go +++ b/relayer/relayer.go @@ -126,11 +126,7 @@ func NewRelayer( } // Get the latest seen block height from the database. - var ( - latestSeenBlockData []byte - latestSeenBlock *big.Int // initialized to nil - ) - latestSeenBlockData, err = r.db.Get(r.sourceChainID, []byte(database.LatestSeenBlockKey)) + latestSeenBlockData, err := r.db.Get(r.sourceChainID, []byte(database.LatestSeenBlockKey)) // The following cases are treated as successful: // 1) The database contains the latest seen block data for the chain @@ -142,12 +138,21 @@ func NewRelayer( // latest seen block to the latest block // This will query the node for any logs that match the filter query from the stored block height, r.logger.Info("latest seen block", zap.String("block", string(latestSeenBlockData))) - var success bool - latestSeenBlock, success = new(big.Int).SetString(string(latestSeenBlockData), 10) + latestSeenBlock, success := new(big.Int).SetString(string(latestSeenBlockData), 10) if !success { r.logger.Error("failed to convert latest block to big.Int", zap.Error(err)) return nil, nil, err } + + err = sub.ProcessFromHeight(latestSeenBlock) + if err != nil { + logger.Warn( + "Encountered an error when processing historical blocks. Continuing to normal relaying operation.", + zap.String("chainID", r.sourceChainID.String()), + zap.Error(err), + ) + } + return &r, sub, nil } else if errors.Is(err, database.ErrChainNotFound) || errors.Is(err, database.ErrKeyNotFound) { // Otherwise, latestSeenBlock is nil, so the call to ProcessFromHeight will simply update the database with the // latest block height @@ -155,21 +160,24 @@ func NewRelayer( "Latest seen block not found in database. Starting from latest block.", zap.String("chainID", r.sourceChainID.String()), ) - } else { - r.logger.Warn("failed to get latest block from database", zap.Error(err)) - return nil, nil, err - } - // Process historical logs. If this fails for any reason, continue with normal relayer operation, but log the error. - err = sub.ProcessFromHeight(latestSeenBlock) - if err != nil { - logger.Warn( - "Encountered an error when processing historical blocks. Continuing to normal relaying operation.", + err := sub.UpdateLatestSeenBlock() + if err != nil { + logger.Warn( + "Failed to update latest seen block. Continuing to normal relaying operation", + zap.String("chainID", r.sourceChainID.String()), + zap.Error(err), + ) + } + return &r, sub, nil + } else { + r.logger.Warn( + "failed to get latest block from database", + zap.String("chainID", r.sourceChainID.String()), zap.Error(err), ) + return nil, nil, err } - - return &r, sub, nil } // RouteToMessageChannel forwards inbound app messages from the per-subnet responseChan to the per-message messageResponseChan diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index 038ebac6..24c61e5e 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -141,11 +141,12 @@ func (s *subscriber) forwardLogs() { } // Process logs from the given block height to the latest block -// If height is nil, then simply store the latest block height in the database, -// but do not process any logs // Cap the number of blocks requested from the client to MaxBlocksToProcess, // counting back from the current block. func (s *subscriber) ProcessFromHeight(height *big.Int) error { + if height == nil { + return fmt.Errorf("cannot process logs from nil height") + } ethClient, err := ethclient.Dial(s.nodeRPCURL) if err != nil { return err @@ -161,58 +162,78 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { return err } - // Only process logs if the provided height is not nil. Otherwise, simply update the database with - // the latest block height - if height != nil { - // Cap the number of blocks to process to MaxBlocksToProcess - toBlock := big.NewInt(0).SetUint64(latestBlock) - if height.Cmp(big.NewInt(0).Add(toBlock, big.NewInt(-MaxBlocksToProcess))) < 0 { - s.logger.Warn( - fmt.Sprintf("Requested to process too many blocks. Processing only the most recent %s blocks", MaxBlocksToProcess), - zap.String("requestedBlockHeight", height.String()), - zap.String("latestBlockHeight", toBlock.String()), - ) - height = big.NewInt(0).Add(toBlock, big.NewInt(-MaxBlocksToProcess)) - } + // Cap the number of blocks to process to MaxBlocksToProcess + toBlock := big.NewInt(0).SetUint64(latestBlock) + if height.Cmp(big.NewInt(0).Add(toBlock, big.NewInt(-MaxBlocksToProcess))) < 0 { + s.logger.Warn( + fmt.Sprintf("Requested to process too many blocks. Processing only the most recent %s blocks", MaxBlocksToProcess), + zap.String("requestedBlockHeight", height.String()), + zap.String("latestBlockHeight", toBlock.String()), + ) + height = big.NewInt(0).Add(toBlock, big.NewInt(-MaxBlocksToProcess)) + } - // Filter logs from the latest seen block to the latest block - // Since initializationFilterQuery does not modify existing fields of warpFilterQuery, - // we can safely reuse warpFilterQuery with only a shallow copy - initializationFilterQuery := interfaces.FilterQuery{ - Topics: warpFilterQuery.Topics, - Addresses: warpFilterQuery.Addresses, - FromBlock: height, - ToBlock: toBlock, - } - logs, err := ethClient.FilterLogs(context.Background(), initializationFilterQuery) + // Filter logs from the latest seen block to the latest block + // Since initializationFilterQuery does not modify existing fields of warpFilterQuery, + // we can safely reuse warpFilterQuery with only a shallow copy + initializationFilterQuery := interfaces.FilterQuery{ + Topics: warpFilterQuery.Topics, + Addresses: warpFilterQuery.Addresses, + FromBlock: height, + ToBlock: toBlock, + } + logs, err := ethClient.FilterLogs(context.Background(), initializationFilterQuery) + if err != nil { + s.logger.Error( + "Failed to get logs on initialization", + zap.Error(err), + ) + return err + } + + // Queue each of the logs to be processed + s.logger.Info( + "Processing logs on initialization", + zap.String("fromBlockHeight", height.String()), + zap.String("toBlockHeight", toBlock.String()), + ) + for _, log := range logs { + messageInfo, err := s.NewWarpLogInfo(log) if err != nil { s.logger.Error( - "Failed to get logs on initialization", + "Invalid log when processing from height. Continuing.", zap.Error(err), ) - return err + continue } + s.logsChan <- *messageInfo + } - // Queue each of the logs to be processed - s.logger.Info( - "Processing logs on initialization", - zap.String("fromBlockHeight", height.String()), - zap.String("toBlockHeight", toBlock.String()), + // Update the database with the latest seen block height + err = s.db.Put(s.chainID, []byte(database.LatestSeenBlockKey), []byte(strconv.FormatUint(latestBlock, 10))) + if err != nil { + s.logger.Error(fmt.Sprintf("failed to put %s into database", database.LatestSeenBlockKey), zap.Error(err)) + return err + } + return nil +} + +func (s *subscriber) UpdateLatestSeenBlock() error { + ethClient, err := ethclient.Dial(s.nodeRPCURL) + if err != nil { + return err + } + + // Grab the latest block before filtering logs so we don't miss any before updating the db + latestBlock, err := ethClient.BlockNumber(context.Background()) + if err != nil { + s.logger.Error( + "Failed to get latest block", + zap.Error(err), ) - for _, log := range logs { - messageInfo, err := s.NewWarpLogInfo(log) - if err != nil { - s.logger.Error( - "Invalid log when processing from height. Continuing.", - zap.Error(err), - ) - continue - } - s.logsChan <- *messageInfo - } + return err } - // Update the database with the latest seen block height err = s.db.Put(s.chainID, []byte(database.LatestSeenBlockKey), []byte(strconv.FormatUint(latestBlock, 10))) if err != nil { s.logger.Error(fmt.Sprintf("failed to put %s into database", database.LatestSeenBlockKey), zap.Error(err)) diff --git a/vms/subscriber.go b/vms/subscriber.go index bb79dc39..461a19e3 100644 --- a/vms/subscriber.go +++ b/vms/subscriber.go @@ -18,6 +18,9 @@ type Subscriber interface { // ProcessFromHeight processes events from {height} to the latest block ProcessFromHeight(height *big.Int) error + // UpdateLatestSeenBlock retreives the latest block from the chain and updates the database + UpdateLatestSeenBlock() error + // Subscribe registers a subscription. After Subscribe is called, // log events that match [filter] are written to the channel returned // by Logs From 44384ca77c0e10fc6945407f9b1adc3ebccd2444 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Tue, 5 Sep 2023 22:31:31 +0000 Subject: [PATCH 32/49] fix test --- vms/evm/subscriber.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index 24c61e5e..0a267bb0 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -166,7 +166,7 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { toBlock := big.NewInt(0).SetUint64(latestBlock) if height.Cmp(big.NewInt(0).Add(toBlock, big.NewInt(-MaxBlocksToProcess))) < 0 { s.logger.Warn( - fmt.Sprintf("Requested to process too many blocks. Processing only the most recent %s blocks", MaxBlocksToProcess), + fmt.Sprintf("Requested to process too many blocks. Processing only the most recent %d blocks", MaxBlocksToProcess), zap.String("requestedBlockHeight", height.String()), zap.String("latestBlockHeight", toBlock.String()), ) From e9c0b019ddef068f20201913d70439a7ba6563af Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Wed, 6 Sep 2023 00:25:32 +0000 Subject: [PATCH 33/49] use Int:Sub --- vms/evm/subscriber.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index 0a267bb0..0a6e6c31 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -164,7 +164,7 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { // Cap the number of blocks to process to MaxBlocksToProcess toBlock := big.NewInt(0).SetUint64(latestBlock) - if height.Cmp(big.NewInt(0).Add(toBlock, big.NewInt(-MaxBlocksToProcess))) < 0 { + if height.Cmp(big.NewInt(0).Sub(toBlock, big.NewInt(MaxBlocksToProcess))) < 0 { s.logger.Warn( fmt.Sprintf("Requested to process too many blocks. Processing only the most recent %d blocks", MaxBlocksToProcess), zap.String("requestedBlockHeight", height.String()), From 878d4c65b00822ecc93af1af8922c22404e03a98 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Wed, 6 Sep 2023 21:07:45 +0000 Subject: [PATCH 34/49] process logs in serial for each source chain --- main/main.go | 14 +----- peers/external_handler.go | 13 +---- relayer/message_relayer.go | 14 +++--- relayer/relayer.go | 94 +++++++++++++------------------------ vms/evm/subscriber.go | 13 +---- vms/subscriber.go | 4 +- vms/vmtypes/message_info.go | 1 + 7 files changed, 47 insertions(+), 106 deletions(-) diff --git a/main/main.go b/main/main.go index 9661fc7b..1ef2d638 100644 --- a/main/main.go +++ b/main/main.go @@ -31,9 +31,8 @@ import ( ) const ( - defaultErrorChanSize = 1000 - defaultApiPort = 8080 - defaultMetricsPort = 9090 + defaultApiPort = 8080 + defaultMetricsPort = 9090 ) func main() { @@ -203,13 +202,11 @@ func runRelayer(logger logging.Logger, "Creating relayer", zap.String("chainID", sourceSubnetInfo.ChainID), ) - errorChan := make(chan error, defaultErrorChanSize) relayer, subscriber, err := relayer.NewRelayer( logger, db, sourceSubnetInfo, - errorChan, pChainClient, network, responseChan, @@ -265,13 +262,6 @@ func runRelayer(logger logging.Logger, ) return } - case err := <-errorChan: - logger.Error( - "Relayer goroutine stopped with error. Relayer goroutine exiting.", - zap.String("originChainID", sourceSubnetInfo.ChainID), - zap.Error(err), - ) - return } } } diff --git a/peers/external_handler.go b/peers/external_handler.go index 718ad10f..f7352902 100644 --- a/peers/external_handler.go +++ b/peers/external_handler.go @@ -71,17 +71,8 @@ func NewRelayerExternalHandler( // async, we must call OnFinishedHandling manually across all code paths. // // This diagram illustrates how HandleInbound forwards relevant AppResponses to the corresponding Teleporter message relayer. -// On startup, one TeleporterRelayer goroutine is created per source subnet, which listens to the subscriber for cross-chain messages -// When a cross-chain message is picked up by a TeleporterRelayer, a teleporterMessageRelayer goroutine is created and closed -// once the cross-chain message is delivered. Messages are routed through the resulting tree structure: -// -// TeleporterRelayer/source subnet teleporterMessageRelayer/Teleporter message -// -// { TeleporterRelayer.responseChan --... { teleporterMessageRelayer.messageResponseChan (consumer) -// HandleInbound (producer) --->{ TeleporterRelayer.responseChan ------>{ teleporterMessageRelayer.messageResponseChan (consumer) -// { ... { ... -// { TeleporterRelayer.responseChan --... { teleporterMessageRelayer.messageResponseChan (consumer) - +// On startup, one Relayer goroutine is created per source subnet, which listens to the subscriber for cross-chain messages +// When a cross-chain message is picked up by a Relayer, HandleInbound routes AppResponses traffic to the appropriate Relayer func (h *RelayerExternalHandler) HandleInbound(_ context.Context, inboundMessage message.InboundMessage) { h.log.Debug( "receiving message", diff --git a/relayer/message_relayer.go b/relayer/message_relayer.go index 4d6dc0af..fed37c21 100644 --- a/relayer/message_relayer.go +++ b/relayer/message_relayer.go @@ -76,7 +76,7 @@ func newMessageRelayer( } } -func (r *messageRelayer) run(warpMessageInfo *vmtypes.WarpMessageInfo, requestID uint32, messageManager messages.MessageManager) { +func (r *messageRelayer) relayMessage(warpMessageInfo *vmtypes.WarpMessageInfo, requestID uint32, messageManager messages.MessageManager) error { shouldSend, err := messageManager.ShouldSendMessage(warpMessageInfo, r.destinationChainID) if err != nil { r.logger.Error( @@ -86,12 +86,11 @@ func (r *messageRelayer) run(warpMessageInfo *vmtypes.WarpMessageInfo, requestID r.incFailedRelayMessageCount("failed to check if message should be sent") - r.relayer.errorChan <- err - return + return err } if !shouldSend { r.logger.Info("Message should not be sent") - return + return nil } startCreateSignedMessageTime := time.Now() @@ -103,8 +102,7 @@ func (r *messageRelayer) run(warpMessageInfo *vmtypes.WarpMessageInfo, requestID zap.Error(err), ) r.incFailedRelayMessageCount("failed to create signed warp message") - r.relayer.errorChan <- err - return + return err } // create signed message latency (ms) @@ -117,14 +115,14 @@ func (r *messageRelayer) run(warpMessageInfo *vmtypes.WarpMessageInfo, requestID zap.Error(err), ) r.incFailedRelayMessageCount("failed to send warp message") - r.relayer.errorChan <- err - return + return err } r.logger.Info( "Finished relaying message to destination chain", zap.String("destinationChainID", r.destinationChainID.String()), ) r.incSuccessfulRelayMessageCount() + return nil } // Run collects signatures from nodes by directly querying them via AppRequest, then aggregates the signatures, and constructs the signed warp message. diff --git a/relayer/relayer.go b/relayer/relayer.go index 7bd38059..e684eb11 100644 --- a/relayer/relayer.go +++ b/relayer/relayer.go @@ -5,9 +5,10 @@ package relayer import ( "errors" + "fmt" "math/big" "math/rand" - "sync" + "strconv" "github.com/ava-labs/avalanchego/ids" "github.com/ava-labs/avalanchego/message" @@ -31,10 +32,7 @@ type Relayer struct { network *peers.AppRequestNetwork sourceSubnetID ids.ID sourceChainID ids.ID - responseChan <-chan message.InboundMessage - messageChanLock *sync.RWMutex - messageChanMap map[uint32]chan message.InboundMessage - errorChan chan error + responseChan chan message.InboundMessage contractMessage vms.ContractMessage messageManagers map[common.Hash]messages.MessageManager logger logging.Logger @@ -45,7 +43,6 @@ func NewRelayer( logger logging.Logger, db database.RelayerDatabase, sourceSubnetInfo config.SourceSubnet, - errorChan chan error, pChainClient platformvm.Client, network *peers.AppRequestNetwork, responseChan chan message.InboundMessage, @@ -102,18 +99,12 @@ func NewRelayer( sourceSubnetID: subnetID, sourceChainID: chainID, responseChan: responseChan, - messageChanLock: new(sync.RWMutex), - messageChanMap: make(map[uint32]chan message.InboundMessage), - errorChan: errorChan, contractMessage: vms.NewContractMessage(logger, sourceSubnetInfo), messageManagers: messageManagers, logger: logger, db: db, } - // Start the message router. We must do this before Subscribing or Initializing for the first time, otherwise we may miss an incoming message - go r.RouteToMessageChannel() - // Open the subscription. We must do this before processing any missed messages, otherwise we may miss an incoming message // in between fetching the latest block and subscribing. err = sub.Subscribe() @@ -153,7 +144,8 @@ func NewRelayer( ) } return &r, sub, nil - } else if errors.Is(err, database.ErrChainNotFound) || errors.Is(err, database.ErrKeyNotFound) { + } + if errors.Is(err, database.ErrChainNotFound) || errors.Is(err, database.ErrKeyNotFound) { // Otherwise, latestSeenBlock is nil, so the call to ProcessFromHeight will simply update the database with the // latest block height logger.Info( @@ -170,36 +162,15 @@ func NewRelayer( ) } return &r, sub, nil - } else { - r.logger.Warn( - "failed to get latest block from database", - zap.String("chainID", r.sourceChainID.String()), - zap.Error(err), - ) - return nil, nil, err } -} -// RouteToMessageChannel forwards inbound app messages from the per-subnet responseChan to the per-message messageResponseChan -// The messageResponseChan to forward to is determined by the requestID, which is unique to each message relayer goroutine -// If the requestID has not been added to the map, then the message is dropped. -func (r *Relayer) RouteToMessageChannel() { - for response := range r.responseChan { - m := response.Message() - requestID, ok := message.GetRequestID(m) - if !ok { - response.OnFinishedHandling() - return - } - r.messageChanLock.RLock() - messageResponseChan, ok := r.messageChanMap[requestID] - r.messageChanLock.RUnlock() - if ok { - messageResponseChan <- response - } else { - response.OnFinishedHandling() - } - } + // If neither of the above conditions are met, then we return an error + r.logger.Warn( + "failed to get latest block from database", + zap.String("chainID", r.sourceChainID.String()), + zap.Error(err), + ) + return nil, nil, err } // RelayMessage relays a single warp message to the destination chain. Warp message relay requests are concurrent with each other, @@ -227,20 +198,11 @@ func (r *Relayer) RelayMessage(warpLogInfo *vmtypes.WarpLogInfo, metrics *Messag return nil } - requestID := r.getAndIncrementRequestID() - - // Add an element to the inbound messages map, keyed by the requestID - // This allows RouteToMessageChannel to forward inbound messages to the correct channel - // Note: It's technically possible to block indefinitely here if the inbound handler is processing an flood of non-relevant app responses. This would occur if - // the RLocks are acquired more quickly than they are released in RouteToMessageChannel. However, given that inbound messages are rate limited and that the - // RLock is only held for a single map access, this is likely not something we need to worry about in practice. - messageResponseChan := make(chan message.InboundMessage, peers.InboundMessageChannelSize) - r.messageChanLock.Lock() - r.messageChanMap[requestID] = messageResponseChan - r.messageChanLock.Unlock() + // Increment the request ID to use for this message + r.currentRequestID++ // Create and run the message relayer to attempt to deliver the message to the destination chain - messageRelayer := newMessageRelayer(r.logger, metrics, r, warpMessageInfo.WarpUnsignedMessage, warpLogInfo.DestinationChainID, messageResponseChan, messageCreator) + messageRelayer := newMessageRelayer(r.logger, metrics, r, warpMessageInfo.WarpUnsignedMessage, warpLogInfo.DestinationChainID, r.responseChan, messageCreator) if err != nil { r.logger.Error( "Failed to create message relayer", @@ -249,15 +211,23 @@ func (r *Relayer) RelayMessage(warpLogInfo *vmtypes.WarpLogInfo, metrics *Messag return err } - go messageRelayer.run(warpMessageInfo, requestID, messageManager) + // Relay the message to the destination. Messages from a given source chain must be processed in serial in order to + // guarantee that the previous block (n-1) is fully processed by the relayer when processing a given log from block n. + err = messageRelayer.relayMessage(warpMessageInfo, r.currentRequestID, messageManager) + if err != nil { + r.logger.Error( + "Failed to run message relayer", + zap.Error(err), + ) + return err + } - return nil -} + // Update the database with the latest seen block height + // We cannot store the latest processed block height, because we do not know if a given log is the last log in a block + err = r.db.Put(r.sourceChainID, []byte(database.LatestSeenBlockKey), []byte(strconv.FormatUint(warpLogInfo.BlockNumber, 10))) + if err != nil { + r.logger.Error(fmt.Sprintf("failed to put %s into database", database.LatestSeenBlockKey), zap.Error(err)) + } -// Get the current app request ID and increment it. Request IDs need to be unique to each teleporter message, but the specific values do not matter. -// This should only be called by the subnet-level TeleporterRelayer, and not by the goroutines that handle individual teleporter messages -func (r *Relayer) getAndIncrementRequestID() uint32 { - id := r.currentRequestID - r.currentRequestID++ - return id + return nil } diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index 0a6e6c31..bfdf4d50 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -116,6 +116,7 @@ func (s *subscriber) NewWarpLogInfo(log types.Log) (*vmtypes.WarpLogInfo, error) SourceAddress: log.Topics[3], SourceTxID: log.TxHash[:], UnsignedMsgBytes: log.Data, + BlockNumber: log.BlockNumber, }, nil } @@ -131,12 +132,6 @@ func (s *subscriber) forwardLogs() { continue } s.logsChan <- *messageInfo - - // Update the database with the latest seen block height - err = s.db.Put(s.chainID, []byte(database.LatestSeenBlockKey), []byte(strconv.FormatUint(msgLog.BlockNumber, 10))) - if err != nil { - s.logger.Error(fmt.Sprintf("failed to put %s into database", database.LatestSeenBlockKey), zap.Error(err)) - } } } @@ -209,12 +204,6 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { s.logsChan <- *messageInfo } - // Update the database with the latest seen block height - err = s.db.Put(s.chainID, []byte(database.LatestSeenBlockKey), []byte(strconv.FormatUint(latestBlock, 10))) - if err != nil { - s.logger.Error(fmt.Sprintf("failed to put %s into database", database.LatestSeenBlockKey), zap.Error(err)) - return err - } return nil } diff --git a/vms/subscriber.go b/vms/subscriber.go index 461a19e3..519a7721 100644 --- a/vms/subscriber.go +++ b/vms/subscriber.go @@ -13,7 +13,9 @@ import ( "github.com/ava-labs/awm-relayer/vms/vmtypes" ) -// Subscriber subscribes to VM events containing Warp message data +// Subscriber subscribes to VM events containing Warp message data. The events written to the +// channel returned by Logs() are assumed to be in block order. Logs within individual blocks +// may be in any order. type Subscriber interface { // ProcessFromHeight processes events from {height} to the latest block ProcessFromHeight(height *big.Int) error diff --git a/vms/vmtypes/message_info.go b/vms/vmtypes/message_info.go index e529df32..b54da2b5 100644 --- a/vms/vmtypes/message_info.go +++ b/vms/vmtypes/message_info.go @@ -17,4 +17,5 @@ type WarpLogInfo struct { DestinationAddress common.Hash SourceTxID []byte UnsignedMsgBytes []byte + BlockNumber uint64 } From 85cf76ce02eaa2db6128742de4b8f8132123873c Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Wed, 6 Sep 2023 21:19:06 +0000 Subject: [PATCH 35/49] return nil error in success case --- vms/evm/contract_message.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/vms/evm/contract_message.go b/vms/evm/contract_message.go index ed95e374..d4441352 100644 --- a/vms/evm/contract_message.go +++ b/vms/evm/contract_message.go @@ -53,5 +53,5 @@ func (m *contractMessage) UnpackWarpMessage(unsignedMsgBytes []byte) (*vmtypes.W WarpUnsignedMessage: unsignedMsg, WarpPayload: warpPayload.Payload, } - return &messageInfo, err + return &messageInfo, nil } From 813a8e925230236fc83cb38f4cd80e20ebe7af37 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Wed, 6 Sep 2023 21:34:42 +0000 Subject: [PATCH 36/49] remove irrelevant comment --- vms/evm/subscriber.go | 1 - 1 file changed, 1 deletion(-) diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index bfdf4d50..9c6fa095 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -213,7 +213,6 @@ func (s *subscriber) UpdateLatestSeenBlock() error { return err } - // Grab the latest block before filtering logs so we don't miss any before updating the db latestBlock, err := ethClient.BlockNumber(context.Background()) if err != nil { s.logger.Error( From fde1675f37f474ca84e055ea27d0f16cc8f141e6 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Thu, 7 Sep 2023 15:09:40 +0000 Subject: [PATCH 37/49] improve logs --- relayer/relayer.go | 19 ++++++++++++++++--- vms/evm/subscriber.go | 33 +++++++++++++++++++++++++++++++-- 2 files changed, 47 insertions(+), 5 deletions(-) diff --git a/relayer/relayer.go b/relayer/relayer.go index e684eb11..2c1e4ddb 100644 --- a/relayer/relayer.go +++ b/relayer/relayer.go @@ -128,7 +128,6 @@ func NewRelayer( // If the database contains the latest seen block data, then back-process all warp messages from the // latest seen block to the latest block // This will query the node for any logs that match the filter query from the stored block height, - r.logger.Info("latest seen block", zap.String("block", string(latestSeenBlockData))) latestSeenBlock, success := new(big.Int).SetString(string(latestSeenBlockData), 10) if !success { r.logger.Error("failed to convert latest block to big.Int", zap.Error(err)) @@ -176,6 +175,11 @@ func NewRelayer( // RelayMessage relays a single warp message to the destination chain. Warp message relay requests are concurrent with each other, // and synchronized by relayer. func (r *Relayer) RelayMessage(warpLogInfo *vmtypes.WarpLogInfo, metrics *MessageRelayerMetrics, messageCreator message.Creator) error { + r.logger.Info( + "Relaying message", + zap.String("chainID", r.sourceChainID.String()), + ) + // Unpack the VM message bytes into a Warp message warpMessageInfo, err := r.contractMessage.UnpackWarpMessage(warpLogInfo.UnsignedMsgBytes) if err != nil { @@ -186,13 +190,19 @@ func (r *Relayer) RelayMessage(warpLogInfo *vmtypes.WarpLogInfo, metrics *Messag return err } + r.logger.Info( + "Unpacked warp message", + zap.String("chainID", r.sourceChainID.String()), + zap.String("warpMessageID", warpMessageInfo.WarpUnsignedMessage.ID().String()), + ) + // Check that the warp message is from a support message protocol contract address. messageManager, supportedMessageProtocol := r.messageManagers[warpLogInfo.SourceAddress] if !supportedMessageProtocol { // Do not return an error here because it is expected for there to be messages from other contracts // than just the ones supported by a single relayer instance. r.logger.Debug( - "Warp message from unsupported message protocol address. not relaying.", + "Warp message from unsupported message protocol address. Not relaying.", zap.String("protocolAddress", warpLogInfo.SourceAddress.Hex()), ) return nil @@ -217,6 +227,8 @@ func (r *Relayer) RelayMessage(warpLogInfo *vmtypes.WarpLogInfo, metrics *Messag if err != nil { r.logger.Error( "Failed to run message relayer", + zap.String("chainID", r.sourceChainID.String()), + zap.String("warpMessageID", warpMessageInfo.WarpUnsignedMessage.ID().String()), zap.Error(err), ) return err @@ -226,7 +238,8 @@ func (r *Relayer) RelayMessage(warpLogInfo *vmtypes.WarpLogInfo, metrics *Messag // We cannot store the latest processed block height, because we do not know if a given log is the last log in a block err = r.db.Put(r.sourceChainID, []byte(database.LatestSeenBlockKey), []byte(strconv.FormatUint(warpLogInfo.BlockNumber, 10))) if err != nil { - r.logger.Error(fmt.Sprintf("failed to put %s into database", database.LatestSeenBlockKey), zap.Error(err)) + r.logger.Error( + fmt.Sprintf("failed to put %s into database", database.LatestSeenBlockKey), zap.Error(err)) } return nil diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index 9c6fa095..6be3ecda 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -139,6 +139,11 @@ func (s *subscriber) forwardLogs() { // Cap the number of blocks requested from the client to MaxBlocksToProcess, // counting back from the current block. func (s *subscriber) ProcessFromHeight(height *big.Int) error { + s.logger.Info( + "Processing historical logs", + zap.String("fromBlockHeight", height.String()), + zap.String("chainID", s.chainID.String()), + ) if height == nil { return fmt.Errorf("cannot process logs from nil height") } @@ -152,6 +157,7 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { if err != nil { s.logger.Error( "Failed to get latest block", + zap.String("chainID", s.chainID.String()), zap.Error(err), ) return err @@ -164,6 +170,7 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { fmt.Sprintf("Requested to process too many blocks. Processing only the most recent %d blocks", MaxBlocksToProcess), zap.String("requestedBlockHeight", height.String()), zap.String("latestBlockHeight", toBlock.String()), + zap.String("chainID", s.chainID.String()), ) height = big.NewInt(0).Add(toBlock, big.NewInt(-MaxBlocksToProcess)) } @@ -181,6 +188,7 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { if err != nil { s.logger.Error( "Failed to get logs on initialization", + zap.String("chainID", s.chainID.String()), zap.Error(err), ) return err @@ -191,12 +199,14 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { "Processing logs on initialization", zap.String("fromBlockHeight", height.String()), zap.String("toBlockHeight", toBlock.String()), + zap.String("chainID", s.chainID.String()), ) for _, log := range logs { messageInfo, err := s.NewWarpLogInfo(log) if err != nil { s.logger.Error( "Invalid log when processing from height. Continuing.", + zap.String("chainID", s.chainID.String()), zap.Error(err), ) continue @@ -208,8 +218,17 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { } func (s *subscriber) UpdateLatestSeenBlock() error { + s.logger.Info( + "Updating latest seen block in database", + zap.String("chainID", s.chainID.String()), + ) ethClient, err := ethclient.Dial(s.nodeRPCURL) if err != nil { + s.logger.Error( + "Failed to dial node", + zap.String("chainID", s.chainID.String()), + zap.Error(err), + ) return err } @@ -217,6 +236,7 @@ func (s *subscriber) UpdateLatestSeenBlock() error { if err != nil { s.logger.Error( "Failed to get latest block", + zap.String("chainID", s.chainID.String()), zap.Error(err), ) return err @@ -224,7 +244,11 @@ func (s *subscriber) UpdateLatestSeenBlock() error { err = s.db.Put(s.chainID, []byte(database.LatestSeenBlockKey), []byte(strconv.FormatUint(latestBlock, 10))) if err != nil { - s.logger.Error(fmt.Sprintf("failed to put %s into database", database.LatestSeenBlockKey), zap.Error(err)) + s.logger.Error( + fmt.Sprintf("failed to put %s into database", + zap.String("chainID", s.chainID.String()), + database.LatestSeenBlockKey), zap.Error(err), + ) return err } return nil @@ -240,13 +264,17 @@ func (s *subscriber) Subscribe() error { } err := s.dialAndSubscribe() if err == nil { - s.logger.Info("Successfully subscribed") + s.logger.Info( + "Successfully subscribed", + zap.String("chainID", s.chainID.String()), + ) return nil } s.logger.Warn( "Failed to subscribe to node", zap.Int("attempt", attempt), + zap.String("chainID", s.chainID.String()), zap.Error(err), ) @@ -271,6 +299,7 @@ func (s *subscriber) dialAndSubscribe() error { if err != nil { s.logger.Error( "Failed to subscribe to logs", + zap.String("chainID", s.chainID.String()), zap.Error(err), ) return err From c4e36bd4647b158c4d8ed9c4f7649b19bdfd4750 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Thu, 7 Sep 2023 15:11:32 +0000 Subject: [PATCH 38/49] sort logs from eth_getLogs --- vms/evm/subscriber.go | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index 6be3ecda..ddf0f5b5 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -8,6 +8,7 @@ import ( "errors" "fmt" "math/big" + "sort" "strconv" "time" @@ -194,6 +195,14 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { return err } + // Sort the logs in ascending block order. Order logs by index within blocks + sort.SliceStable(logs, func(i, j int) bool { + if logs[i].BlockNumber == logs[j].BlockNumber { + return logs[i].TxIndex < logs[j].TxIndex + } + return logs[i].BlockNumber < logs[j].BlockNumber + }) + // Queue each of the logs to be processed s.logger.Info( "Processing logs on initialization", From b8902c564080e8e231fb804c4d9b1b2edae7c765 Mon Sep 17 00:00:00 2001 From: cam-schultz Date: Thu, 7 Sep 2023 15:25:48 +0000 Subject: [PATCH 39/49] fix logs --- relayer/relayer.go | 4 +++- vms/evm/subscriber.go | 6 +++--- 2 files changed, 6 insertions(+), 4 deletions(-) diff --git a/relayer/relayer.go b/relayer/relayer.go index 2c1e4ddb..50921825 100644 --- a/relayer/relayer.go +++ b/relayer/relayer.go @@ -239,7 +239,9 @@ func (r *Relayer) RelayMessage(warpLogInfo *vmtypes.WarpLogInfo, metrics *Messag err = r.db.Put(r.sourceChainID, []byte(database.LatestSeenBlockKey), []byte(strconv.FormatUint(warpLogInfo.BlockNumber, 10))) if err != nil { r.logger.Error( - fmt.Sprintf("failed to put %s into database", database.LatestSeenBlockKey), zap.Error(err)) + fmt.Sprintf("failed to put %s into database", database.LatestSeenBlockKey), + zap.Error(err), + ) } return nil diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index ddf0f5b5..1faa3d10 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -254,9 +254,9 @@ func (s *subscriber) UpdateLatestSeenBlock() error { err = s.db.Put(s.chainID, []byte(database.LatestSeenBlockKey), []byte(strconv.FormatUint(latestBlock, 10))) if err != nil { s.logger.Error( - fmt.Sprintf("failed to put %s into database", - zap.String("chainID", s.chainID.String()), - database.LatestSeenBlockKey), zap.Error(err), + fmt.Sprintf("failed to put %s into database", database.LatestSeenBlockKey), + zap.String("chainID", s.chainID.String()), + zap.Error(err), ) return err } From 9bda67347aec5152b8af027c1acd6c279d3b68d7 Mon Sep 17 00:00:00 2001 From: Cameron Schultz Date: Mon, 11 Sep 2023 17:38:17 -0500 Subject: [PATCH 40/49] sort by log index --- vms/evm/subscriber.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index 1faa3d10..8349a231 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -198,7 +198,7 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { // Sort the logs in ascending block order. Order logs by index within blocks sort.SliceStable(logs, func(i, j int) bool { if logs[i].BlockNumber == logs[j].BlockNumber { - return logs[i].TxIndex < logs[j].TxIndex + return logs[i].Index < logs[j].Index } return logs[i].BlockNumber < logs[j].BlockNumber }) From 48ec689f03960b46b89f6cd903a4503a68b198d3 Mon Sep 17 00:00:00 2001 From: Cameron Schultz Date: Mon, 11 Sep 2023 17:38:35 -0500 Subject: [PATCH 41/49] cleanup --- relayer/relayer.go | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/relayer/relayer.go b/relayer/relayer.go index 50921825..89232b98 100644 --- a/relayer/relayer.go +++ b/relayer/relayer.go @@ -125,9 +125,8 @@ func NewRelayer( // 2) The database has been configured for the chain, but does not contain the latest seen block data // - In this case, we save the current block height in the database, but do not process any historical warp logs if err == nil { - // If the database contains the latest seen block data, then back-process all warp messages from the - // latest seen block to the latest block - // This will query the node for any logs that match the filter query from the stored block height, + // If the database contains the latest seen block data, then back-process all warp messages from that block to the latest block + // This will query the node for any logs that match the filter query in that range latestSeenBlock, success := new(big.Int).SetString(string(latestSeenBlockData), 10) if !success { r.logger.Error("failed to convert latest block to big.Int", zap.Error(err)) @@ -208,9 +207,6 @@ func (r *Relayer) RelayMessage(warpLogInfo *vmtypes.WarpLogInfo, metrics *Messag return nil } - // Increment the request ID to use for this message - r.currentRequestID++ - // Create and run the message relayer to attempt to deliver the message to the destination chain messageRelayer := newMessageRelayer(r.logger, metrics, r, warpMessageInfo.WarpUnsignedMessage, warpLogInfo.DestinationChainID, r.responseChan, messageCreator) if err != nil { @@ -234,6 +230,9 @@ func (r *Relayer) RelayMessage(warpLogInfo *vmtypes.WarpLogInfo, metrics *Messag return err } + // Increment the request ID for the next message relay request + r.currentRequestID++ + // Update the database with the latest seen block height // We cannot store the latest processed block height, because we do not know if a given log is the last log in a block err = r.db.Put(r.sourceChainID, []byte(database.LatestSeenBlockKey), []byte(strconv.FormatUint(warpLogInfo.BlockNumber, 10))) From 4ed7671ead53541a2b9bf2d8f206653b25aa3830 Mon Sep 17 00:00:00 2001 From: Cameron Schultz Date: Mon, 11 Sep 2023 17:38:52 -0500 Subject: [PATCH 42/49] cache current state --- database/json_file_storage.go | 63 ++++++++++++++++++++--------------- 1 file changed, 36 insertions(+), 27 deletions(-) diff --git a/database/json_file_storage.go b/database/json_file_storage.go index 62b525a0..6e1e5b8f 100644 --- a/database/json_file_storage.go +++ b/database/json_file_storage.go @@ -28,16 +28,18 @@ type JSONFileStorage struct { // Each network has its own mutex // The chainIDs used to index the JSONFileStorage are created at initialization // and are not modified afterwards, so we don't need to lock the map itself. - mutexes map[ids.ID]*sync.RWMutex - logger logging.Logger + mutexes map[ids.ID]*sync.RWMutex + logger logging.Logger + currentState map[ids.ID]chainState } // NewJSONFileStorage creates a new JSONFileStorage instance func NewJSONFileStorage(logger logging.Logger, dir string, networks []ids.ID) (*JSONFileStorage, error) { storage := &JSONFileStorage{ - dir: filepath.Clean(dir), - mutexes: make(map[ids.ID]*sync.RWMutex), - logger: logger, + dir: filepath.Clean(dir), + mutexes: make(map[ids.ID]*sync.RWMutex), + logger: logger, + currentState: make(map[ids.ID]chainState), } for _, network := range networks { @@ -47,7 +49,16 @@ func NewJSONFileStorage(logger logging.Logger, dir string, networks []ids.ID) (* _, err := os.Stat(dir) if err == nil { // Directory already exists. - // Return the existing storage. + // Read the existing storage. + for _, network := range networks { + currentState, fileExists, err := storage.getCurrentState(network) + if err != nil { + return nil, err + } + if fileExists { + storage.currentState[network] = currentState + } + } return storage, nil } @@ -76,14 +87,8 @@ func (s *JSONFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { mutex.RLock() defer mutex.RUnlock() - currentState := make(chainState) - fileExists, err := s.read(chainID, ¤tState) + currentState, fileExists, err := s.getCurrentState(chainID) if err != nil { - s.logger.Error( - "failed to read file", - zap.String("chainID", chainID.String()), - zap.Error(err), - ) return nil, err } if !fileExists { @@ -98,6 +103,21 @@ func (s *JSONFileStorage) Get(chainID ids.ID, key []byte) ([]byte, error) { return []byte(val), nil } +// Helper to get the current state of a chainID. Not thread-safe. +func (s *JSONFileStorage) getCurrentState(chainID ids.ID) (chainState, bool, error) { + currentState := make(chainState) + fileExists, err := s.read(chainID, ¤tState) + if err != nil { + s.logger.Error( + "failed to read file", + zap.String("chainID", chainID.String()), + zap.Error(err), + ) + return nil, false, err + } + return currentState, fileExists, nil +} + // Put the value into the JSON database. Read the current chain state and overwrite the key, if it exists // If the file corresponding to {chainID} does not exist, then it will be created func (s *JSONFileStorage) Put(chainID ids.ID, key []byte, value []byte) error { @@ -112,20 +132,9 @@ func (s *JSONFileStorage) Put(chainID ids.ID, key []byte, value []byte) error { mutex.Lock() defer mutex.Unlock() - currentState := make(chainState) - _, err := s.read(chainID, ¤tState) - if err != nil { - s.logger.Error( - "failed to read file", - zap.String("chainID", chainID.String()), - zap.Error(err), - ) - return err - } - - currentState[string(key)] = string(value) - - return s.write(chainID, currentState) + // Update the in-memory state and write to disk + s.currentState[chainID][string(key)] = string(value) + return s.write(chainID, s.currentState[chainID]) } // Write the value to the file. The caller is responsible for ensuring proper synchronization From 4cdc4870eaecde29371c1721c1c9bf3c45461f6d Mon Sep 17 00:00:00 2001 From: Cameron Schultz Date: Mon, 11 Sep 2023 17:50:49 -0500 Subject: [PATCH 43/49] clarify latestSeenBlock comments --- relayer/relayer.go | 8 ++++---- vms/subscriber.go | 2 +- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/relayer/relayer.go b/relayer/relayer.go index 89232b98..36c38bd3 100644 --- a/relayer/relayer.go +++ b/relayer/relayer.go @@ -126,7 +126,9 @@ func NewRelayer( // - In this case, we save the current block height in the database, but do not process any historical warp logs if err == nil { // If the database contains the latest seen block data, then back-process all warp messages from that block to the latest block - // This will query the node for any logs that match the filter query in that range + // Note that the latest seen block may have already been partially (or fully) processed by the relayer on a previous run. When + // processing a warp message in real time, which is when we update the latest seen block in the database, we have no way of knowing + // if that is the last warp message to process in the block latestSeenBlock, success := new(big.Int).SetString(string(latestSeenBlockData), 10) if !success { r.logger.Error("failed to convert latest block to big.Int", zap.Error(err)) @@ -144,8 +146,7 @@ func NewRelayer( return &r, sub, nil } if errors.Is(err, database.ErrChainNotFound) || errors.Is(err, database.ErrKeyNotFound) { - // Otherwise, latestSeenBlock is nil, so the call to ProcessFromHeight will simply update the database with the - // latest block height + // Otherwise, latestSeenBlock is nil, so we instead store the latest block height. logger.Info( "Latest seen block not found in database. Starting from latest block.", zap.String("chainID", r.sourceChainID.String()), @@ -234,7 +235,6 @@ func (r *Relayer) RelayMessage(warpLogInfo *vmtypes.WarpLogInfo, metrics *Messag r.currentRequestID++ // Update the database with the latest seen block height - // We cannot store the latest processed block height, because we do not know if a given log is the last log in a block err = r.db.Put(r.sourceChainID, []byte(database.LatestSeenBlockKey), []byte(strconv.FormatUint(warpLogInfo.BlockNumber, 10))) if err != nil { r.logger.Error( diff --git a/vms/subscriber.go b/vms/subscriber.go index 519a7721..50103622 100644 --- a/vms/subscriber.go +++ b/vms/subscriber.go @@ -20,7 +20,7 @@ type Subscriber interface { // ProcessFromHeight processes events from {height} to the latest block ProcessFromHeight(height *big.Int) error - // UpdateLatestSeenBlock retreives the latest block from the chain and updates the database + // UpdateLatestSeenBlock retrieves the latest block from the chain and updates the database UpdateLatestSeenBlock() error // Subscribe registers a subscription. After Subscribe is called, From 55bc03cfd4c65c0a092c10a20bf0a5e289b6b45c Mon Sep 17 00:00:00 2001 From: Cameron Schultz Date: Mon, 11 Sep 2023 17:51:13 -0500 Subject: [PATCH 44/49] clarify latestSeenBlock comments --- relayer/relayer.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/relayer/relayer.go b/relayer/relayer.go index 36c38bd3..6bba830e 100644 --- a/relayer/relayer.go +++ b/relayer/relayer.go @@ -128,7 +128,7 @@ func NewRelayer( // If the database contains the latest seen block data, then back-process all warp messages from that block to the latest block // Note that the latest seen block may have already been partially (or fully) processed by the relayer on a previous run. When // processing a warp message in real time, which is when we update the latest seen block in the database, we have no way of knowing - // if that is the last warp message to process in the block + // if that is the last warp message in the block latestSeenBlock, success := new(big.Int).SetString(string(latestSeenBlockData), 10) if !success { r.logger.Error("failed to convert latest block to big.Int", zap.Error(err)) From 232f6fe868a74c6e7657ffeb3588ab8c42f3a836 Mon Sep 17 00:00:00 2001 From: Cameron Schultz Date: Mon, 11 Sep 2023 18:02:11 -0500 Subject: [PATCH 45/49] fix test --- database/json_file_storage.go | 1 + database/json_file_storage_test.go | 8 ++++---- 2 files changed, 5 insertions(+), 4 deletions(-) diff --git a/database/json_file_storage.go b/database/json_file_storage.go index 6e1e5b8f..809df06b 100644 --- a/database/json_file_storage.go +++ b/database/json_file_storage.go @@ -43,6 +43,7 @@ func NewJSONFileStorage(logger logging.Logger, dir string, networks []ids.ID) (* } for _, network := range networks { + storage.currentState[network] = make(chainState) storage.mutexes[network] = &sync.RWMutex{} } diff --git a/database/json_file_storage_test.go b/database/json_file_storage_test.go index ed2f6e3b..71741baf 100644 --- a/database/json_file_storage_test.go +++ b/database/json_file_storage_test.go @@ -40,11 +40,11 @@ func TestConcurrentWriteReadSingleChain(t *testing.T) { latestSeenBlockData, err := jsonStorage.Get(networks[0], []byte(LatestSeenBlockKey)) if err != nil { - t.Fatal(fmt.Sprintf("failed to retrieve from JSON storage. err: %v", err)) + t.Fatalf("failed to retrieve from JSON storage. err: %v", err) } latestSeenBlock, success := new(big.Int).SetString(string(latestSeenBlockData), 10) if !success { - t.Fatal(fmt.Sprintf("failed to convert latest block to big.Int. err: %v", err)) + t.Fatalf("failed to convert latest block to big.Int. err: %v", err) } assert.Equal(t, finalTargetValue, latestSeenBlock.Uint64(), "latest seen block height is not correct.") @@ -80,11 +80,11 @@ func TestConcurrentWriteReadMultipleChains(t *testing.T) { for i, id := range networks { latestSeenBlockData, err := jsonStorage.Get(id, []byte(LatestSeenBlockKey)) if err != nil { - t.Fatal(fmt.Sprintf("failed to retrieve from JSON storage. networkID: %d err: %v", i, err)) + t.Fatalf("failed to retrieve from JSON storage. networkID: %d err: %v", i, err) } latestSeenBlock, success := new(big.Int).SetString(string(latestSeenBlockData), 10) if !success { - t.Fatal(fmt.Sprintf("failed to convert latest block to big.Int. err: %v", err)) + t.Fatalf("failed to convert latest block to big.Int. err: %v", err) } assert.Equal(t, finalTargetValue, latestSeenBlock.Uint64(), fmt.Sprintf("latest seen block height is not correct. networkID: %d", i)) } From 5b0cc6312cc56a1efa500019866d6ab2f83eb461 Mon Sep 17 00:00:00 2001 From: Cameron Schultz Date: Tue, 12 Sep 2023 17:18:41 -0500 Subject: [PATCH 46/49] rename latestProcessedBlock --- database/database.go | 2 +- database/json_file_storage_test.go | 14 ++++++------- relayer/relayer.go | 32 +++++++++++++++--------------- vms/evm/subscriber.go | 10 +++++----- vms/subscriber.go | 4 ++-- 5 files changed, 31 insertions(+), 31 deletions(-) diff --git a/database/database.go b/database/database.go index 152acb3d..4a5de5b0 100644 --- a/database/database.go +++ b/database/database.go @@ -9,7 +9,7 @@ import ( ) const ( - LatestSeenBlockKey = "latestSeenBlock" + LatestProcessedBlockKey = "latestProcessedBlock" ) var ( diff --git a/database/json_file_storage_test.go b/database/json_file_storage_test.go index 71741baf..13ed4f0a 100644 --- a/database/json_file_storage_test.go +++ b/database/json_file_storage_test.go @@ -38,15 +38,15 @@ func TestConcurrentWriteReadSingleChain(t *testing.T) { finalTargetValue := uint64(11) testWrite(jsonStorage, networks[0], finalTargetValue) - latestSeenBlockData, err := jsonStorage.Get(networks[0], []byte(LatestSeenBlockKey)) + latestProcessedBlockData, err := jsonStorage.Get(networks[0], []byte(LatestProcessedBlockKey)) if err != nil { t.Fatalf("failed to retrieve from JSON storage. err: %v", err) } - latestSeenBlock, success := new(big.Int).SetString(string(latestSeenBlockData), 10) + latestProcessedBlock, success := new(big.Int).SetString(string(latestProcessedBlockData), 10) if !success { t.Fatalf("failed to convert latest block to big.Int. err: %v", err) } - assert.Equal(t, finalTargetValue, latestSeenBlock.Uint64(), "latest seen block height is not correct.") + assert.Equal(t, finalTargetValue, latestProcessedBlock.Uint64(), "latest processed block height is not correct.") } @@ -78,15 +78,15 @@ func TestConcurrentWriteReadMultipleChains(t *testing.T) { } for i, id := range networks { - latestSeenBlockData, err := jsonStorage.Get(id, []byte(LatestSeenBlockKey)) + latestProcessedBlockData, err := jsonStorage.Get(id, []byte(LatestProcessedBlockKey)) if err != nil { t.Fatalf("failed to retrieve from JSON storage. networkID: %d err: %v", i, err) } - latestSeenBlock, success := new(big.Int).SetString(string(latestSeenBlockData), 10) + latestProcessedBlock, success := new(big.Int).SetString(string(latestProcessedBlockData), 10) if !success { t.Fatalf("failed to convert latest block to big.Int. err: %v", err) } - assert.Equal(t, finalTargetValue, latestSeenBlock.Uint64(), fmt.Sprintf("latest seen block height is not correct. networkID: %d", i)) + assert.Equal(t, finalTargetValue, latestProcessedBlock.Uint64(), fmt.Sprintf("latest processed block height is not correct. networkID: %d", i)) } } @@ -110,7 +110,7 @@ func setupJsonStorage(t *testing.T, networks []ids.ID) *JSONFileStorage { func testWrite(storage *JSONFileStorage, chainID ids.ID, height uint64) { fmt.Println(chainID, height) - err := storage.Put(chainID, []byte(LatestSeenBlockKey), []byte(strconv.FormatUint(height, 10))) + err := storage.Put(chainID, []byte(LatestProcessedBlockKey), []byte(strconv.FormatUint(height, 10))) if err != nil { fmt.Printf("failed to put data: %v", err) return diff --git a/relayer/relayer.go b/relayer/relayer.go index 6bba830e..4f23c290 100644 --- a/relayer/relayer.go +++ b/relayer/relayer.go @@ -116,26 +116,26 @@ func NewRelayer( return nil, nil, err } - // Get the latest seen block height from the database. - latestSeenBlockData, err := r.db.Get(r.sourceChainID, []byte(database.LatestSeenBlockKey)) + // Get the latest processed block height from the database. + latestProcessedBlockData, err := r.db.Get(r.sourceChainID, []byte(database.LatestProcessedBlockKey)) // The following cases are treated as successful: - // 1) The database contains the latest seen block data for the chain + // 1) The database contains the latest processed block data for the chain // - In this case, we parse the block height and process warp logs from that height to the current block - // 2) The database has been configured for the chain, but does not contain the latest seen block data + // 2) The database has been configured for the chain, but does not contain the latest processed block data // - In this case, we save the current block height in the database, but do not process any historical warp logs if err == nil { - // If the database contains the latest seen block data, then back-process all warp messages from that block to the latest block - // Note that the latest seen block may have already been partially (or fully) processed by the relayer on a previous run. When - // processing a warp message in real time, which is when we update the latest seen block in the database, we have no way of knowing + // If the database contains the latest processed block data, then back-process all warp messages from that block to the latest block + // Note that the retrieved latest processed block may have already been partially (or fully) processed by the relayer on a previous run. When + // processing a warp message in real time, which is when we update the latest processed block in the database, we have no way of knowing // if that is the last warp message in the block - latestSeenBlock, success := new(big.Int).SetString(string(latestSeenBlockData), 10) + latestProcessedBlock, success := new(big.Int).SetString(string(latestProcessedBlockData), 10) if !success { r.logger.Error("failed to convert latest block to big.Int", zap.Error(err)) return nil, nil, err } - err = sub.ProcessFromHeight(latestSeenBlock) + err = sub.ProcessFromHeight(latestProcessedBlock) if err != nil { logger.Warn( "Encountered an error when processing historical blocks. Continuing to normal relaying operation.", @@ -146,16 +146,16 @@ func NewRelayer( return &r, sub, nil } if errors.Is(err, database.ErrChainNotFound) || errors.Is(err, database.ErrKeyNotFound) { - // Otherwise, latestSeenBlock is nil, so we instead store the latest block height. + // Otherwise, latestProcessedBlock is nil, so we instead store the latest block height. logger.Info( - "Latest seen block not found in database. Starting from latest block.", + "Latest processed block not found in database. Starting from latest block.", zap.String("chainID", r.sourceChainID.String()), ) - err := sub.UpdateLatestSeenBlock() + err := sub.UpdateLatestProcessedBlock() if err != nil { logger.Warn( - "Failed to update latest seen block. Continuing to normal relaying operation", + "Failed to update latest processed block. Continuing to normal relaying operation", zap.String("chainID", r.sourceChainID.String()), zap.Error(err), ) @@ -234,11 +234,11 @@ func (r *Relayer) RelayMessage(warpLogInfo *vmtypes.WarpLogInfo, metrics *Messag // Increment the request ID for the next message relay request r.currentRequestID++ - // Update the database with the latest seen block height - err = r.db.Put(r.sourceChainID, []byte(database.LatestSeenBlockKey), []byte(strconv.FormatUint(warpLogInfo.BlockNumber, 10))) + // Update the database with the latest processed block height + err = r.db.Put(r.sourceChainID, []byte(database.LatestProcessedBlockKey), []byte(strconv.FormatUint(warpLogInfo.BlockNumber, 10))) if err != nil { r.logger.Error( - fmt.Sprintf("failed to put %s into database", database.LatestSeenBlockKey), + fmt.Sprintf("failed to put %s into database", database.LatestProcessedBlockKey), zap.Error(err), ) } diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index 8349a231..b70ccbf2 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -176,7 +176,7 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { height = big.NewInt(0).Add(toBlock, big.NewInt(-MaxBlocksToProcess)) } - // Filter logs from the latest seen block to the latest block + // Filter logs from the latest processed block to the latest block // Since initializationFilterQuery does not modify existing fields of warpFilterQuery, // we can safely reuse warpFilterQuery with only a shallow copy initializationFilterQuery := interfaces.FilterQuery{ @@ -226,9 +226,9 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { return nil } -func (s *subscriber) UpdateLatestSeenBlock() error { +func (s *subscriber) UpdateLatestProcessedBlock() error { s.logger.Info( - "Updating latest seen block in database", + "Updating latest processed block in database", zap.String("chainID", s.chainID.String()), ) ethClient, err := ethclient.Dial(s.nodeRPCURL) @@ -251,10 +251,10 @@ func (s *subscriber) UpdateLatestSeenBlock() error { return err } - err = s.db.Put(s.chainID, []byte(database.LatestSeenBlockKey), []byte(strconv.FormatUint(latestBlock, 10))) + err = s.db.Put(s.chainID, []byte(database.LatestProcessedBlockKey), []byte(strconv.FormatUint(latestBlock, 10))) if err != nil { s.logger.Error( - fmt.Sprintf("failed to put %s into database", database.LatestSeenBlockKey), + fmt.Sprintf("failed to put %s into database", database.LatestProcessedBlockKey), zap.String("chainID", s.chainID.String()), zap.Error(err), ) diff --git a/vms/subscriber.go b/vms/subscriber.go index 50103622..e7520342 100644 --- a/vms/subscriber.go +++ b/vms/subscriber.go @@ -20,8 +20,8 @@ type Subscriber interface { // ProcessFromHeight processes events from {height} to the latest block ProcessFromHeight(height *big.Int) error - // UpdateLatestSeenBlock retrieves the latest block from the chain and updates the database - UpdateLatestSeenBlock() error + // UpdateLatestProcessedBlock retrieves the latest block from the chain and updates the database + UpdateLatestProcessedBlock() error // Subscribe registers a subscription. After Subscribe is called, // log events that match [filter] are written to the channel returned From 995d20480816ee11d75635a5284b5ddaa64a7df2 Mon Sep 17 00:00:00 2001 From: Cameron Schultz Date: Wed, 13 Sep 2023 09:33:05 -0500 Subject: [PATCH 47/49] rename SetProcessedBlockHeightToLatest --- relayer/relayer.go | 2 +- vms/evm/subscriber.go | 2 +- vms/subscriber.go | 4 ++-- 3 files changed, 4 insertions(+), 4 deletions(-) diff --git a/relayer/relayer.go b/relayer/relayer.go index 4f23c290..24d27ed9 100644 --- a/relayer/relayer.go +++ b/relayer/relayer.go @@ -152,7 +152,7 @@ func NewRelayer( zap.String("chainID", r.sourceChainID.String()), ) - err := sub.UpdateLatestProcessedBlock() + err := sub.SetProcessedBlockHeightToLatest() if err != nil { logger.Warn( "Failed to update latest processed block. Continuing to normal relaying operation", diff --git a/vms/evm/subscriber.go b/vms/evm/subscriber.go index b70ccbf2..c42aac03 100644 --- a/vms/evm/subscriber.go +++ b/vms/evm/subscriber.go @@ -226,7 +226,7 @@ func (s *subscriber) ProcessFromHeight(height *big.Int) error { return nil } -func (s *subscriber) UpdateLatestProcessedBlock() error { +func (s *subscriber) SetProcessedBlockHeightToLatest() error { s.logger.Info( "Updating latest processed block in database", zap.String("chainID", s.chainID.String()), diff --git a/vms/subscriber.go b/vms/subscriber.go index e7520342..82682cca 100644 --- a/vms/subscriber.go +++ b/vms/subscriber.go @@ -20,8 +20,8 @@ type Subscriber interface { // ProcessFromHeight processes events from {height} to the latest block ProcessFromHeight(height *big.Int) error - // UpdateLatestProcessedBlock retrieves the latest block from the chain and updates the database - UpdateLatestProcessedBlock() error + // SetProcessedBlockHeightToLatest retrieves the latest block from the chain and updates the database + SetProcessedBlockHeightToLatest() error // Subscribe registers a subscription. After Subscribe is called, // log events that match [filter] are written to the channel returned From e30a4acc7ab8150a7786cbd56bd51894d47ffbdd Mon Sep 17 00:00:00 2001 From: Cameron Schultz Date: Wed, 13 Sep 2023 10:19:46 -0500 Subject: [PATCH 48/49] update comment --- relayer/relayer.go | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/relayer/relayer.go b/relayer/relayer.go index 24d27ed9..66dd588d 100644 --- a/relayer/relayer.go +++ b/relayer/relayer.go @@ -172,8 +172,7 @@ func NewRelayer( return nil, nil, err } -// RelayMessage relays a single warp message to the destination chain. Warp message relay requests are concurrent with each other, -// and synchronized by relayer. +// RelayMessage relays a single warp message to the destination chain. Warp message relay requests from the same origin chain are processed serially func (r *Relayer) RelayMessage(warpLogInfo *vmtypes.WarpLogInfo, metrics *MessageRelayerMetrics, messageCreator message.Creator) error { r.logger.Info( "Relaying message", From 8870d8b5513573f5ccc2f6ce362f824c469fe1e6 Mon Sep 17 00:00:00 2001 From: Cameron Schultz Date: Wed, 13 Sep 2023 10:44:42 -0500 Subject: [PATCH 49/49] appease linter --- database/json_file_storage_test.go | 4 ++-- relayer/relayer.go | 1 - 2 files changed, 2 insertions(+), 3 deletions(-) diff --git a/database/json_file_storage_test.go b/database/json_file_storage_test.go index 13ed4f0a..b2d8931b 100644 --- a/database/json_file_storage_test.go +++ b/database/json_file_storage_test.go @@ -27,9 +27,10 @@ func TestConcurrentWriteReadSingleChain(t *testing.T) { wg := sync.WaitGroup{} for i := 0; i < 10; i++ { wg.Add(1) + idx := i go func() { defer wg.Done() - testWrite(jsonStorage, networks[0], uint64(i)) + testWrite(jsonStorage, networks[0], uint64(idx)) }() } wg.Wait() @@ -47,7 +48,6 @@ func TestConcurrentWriteReadSingleChain(t *testing.T) { t.Fatalf("failed to convert latest block to big.Int. err: %v", err) } assert.Equal(t, finalTargetValue, latestProcessedBlock.Uint64(), "latest processed block height is not correct.") - } // Test that the JSON database can write and read from multiple chains concurrently. Write to any given chain are not concurrent. diff --git a/relayer/relayer.go b/relayer/relayer.go index 66dd588d..6513f3c9 100644 --- a/relayer/relayer.go +++ b/relayer/relayer.go @@ -48,7 +48,6 @@ func NewRelayer( responseChan chan message.InboundMessage, destinationClients map[ids.ID]vms.DestinationClient, ) (*Relayer, vms.Subscriber, error) { - sub := vms.NewSubscriber(logger, sourceSubnetInfo, db) subnetID, err := ids.FromString(sourceSubnetInfo.SubnetID)