diff --git a/host/min.py b/host/min.py index 31a4ead..842e933 100644 --- a/host/min.py +++ b/host/min.py @@ -11,7 +11,7 @@ from binascii import crc32 from threading import Lock from time import time -from logging import getLogger, ERROR +from logging import getLogger, ERROR, DEBUG, INFO from typing import Dict, Optional, List from serial import Serial, SerialException @@ -28,7 +28,7 @@ def int32_to_bytes(value: int) -> bytes: def bytes_to_hexstr(bytesequence: bytes) -> str: - return "".join(f"{b:02X}" for b in bytesequence) + return bytesequence.hex().upper() class MINConnectionError(Exception): @@ -254,14 +254,16 @@ def send_frame(self, min_id: int, payload: bytes): raise ValueError("MIN ID out of range") frame = MINFrame(min_id=min_id, payload=payload, transport=False, seq=0) on_wire_bytes = self._on_wire_bytes(frame=frame) - min_logger.info( - "Sending MIN frame, min_id=0x%02X, payload=%s", - min_id, - bytes_to_hexstr(payload), - ) - min_logger.debug( - "Sending MIN frame, on wire bytes=%s", bytes_to_hexstr(on_wire_bytes) - ) + if min_logger.isEnabledFor(INFO): + min_logger.info( + "Sending MIN frame, min_id=0x%02X, payload=%s", + min_id, + bytes_to_hexstr(payload), + ) + if min_logger.isEnabledFor(DEBUG): + min_logger.debug( + "Sending MIN frame, on wire bytes=%s", bytes_to_hexstr(on_wire_bytes) + ) self._serial_write(on_wire_bytes) def queue_frame(self, min_id: int, payload: bytes): @@ -485,7 +487,8 @@ def _rx_bytes(self, data: bytes): Called by handler to pass over a sequence of bytes :param data: """ - min_logger.debug("Received bytes: %s", bytes_to_hexstr(data)) + if min_logger.isEnabledFor(DEBUG): + min_logger.debug("Received bytes: %s", bytes_to_hexstr(data)) for byte in data: if self._rx_header_bytes_seen == 2: self._rx_header_bytes_seen = 0 @@ -660,12 +663,13 @@ def _find_oldest_frame(self): if len(self._transport_fifo) == 0: raise AssertionError + now_ms = self._now_ms() window_size = (self._sn_max - self._sn_min) & 0xFF oldest_frame = self._transport_fifo[0] # type: MINFrame - longest_elapsed_time = self._now_ms() - oldest_frame.last_sent_time + longest_elapsed_time = now_ms - oldest_frame.last_sent_time for i in range(window_size): - elapsed = self._now_ms() - self._transport_fifo[i].last_sent_time + elapsed = now_ms - self._transport_fifo[i].last_sent_time if elapsed >= longest_elapsed_time: oldest_frame = self._transport_fifo[i] longest_elapsed_time = elapsed @@ -680,11 +684,12 @@ def poll(self): :return: array of accepted MIN frames """ + now_ms = self._now_ms() remote_connected = ( - self._now_ms() - self._last_received_anything_ms + now_ms - self._last_received_anything_ms ) < self.idle_timeout_ms remote_active = ( - self._now_ms() - self._last_received_frame_ms + now_ms - self._last_received_frame_ms ) < self.idle_timeout_ms self._rx_list = [] @@ -701,15 +706,16 @@ def poll(self): # Frames still to send frame = self._transport_fifo_get(n=window_size) frame.seq = self._sn_max - self._last_sent_frame_ms = self._now_ms() - frame.last_sent_time = self._now_ms() - min_logger.debug( - "Sending new frame id=0x%02X seq=%d len=%d payload=%s", - frame.min_id, - frame.seq, - len(frame.payload), - bytes_to_hexstr(frame.payload), - ) + self._last_sent_frame_ms = now_ms + frame.last_sent_time = now_ms + if min_logger.isEnabledFor(DEBUG): + min_logger.debug( + "Sending new frame id=0x%02X seq=%d len=%d payload=%s", + frame.min_id, + frame.seq, + len(frame.payload), + bytes_to_hexstr(frame.payload), + ) self._transport_fifo_send(frame=frame) self._sn_max = (self._sn_max + 1) & 0xFF else: @@ -717,7 +723,7 @@ def poll(self): if window_size > 0 and remote_connected: oldest_frame = self._find_oldest_frame() if ( - self._now_ms() - oldest_frame.last_sent_time + now_ms - oldest_frame.last_sent_time > self.frame_retransmit_timeout_ms ): min_logger.debug( @@ -729,7 +735,7 @@ def poll(self): # Periodically transmit ACK if ( - self._now_ms() - self._last_sent_ack_time_ms + now_ms - self._last_sent_ack_time_ms > self.ack_retransmit_timeout_ms ): if remote_active: @@ -777,8 +783,8 @@ def _now_ms(self): def _serial_write(self, data: bytes): if self.fake_errors: data = self._corrupted_data(data) - - min_logger.debug("_serial_write: %s", bytes_to_hexstr(data)) + if min_logger.isEnabledFor(DEBUG): + min_logger.debug("_serial_write: %s", bytes_to_hexstr(data)) self._serial.write(data) def _serial_any(self):