fix(hardware): increase move group timeout (#12870)

* Adjusted timeout behavior to reduce full-blown failures but retain logs for the shorter timeout
Opentrons · Jun 7, 2023 · c4aae62 · c4aae62
1 parent 299ee90
commit c4aae62
Show file tree

Hide file tree

Showing 2 changed files with 18 additions and 3 deletions.
diff --git a/hardware/opentrons_hardware/hardware_control/move_group_runner.py b/hardware/opentrons_hardware/hardware_control/move_group_runner.py
@@ -4,6 +4,7 @@
 import logging
 from typing import List, Set, Tuple, Iterator, Union, Optional
 import numpy as np
+import time
 
 from opentrons_hardware.firmware_bindings import ArbitrationId
 from opentrons_hardware.firmware_bindings.constants import (
@@ -486,6 +487,14 @@ async def run(self, can_messenger: CanMessenger) -> _Completions:
             if error != ErrorCode.ok:
                 log.error(f"recieved error trying to execute move group {str(error)}")
 
+            expected_time = max(
+                1.0, self._durations[group_id - self._start_at_index] * 1.1
+            )
+            full_timeout = max(
+                1.0, self._durations[group_id - self._start_at_index] * 2
+            )
+            start_time = time.time()
+
             try:
                 # TODO: The max here can be removed once can_driver.send() no longer
                 # returns before the message actually hits the bus. Right now it
@@ -494,12 +503,18 @@ async def run(self, can_messenger: CanMessenger) -> _Completions:
                 # the execute even gets sent.
                 await asyncio.wait_for(
                     self._event.wait(),
-                    max(1.0, self._durations[group_id - self._start_at_index] * 1.1),
+                    full_timeout,
                 )
+                duration = time.time() - start_time
                 await self._send_stop_if_necessary(can_messenger, group_id)
+
+                if duration >= expected_time:
+                    log.warning(
+                        f"Move set {str(group_id)} took longer ({duration} seconds) than expected ({expected_time} seconds)."
+                    )
             except asyncio.TimeoutError:
                 log.warning(
-                    f"Move set {str(group_id)} timed out, expected duration {str(max(1.0, self._durations[group_id - self._start_at_index] * 1.1))}"
+                    f"Move set {str(group_id)} timed out of max duration {full_timeout}. Expected time: {expected_time}"
                 )
                 log.warning(
                     f"Expected nodes in group {str(group_id)}: {str(self._get_nodes_in_move_group(group_id))}"

diff --git a/hardware/tests/opentrons_hardware/hardware_control/test_move_group_runner.py b/hardware/tests/opentrons_hardware/hardware_control/test_move_group_runner.py
@@ -795,7 +795,7 @@ async def test_tip_action_move_runner_fail_receives_one_response(
         (
             "opentrons_hardware.hardware_control.move_group_runner",
             30,
-            "Move set 0 timed out, expected duration 1.1",
+            "Move set 0 timed out of max duration 2.0. Expected time: 1.1",
         ),
         (
             "opentrons_hardware.hardware_control.move_group_runner",