Merge pull request #120 from spacetelescope/bugfix/picomotor_stalling…

…_logging

Add log messages to figure out picomotor stalling

catkit2/services/newport_picomotor/newport_picomotor.py

@@ -60,13 +60,17 @@ def set_current_position(self, axis_name, position):
 
         position_before = self.get_current_position(axis_name)
 
+        self.log.info(f'Setting picomotor {axis_name} from {position_before} to {position}.')
+
         self.send_command('exact_move', axis, position)
 
         sleep_time = self.sleep_per_step * abs(position_before - position) + self.sleep_base
         time.sleep(sleep_time)
 
         position_after = self.get_current_position(axis_name)
 
+        self.log.info(f'Done. Position is now {position_after}.')
+
         if position_after != position:
             raise RuntimeError('Newport picomotor failed to move to {position}; currently at {position_after}. Try increasing sleep_per_step.')
 

catkit2/testbed/proxies/newport_picomotor.py

@@ -1,10 +1,16 @@
 import time
+import logging
+
 import numpy as np
 from ..service_proxy import ServiceProxy
 
 
+MAX_TIMEOUT_FOR_CHECKING = 1000  # ms
+
+
 @ServiceProxy.register_service_interface('newport_picomotor')
 class NewportPicomotorProxy(ServiceProxy):
+    log = logging.getLogger(__name__)
 
     def move_relative(self, axis_name, distance, timeout=None):
         # Get current position.
@@ -31,19 +37,32 @@ def move_absolute(self, axis_name, position, timeout=None):
         if timeout is None or timeout > 0:
             while True:
                 try:
-                    wait_time_ms = None if timeout is None else int((timeout - (time.time() - waiting_start)) * 1000)
+                    if timeout is None:
+                        wait_time_ms = MAX_TIMEOUT_FOR_CHECKING
+                    else:
+                        # Wait for MAX_TIMEOUT_FOR_CHECKING ms or the remaining time until timeout, whichever is shortest.
+                        wait_time_ms = int((timeout - (time.time() - waiting_start)) * 1000)
+                        wait_time_ms = min(MAX_TIMEOUT_FOR_CHECKING, wait_time_ms)
+
                     if wait_time_ms is not None and wait_time_ms <= 0:
+                        # The final timeout was reached. Raise an exception.
                         raise RuntimeError(exception_text)
 
-                    current_position = stream.get()[0]
+                    # Check if we are at our final position, within absolute tolerance.
+                    current_position = stream.get_next_frame(wait_time_ms).data[0]
                     if abs(current_position - position) < self.atol:
                         break
                 except RuntimeError as e:
                     if str(e) == exception_text:
+                        # The final timeout was reached, so reraise the exception.
                         raise
                     else:
-                        # Datastream read timed out. This is to facilitate wait time checking.
-                        continue
+                        # Datastream read timed out. This is to facilitate wait time checking, so this is normal.
+                        pass
+
+                # Send a log message to indicate we are still waiting.
+                current_position = stream.get()[0]
+                self.log.info(f'Waiting for stage movement: currently {current_position}, waiting for {position}.')
 
     @property
     def atol(self):