async def _display_stats(self) -> None: last_head = await self.wait(self.db.coro_get_canonical_head()) timer = Timer() while self.is_operational: await self.sleep(5) self.logger.debug( "(in progress, queued, max size) of headers, bodies, receipts: %r", [(q.num_in_progress(), len(q), q._maxsize) for q in ( self.header_queue, self._block_body_tasks, self._receipt_tasks, )], ) head = await self.wait(self.db.coro_get_canonical_head()) if head == last_head: continue else: block_num_change = head.block_number - last_head.block_number last_head = head self.logger.info( "Advanced by %d blocks in %0.1f seconds, new head: #%d", block_num_change, timer.pop_elapsed(), head.block_number)
async def _process_headers(self, peer: HeaderRequestingPeer, headers: Tuple[BlockHeader, ...]) -> int: timer = Timer() target_td = await self._calculate_td(headers) bodies_by_key = await self._download_block_bodies(target_td, headers) self.logger.debug("Got block bodies for chain segment") await self._download_receipts(target_td, headers) self.logger.debug("Got block receipts for chain segment") for header in headers: if header.uncles_hash != EMPTY_UNCLE_HASH: key = (header.transaction_root, header.uncles_hash) body = cast(BlockBody, bodies_by_key[key]) uncles = body.uncles else: uncles = tuple() vm_class = self.chain.get_vm_class_for_block_number( header.block_number) block_class = vm_class.get_block_class() # We don't need to use our block transactions here because persist_block() doesn't do # anything with them as it expects them to have been persisted already. block = block_class(header, uncles=uncles) await self.wait(self.db.coro_persist_block(block)) head = await self.wait(self.db.coro_get_canonical_head()) txs = sum( len(cast(BlockBody, body).transactions) for body in bodies_by_key.values()) self.logger.info( "Imported %d blocks (%d txs) in %0.2f seconds, new head: #%d", len(headers), txs, timer.elapsed, head.block_number) return head.block_number
async def _process_headers(self, peer: HeaderRequestingPeer, headers: Tuple[BlockHeader, ...]) -> int: target_td = await self._calculate_td(headers) bodies_by_key = await self._download_block_bodies(target_td, headers) self.logger.info("Got block bodies for chain segment") for header in headers: vm_class = self.chain.get_vm_class_for_block_number( header.block_number) block_class = vm_class.get_block_class() if _is_body_empty(header): transactions: List[BaseTransaction] = [] uncles: List[BlockHeader] = [] else: key = (header.transaction_root, header.uncles_hash) body = cast(BlockBody, bodies_by_key[key]) tx_class = block_class.get_transaction_class() transactions = [ tx_class.from_base_transaction(tx) for tx in body.transactions ] uncles = body.uncles block = block_class(header, transactions, uncles) timer = Timer() await self.wait( self.chain.coro_import_block(block, perform_validation=True)) self.logger.info("Imported block %d (%d txs) in %f seconds", block.number, len(transactions), timer.elapsed) head = await self.wait(self.db.coro_get_canonical_head()) self.logger.info("Imported chain segment, new head: #%d", head.block_number) return head.block_number
def __init__(self, head: BlockHeader) -> None: # The `head` from the previous time we reported stats self.prev_head = head # The latest `head` we have synced self.latest_head = head # A `Timer` object to report elapsed time between reports self.timer = Timer() # EMA of the blocks per second self.blocks_per_second_ema = EMA(initial_value=0, smoothing_factor=0.05) # EMA of the transactions per second self.transactions_per_second_ema = EMA(initial_value=0, smoothing_factor=0.05) # Number of transactions processed self.num_transactions = 0
async def _process_headers(self, peer: HeaderRequestingPeer, headers: Tuple[BlockHeader, ...]) -> int: timer = Timer() for header in headers: await self.wait(self.db.coro_persist_header(header)) head = await self.wait(self.db.coro_get_canonical_head()) self.logger.info("Imported %d headers in %0.2f seconds, new head: #%d", len(headers), timer.elapsed, head.block_number) return head.block_number
async def _process_headers(self, headers: Tuple[BlockHeader, ...]) -> None: target_td = await self._calculate_td(headers) bodies_by_key = await self._download_block_bodies(target_td, headers) self.logger.info("Got block bodies for chain segment") for header in headers: vm_class = self.chain.get_vm_class_for_block_number( header.block_number) block_class = vm_class.get_block_class() if _is_body_empty(header): transactions: List[BaseTransaction] = [] uncles: List[BlockHeader] = [] else: key = (header.transaction_root, header.uncles_hash) body = cast(BlockBody, bodies_by_key[key]) tx_class = block_class.get_transaction_class() transactions = [ tx_class.from_base_transaction(tx) for tx in body.transactions ] uncles = body.uncles block = block_class(header, transactions, uncles) timer = Timer() _, new_canonical_blocks, old_canonical_blocks = await self.wait( self.chain.coro_import_block(block, perform_validation=True)) if new_canonical_blocks == (block, ): # simple import of a single new block. self.logger.info("Imported block %d (%d txs) in %f seconds", block.number, len(transactions), timer.elapsed) elif not new_canonical_blocks: # imported block from a fork. self.logger.info( "Imported non-canonical block %d (%d txs) in %f seconds", block.number, len(transactions), timer.elapsed) elif old_canonical_blocks: self.logger.info( "Chain Reorganization: Imported block %d (%d txs) in %f " "seconds, %d blocks discarded and %d new canonical blocks added", block.number, len(transactions), timer.elapsed, len(old_canonical_blocks), len(new_canonical_blocks), ) else: raise Exception("Invariant: unreachable code path") head = await self.wait(self.db.coro_get_canonical_head()) self.logger.info("Imported chain segment, new head: #%d", head.block_number)
class ChainSyncPerformanceTracker: def __init__(self, head: BlockHeader) -> None: # The `head` from the previous time we reported stats self.prev_head = head # The latest `head` we have synced self.latest_head = head # A `Timer` object to report elapsed time between reports self.timer = Timer() # EMA of the blocks per second self.blocks_per_second_ema = EMA(initial_value=0, smoothing_factor=0.05) # EMA of the transactions per second self.transactions_per_second_ema = EMA(initial_value=0, smoothing_factor=0.05) # Number of transactions processed self.num_transactions = 0 def record_transactions(self, count: int) -> None: self.num_transactions += count def set_latest_head(self, head: BlockHeader) -> None: self.latest_head = head def report(self) -> ChainSyncStats: elapsed = self.timer.pop_elapsed() num_blocks = self.latest_head.block_number - self.prev_head.block_number blocks_per_second = num_blocks / elapsed transactions_per_second = self.num_transactions / elapsed self.blocks_per_second_ema.update(blocks_per_second) self.transactions_per_second_ema.update(transactions_per_second) stats = ChainSyncStats( prev_head=self.prev_head, latest_head=self.latest_head, elapsed=elapsed, num_blocks=num_blocks, blocks_per_second=self.blocks_per_second_ema.value, num_transactions=self.num_transactions, transactions_per_second=self.transactions_per_second_ema.value, ) # reset the counters self.num_transactions = 0 self.prev_head = self.latest_head return stats
async def _persist_headers(self) -> None: while self.is_operational: batch_id, headers = await self.wait(self.header_queue.get()) timer = Timer() await self.wait(self.db.coro_persist_header_chain(headers)) head = await self.wait(self.db.coro_get_canonical_head()) self.logger.info( "Imported %d headers in %0.2f seconds, new head: %s", len(headers), timer.elapsed, head) self.header_queue.complete(batch_id, headers)
async def _import_blocks(self, headers: Tuple[BlockHeader, ...]) -> None: """ Import the blocks for the corresponding headers :param headers: headers that have the block bodies downloaded """ for header in headers: vm_class = self.chain.get_vm_class(header) block_class = vm_class.get_block_class() if _is_body_empty(header): transactions: List[BaseTransaction] = [] uncles: List[BlockHeader] = [] else: body = self._pending_bodies.pop(header) tx_class = block_class.get_transaction_class() transactions = [ tx_class.from_base_transaction(tx) for tx in body.transactions ] uncles = body.uncles block = block_class(header, transactions, uncles) timer = Timer() _, new_canonical_blocks, old_canonical_blocks = await self.wait( self.chain.coro_import_block(block, perform_validation=True)) if new_canonical_blocks == (block, ): # simple import of a single new block. self.logger.info("Imported block %d (%d txs) in %.2f seconds", block.number, len(transactions), timer.elapsed) elif not new_canonical_blocks: # imported block from a fork. self.logger.info( "Imported non-canonical block %d (%d txs) in %.2f seconds", block.number, len(transactions), timer.elapsed) elif old_canonical_blocks: self.logger.info( "Chain Reorganization: Imported block %d (%d txs) in %.2f " "seconds, %d blocks discarded and %d new canonical blocks added", block.number, len(transactions), timer.elapsed, len(old_canonical_blocks), len(new_canonical_blocks), ) else: raise Exception("Invariant: unreachable code path")
async def _process_headers(self, peer: HeaderRequestingPeer, headers: Tuple[BlockHeader, ...]) -> int: timer = Timer() target_td = await self._calculate_td(headers) bodies = await self._download_block_parts( target_td, [header for header in headers if not _is_body_empty(header)], self.request_bodies, self._downloaded_bodies, _body_key, 'body') self.logger.debug("Got block bodies for chain segment") missing_receipts = [ header for header in headers if not _is_receipts_empty(header) ] # Post-Byzantium blocks may have identical receipt roots (e.g. when they have the same # number of transactions and all succeed/failed: ropsten blocks 2503212 and 2503284), # so we do this to avoid requesting the same receipts multiple times. missing_receipts = list(unique(missing_receipts, key=_receipts_key)) await self._download_block_parts(target_td, missing_receipts, self.request_receipts, self._downloaded_receipts, _receipts_key, 'receipt') self.logger.debug("Got block receipts for chain segment") for header in headers: if header.uncles_hash != EMPTY_UNCLE_HASH: body = cast(BlockBody, bodies[_body_key(header)]) uncles = body.uncles else: uncles = tuple() vm_class = self.chain.get_vm_class_for_block_number( header.block_number) block_class = vm_class.get_block_class() # We don't need to use our block transactions here because persist_block() doesn't do # anything with them as it expects them to have been persisted already. block = block_class(header, uncles=uncles) await self.wait(self.db.coro_persist_block(block)) head = await self.wait(self.db.coro_get_canonical_head()) txs = sum( len(cast(BlockBody, body).transactions) for body in bodies.values()) self.logger.info( "Imported %d blocks (%d txs) in %0.2f seconds, new head: #%d", len(headers), txs, timer.elapsed, head.block_number) return head.block_number
async def _import_ready_blocks(self) -> None: """ Wait for block bodies to be downloaded, then import the blocks. """ while self.is_operational: timer = Timer() # wait for block bodies to become ready for execution completed_headers = await self.wait(self._block_import_tracker.ready_tasks()) await self._import_blocks(completed_headers) head = await self.wait(self.db.coro_get_canonical_head()) self.logger.info( "Synced chain segment with %d blocks in %.2f seconds, new head: %s", len(completed_headers), timer.elapsed, head, )
async def _process_headers(self, headers: Tuple[BlockHeader, ...]) -> None: timer = Timer() target_td = await self._calculate_td(headers) bodies_by_key = await self._download_block_bodies(target_td, headers) self.logger.debug("Got block bodies for chain segment") await self._download_receipts(target_td, headers) self.logger.debug("Got block receipts for chain segment") for header in headers: if header.uncles_hash != EMPTY_UNCLE_HASH: key = (header.transaction_root, header.uncles_hash) body = cast(BlockBody, bodies_by_key[key]) uncles = body.uncles else: uncles = tuple() vm_class = self.chain.get_vm_class_for_block_number( header.block_number) block_class = vm_class.get_block_class() # We don't need to use our block transactions here because persist_block() doesn't do # anything with them as it expects them to have been persisted already. block = block_class(header, uncles=uncles) await self.wait(self.db.coro_persist_block(block)) head = await self.wait(self.db.coro_get_canonical_head()) txs = sum( len(cast(BlockBody, body).transactions) for body in bodies_by_key.values()) self.logger.info( "Imported %d blocks (%d txs) in %0.2f seconds, new head: #%d", len(headers), txs, timer.elapsed, head.block_number) # during fast sync, exit the service when reaching the target hash target_hash = self.get_target_header_hash() # Quite often the header batch we receive includes headers past the peer's reported # head (via the NewBlock msg), so we can't compare our head's hash to the peer's in # order to see if the sync is completed. Instead we just check that we have the peer's # head_hash in our chain. if await self.wait(self.db.coro_header_exists(target_hash)): self.complete_token.trigger()
class StateDownloader(BaseService, PeerSubscriber): _total_processed_nodes = 0 _report_interval = 10 # Number of seconds between progress reports. _reply_timeout = 20 # seconds _timer = Timer(auto_start=False) _total_timeouts = 0 def __init__(self, chaindb: AsyncChainDB, account_db: AsyncBaseDB, root_hash: bytes, peer_pool: PeerPool, token: CancelToken = None) -> None: super().__init__(token) self.chaindb = chaindb self.peer_pool = peer_pool self.root_hash = root_hash # We use a LevelDB instance for the nodes cache because a full state download, if run # uninterrupted will visit more than 180M nodes, making an in-memory cache unfeasible. self._nodes_cache_dir = tempfile.TemporaryDirectory( prefix="pyevm-state-sync-cache") self.scheduler = StateSync( root_hash, account_db, LevelDB(cast(Path, self._nodes_cache_dir.name)), self.logger) self._handler = PeerRequestHandler(self.chaindb, self.logger, self.cancel_token) self.request_tracker = TrieNodeRequestTracker(self._reply_timeout, self.logger) self._peer_missing_nodes: Dict[ ETHPeer, Set[Hash32]] = collections.defaultdict(set) # Throughout the whole state sync our chain head is fixed, so it makes sense to ignore # messages related to new blocks/transactions, but we must handle requests for data from # other peers or else they will disconnect from us. subscription_msg_types: Set[Type[Command]] = { commands.GetBlockHeaders, commands.GetBlockBodies, commands.GetReceipts, commands.GetNodeData, # TODO: all of the following are here to quiet warning logging output # until the messages are properly handled. commands.Transactions, commands.NewBlock, commands.NewBlockHashes, } # This is a rather arbitrary value, but when the sync is operating normally we never see # the msg queue grow past a few hundred items, so this should be a reasonable limit for # now. msg_queue_maxsize: int = 2000 def deregister_peer(self, peer: BasePeer) -> None: # Use .pop() with a default value as it's possible we never requested anything to this # peer or it had all the trie nodes we requested, so there'd be no entry in # self._peer_missing_nodes for it. self._peer_missing_nodes.pop(cast(ETHPeer, peer), None) async def get_peer_for_request(self, node_keys: Set[Hash32]) -> ETHPeer: """Return an idle peer that may have any of the trie nodes in node_keys. If none of our peers have any of the given node keys, raise NoEligiblePeers. If none of the peers which may have at least one of the given node keys is idle, raise NoIdlePeers. """ has_eligible_peers = False async for peer in self.peer_pool: peer = cast(ETHPeer, peer) if self._peer_missing_nodes[peer].issuperset(node_keys): self.logger.trace( "%s doesn't have any of the nodes we want, skipping it", peer) continue has_eligible_peers = True if peer in self.request_tracker.active_requests: self.logger.trace("%s is not idle, skipping it", peer) continue return peer if not has_eligible_peers: raise NoEligiblePeers() else: raise NoIdlePeers() async def _handle_msg_loop(self) -> None: while self.is_operational: peer, cmd, msg = await self.wait(self.msg_queue.get()) # Run self._handle_msg() with self.run_task() instead of awaiting for it so that we # can keep consuming msgs while _handle_msg() performs cpu-intensive tasks in separate # processes. peer = cast(ETHPeer, peer) self.run_task(self._handle_msg(peer, cmd, msg)) async def _process_nodes(self, nodes: Iterable[Tuple[Hash32, bytes]]) -> None: for node_key, node in nodes: self._total_processed_nodes += 1 try: await self.scheduler.process([(node_key, node)]) except SyncRequestAlreadyProcessed: # This means we received a node more than once, which can happen when we # retry after a timeout. pass async def _handle_msg(self, peer: ETHPeer, cmd: Command, msg: _DecodedMsgType) -> None: # TODO: stop ignoring these once we have proper handling for these messages. ignored_commands = (commands.Transactions, commands.NewBlock, commands.NewBlockHashes) if isinstance(cmd, ignored_commands): pass elif isinstance(cmd, commands.GetBlockHeaders): query = cast(Dict[Any, Union[bool, int]], msg) request = HeaderRequest( query['block_number_or_hash'], query['max_headers'], query['skip'], cast(bool, query['reverse']), ) await self._handle_get_block_headers(peer, request) elif isinstance(cmd, commands.GetBlockBodies): # Only serve up to MAX_BODIES_FETCH items in every request. block_hashes = cast(List[Hash32], msg)[:eth_constants.MAX_BODIES_FETCH] await self._handler.handle_get_block_bodies(peer, block_hashes) elif isinstance(cmd, commands.GetReceipts): # Only serve up to MAX_RECEIPTS_FETCH items in every request. block_hashes = cast(List[Hash32], msg)[:eth_constants.MAX_RECEIPTS_FETCH] await self._handler.handle_get_receipts(peer, block_hashes) elif isinstance(cmd, commands.GetNodeData): # Only serve up to MAX_STATE_FETCH items in every request. node_hashes = cast(List[Hash32], msg)[:eth_constants.MAX_STATE_FETCH] await self._handler.handle_get_node_data(peer, node_hashes) else: self.logger.warn( "%s not handled during StateSync, must be implemented", cmd) async def _handle_get_block_headers(self, peer: ETHPeer, request: HeaderRequest) -> None: headers = await self._handler.lookup_headers(request) peer.sub_proto.send_block_headers(headers) async def _cleanup(self) -> None: self._nodes_cache_dir.cleanup() async def request_nodes(self, node_keys: Iterable[Hash32]) -> None: not_yet_requested = set(node_keys) while not_yet_requested: try: peer = await self.get_peer_for_request(not_yet_requested) except NoIdlePeers: self.logger.trace( "No idle peers have any of the %d trie nodes we want, sleeping a bit", len(not_yet_requested), ) await self.sleep(0.2) continue except NoEligiblePeers: self.request_tracker.missing[time.time()] = list( not_yet_requested) self.logger.debug( "No peers have any of the %d trie nodes in this batch, will retry later", len(not_yet_requested), ) # TODO: disconnect a peer if the pool is full return candidates = list( not_yet_requested.difference(self._peer_missing_nodes[peer])) batch = tuple(candidates[:eth_constants.MAX_STATE_FETCH]) not_yet_requested = not_yet_requested.difference(batch) self.request_tracker.active_requests[peer] = (time.time(), batch) self.run_task(self._request_and_process_nodes(peer, batch)) async def _request_and_process_nodes(self, peer: ETHPeer, batch: Tuple[Hash32, ...]) -> None: self.logger.debug("Requesting %d trie nodes from %s", len(batch), peer) try: node_data = await peer.requests.get_node_data(batch) except TimeoutError as err: self.logger.debug( "Timed out waiting for %s trie nodes from %s: %s", len(batch), peer, err, ) node_data = tuple() except AlreadyWaiting as err: self.logger.warn( "Already waiting for a NodeData response from %s", peer, ) return try: self.request_tracker.active_requests.pop(peer) except KeyError: self.logger.warn( "Unexpected error removing peer from active requests: %s", peer) self.logger.debug("Got %d NodeData entries from %s", len(node_data), peer) if node_data: node_keys, _ = zip(*node_data) else: node_keys = tuple() # check for missing nodes and re-schedule them missing = set(batch).difference(node_keys) # TODO: this doesn't necessarily mean the peer doesn't have them, just # that they didn't respond with them this time. We should explore # alternate ways to do this since a false negative here will result in # not requesting this node from this peer again. if missing: self._peer_missing_nodes[peer].update(missing) self.logger.debug( "Re-requesting %d/%d NodeData entries not returned by %s", len(missing), len(batch), peer, ) await self.request_nodes(missing) if node_data: await self._process_nodes(node_data) async def _periodically_retry_timedout_and_missing(self) -> None: while self.is_operational: timed_out = self.request_tracker.get_timed_out() if timed_out: self.logger.debug("Re-requesting %d timed out trie nodes", len(timed_out)) self._total_timeouts += len(timed_out) await self.request_nodes(timed_out) retriable_missing = self.request_tracker.get_retriable_missing() if retriable_missing: self.logger.debug("Re-requesting %d missing trie nodes", len(retriable_missing)) await self.request_nodes(retriable_missing) # Finally, sleep until the time either our oldest request is scheduled to timeout or # one of our missing batches is scheduled to be retried. next_timeout = self.request_tracker.get_next_timeout() await self.sleep(next_timeout - time.time()) async def _run(self) -> None: """Fetch all trie nodes starting from self.root_hash, and store them in self.db. Raises OperationCancelled if we're interrupted before that is completed. """ self._timer.start() self.logger.info("Starting state sync for root hash %s", encode_hex(self.root_hash)) self.run_task(self._handle_msg_loop()) self.run_task(self._periodically_report_progress()) self.run_task(self._periodically_retry_timedout_and_missing()) with self.subscribe(self.peer_pool): while self.scheduler.has_pending_requests: # This ensures we yield control and give _handle_msg() a chance to process any nodes # we may have received already, also ensuring we exit when our cancel token is # triggered. await self.sleep(0) requests = self.scheduler.next_batch( eth_constants.MAX_STATE_FETCH) if not requests: # Although we frequently yield control above, to let our msg handler process # received nodes (scheduling new requests), there may be cases when the # pending nodes take a while to arrive thus causing the scheduler to run out # of new requests for a while. self.logger.debug( "Scheduler queue is empty, sleeping a bit") await self.sleep(0.5) continue await self.request_nodes( [request.node_key for request in requests]) self.logger.info("Finished state sync with root hash %s", encode_hex(self.root_hash)) async def _periodically_report_progress(self) -> None: while self.is_operational: requested_nodes = sum( len(node_keys) for _, node_keys in self.request_tracker.active_requests.values()) msg = "processed=%d " % self._total_processed_nodes msg += "tnps=%d " % (self._total_processed_nodes / self._timer.elapsed) msg += "committed=%d " % self.scheduler.committed_nodes msg += "active_requests=%d " % requested_nodes msg += "queued=%d " % len(self.scheduler.queue) msg += "pending=%d " % len(self.scheduler.requests) msg += "missing=%d " % len(self.request_tracker.missing) msg += "timeouts=%d" % self._total_timeouts self.logger.info("State-Sync: %s", msg) await self.sleep(self._report_interval)
class StateDownloader(BaseService, PeerSubscriber): _total_processed_nodes = 0 _report_interval = 10 # Number of seconds between progress reports. _reply_timeout = 20 # seconds _timer = Timer(auto_start=False) _total_timeouts = 0 def __init__(self, chaindb: AsyncChainDB, account_db: BaseDB, root_hash: bytes, peer_pool: PeerPool, token: CancelToken = None) -> None: super().__init__(token) self.chaindb = chaindb self.peer_pool = peer_pool self.root_hash = root_hash self.scheduler = StateSync(root_hash, account_db) self._handler = PeerRequestHandler(self.chaindb, self.logger, self.cancel_token) self.request_tracker = TrieNodeRequestTracker(self._reply_timeout, self.logger) self._peer_missing_nodes: Dict[ETHPeer, Set[Hash32]] = collections.defaultdict(set) self._executor = get_asyncio_executor() # Throughout the whole state sync our chain head is fixed, so it makes sense to ignore # messages related to new blocks/transactions, but we must handle requests for data from # other peers or else they will disconnect from us. subscription_msg_types: Set[Type[Command]] = { commands.NodeData, commands.GetBlockHeaders, commands.GetBlockBodies, commands.GetReceipts, commands.GetNodeData, # TODO: all of the following are here to quiet warning logging output # until the messages are properly handled. commands.Transactions, commands.NewBlock, commands.NewBlockHashes, } # This is a rather arbitrary value, but when the sync is operating normally we never see # the msg queue grow past a few hundred items, so this should be a reasonable limit for # now. msg_queue_maxsize: int = 2000 def deregister_peer(self, peer: BasePeer) -> None: # Use .pop() with a default value as it's possible we never requested anything to this # peer or it had all the trie nodes we requested, so there'd be no entry in # self._peer_missing_nodes for it. self._peer_missing_nodes.pop(cast(ETHPeer, peer), None) async def get_peer_for_request(self, node_keys: Set[Hash32]) -> ETHPeer: """Return an idle peer that may have any of the trie nodes in node_keys. If none of our peers have any of the given node keys, raise NoEligiblePeers. If none of the peers which may have at least one of the given node keys is idle, raise NoIdlePeers. """ has_eligible_peers = False async for peer in self.peer_pool: peer = cast(ETHPeer, peer) if self._peer_missing_nodes[peer].issuperset(node_keys): self.logger.trace("%s doesn't have any of the nodes we want, skipping it", peer) continue has_eligible_peers = True if peer in self.request_tracker.active_requests: self.logger.trace("%s is not idle, skipping it", peer) continue return peer if not has_eligible_peers: raise NoEligiblePeers() else: raise NoIdlePeers() async def _handle_msg_loop(self) -> None: while self.is_running: try: peer, cmd, msg = await self.wait(self.msg_queue.get()) except OperationCancelled: break # Run self._handle_msg() with ensure_future() instead of awaiting for it so that we # can keep consuming msgs while _handle_msg() performs cpu-intensive tasks in separate # processes. peer = cast(ETHPeer, peer) asyncio.ensure_future(self._handle_msg(peer, cmd, msg)) async def _process_nodes(self, nodes: Iterable[Tuple[Hash32, bytes]]) -> None: for idx, (node_key, node) in enumerate(nodes): self._total_processed_nodes += 1 try: self.scheduler.process([(node_key, node)]) except SyncRequestAlreadyProcessed: # This means we received a node more than once, which can happen when we # retry after a timeout. pass if idx % 10 == 0: # XXX: This is a quick workaround for # https://github.com/ethereum/py-evm/issues/1074, which will be replaced soon # with a proper fix. await self.sleep(0) async def _handle_msg( self, peer: ETHPeer, cmd: Command, msg: _DecodedMsgType) -> None: # TODO: stop ignoring these once we have proper handling for these messages. ignored_commands = (commands.Transactions, commands.NewBlock, commands.NewBlockHashes) if isinstance(cmd, ignored_commands): pass elif isinstance(cmd, commands.NodeData): msg = cast(List[bytes], msg) if peer not in self.request_tracker.active_requests: # This is probably a batch that we retried after a timeout and ended up receiving # more than once, so ignore but log as an INFO just in case. self.logger.info( "Got %d NodeData entries from %s that were not expected, ignoring them", len(msg), peer) return self.logger.debug("Got %d NodeData entries from %s", len(msg), peer) _, requested_node_keys = self.request_tracker.active_requests.pop(peer) loop = asyncio.get_event_loop() node_keys = await loop.run_in_executor(self._executor, list, map(keccak, msg)) missing = set(requested_node_keys).difference(node_keys) self._peer_missing_nodes[peer].update(missing) if missing: await self.request_nodes(missing) await self._process_nodes(zip(node_keys, msg)) elif isinstance(cmd, commands.GetBlockHeaders): query = cast(Dict[Any, Union[bool, int]], msg) request = HeaderRequest( query['block_number_or_hash'], query['max_headers'], query['skip'], cast(bool, query['reverse']), ) await self._handle_get_block_headers(peer, request) elif isinstance(cmd, commands.GetBlockBodies): # Only serve up to MAX_BODIES_FETCH items in every request. block_hashes = cast(List[Hash32], msg)[:eth_constants.MAX_BODIES_FETCH] await self._handler.handle_get_block_bodies(peer, block_hashes) elif isinstance(cmd, commands.GetReceipts): # Only serve up to MAX_RECEIPTS_FETCH items in every request. block_hashes = cast(List[Hash32], msg)[:eth_constants.MAX_RECEIPTS_FETCH] await self._handler.handle_get_receipts(peer, block_hashes) elif isinstance(cmd, commands.GetNodeData): # Only serve up to MAX_STATE_FETCH items in every request. node_hashes = cast(List[Hash32], msg)[:eth_constants.MAX_STATE_FETCH] await self._handler.handle_get_node_data(peer, node_hashes) else: self.logger.warn("%s not handled during StateSync, must be implemented", cmd) async def _handle_get_block_headers(self, peer: ETHPeer, request: HeaderRequest) -> None: headers = await self._handler.lookup_headers(request) peer.sub_proto.send_block_headers(headers) async def _cleanup(self) -> None: # We don't need to cancel() anything, but we yield control just so that the coroutines we # run in the background notice the cancel token has been triggered and return. # Also, don't use self.sleep() here as the cancel token will be triggered and that will # raise OperationCancelled. await asyncio.sleep(0) async def request_nodes(self, node_keys: Iterable[Hash32]) -> None: not_yet_requested = set(node_keys) while not_yet_requested: try: peer = await self.get_peer_for_request(not_yet_requested) except NoIdlePeers: self.logger.debug( "No idle peers have any of the trie nodes we want, sleeping a bit") await self.sleep(0.2) continue except NoEligiblePeers: self.request_tracker.missing[time.time()] = list(not_yet_requested) self.logger.debug( "No peers have any of the trie nodes in this batch, will retry later") # TODO: disconnect a peer if the pool is full return candidates = list(not_yet_requested.difference(self._peer_missing_nodes[peer])) batch = candidates[:eth_constants.MAX_STATE_FETCH] not_yet_requested = not_yet_requested.difference(batch) self.request_tracker.active_requests[peer] = (time.time(), batch) self.logger.debug("Requesting %d trie nodes to %s", len(batch), peer) peer.sub_proto.send_get_node_data(batch) async def _periodically_retry_timedout_and_missing(self) -> None: while self.is_running: timed_out = self.request_tracker.get_timed_out() if timed_out: self.logger.debug("Re-requesting %d timed out trie nodes", len(timed_out)) self._total_timeouts += len(timed_out) try: await self.request_nodes(timed_out) except OperationCancelled: break retriable_missing = self.request_tracker.get_retriable_missing() if retriable_missing: self.logger.debug("Re-requesting %d missing trie nodes", len(timed_out)) try: await self.request_nodes(retriable_missing) except OperationCancelled: break # Finally, sleep until the time either our oldest request is scheduled to timeout or # one of our missing batches is scheduled to be retried. next_timeout = self.request_tracker.get_next_timeout() try: await self.sleep(next_timeout - time.time()) except OperationCancelled: break async def _run(self) -> None: """Fetch all trie nodes starting from self.root_hash, and store them in self.db. Raises OperationCancelled if we're interrupted before that is completed. """ self._timer.start() self.logger.info("Starting state sync for root hash %s", encode_hex(self.root_hash)) asyncio.ensure_future(self._handle_msg_loop()) asyncio.ensure_future(self._periodically_report_progress()) asyncio.ensure_future(self._periodically_retry_timedout_and_missing()) with self.subscribe(self.peer_pool): while self.scheduler.has_pending_requests: # This ensures we yield control and give _handle_msg() a chance to process any nodes # we may have received already, also ensuring we exit when our cancel token is # triggered. await self.sleep(0) requests = self.scheduler.next_batch(eth_constants.MAX_STATE_FETCH) if not requests: # Although we frequently yield control above, to let our msg handler process # received nodes (scheduling new requests), there may be cases when the # pending nodes take a while to arrive thus causing the scheduler to run out # of new requests for a while. self.logger.debug("Scheduler queue is empty, sleeping a bit") await self.sleep(0.5) continue await self.request_nodes([request.node_key for request in requests]) self.logger.info("Finished state sync with root hash %s", encode_hex(self.root_hash)) async def _periodically_report_progress(self) -> None: while self.is_running: requested_nodes = sum( len(node_keys) for _, node_keys in self.request_tracker.active_requests.values()) msg = "processed=%d " % self._total_processed_nodes msg += "tnps=%d " % (self._total_processed_nodes / self._timer.elapsed) msg += "committed=%d " % self.scheduler.committed_nodes msg += "requested=%d " % requested_nodes msg += "scheduled=%d " % len(self.scheduler.requests) msg += "timeouts=%d" % self._total_timeouts self.logger.info("State-Sync: %s", msg) try: await self.sleep(self._report_interval) except OperationCancelled: break