def test_adding_ping_event(self):
add_throughput_event(Direction.INBOUND,"ping", 40, "localhost 0000")
add_measurement("localhost 0000", MeasurementType.PING, 0.1)
add_measurement("localhost 0000", MeasurementType.PING, 0.3)
add_measurement("localhost 0000", MeasurementType.PING, 0.2)
self.assertEqual(throughput_statistics.interval_data.peer_to_stats["localhost 0000"].ping_max, 0.3)
throughput_statistics.flush_info()
def send_bytes(self, bytes_to_send: typing.Union[memoryview, bytearray]):
conn = self._node.connection_pool.get_by_fileno(self.file_no)
if not conn:
return
transport = self.transport
assert transport is not None, "Connection is broken!"
# pyre-fixme[16]: `Transport` has no attribute `get_write_buffer_limits`.
buffer_limits = transport.get_write_buffer_limits()
logger.trace(
"[{}] - about to send {} bytes, current buffer used {} with limits {}",
self,
bytes_to_send,
transport.get_write_buffer_size(),
buffer_limits
)
transport.write(bytes_to_send)
len_bytes_to_sent = len(bytes_to_send)
hooks.add_throughput_event(
NetworkDirection.OUTBOUND,
"outgoing",
len_bytes_to_sent,
conn.peer_desc,
conn.peer_id
)
logger.trace("[{}] - sent {} bytes", self, len_bytes_to_sent)
def advance_bytes_on_buffer(self, buf, bytes_written):
hooks.add_throughput_event(Direction.OUTBOUND, None, bytes_written,
self.peer_desc)
try:
buf.advance_buffer(bytes_written)
except ValueError as e:
raise RuntimeError(
"Connection: {}, Failed to advance buffer".format(self)) from e
def test_adding_outbound_event(self):
add_throughput_event(**self.outbound_throughput_event1.__dict__)
peer_stats = throughput_statistics.interval_data.peer_to_stats[self.inbound_throughput_event1.peer_desc]
self.assertEqual(self.outbound_throughput_event1.peer_desc, peer_stats.address)
self.assertEqual(self.outbound_throughput_event1.msg_size, peer_stats.messages_sent.bytes)
self.assertNotEqual(self.outbound_throughput_event1.msg_size,
peer_stats.messages_received[self.inbound_throughput_event1.msg_size].bytes)
def test_get_json_for_same_events(self):
add_throughput_event(**self.inbound_throughput_event1.__dict__)
add_throughput_event(**self.inbound_throughput_event2.__dict__)
add_throughput_event(**self.outbound_throughput_event1.__dict__)
add_throughput_event(**self.outbound_throughput_event2.__dict__)
stats_json = throughput_statistics.get_info()
self.assertEqual(1, len(stats_json["peer_stats"]))
self.assertEqual(
self.inbound_throughput_event1.msg_size +
self.inbound_throughput_event2.msg_size,
stats_json["peer_stats"][0].messages_received["test_in_msg"].bytes)
self.assertEqual(
self.outbound_throughput_event1.msg_size +
self.outbound_throughput_event2.msg_size,
stats_json["peer_stats"][0].messages_sent.bytes)
self.assertEqual(
self.inbound_throughput_event1.msg_size +
self.inbound_throughput_event2.msg_size,
stats_json["total_bytes_received"])
self.assertEqual(
self.outbound_throughput_event1.msg_size +
self.outbound_throughput_event2.msg_size,
stats_json["total_bytes_sent"])
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.
"""
start_time = time.time()
messages_processed = defaultdict(int)
while True:
input_buffer_len_before = self.inputbuf.length
is_full_msg = False
payload_len = 0
msg = None
msg_type = None
try:
# abort message processing if connection has been closed
if self.state & ConnectionState.MARK_FOR_CLOSE:
return
is_full_msg, msg_type, payload_len = self.pre_process_msg()
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)
# 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.state & ConnectionState.ESTABLISHED == ConnectionState.ESTABLISHED) \
and msg_type not in self.hello_messages:
self.log_warning(
"Received unexpected message ({}) before handshake completed. Closing.",
msg_type)
self.mark_for_close()
return
if self.log_throughput:
hooks.add_throughput_event(Direction.INBOUND, msg_type,
len(msg.rawbytes()),
self.peer_desc)
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]
msg_handler(msg)
messages_processed[msg_type] += 1
# TODO: Investigate possible solutions to recover from PayloadLenError errors
except PayloadLenError as e:
self.log_error("Could not parse message. Error: {}", e.msg)
self.mark_for_close()
return
except MemoryError as e:
self.log_error(
"Out of memory error occurred during message processing. Error: {}. ",
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("Unauthorized message {} from {}.",
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:
self.log_warning(
"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(
"Unable to recover after message that failed validation. Closing connection."
)
self.mark_for_close()
return
if self._report_bad_message():
return
# TODO: Throw custom exception for any errors that come from input that has not been validated and only catch that subclass of exceptions
except Exception as e:
# Attempt to recover connection by removing bad full message
if is_full_msg:
self.log_error(
"Message processing error; trying to recover. Error: {}.",
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(
"Message processing error; unable to recover. Error: {}.",
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
time_elapsed = time.time() - start_time
self.log_trace("Processed {} messages in {:.2f} seconds",
messages_processed, time_elapsed)
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))