Merge pull request #5 from BNL-ATF/fix-timeout-processing-with-tests

Fix timeout processing + tests

atfdb/__init__.py

@@ -1,4 +1,5 @@
 from ._version import get_versions
+from .utils import configure_logger, logger  # noqa F401
 
 __version__ = get_versions()["version"]
 del get_versions

atfdb/ophyd.py

@@ -3,7 +3,8 @@
 from ophyd import Signal
 from ophyd.sim import NullStatus
 
-from atfdb import atfdb
+from . import atfdb
+from .utils import logger
 
 
 def open_close_conn(socket_server=None, socket_port=None):
@@ -21,6 +22,10 @@ def wrapped(*args, **kwargs):
     return inner_decorator
 
 
+class TimeoutException(Exception):
+    ...
+
+
 class ATFSignalNoConn(Signal):
     def __init__(
         self,
@@ -78,12 +83,25 @@ def put(self, value):
             atfdb.get_channel_index(f"{self._db}::{self._psname};{self._write_suffix}"),
             value,
         )
-        while ttime.monotonic() - start_time < self._timeout:
-            if abs(self._get_readback() - value) < self._tol:
-                break
+        while True:
+            waited_time = ttime.monotonic() - start_time
+            how_far = self._get_readback() - value
+            logger.debug(f"{waited_time = :.3f}s  {how_far = :.6f}")
+            if waited_time < self._timeout:
+                if abs(how_far) < self._tol:
+                    break
+                else:
+                    # not reached yet, wait a bit
+                    ttime.sleep(0.1)
             else:
-                # not reached yet, wait a bit
-                ttime.sleep(0.1)
+                raise TimeoutException(
+                    f"'{self.name}' ophyd object has not reached the setpoint={self._setpoint} "
+                    f"within the timeout of {self._timeout} seconds (waited {waited_time:.3f}s).\n"
+                    f"Current position: {self._get_readback():.6f}\n\n"
+                    f"Details:\n  db='{self._db}'\n  psname='{self._psname}'\n"
+                    f"  read_suffix='{self._read_suffix}'\n  write_suffix='{self._write_suffix}'\n"
+                    f"  tolerance={self._tol}"
+                )
 
     def set(self, *args, **kwargs):
         self.put(*args, **kwargs)

atfdb/tests/test_ophyd.py

@@ -1,9 +1,28 @@
-from atfdb.ophyd import ATFSignalNoConn
+import pytest
+
+from atfdb.ophyd import ATFSignalNoConn, TimeoutException
+from atfdb.utils import configure_logger, logger
+
+
+def test_ophyd_atfsignal_never_sets(socket_server):
+    test1 = ATFSignalNoConn(psname="test1", db="test", name="test1", tol=0.0, timeout=2.0)
+    print(f"{test1.get() = }")
+    print(f"{test1.read() = }")
+
+    configure_logger(logger=logger)
+    with pytest.raises(TimeoutException) as excinfo:
+        test1.put(1)
+
+    excinfo_value = excinfo.exconly()
+    assert "ophyd object has not reached the setpoint" in excinfo_value, excinfo_value
+    print(excinfo_value)
+
+    print(f"{test1.get() = }")
 
 
 def test_ophyd_atfsignal(socket_server):
-    test = ATFSignalNoConn(psname="test", db="test", name="test")
-    print(test.get())
-    print(test.read())
-    test.put(1)
-    print(test.get())
+    test2 = ATFSignalNoConn(psname="test2", db="test2", name="test2", tol=0.25, timeout=2.0)
+    print(f"{test2.get() = }")
+    print(f"{test2.read() = }")
+    test2.put(1)
+    print(f"{test2.get() = }")

atfdb/utils.py

@@ -0,0 +1,18 @@
+import logging
+from logging import StreamHandler
+
+logger = logging.getLogger("atfdb")
+
+
+def configure_logger(logger, log_level=logging.DEBUG, handlers=[StreamHandler]):
+    log_file_format = "[%(levelname)1.1s %(asctime)s %(name)s %(module)s:%(lineno)d] %(message)s"
+    logger.setLevel(log_level)
+
+    if logger.hasHandlers():
+        logger.handlers.clear()
+
+    for handler_class in handlers:
+        handler = handler_class()
+        handler.setFormatter(logging.Formatter(fmt=log_file_format))
+        logger.addHandler(handler)
+        handler.setLevel(log_level)