diff --git a/chirp/wxui/serialtrace.py b/chirp/wxui/serialtrace.py index 35f9e9fd..cb4cf596 100644 --- a/chirp/wxui/serialtrace.py +++ b/chirp/wxui/serialtrace.py @@ -59,6 +59,15 @@ def purge_trace_files(keep=10): LOG.error('Failed to remove old trace file %s: %s', fn, e) +def calculate_baud_time(serial, size): + """Calculate the time in milliseconds required to transfer size bytes""" + cps = serial.baudrate / (1 + # start bit + serial.stopbits + + serial.bytesize + + (serial.parity and 1 or 0)) + return size / cps * 1000 + + def warn_timeout(f): @functools.wraps(f) def wrapper(self, *a, **k): @@ -66,16 +75,33 @@ def warn_timeout(f): size = a[0] except IndexError: size = k.get('size', 1) - cps = self.baudrate / (1 + # start bit - self.stopbits + - self.bytesize + - (self.parity and 1 or 0)) - required_time = size / cps - if self.timeout is not None and required_time > self.timeout: + required_time = calculate_baud_time(self, size) + write_required_time = write_of = 0 + if self.last_write: + write_at, write_of = self.last_write + # The last operation was a write and it should require this much + # time to complete + write_required_time = calculate_baud_time(self, write_of) + # If not enough time has passed to finish the write, calculate + # remaining + write_required_time -= max(time.monotonic() - write_at, 0) + required_time += write_required_time + if self.timeout is not None and required_time > (self.timeout * 1000): warnings.warn( - ('Read of %i bytes requires %.3f seconds at %i baud, ' - 'but timeout is %.3fs') % ( - size, required_time, self.baudrate, self.timeout)) + ('Read of %i bytes requires %ims at %i baud, ' + 'but timeout is %ims (accounting for %i written bytes ' + 'in %ims)') % ( + size, required_time, self.baudrate, self.timeout * 1000, + write_of, write_required_time)) + self.log('timeout %ims less than required %ims ' + 'for read of %i bytes at %i baud (%ims remaining ' + 'for %i bytes written)' % ( + self.timeout * 1000, + required_time, + size, + self.baudrate, + write_required_time, + write_of)) return f(self, *a, **k) return wrapper @@ -83,8 +109,13 @@ def warn_timeout(f): class SerialTrace(serial.Serial): def __init__(self, *a, **k): self.__tracef = None + self.__last_write = None super().__init__(*a, **k) + @property + def last_write(self): + return self.__last_write + def open(self): super().open() try: @@ -103,6 +134,7 @@ class SerialTrace(serial.Serial): self.__tracef = None def write(self, data): + self.__last_write = (time.monotonic(), len(data)) super().write(data) if self.__tracef: try: @@ -115,6 +147,7 @@ class SerialTrace(serial.Serial): @warn_timeout def read(self, size=1): + self.__last_write = None data = super().read(size) if self.__tracef: try: diff --git a/tests/unit/test_serialtrace.py b/tests/unit/test_serialtrace.py index 094db263..cce7a71e 100644 --- a/tests/unit/test_serialtrace.py +++ b/tests/unit/test_serialtrace.py @@ -106,3 +106,19 @@ class TestSerialTrace(unittest.TestCase): # 1000 bytes takes about 1s, so 2s timeout should yield no warning trace.read(1000) self.assertTrue(len(w) == 0) + + @mock.patch('tempfile.NamedTemporaryFile') + @mock.patch('serial.Serial.open') + @mock.patch('serial.Serial.write') + @mock.patch('serial.Serial.read') + def test_timeout_write_read_warning(self, mock_read, mock_write, mock_open, + mock_tf): + mock_tf.return_value.writelines.side_effect = [None] + trace = serialtrace.SerialTrace(timeout=2, baudrate=9600) + trace.open() + with warnings.catch_warnings(record=True) as w: + # If we do a write before the read, the time to complete the write + # should be accounted for in the read timeout calculation + trace.write(b'f' * 1000) + trace.read(1000) + self.assertIn('1000 written bytes in 1145ms', str(w[0].message))