Implement open timeout for hislip (#430)

* tcpip: implement open timeout for hislip * tcpip: fix typing * testsuite: add debug prints * fix issue on 3.9 and add a changelog entry * fix linting issues * [pre-commit.ci] pre-commit autoupdate (#440) updates: - [github.com/astral-sh/ruff-pre-commit: v0.5.0 → v0.5.1](astral-sh/ruff-pre-commit@v0.5.0...v0.5.1) Co-authored-by: pre-commit-ci[bot] <66853113+pre-commit-ci[bot]@users.noreply.github.com> * fix issue on 3.9 and add a changelog entry * sessions: improve handling of open connection error for TCPIP resources * ci and linter fixes * linter fixes * use the right logger in tcpip sessions * hislip: respect the VISA spec and do not use open_timeout for socket connection * hislip: respect the VISA spec and do not use open_timeout for socket connection * tcpip: allow more exception to cause a failure to open a connection * highlevel: handle return code when connection opening fails * consistently use the logger adapter signaling the message originate from the py backend * fix linter complaint --------- Co-authored-by: pre-commit-ci[bot] <66853113+pre-commit-ci[bot]@users.noreply.github.com>
pyvisa · Dec 29, 2024 · b4693f6 · b4693f6
1 parent 3eb0986
commit b4693f6
Show file tree

Hide file tree

Showing 13 changed files with 118 additions and 69 deletions.
diff --git a/CHANGES b/CHANGES
@@ -16,6 +16,7 @@ PyVISA-py Changelog
 - Implemented partial USBTMC message functionality that allows reading the amount of bytes 
   specified by host PR #470
 - add support for VI_ATTR_SUPPRESS_END_EN for USB resources PR #449
+- support open_timeout for TCPIP hislip resources PR #430
 
 0.7.2 (07/03/2024)
 ------------------

diff --git a/dev-requirements.txt b/dev-requirements.txt
@@ -1,3 +1,4 @@
 ruff
+pytest
 sphinx
 sphinx-rtd-theme
diff --git a/pyvisa_py/__init__.py b/pyvisa_py/__init__.py
@@ -9,15 +9,16 @@
 
 from importlib.metadata import PackageNotFoundError, version
 
+# We need to import all attributes so that __init_subclass__() is executed once
+# (hence the noqa)
+from . import attributes  # noqa: F401
+from .highlevel import PyVisaLibrary
+
 __version__ = "unknown"
 try:
     __version__ = version(__name__)
 except PackageNotFoundError:
     # package is not installed
     pass
 
-# We need to import all attributes so that __init_subclass__() is executed once
-from . import attributes  # noqa: F401
-from .highlevel import PyVisaLibrary
-
 WRAPPER_CLASS = PyVisaLibrary
diff --git a/pyvisa_py/common.py b/pyvisa_py/common.py
@@ -11,7 +11,7 @@
 
 from pyvisa import logger
 
-logger = logging.LoggerAdapter(logger, {"backend": "py"})  # type: ignore
+LOGGER = logging.LoggerAdapter(logger, {"backend": "py"})  # type: ignore
 
 
 class NamedObject(object):

diff --git a/pyvisa_py/gpib.py b/pyvisa_py/gpib.py
@@ -11,10 +11,11 @@
 from bisect import bisect
 from typing import Any, Iterator, List, Tuple, Union
 
-from pyvisa import attributes, constants, logger
+from pyvisa import attributes, constants
 from pyvisa.constants import ResourceAttribute, StatusCode
 from pyvisa.rname import GPIBInstr, GPIBIntfc
 
+from .common import LOGGER
 from .sessions import Session, UnknownAttribute
 
 try:
@@ -83,7 +84,7 @@ def _find_boards() -> Iterator[Tuple[int, int]]:
         try:
             yield board, gpib.ask(board, 1)
         except gpib.GpibError as e:
-            logger.debug("GPIB board %i error in _find_boards(): %s", board, repr(e))
+            LOGGER.debug("GPIB board %i error in _find_boards(): %s", board, repr(e))
 
 
 def _find_listeners() -> Iterator[Tuple[int, int, int]]:
@@ -99,7 +100,7 @@ def _find_listeners() -> Iterator[Tuple[int, int, int]]:
                         if gpib.listener(board, i, j):
                             yield board, i, j
             except gpib.GpibError as e:
-                logger.debug(
+                LOGGER.debug(
                     "GPIB board %i paddr %i saddr %i error in _find_listeners(): %s",
                     board,
                     i,
@@ -204,7 +205,7 @@ def convert_gpib_error(
     # feels brittle. As a consequence we only try to be smart when using
     # gpib-ctypes. However in both cases we log the exception at debug level.
     else:
-        logger.debug("Failed to %s.", operation, exc_info=error)
+        LOGGER.debug("Failed to %s.", operation, exc_info=error)
         if not GPIB_CTYPES:
             return StatusCode.error_system_error
         if error.code == 1:
@@ -410,7 +411,7 @@ def write(self, data: bytes) -> Tuple[int, StatusCode]:
             Return value of the library call.
 
         """
-        logger.debug("GPIB.write %r" % data)
+        LOGGER.debug("GPIB.write %r" % data)
 
         # INTFC don't have an interface so use the controller
         ifc = self.interface or self.controller
@@ -663,7 +664,7 @@ def clear(self) -> StatusCode:
             Return value of the library call.
 
         """
-        logger.debug("GPIB.device clear")
+        LOGGER.debug("GPIB.device clear")
         try:
             self.interface.clear()
             return StatusCode.success
@@ -685,7 +686,7 @@ def assert_trigger(self, protocol: constants.TriggerProtocol) -> StatusCode:
             Return value of the library call.
 
         """
-        logger.debug("GPIB.device assert hardware trigger")
+        LOGGER.debug("GPIB.device assert hardware trigger")
 
         try:
             if protocol == constants.VI_TRIG_PROT_DEFAULT:
@@ -838,7 +839,7 @@ def gpib_send_ifc(self) -> StatusCode:
         Corresponds to viGpibSendIFC function of the VISA library.
 
         """
-        logger.debug("GPIB.interface clear")
+        LOGGER.debug("GPIB.interface clear")
         try:
             self.controller.interface_clear()
             return StatusCode.success
@@ -862,7 +863,7 @@ def gpib_control_atn(self, mode: constants.ATNLineOperation) -> StatusCode:
             Return value of the library call.
 
         """
-        logger.debug("GPIB.control atn")
+        LOGGER.debug("GPIB.control atn")
         if mode == constants.VI_GPIB_ATN_ASSERT:
             status = gpib_lib.ibcac(self.controller.id, 0)
         elif mode == constants.VI_GPIB_ATN_DEASSERT:
@@ -899,11 +900,11 @@ def gpib_pass_control(
 
         """
         # ibpct need to get the device id matching the primary and secondary address
-        logger.debug("GPIB.pass control")
+        LOGGER.debug("GPIB.pass control")
         try:
             did = gpib.dev(self.parsed.board, primary_address, secondary_address)
         except gpib.GpibError:
-            logger.exception(
+            LOGGER.exception(
                 "Failed to get id for %s, %d", primary_address, secondary_address
             )
             return StatusCode.error_resource_not_found

diff --git a/pyvisa_py/highlevel.py b/pyvisa_py/highlevel.py
@@ -17,7 +17,7 @@
 from pyvisa.util import DebugInfo, LibraryPath
 
 from . import sessions
-from .common import logger
+from .common import LOGGER
 
 
 class PyVisaLibrary(highlevel.VisaLibraryBase):
@@ -45,30 +45,30 @@ class PyVisaLibrary(highlevel.VisaLibraryBase):
     try:
         from .serial import SerialSession
 
-        logger.debug("SerialSession was correctly imported.")
+        LOGGER.debug("SerialSession was correctly imported.")
     except Exception as e:
-        logger.debug("SerialSession was not imported %s." % e)
+        LOGGER.debug("SerialSession was not imported %s." % e)
 
     try:
         from .usb import USBRawSession, USBSession
 
-        logger.debug("USBSession and USBRawSession were correctly imported.")
+        LOGGER.debug("USBSession and USBRawSession were correctly imported.")
     except Exception as e:
-        logger.debug("USBSession and USBRawSession were not imported %s." % e)
+        LOGGER.debug("USBSession and USBRawSession were not imported %s." % e)
 
     try:
         from .tcpip import TCPIPInstrSession, TCPIPSocketSession
 
-        logger.debug("TCPIPSession was correctly imported.")
+        LOGGER.debug("TCPIPSession was correctly imported.")
     except Exception as e:
-        logger.debug("TCPIPSession was not imported %s." % e)
+        LOGGER.debug("TCPIPSession was not imported %s." % e)
 
     try:
         from .gpib import GPIBSession
 
-        logger.debug("GPIBSession was correctly imported.")
+        LOGGER.debug("GPIBSession was correctly imported.")
     except Exception as e:
-        logger.debug("GPIBSession was not imported %s." % e)
+        LOGGER.debug("GPIBSession was not imported %s." % e)
 
     @staticmethod
     def get_library_paths() -> Iterable[LibraryPath]:
@@ -165,7 +165,10 @@ def open(
             parsed.interface_type_const, parsed.resource_class
         )
 
-        sess = cls(session, resource_name, parsed, open_timeout)
+        try:
+            sess = cls(session, resource_name, parsed, open_timeout)
+        except sessions.OpenError as e:
+            return VISASession(0), self.handle_return_value(None, e.error_code)
 
         return self._register(sess), StatusCode.success
 

diff --git a/pyvisa_py/protocols/hislip.py b/pyvisa_py/protocols/hislip.py
@@ -162,6 +162,8 @@ def receive_exact_into(sock: socket.socket, recv_buffer: bytes) -> None:
     while bytes_recvd < recv_len:
         request_size = recv_len - bytes_recvd
         data_len = sock.recv_into(view, request_size)
+        if data_len == 0:
+            raise RuntimeError("Connection was dropped by server.")
         bytes_recvd += data_len
         view = view[data_len:]
 
@@ -367,6 +369,7 @@ class Instrument:
     def __init__(
         self,
         ip_addr: str,
+        open_timeout: Optional[float] = 0.0,
         timeout: Optional[float] = None,
         port: int = PORT,
         sub_address: str = "hislip0",
@@ -381,19 +384,26 @@ def __init__(
 
         # open the synchronous socket and send an initialize packet
         self._sync = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
+        # The VISA spec does not allow to tune the socket timeout when opening
+        # a connection. ``open_timeout`` only applies to attempt to acquire a
+        # lock.
+        self._sync.settimeout(5.0)
         self._sync.connect((ip_addr, port))
-        self._sync.settimeout(timeout)
         self._sync.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1)
         init = self.initialize(sub_address=sub_address.encode("ascii"))
         if init.overlap != 0:
             print("**** prefer overlap = %d" % init.overlap)
+        # We set the user timeout once we managed to initialize the connection.
+        self._sync.settimeout(timeout)
 
         # open the asynchronous socket and send an initialize packet
         self._async = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
         self._async.connect((ip_addr, port))
-        self._async.settimeout(timeout)
+        self._async.settimeout(5.0)
         self._async.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1)
         self._async_init = self.async_initialize(session_id=init.session_id)
+        # We set the user timeout once we managed to initialize the connection.
+        self._async.settimeout(timeout)
 
         # initialize variables
         self.max_msg_size = DEFAULT_MAX_MSG_SIZE

diff --git a/pyvisa_py/protocols/rpc.py b/pyvisa_py/protocols/rpc.py
@@ -25,7 +25,7 @@
 import sys
 import time
 
-from ..common import logger
+from ..common import LOGGER
 from . import xdrlib
 
 #: Version of the protocol
@@ -225,7 +225,7 @@ def __init__(self, host, prog, vers, port):
 
     def make_call(self, proc, args, pack_func, unpack_func):
         # Don't normally override this (but see Broadcast)
-        logger.debug("Make call %r, %r, %r, %r", proc, args, pack_func, unpack_func)
+        LOGGER.debug("Make call %r, %r, %r, %r", proc, args, pack_func, unpack_func)
 
         if pack_func is None and args is not None:
             raise TypeError("non-null args with null pack_func")
@@ -296,7 +296,7 @@ def sendfrag(sock, last, frag):
 
 
 def _sendrecord(sock, record, fragsize=None, timeout=None):
-    logger.debug("Sending record through %s: %r", sock, record)
+    LOGGER.debug("Sending record through %s: %r", sock, record)
     if timeout is not None:
         r, w, x = select.select([], [sock], [], timeout)
         if sock not in w:
@@ -330,7 +330,7 @@ def _recvrecord(sock, timeout, read_fun=None, min_packages=0):
     packages_received = 0
 
     if min_packages != 0:
-        logger.debug("Start receiving at least %i packages" % min_packages)
+        LOGGER.debug("Start receiving at least %i packages" % min_packages)
 
     # minimum is in interval 1 - 100ms based on timeout or for infinite it is
     # 1 sec
@@ -355,11 +355,11 @@ def _recvrecord(sock, timeout, read_fun=None, min_packages=0):
             if sock in r:
                 read_data = read_fun(exp_length)
                 buffer.extend(read_data)
-                logger.debug("received %r" % read_data)
+                LOGGER.debug("received %r" % read_data)
             # Timeout was reached
             if not read_data:  # no response or empty response
                 if timeout is not None and time.time() >= finish_time:
-                    logger.debug(
+                    LOGGER.debug(
                         (
                             "Time out encountered in %s."
                             "Already receieved %d bytes. Last fragment is %d "
@@ -376,7 +376,7 @@ def _recvrecord(sock, timeout, read_fun=None, min_packages=0):
                     )
                     raise socket.timeout(msg)
                 elif min_packages != 0 and packages_received >= min_packages:
-                    logger.debug(
+                    LOGGER.debug(
                         "Stop receiving after %i of %i requested packages. Received record through %s: %r",
                         packages_received,
                         min_packages,
@@ -404,7 +404,7 @@ def _recvrecord(sock, timeout, read_fun=None, min_packages=0):
                 record.extend(buffer[:exp_length])
                 buffer = buffer[exp_length:]
                 if last:
-                    logger.debug("Received record through %s: %r", sock, record)
+                    LOGGER.debug("Received record through %s: %r", sock, record)
                     return bytes(record)
                 else:
                     wait_header = True
@@ -480,15 +480,15 @@ def make_call(self, proc, args, pack_func, unpack_func):
         return super(RawTCPClient, self).make_call(proc, args, pack_func, unpack_func)
 
     def connect(self, timeout=5.0):
-        logger.debug(
+        LOGGER.debug(
             "RawTCPClient: connecting to socket at (%s, %s)", self.host, self.port
         )
         self.sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
         if not _connect(self.sock, self.host, self.port, timeout):
             raise RPCError("can't connect to server")
 
     def close(self):
-        logger.debug("RawTCPClient: closing socket")
+        LOGGER.debug("RawTCPClient: closing socket")
         self.sock.close()
 
     def do_call(self):
@@ -498,7 +498,7 @@ def do_call(self):
 
         try:
             min_packages = int(self.packer.proc == 3)
-            logger.debug("RawTCPClient: procedure type %i" % self.packer.proc)
+            LOGGER.debug("RawTCPClient: procedure type %i" % self.packer.proc)
             # if the command is get_port, we only expect one package.
             # This is a workaround for misbehaving instruments.
         except AttributeError:
@@ -531,14 +531,14 @@ def __init__(self, host, prog, vers, port):
         self.connect()
 
     def connect(self):
-        logger.debug(
+        LOGGER.debug(
             "RawTCPClient: connecting to socket at (%s, %s)", self.host, self.port
         )
         self.sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
         self.sock.connect((self.host, self.port))
 
     def close(self):
-        logger.debug("RawTCPClient: closing socket")
+        LOGGER.debug("RawTCPClient: closing socket")
         self.sock.close()
 
     def do_call(self):
@@ -1005,7 +1005,7 @@ def session(self, connection):
             except EOFError:
                 break
             except socket.error:
-                logger.exception("socket error: %r", sys.exc_info()[0])
+                LOGGER.exception("socket error: %r", sys.exc_info()[0])
                 break
             reply = self.handle(call)
             if reply is not None: