def send_block_to_node(self,
block_hash: Sha256Hash,
block_msg: Optional[TBlockMessage] = None) -> None:
if not self.node.should_process_block_hash(block_hash):
return
if block_msg is None:
block_msg = self.node.block_storage[block_hash]
self.connection.log_info("Forwarding block {} to node", block_hash)
assert block_msg is not None
self.connection.enqueue_msg(block_msg)
# TODO: revisit this metric for multi-node gateway
(handling_time, relay_desc
) = self.node.track_block_from_bdn_handling_ended(block_hash)
block_stats.add_block_event_by_block_hash(
block_hash,
BlockStatEventType.BLOCK_SENT_TO_BLOCKCHAIN_NODE,
network_num=self.node.network_num,
more_info="{} bytes; Handled in {}; R - {}; {}".format(
len(block_msg.rawbytes()),
stats_format.duration(handling_time),
relay_desc,
block_msg.extra_stats_data(),
),
)
def send_block_to_node(self,
block_hash: Sha256Hash,
block_msg: Optional[TBlockMessage] = None) -> None:
if not self.node.should_process_block_hash(block_hash):
return
if block_msg is None:
block_msg = self._blocks[block_hash]
logger.info("Forwarding block {} to blockchain node.", block_hash)
assert block_msg is not None
self.node.send_msg_to_node(block_msg)
(
handling_time,
relay_desc,
) = self.node.track_block_from_bdn_handling_ended(block_hash)
# if tracking detailed send info, log this event only after all
# bytes written to sockets
if not self.node.opts.track_detailed_sent_messages:
block_stats.add_block_event_by_block_hash(
block_hash,
BlockStatEventType.BLOCK_SENT_TO_BLOCKCHAIN_NODE,
network_num=self.node.network_num,
more_info="{} bytes; Handled in {}; R - {}; {}".format(
len(block_msg.rawbytes()),
stats_format.duration(handling_time),
relay_desc,
block_msg.extra_stats_data(),
),
)
def advance_bytes_written_to_socket(self, bytes_sent):
if self.message_tracker and self.message_tracker.is_sending_block_message():
assert self.node.opts.track_detailed_sent_messages
entry = self.message_tracker.messages[0]
super(AbstractGatewayBlockchainConnection, self).advance_bytes_written_to_socket(bytes_sent)
if not self.message_tracker.is_sending_block_message():
block_message = typing.cast(AbstractBlockMessage, entry.message)
block_message_queue_time = entry.queued_time
block_message_length = entry.length
block_hash = block_message.block_hash()
handling_time, relay_desc = self.node.track_block_from_bdn_handling_ended(block_hash)
block_stats.add_block_event_by_block_hash(block_hash,
BlockStatEventType.BLOCK_SENT_TO_BLOCKCHAIN_NODE,
network_num=self.network_num,
more_info="{} in {}; Handled in {}; R - {}; {}".format(
stats_format.byte_count(
block_message_length
),
stats_format.timespan(
block_message_queue_time,
time.time()
),
stats_format.duration(handling_time),
relay_desc,
block_message.extra_stats_data()
))
else:
super(AbstractGatewayBlockchainConnection, self).advance_bytes_written_to_socket(bytes_sent)
def _format_block_info_stats(self, block_info):
if block_info is None:
return ""
return "Compression: {}, {}" \
.format(stats_format.duration(block_info.duration_ms),
stats_format.percentage(block_info.compression_rate))
def _propagate_unencrypted_block_to_network(self, bx_block, connection,
block_info):
if block_info is None:
raise ValueError(
"Block info is required to propagate unencrypted block")
broadcast_message = BroadcastMessage(block_info.block_hash,
self._node.network_num,
is_encrypted=False,
blob=bx_block)
conns = self._node.broadcast(
broadcast_message,
connection,
connection_types=[ConnectionType.RELAY_BLOCK])
handling_duration = self._node.track_block_from_node_handling_ended(
block_info.block_hash)
block_stats.add_block_event_by_block_hash(
block_info.block_hash,
BlockStatEventType.ENC_BLOCK_SENT_FROM_GATEWAY_TO_NETWORK,
network_num=self._node.network_num,
requested_by_peer=False,
peers=conns,
more_info="Peers: {}; Unencrypted; {}; Handled in {}".format(
stats_format.connections(conns),
self._format_block_info_stats(block_info),
stats_format.duration(handling_duration)))
logger.info("Propagating block {} to the BDN.", block_info.block_hash)
return broadcast_message
def _propagate_encrypted_block_to_network(self, bx_block, connection,
block_info):
if block_info is None or block_info.block_hash is None:
block_hash = b"Unknown"
requested_by_peer = True
else:
block_hash = block_info.block_hash
requested_by_peer = False
encrypt_start_datetime = datetime.datetime.utcnow()
encrypt_start_timestamp = time.time()
encrypted_block, raw_cipher_hash = self._node.in_progress_blocks.encrypt_and_add_payload(
bx_block)
compressed_size = len(bx_block)
encrypted_size = len(encrypted_block)
encryption_details = "Encryption: {}; Size change: {}->{}bytes, {}".format(
stats_format.timespan(encrypt_start_timestamp, time.time()),
compressed_size, encrypted_size,
stats_format.ratio(encrypted_size, compressed_size))
block_stats.add_block_event_by_block_hash(
block_hash,
BlockStatEventType.BLOCK_ENCRYPTED,
start_date_time=encrypt_start_datetime,
end_date_time=datetime.datetime.utcnow(),
network_num=self._node.network_num,
matching_block_hash=convert.bytes_to_hex(raw_cipher_hash),
matching_block_type=StatBlockType.ENCRYPTED.value,
more_info=encryption_details)
cipher_hash = Sha256Hash(raw_cipher_hash)
broadcast_message = BroadcastMessage(cipher_hash,
self._node.network_num,
is_encrypted=True,
blob=encrypted_block)
conns = self._node.broadcast(
broadcast_message,
connection,
connection_types=[ConnectionType.RELAY_BLOCK])
handling_duration = self._node.track_block_from_node_handling_ended(
block_hash)
block_stats.add_block_event_by_block_hash(
cipher_hash,
BlockStatEventType.ENC_BLOCK_SENT_FROM_GATEWAY_TO_NETWORK,
network_num=self._node.network_num,
requested_by_peer=requested_by_peer,
peers=conns,
more_info="Peers: {}; {}; {}; Requested by peer: {}; Handled in {}"
.format(stats_format.connections(conns), encryption_details,
self._format_block_info_stats(block_info),
requested_by_peer,
stats_format.duration(handling_duration)))
self.register_for_block_receipts(cipher_hash, bx_block)
return broadcast_message
def get_info(self) -> Dict[str, Any]:
assert self.interval_data is not None
# pyre-fixme[16]: Optional type has no attribute `total_encryption_time`.
if self.interval_data.total_encryption_time > 0:
average_encryption_time = (
self.interval_data.total_encryption_time
/ self.interval_data.total_encrypted_msgs_count
)
else:
average_encryption_time = 0
# pyre-fixme[16]: Optional type has no attribute `total_decryption_time`.
if self.interval_data.total_decryption_time > 0:
average_decryption_time = (
self.interval_data.total_decryption_time
/ self.interval_data.total_decrypted_msgs_count
)
else:
average_decryption_time = 0
# pyre-fixme[16]: Optional type has no attribute `total_serialization_time`.
if self.interval_data.total_serialization_time > 0:
average_serialization_time = (
self.interval_data.total_serialization_time
/ self.interval_data.total_serialized_msgs_count
)
else:
average_serialization_time = 0
return {
# pyre-fixme[16]: Optional type has no attribute
# `total_encrypted_msgs_count`.
"total_encrypted_msgs_count": self.interval_data.total_encrypted_msgs_count,
"average_encryption_time": stats_format.duration(average_encryption_time * 1000),
"max_encryption_time": stats_format.duration(
# pyre-fixme[16]: Optional type has no attribute `max_encryption_time`.
self.interval_data.max_encryption_time * 1000
),
# pyre-fixme[16]: Optional type has no attribute
# `total_decrypted_msgs_count`.
"total_decrypted_msgs_count": self.interval_data.total_decrypted_msgs_count,
"average_decryption_time": stats_format.duration(average_decryption_time * 1000),
"max_decryption_time": stats_format.duration(
# pyre-fixme[16]: Optional type has no attribute `max_decryption_time`.
self.interval_data.max_decryption_time * 1000
),
# pyre-fixme[16]: Optional type has no attribute
# `total_serialized_msgs_count`.
"total_serialized_msgs_count": self.interval_data.total_serialized_msgs_count,
"average_serialization_time": stats_format.duration(average_serialization_time * 1000),
"max_serialization_time": stats_format.duration(
# pyre-fixme[16]: Optional type has no attribute
# `max_serialization_time`.
self.interval_data.max_serialization_time * 1000
),
}
def get_info(self) -> Dict[str, Any]:
if self.interval_data.total_encryption_time > 0:
average_encryption_time = (
self.interval_data.total_encryption_time /
self.interval_data.total_encrypted_msgs_count)
else:
average_encryption_time = 0
if self.interval_data.total_decryption_time > 0:
average_decryption_time = (
self.interval_data.total_decryption_time /
self.interval_data.total_decrypted_msgs_count)
else:
average_decryption_time = 0
if self.interval_data.total_serialization_time > 0:
average_serialization_time = (
self.interval_data.total_serialization_time /
self.interval_data.total_serialized_msgs_count)
else:
average_serialization_time = 0
return {
"total_encrypted_msgs_count":
self.interval_data.total_encrypted_msgs_count,
"average_encryption_time":
stats_format.duration(average_encryption_time * 1000),
"max_encryption_time":
stats_format.duration(self.interval_data.max_encryption_time *
1000),
"total_decrypted_msgs_count":
self.interval_data.total_decrypted_msgs_count,
"average_decryption_time":
stats_format.duration(average_decryption_time * 1000),
"max_decryption_time":
stats_format.duration(self.interval_data.max_decryption_time *
1000),
"total_serialized_msgs_count":
self.interval_data.total_serialized_msgs_count,
"average_serialization_time":
stats_format.duration(average_serialization_time * 1000),
"max_serialization_time":
stats_format.duration(self.interval_data.max_serialization_time *
1000),
}
def _propagate_unencrypted_block_to_network(self, bx_block, connection, block_info):
if block_info is None:
raise ValueError("Block info is required to propagate unencrypted block")
is_consensus_msg, = struct.unpack_from("?", bx_block[8:9])
broadcast_type = BroadcastMessageType.CONSENSUS if is_consensus_msg else BroadcastMessageType.BLOCK
broadcast_message = BroadcastMessage(block_info.block_hash, self._node.network_num,
broadcast_type=broadcast_type, is_encrypted=False, blob=bx_block)
conns = self._node.broadcast(broadcast_message, connection, connection_types=[ConnectionType.RELAY_BLOCK])
handling_duration = self._node.track_block_from_node_handling_ended(block_info.block_hash)
block_stats.add_block_event_by_block_hash(block_info.block_hash,
BlockStatEventType.ENC_BLOCK_SENT_FROM_GATEWAY_TO_NETWORK,
network_num=self._node.network_num,
broadcast_type=broadcast_type,
requested_by_peer=False,
peers=map(lambda conn: (conn.peer_desc, conn.CONNECTION_TYPE), conns),
more_info="Peers: {}; Unencrypted; {}; Handled in {}".format(
stats_format.connections(conns),
self._format_block_info_stats(block_info),
stats_format.duration(handling_duration)))
logger.info("Propagating block {} to the BDN.", block_info.block_hash)
return broadcast_message
def push(
self,
block_hash: Sha256Hash,
# pyre-fixme[9]: block_msg is declared to have type `Union[BlockOntMessage, OntConsensusMessage]`
# but is used as type `None`.
block_msg: Union[BlockOntMessage, OntConsensusMessage] = None,
waiting_for_recovery: bool = False,
):
if self.node.opts.is_consensus and isinstance(block_msg,
BlockOntMessage):
return
super().push(block_hash, block_msg, waiting_for_recovery)
self.connection.log_debug(
"Added block {} to queuing service (waiting for recovery: {})",
block_hash, waiting_for_recovery)
self._clean_block_queue()
if block_msg is None:
return
try:
block_msg.validate_payload(block_msg.buf,
block_msg.unpack(block_msg.buf))
except ChecksumError:
logger.debug(
"Encountered checksum error, which can be caused by duplicate transaction. "
"Stop processing block {}", block_hash)
return
block_hash = cast(OntObjectHash, block_hash)
if isinstance(block_msg, BlockOntMessage):
if block_hash in self._blocks and not waiting_for_recovery:
self.node.update_current_block_height(block_msg.height(),
block_hash)
inv_msg = InvOntMessage(
magic=block_msg.magic(),
inv_type=InventoryOntType.MSG_BLOCK,
blocks=[block_hash],
)
self.connection.enqueue_msg(inv_msg)
# pyre-fixme[25]: `block_msg` has type `OntConsensusMessage`,
# assertion `not isinstance(block_msg, bxgateway.messages.ont.consensus_ont_message.OntConsensusMessage)`
# will always fail.
elif isinstance(block_msg, OntConsensusMessage):
if block_hash in self._blocks and not waiting_for_recovery:
self.connection.log_info(
"Sending consensus message with block hash {} to blockchain node",
block_hash,
)
self.connection.enqueue_msg(block_msg)
handling_time, relay_desc = self.node.track_block_from_bdn_handling_ended(
block_hash)
block_stats.add_block_event_by_block_hash(
block_hash,
BlockStatEventType.BLOCK_SENT_TO_BLOCKCHAIN_NODE,
network_num=self.node.network_num,
broadcast_type=BroadcastMessageType.CONSENSUS,
more_info="{} bytes; Handled in {}; R - {}; {}".format(
len(block_msg.rawbytes()),
stats_format.duration(handling_time),
relay_desc,
block_msg.extra_stats_data(),
),
)
def _handle_decrypted_block(
self,
bx_block: memoryview,
connection: AbstractRelayConnection,
encrypted_block_hash_hex: Optional[str] = None,
recovered: bool = False,
recovered_txs_source: Optional[RecoveredTxsSource] = None) -> None:
transaction_service = self._node.get_tx_service()
message_converter = self._node.message_converter
assert message_converter is not None
valid_block = self._validate_compressed_block_header(bx_block)
if not valid_block.is_valid:
reason = valid_block.reason
assert reason is not None
block_stats.add_block_event_by_block_hash(
valid_block.block_hash,
BlockStatEventType.BLOCK_DECOMPRESSED_FAILED_VALIDATION,
connection.network_num,
more_info=reason)
return
# TODO: determine if a real block or test block. Discard if test block.
if self._node.remote_node_conn or self._node.has_active_blockchain_peer(
):
try:
(block_message, block_info, unknown_sids,
unknown_hashes) = message_converter.bx_block_to_block(
bx_block, transaction_service)
block_content_debug_utils.log_compressed_block_debug_info(
transaction_service, bx_block)
except MessageConversionError as e:
block_stats.add_block_event_by_block_hash(
e.msg_hash,
BlockStatEventType.BLOCK_CONVERSION_FAILED,
network_num=connection.network_num,
conversion_type=e.conversion_type.value)
transaction_service.on_block_cleaned_up(e.msg_hash)
connection.log_warning(log_messages.FAILED_TO_DECOMPRESS_BLOCK,
e.msg_hash, e)
return
else:
connection.log_warning(log_messages.LACK_BLOCKCHAIN_CONNECTION)
return
block_hash = block_info.block_hash
all_sids = block_info.short_ids
if encrypted_block_hash_hex is not None:
block_stats.add_block_event_by_block_hash(
block_hash,
BlockStatEventType.BLOCK_TO_ENC_BLOCK_MATCH,
matching_block_hash=encrypted_block_hash_hex,
matching_block_type=StatBlockType.ENCRYPTED.value,
network_num=connection.network_num)
self.cancel_hold_timeout(block_hash, connection)
if recovered:
block_stats.add_block_event_by_block_hash(
block_hash,
BlockStatEventType.BLOCK_RECOVERY_COMPLETED,
network_num=connection.network_num,
more_info=str(recovered_txs_source))
if block_hash in self._node.blocks_seen.contents:
block_stats.add_block_event_by_block_hash(
block_hash,
BlockStatEventType.BLOCK_DECOMPRESSED_IGNORE_SEEN,
start_date_time=block_info.start_datetime,
end_date_time=block_info.end_datetime,
network_num=connection.network_num,
prev_block_hash=block_info.prev_block_hash,
original_size=block_info.original_size,
compressed_size=block_info.compressed_size,
txs_count=block_info.txn_count,
blockchain_network=self._node.opts.blockchain_network,
blockchain_protocol=self._node.opts.blockchain_protocol,
matching_block_hash=block_info.compressed_block_hash,
matching_block_type=StatBlockType.COMPRESSED.value,
more_info=stats_format.duration(block_info.duration_ms))
self._node.track_block_from_bdn_handling_ended(block_hash)
transaction_service.track_seen_short_ids(block_hash, all_sids)
connection.log_info("Discarding duplicate block {} from the BDN.",
block_hash)
if block_message is not None:
self._node.on_block_received_from_bdn(block_hash,
block_message)
if self._node.block_queuing_service_manager.get_block_data(
block_hash) is None:
self._node.block_queuing_service_manager.store_block_data(
block_hash, block_message)
return
if not recovered:
connection.log_info("Received block {} from the BDN.", block_hash)
else:
connection.log_info("Successfully recovered block {}.", block_hash)
if block_message is not None:
compression_rate = block_info.compression_rate
assert compression_rate is not None
block_stats.add_block_event_by_block_hash(
block_hash,
BlockStatEventType.BLOCK_DECOMPRESSED_SUCCESS,
start_date_time=block_info.start_datetime,
end_date_time=block_info.end_datetime,
network_num=connection.network_num,
prev_block_hash=block_info.prev_block_hash,
original_size=block_info.original_size,
compressed_size=block_info.compressed_size,
txs_count=block_info.txn_count,
blockchain_network=self._node.opts.blockchain_network,
blockchain_protocol=self._node.opts.blockchain_protocol,
matching_block_hash=block_info.compressed_block_hash,
matching_block_type=StatBlockType.COMPRESSED.value,
more_info="Compression rate {}, Decompression time {}, "
"Queued behind {} blocks".format(
stats_format.percentage(compression_rate),
stats_format.duration(block_info.duration_ms),
self._node.block_queuing_service_manager.
get_length_of_each_queuing_service_stats_format()))
self._on_block_decompressed(block_message)
if recovered or self._node.block_queuing_service_manager.is_in_any_queuing_service(
block_hash):
self._node.block_queuing_service_manager.update_recovered_block(
block_hash, block_message)
else:
self._node.block_queuing_service_manager.push(
block_hash, block_message)
gateway_bdn_performance_stats_service.log_block_from_bdn()
self._node.on_block_received_from_bdn(block_hash, block_message)
transaction_service.track_seen_short_ids(block_hash, all_sids)
self._node.publish_block(None, block_hash, block_message,
FeedSource.BDN_SOCKET)
self._node.log_blocks_network_content(self._node.network_num,
block_message)
else:
if self._node.block_queuing_service_manager.is_in_any_queuing_service(
block_hash) and not recovered:
connection.log_trace(
"Handling already queued block again. Ignoring.")
return
self._node.block_recovery_service.add_block(
bx_block, block_hash, unknown_sids, unknown_hashes)
block_stats.add_block_event_by_block_hash(
block_hash,
BlockStatEventType.BLOCK_DECOMPRESSED_WITH_UNKNOWN_TXS,
start_date_time=block_info.start_datetime,
end_date_time=block_info.end_datetime,
network_num=connection.network_num,
prev_block_hash=block_info.prev_block_hash,
original_size=block_info.original_size,
compressed_size=block_info.compressed_size,
txs_count=block_info.txn_count,
blockchain_network=self._node.opts.blockchain_network,
blockchain_protocol=self._node.opts.blockchain_protocol,
matching_block_hash=block_info.compressed_block_hash,
matching_block_type=StatBlockType.COMPRESSED.value,
more_info="{} sids, {} hashes, [{},...]".format(
len(unknown_sids), len(unknown_hashes), unknown_sids[:5]))
connection.log_info(
"Block {} requires short id recovery. Querying BDN...",
block_hash)
self.start_transaction_recovery(unknown_sids, unknown_hashes,
block_hash, connection)
if recovered:
# should never happen –– this should not be called on blocks that have not recovered
connection.log_error(log_messages.BLOCK_DECOMPRESSION_FAILURE,
block_hash)
else:
self._node.block_queuing_service_manager.push(
block_hash, waiting_for_recovery=True)
def _process_and_broadcast_block(
self, block_message,
connection: AbstractGatewayBlockchainConnection) -> None:
"""
Compresses and propagates block message if enabled, else return.
:param block_message: block message to propagate
:param connection: receiving connection (AbstractBlockchainConnection)
"""
block_hash = block_message.block_hash()
message_converter = self._node.message_converter
assert message_converter is not None
try:
bx_block, block_info = message_converter.block_to_bx_block(
block_message, self._node.get_tx_service(),
self._node.opts.enable_block_compression,
self._node.network.min_tx_age_seconds)
except MessageConversionError as e:
block_stats.add_block_event_by_block_hash(
e.msg_hash,
BlockStatEventType.BLOCK_CONVERSION_FAILED,
network_num=connection.network_num,
conversion_type=e.conversion_type.value)
connection.log_error(log_messages.BLOCK_COMPRESSION_FAIL,
e.msg_hash, e)
return
if block_info.ignored_short_ids:
assert block_info.ignored_short_ids is not None
logger.debug("Ignoring {} new SIDs for {}: {}",
len(block_info.ignored_short_ids),
block_info.block_hash, block_info.ignored_short_ids)
compression_rate = block_info.compression_rate
assert compression_rate is not None
block_stats.add_block_event_by_block_hash(
block_hash,
BlockStatEventType.BLOCK_COMPRESSED,
start_date_time=block_info.start_datetime,
end_date_time=block_info.end_datetime,
network_num=connection.network_num,
prev_block_hash=block_info.prev_block_hash,
original_size=block_info.original_size,
txs_count=block_info.txn_count,
blockchain_network=self._node.opts.blockchain_network,
blockchain_protocol=self._node.opts.blockchain_protocol,
matching_block_hash=block_info.compressed_block_hash,
matching_block_type=StatBlockType.COMPRESSED.value,
more_info="Compression: {}->{} bytes, {}, {}; Tx count: {}".format(
block_info.original_size, block_info.compressed_size,
stats_format.percentage(compression_rate),
stats_format.duration(block_info.duration_ms),
block_info.txn_count))
if self._node.opts.dump_short_id_mapping_compression:
mapping = {}
for short_id in block_info.short_ids:
tx_hash = self._node.get_tx_service().get_transaction(
short_id).hash
assert tx_hash is not None
mapping[short_id] = convert.bytes_to_hex(tx_hash.binary)
with open(
f"{self._node.opts.dump_short_id_mapping_compression_path}/"
f"{convert.bytes_to_hex(block_hash.binary)}", "w") as f:
f.write(str(mapping))
self._process_and_broadcast_compressed_block(bx_block, connection,
block_info, block_hash)
self._node.log_blocks_network_content(self._node.network_num,
block_message)
def process_message(self):
"""
Processes the next bytes on the socket's inputbuffer.
Returns 0 in order to avoid being rescheduled if this was an alarm.
"""
# pylint: disable=too-many-return-statements, too-many-branches, too-many-statements
logger.trace("START PROCESSING from {}", self)
start_time = time.time()
messages_processed = defaultdict(int)
total_bytes_processed = 0
self.processing_message_index = 0
while True:
input_buffer_len_before = self.inputbuf.length
is_full_msg = False
payload_len = None
msg = None
msg_type = None
try:
# abort message processing if connection has been closed
if not self.socket_connection.alive:
return
is_full_msg, should_process, msg_type, payload_len = self.pre_process_msg()
if not should_process and is_full_msg:
self.pop_next_bytes(payload_len)
continue
self.message_validator.validate(
is_full_msg,
msg_type,
self.header_size,
payload_len,
self.inputbuf
)
self.process_msg_type(msg_type, is_full_msg, payload_len)
if not is_full_msg:
break
msg = self.pop_next_message(payload_len)
total_bytes_processed += len(msg.rawbytes())
# If there was some error in parsing this message, then continue the loop.
if msg is None:
if self._report_bad_message():
return
continue
# Full messages must be one of the handshake messages if the connection isn't established yet.
if (
not self.established and msg_type not in self.hello_messages
):
self.log_warning(log_messages.UNEXPECTED_MESSAGE, msg_type)
self.mark_for_close()
return
if self.log_throughput:
hooks.add_throughput_event(
NetworkDirection.INBOUND,
msg_type,
len(msg.rawbytes()),
self.peer_desc,
self.peer_id
)
if not logger.isEnabledFor(msg.log_level()) and logger.isEnabledFor(LogLevel.INFO):
self._debug_message_tracker[msg_type] += 1
elif len(self._debug_message_tracker) > 0:
self.log_debug(
"Processed the following messages types: {} over {:.2f} seconds.",
self._debug_message_tracker,
time.time() - self._last_debug_message_log_time
)
self._debug_message_tracker.clear()
self._last_debug_message_log_time = time.time()
self._log_message(msg.log_level(), "Processing message: {}", msg)
if msg_type in self.message_handlers:
msg_handler = self.message_handlers[msg_type]
handler_start = time.time()
msg_handler(msg)
performance_utils.log_operation_duration(
msg_handling_logger,
"Single message handler",
handler_start,
constants.MSG_HANDLERS_CYCLE_DURATION_WARN_THRESHOLD_S,
connection=self,
handler=msg_handler,
message=msg
)
messages_processed[msg_type] += 1
# TODO: Investigate possible solutions to recover from PayloadLenError errors
except PayloadLenError as e:
self.log_error(log_messages.COULD_NOT_PARSE_MESSAGE, e.msg)
self.mark_for_close()
return
except MemoryError as e:
self.log_error(log_messages.OUT_OF_MEMORY, e, exc_info=True)
self.log_debug(
"Failed message bytes: {}",
self._get_last_msg_bytes(msg, input_buffer_len_before, payload_len)
)
raise
except UnauthorizedMessageError as e:
self.log_error(log_messages.UNAUTHORIZED_MESSAGE, e.msg.MESSAGE_TYPE, self.peer_desc)
self.log_debug(
"Failed message bytes: {}",
self._get_last_msg_bytes(msg, input_buffer_len_before, payload_len)
)
# give connection a chance to restore its state and get ready to process next message
self.clean_up_current_msg(payload_len, input_buffer_len_before == self.inputbuf.length)
if self._report_bad_message():
return
except MessageValidationError as e:
if self.node.NODE_TYPE not in NodeType.GATEWAY_TYPE:
if isinstance(e, ControlFlagValidationError):
if e.is_cancelled_cut_through:
self.log_debug(
"Message validation failed for {} message: {}. Probably cut-through cancellation",
msg_type, e.msg)
else:
self.log_warning(log_messages.MESSAGE_VALIDATION_FAILED, msg_type, e.msg)
else:
self.log_warning(log_messages.MESSAGE_VALIDATION_FAILED, msg_type, e.msg)
else:
self.log_debug("Message validation failed for {} message: {}.", msg_type, e.msg)
self.log_debug("Failed message bytes: {}",
self._get_last_msg_bytes(msg, input_buffer_len_before, payload_len))
if is_full_msg:
self.clean_up_current_msg(payload_len, input_buffer_len_before == self.inputbuf.length)
else:
self.log_error(log_messages.UNABLE_TO_RECOVER_PARTIAL_MESSAGE)
self.mark_for_close()
return
if self._report_bad_message():
return
except NonVersionMessageError as e:
if e.is_known:
self.log_debug("Received invalid handshake request on {}:{}, {}", self.peer_ip, self.peer_port,
e.msg)
else:
self.log_warning(log_messages.INVALID_HANDSHAKE, self.peer_ip, self.peer_port, e.msg)
self.log_debug("Failed message bytes: {}",
self._get_last_msg_bytes(msg, input_buffer_len_before, payload_len))
self.mark_for_close()
return
# TODO: Throw custom exception for any errors that come from input that has not been
# validated and only catch that subclass of exceptions
# pylint: disable=broad-except
except Exception as e:
# Attempt to recover connection by removing bad full message
if is_full_msg:
self.log_error(log_messages.TRYING_TO_RECOVER_MESSAGE, e, exc_info=True)
self.log_debug("Failed message bytes: {}",
self._get_last_msg_bytes(msg, input_buffer_len_before, payload_len))
# give connection a chance to restore its state and get ready to process next message
self.clean_up_current_msg(payload_len, input_buffer_len_before == self.inputbuf.length)
# Connection is unable to recover from message processing error if incomplete message is received
else:
self.log_error(log_messages.UNABLE_TO_RECOVER_FULL_MESSAGE, e, exc_info=True)
self.log_debug("Failed message bytes: {}",
self._get_last_msg_bytes(msg, input_buffer_len_before, payload_len))
self.mark_for_close()
return
if self._report_bad_message():
return
else:
self.num_bad_messages = 0
self.processing_message_index += 1
performance_utils.log_operation_duration(msg_handling_logger,
"Message handlers",
start_time,
constants.MSG_HANDLERS_DURATION_WARN_THRESHOLD_S,
connection=self, count=messages_processed)
duration_ms = (time.time() - start_time) * 1000
logger.trace("DONE PROCESSING from {}. Bytes processed: {}. Messages processed: {}. Duration: {}",
self, total_bytes_processed, messages_processed, stats_format.duration(duration_ms))
def process_compact_block(
self, block_message: CompactBlockBtcMessage, connection: BtcNodeConnection
) -> CompactBlockCompressionResult:
"""
Process compact block for processing on timeout if hold message received.
If no hold exists, compress and broadcast block immediately.
:param block_message: compact block message to process
:param connection: receiving connection (AbstractBlockchainConnection)
"""
block_hash = block_message.block_hash()
parse_result = self._node.message_converter.compact_block_to_bx_block( # pyre-ignore
block_message,
self._node.get_tx_service()
)
block_info = parse_result.block_info
if parse_result.success:
block_stats.add_block_event_by_block_hash(
block_hash,
BlockStatEventType.COMPACT_BLOCK_COMPRESSED_SUCCESS,
network_num=connection.network_num,
start_date_time=block_info.start_datetime,
end_date_time=block_info.end_datetime,
duration=block_info.duration_ms / 1000,
success=parse_result.success,
txs_count=parse_result.block_info.txn_count,
prev_block_hash=parse_result.block_info.prev_block_hash,
original_size=block_info.original_size,
more_info="Compression: {}->{} bytes, {}, {}; Tx count: {}".format(
block_info.original_size,
block_info.compressed_size,
stats_format.percentage(block_info.compression_rate),
stats_format.duration(block_info.duration_ms),
block_info.txn_count)
)
self._node.block_cleanup_service.on_new_block_received(block_hash, block_message.prev_block_hash())
self._process_and_broadcast_compressed_block(
parse_result.bx_block,
connection,
parse_result.block_info,
block_hash
)
else:
missing_indices = parse_result.missing_indices
missing_indices_count = 0 if missing_indices is None else len(missing_indices)
start_datetime = block_info.start_datetime
end_datetime = datetime.utcnow()
duration = (end_datetime - start_datetime).total_seconds()
block_stats.add_block_event_by_block_hash(
block_hash,
BlockStatEventType.COMPACT_BLOCK_COMPRESSED_FAILED,
network_num=connection.network_num,
start_date_time=start_datetime,
end_date_time=end_datetime,
duration=duration,
success=parse_result.success,
missing_short_id_count=missing_indices_count,
more_info="{:.2f}ms".format(
duration * 1000
)
)
logger.warning(log_messages.UNKNOWN_SHORT_IDS,
missing_indices_count)
return parse_result
def msg_consensus(self, msg: OntConsensusMessage):
if not self.node.opts.is_consensus:
return
if msg.consensus_data_type() != ont_constants.BLOCK_PROPOSAL_CONSENSUS_MESSAGE_TYPE:
return
block_hash = msg.block_hash()
node = self.connection.node
if not node.should_process_block_hash(block_hash):
return
node.block_cleanup_service.on_new_block_received(block_hash, msg.prev_block_hash())
block_stats.add_block_event_by_block_hash(block_hash,
BlockStatEventType.BLOCK_RECEIVED_FROM_BLOCKCHAIN_NODE,
network_num=self.connection.network_num,
broadcast_type=BroadcastMessageType.CONSENSUS,
more_info="Protocol: {}, Network: {}".format(
node.opts.blockchain_protocol,
node.opts.blockchain_network
),
msg_size=len(msg.rawbytes())
)
if block_hash in self.connection.node.blocks_seen.contents:
self.node.on_block_seen_by_blockchain_node(block_hash, self.connection)
block_stats.add_block_event_by_block_hash(block_hash,
BlockStatEventType.BLOCK_RECEIVED_FROM_BLOCKCHAIN_NODE_IGNORE_SEEN,
network_num=self.connection.network_num,
broadcast_type=BroadcastMessageType.CONSENSUS)
self.connection.log_info(
"Discarding duplicate consensus block {} from local blockchain node.",
block_hash
)
return
node.track_block_from_node_handling_started(block_hash)
self.connection.log_info(
"Processing consensus block {} from local blockchain node.",
block_hash
)
# Broadcast BlockHoldingMessage through relays and gateways
conns = self.node.broadcast(BlockHoldingMessage(block_hash, self.node.network_num),
broadcasting_conn=self.connection, prepend_to_queue=True,
connection_types=[ConnectionType.RELAY_BLOCK, ConnectionType.GATEWAY])
if len(conns) > 0:
block_stats.add_block_event_by_block_hash(block_hash,
BlockStatEventType.BLOCK_HOLD_SENT_BY_GATEWAY_TO_PEERS,
network_num=self.node.network_num,
broadcast_type=BroadcastMessageType.CONSENSUS,
peers=conns
)
try:
bx_block, block_info = self.node.consensus_message_converter.block_to_bx_block(
msg,
self.node.get_tx_service(),
self.node.opts.enable_block_compression,
self.node.network.min_tx_age_seconds
)
except MessageConversionError as e:
block_stats.add_block_event_by_block_hash(
e.msg_hash,
BlockStatEventType.BLOCK_CONVERSION_FAILED,
network_num=self.connection.network_num,
broadcast_type=BroadcastMessageType.CONSENSUS,
conversion_type=e.conversion_type.value
)
self.connection.log_error(log_messages.BLOCK_COMPRESSION_FAIL_ONT_CONSENSUS, e.msg_hash, e)
return
if block_info.ignored_short_ids:
self.connection.log_debug(
"Ignoring {} new SIDs for {}: {}",
len(block_info.ignored_short_ids), block_info.block_hash, block_info.ignored_short_ids
)
block_stats.add_block_event_by_block_hash(block_hash,
BlockStatEventType.BLOCK_COMPRESSED,
start_date_time=block_info.start_datetime,
end_date_time=block_info.end_datetime,
network_num=self.connection.network_num,
broadcast_type=BroadcastMessageType.CONSENSUS,
prev_block_hash=block_info.prev_block_hash,
original_size=block_info.original_size,
txs_count=block_info.txn_count,
blockchain_network=self.node.opts.blockchain_network,
blockchain_protocol=self.node.opts.blockchain_protocol,
matching_block_hash=block_info.compressed_block_hash,
matching_block_type=StatBlockType.COMPRESSED.value,
more_info="Consensus compression: {}->{} bytes, {}, {}; "
"Tx count: {}".format(
block_info.original_size,
block_info.compressed_size,
stats_format.percentage(block_info.compression_rate),
stats_format.duration(block_info.duration_ms),
block_info.txn_count
)
)
self.node.block_processing_service._process_and_broadcast_compressed_block(
bx_block, self.connection, block_info, block_hash
)
def push(
self,
block_hash: Sha256Hash,
# pyre-fixme[9]: block_msg is declared to have type `Union[BlockOntMessage, OntConsensusMessage]`
# but is used as type `None`.
block_msg: Union[BlockOntMessage, OntConsensusMessage] = None,
waiting_for_recovery: bool = False,
):
if self.node.opts.is_consensus and isinstance(block_msg,
BlockOntMessage):
return
# pyre-fixme[6]: Expected `Optional[Variable[bxgateway.services.abstract_block_queuing_service.TBlockMessage
# (bound to bxcommon.messages.abstract_block_message.AbstractBlockMessage)]]` for 2nd positional only
# parameter to call `AbstractBlockQueuingService.push` but got `Union[BlockOntMessage, OntConsensusMessage]`.
super().push(block_hash, block_msg, waiting_for_recovery)
logger.debug("Added block {} to queuing service", block_hash)
self._clean_block_queue()
if block_msg is None:
return
try:
block_msg.validate_payload(block_msg.buf,
block_msg.unpack(block_msg.buf))
except ChecksumError:
logger.debug(
"Encountered checksum error, which can be caused by duplicate transaction. "
"Stop processing block {}", block_hash)
return
block_hash = cast(OntObjectHash, block_hash)
if isinstance(block_msg, BlockOntMessage):
if block_hash in self._blocks and not waiting_for_recovery:
self.node.update_current_block_height(block_msg.height(),
block_hash)
inv_msg = InvOntMessage(
magic=block_msg.magic(),
inv_type=InventoryOntType.MSG_BLOCK,
blocks=[block_hash],
)
self.node.send_msg_to_node(inv_msg)
# pyre-fixme[25]: `block_msg` has type `OntConsensusMessage`,
# assertion `not isinstance(block_msg, bxgateway.messages.ont.consensus_ont_message.OntConsensusMessage)`
# will always fail.
elif isinstance(block_msg, OntConsensusMessage):
if block_hash in self._blocks and not waiting_for_recovery:
logger.info(
"Sending consensus message with block hash {} to blockchain node",
block_hash)
# self.node.block_queuing_service.send_block_to_node(block_hash)
# the above one line is good, except for the wrong broadcast type in BLOCK_SENT_TO_BLOCKCHAIN_NODE
self.node.send_msg_to_node(block_msg)
handling_time, relay_desc = self.node.track_block_from_bdn_handling_ended(
block_hash)
if not self.node.opts.track_detailed_sent_messages:
block_stats.add_block_event_by_block_hash(
block_hash,
BlockStatEventType.BLOCK_SENT_TO_BLOCKCHAIN_NODE,
network_num=self.node.network_num,
broadcast_type=BroadcastMessageType.CONSENSUS,
more_info="{} bytes; Handled in {}; R - {}; {}".format(
len(block_msg.rawbytes()),
stats_format.duration(handling_time),
relay_desc,
block_msg.extra_stats_data(),
),
)
def _handle_decrypted_consensus_block(
self,
bx_block: memoryview,
connection: AbstractRelayConnection,
encrypted_block_hash_hex: Optional[str] = None,
recovered: bool = False,
recovered_txs_source: Optional[RecoveredTxsSource] = None
):
transaction_service = self._node.get_tx_service()
if self._node.has_active_blockchain_peer() or self._node.remote_node_conn:
try:
block_message, block_info, unknown_sids, unknown_hashes = \
self._node.consensus_message_converter.bx_block_to_block(bx_block, transaction_service)
except MessageConversionError as e:
block_stats.add_block_event_by_block_hash(
e.msg_hash,
BlockStatEventType.BLOCK_CONVERSION_FAILED,
network_num=connection.network_num,
broadcast_type=BroadcastMessageType.CONSENSUS,
conversion_type=e.conversion_type.value
)
transaction_service.on_block_cleaned_up(e.msg_hash)
connection.log_warning(log_messages.FAILED_TO_DECOMPRESS_BLOCK_ONT_CONSENSUS, e.msg_hash, e)
return
else:
connection.log_warning(log_messages.LACK_BLOCKCHAIN_CONNECTION_ONT_CONSENSUS)
return
block_hash = block_info.block_hash
all_sids = block_info.short_ids
if encrypted_block_hash_hex is not None:
block_stats.add_block_event_by_block_hash(block_hash,
BlockStatEventType.BLOCK_TO_ENC_BLOCK_MATCH,
matching_block_hash=encrypted_block_hash_hex,
matching_block_type=StatBlockType.ENCRYPTED.value,
network_num=connection.network_num,
broadcast_type=BroadcastMessageType.CONSENSUS)
self.cancel_hold_timeout(block_hash, connection)
if recovered:
block_stats.add_block_event_by_block_hash(block_hash,
BlockStatEventType.BLOCK_RECOVERY_COMPLETED,
network_num=connection.network_num,
broadcast_type=BroadcastMessageType.CONSENSUS,
more_info=str(recovered_txs_source))
if block_hash in self._node.blocks_seen.contents:
block_stats.add_block_event_by_block_hash(block_hash, BlockStatEventType.BLOCK_DECOMPRESSED_IGNORE_SEEN,
start_date_time=block_info.start_datetime,
end_date_time=block_info.end_datetime,
network_num=connection.network_num,
broadcast_type=BroadcastMessageType.CONSENSUS,
prev_block_hash=block_info.prev_block_hash,
original_size=block_info.original_size,
compressed_size=block_info.compressed_size,
txs_count=block_info.txn_count,
blockchain_network=self._node.opts.blockchain_protocol,
blockchain_protocol=self._node.opts.blockchain_network,
matching_block_hash=block_info.compressed_block_hash,
matching_block_type=StatBlockType.COMPRESSED.value,
more_info=stats_format.duration(block_info.duration_ms))
self._node.track_block_from_bdn_handling_ended(block_hash)
transaction_service.track_seen_short_ids(block_hash, all_sids)
connection.log_info(
"Discarding duplicate consensus block {} from the BDN.",
block_hash
)
return
if not recovered:
connection.log_info("Received consensus block {} from the BDN.", block_hash)
else:
connection.log_info("Successfully recovered consensus block {}.", block_hash)
if block_message is not None:
block_stats.add_block_event_by_block_hash(block_hash, BlockStatEventType.BLOCK_DECOMPRESSED_SUCCESS,
start_date_time=block_info.start_datetime,
end_date_time=block_info.end_datetime,
network_num=connection.network_num,
broadcast_type=BroadcastMessageType.CONSENSUS,
prev_block_hash=block_info.prev_block_hash,
original_size=block_info.original_size,
compressed_size=block_info.compressed_size,
txs_count=block_info.txn_count,
blockchain_network=self._node.opts.blockchain_protocol,
blockchain_protocol=self._node.opts.blockchain_network,
matching_block_hash=block_info.compressed_block_hash,
matching_block_type=StatBlockType.COMPRESSED.value,
peer=connection.peer_desc,
more_info="Consensus compression rate {}, Decompression time {}, "
"Queued behind {} blocks".format(
stats_format.percentage(block_info.compression_rate),
stats_format.duration(block_info.duration_ms),
self._node.block_queueing_service_manager.get_length_of_each_queuing_service_stats_format()))
if recovered or block_hash in self._node.block_queueing_service_manager:
self._node.block_queueing_service_manager.update_recovered_block(block_hash, block_message)
else:
self._node.block_queueing_service_manager.push(block_hash, block_message)
self._node.block_recovery_service.cancel_recovery_for_block(block_hash)
# self._node.blocks_seen.add(block_hash)
transaction_service.track_seen_short_ids(block_hash, all_sids)
else:
if block_hash in self._node.block_queueing_service_manager and not recovered:
connection.log_trace("Handling already queued consensus block again. Ignoring.")
return
self._node.block_recovery_service.add_block(bx_block, block_hash, unknown_sids, unknown_hashes)
block_stats.add_block_event_by_block_hash(block_hash,
BlockStatEventType.BLOCK_DECOMPRESSED_WITH_UNKNOWN_TXS,
start_date_time=block_info.start_datetime,
end_date_time=block_info.end_datetime,
network_num=connection.network_num,
broadcast_type=BroadcastMessageType.CONSENSUS,
prev_block_hash=block_info.prev_block_hash,
original_size=block_info.original_size,
compressed_size=block_info.compressed_size,
txs_count=block_info.txn_count,
blockchain_network=self._node.opts.blockchain_protocol,
blockchain_protocol=self._node.opts.blockchain_network,
matching_block_hash=block_info.compressed_block_hash,
matching_block_type=StatBlockType.COMPRESSED.value,
more_info="{} sids, {} hashes".format(
len(unknown_sids), len(unknown_hashes)))
connection.log_info("Consensus block {} requires short id recovery. Querying BDN...", block_hash)
self.start_transaction_recovery(unknown_sids, unknown_hashes, block_hash, connection)
if recovered:
# should never happen –– this should not be called on blocks that have not recovered
connection.log_error(log_messages.BLOCK_DECOMPRESSION_FAILURE_ONT_CONSENSUS,
block_hash)
else:
self._node.block_queueing_service_manager.push(block_hash, waiting_for_recovery=True)
