Improve timeout sanity checks

This makes the timeout sanity checking also consider a large write
before a read in determining how much time must be available for the
data to flush in and out.

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:

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