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))