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
