search

pyvisa / pyvisa-py

A pure python PyVISA backend
https://pyvisa-py.readthedocs.io
MIT License
282 stars 120 forks source link

TRACE:DATA? times out in 0.3.0/master, works in 0.2 #161

Open jake42 opened 6 years ago

jake42 commented 6 years ago

Hi there, I experience the following issue: The script below works in 0.2 but does not in 0.3.0 (and master d12ef43a576fa4a856f686796b75cceb0efe8e26): 

import visa
rm = visa.ResourceManager('@py')
scp = rm.open_resource('TCPIP::10.54.231.16::INSTR')
scp.write("*RST")
scp.write("INIT:CONT OFF")
scp.write("INIT;*WAI")
scp.query("TRACE1:DATA? TRACE1")

In 0.2 the last query returns in under a second In 0.3.0 I get a timeout (or with indefinite timeout it just sits there)

I tried to git bisect the issue. It stopped working with an EOFError in 15b814171ea048653f5bcd4db625c4b855557ef3. This EOFError was adressed in the more recent commit 7d876c5e5c08334815a2648911316bd5c23fb57a. With that commit it times out:

Traceback (most recent call last):
  File "traceminimal.py", line 7, in <module>
    scp.query("TRACE1:DATA? TRACE1")
  File "/home/test/visatest/env3/lib/python3.5/site-packages/pyvisa/resources/messagebased.py", line 569, in query
    return self.read()
  File "/home/test/visatest/env3/lib/python3.5/site-packages/pyvisa/resources/messagebased.py", line 413, in read
    message = self._read_raw().decode(enco)
  File "/home/test/visatest/env3/lib/python3.5/site-packages/pyvisa/resources/messagebased.py", line 386, in _read_raw
    chunk, status = self.visalib.read(self.session, size)
  File "/home/test/visatest/pyvisa-py/pyvisa-py/highlevel.py", line 350, in read
    raise errors.VisaIOError(ret[1])
pyvisa.errors.VisaIOError: VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.
jake42 commented 6 years ago

Here is the output with logging set to debug for d12ef43a576fa4a856f686796b75cceb0efe8e26:

DEBUG:pyvisa:SerialSession was not imported No module named 'serial'.
DEBUG:pyvisa:USBSession and USBRawSession were correctly imported.
DEBUG:pyvisa:TCPIPSession was correctly imported.
DEBUG:pyvisa:GPIBSession was not imported No module named 'gpib'.
DEBUG:pyvisa:Created library wrapper for unset
DEBUG:pyvisa:Created ResourceManager with session 9997676
DEBUG:pyvisa:TCPIP::10.54.230.109::INSTR - opening ...
DEBUG:pyvisa:RawTCPClient: connecting to socket at (10.54.230.109, 111)
DEBUG:pyvisa:Make call <PortMapperVersion.get_port: 3>, (395183, 1, 6, 0), <bound method PortMapperPacker.pack_mapping of <pyvisa-py.protocols.rpc.PortMapperPacker object at 0x7fa58ce45cf8>>, <bound method Unpacker.unpack_uint of <pyvisa-py.protocols.rpc.PortMapperUnpacker object at 0x7fa58ce45d30>>
DEBUG:pyvisa:Sending record through <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('10.54.78.177', 36752), raddr=('10.54.230.109', 111)>: b'\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x02\x00\x01\x86\xa0\x00\x00\x00\x02\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x06\x07\xaf\x00\x00\x00\x01\x00\x00\x00\x06\x00\x00\x00\x00'
DEBUG:pyvisa:Received record through <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('10.54.78.177', 36752), raddr=('10.54.230.109', 111)>: bytearray(b'\x00\x00\x00\x01\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00?F')
DEBUG:pyvisa:RawTCPClient: closing socket
DEBUG:pyvisa:RawTCPClient: connecting to socket at (10.54.230.109, 16198)
DEBUG:pyvisa:Make call 10, (1842016477, 0, 10000, 'inst0'), <bound method Vxi11Packer.pack_create_link_parms of <pyvisa-py.protocols.vxi11.Vxi11Packer object at 0x7fa58ce45be0>>, <bound method Vxi11Unpacker.unpack_create_link_resp of <pyvisa-py.protocols.vxi11.Vxi11Unpacker object at 0x7fa58ce45c50>>
DEBUG:pyvisa:Sending record through <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('10.54.78.177', 52660), raddr=('10.54.230.109', 16198)>: b"\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x02\x00\x06\x07\xaf\x00\x00\x00\x01\x00\x00\x00\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00m\xca\xf0\xdd\x00\x00\x00\x00\x00\x00'\x10\x00\x00\x00\x05inst0\x00\x00\x00"
DEBUG:pyvisa:Received record through <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('10.54.78.177', 52660), raddr=('10.54.230.109', 16198)>: bytearray(b'\x00\x00\x00\x01\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x0f\x00\x00?G\x00\x00\x10\x00')
DEBUG:pyvisa:TCPIP::10.54.230.109::INSTR - is open with session 3664261
DEBUG:pyvisa:Make call 11, (15, 2000, 10000, 136, b'*RST\r\n'), <bound method Vxi11Packer.pack_device_write_parms of <pyvisa-py.protocols.vxi11.Vxi11Packer object at 0x7fa58ce45be0>>, <bound method Vxi11Unpacker.unpack_device_write_resp of <pyvisa-py.protocols.vxi11.Vxi11Unpacker object at 0x7fa58ce45c50>>
DEBUG:pyvisa:Sending record through <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('10.54.78.177', 52660), raddr=('10.54.230.109', 16198)>: b"\x00\x00\x00\x02\x00\x00\x00\x00\x00\x00\x00\x02\x00\x06\x07\xaf\x00\x00\x00\x01\x00\x00\x00\x0b\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x0f\x00\x00\x07\xd0\x00\x00'\x10\x00\x00\x00\x88\x00\x00\x00\x06*RST\r\n\x00\x00"
DEBUG:pyvisa:Received record through <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('10.54.78.177', 52660), raddr=('10.54.230.109', 16198)>: bytearray(b'\x00\x00\x00\x02\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x06')
DEBUG:pyvisa:Make call 11, (15, 2000, 10000, 136, b'INIT:CONT OFF\r\n'), <bound method Vxi11Packer.pack_device_write_parms of <pyvisa-py.protocols.vxi11.Vxi11Packer object at 0x7fa58ce45be0>>, <bound method Vxi11Unpacker.unpack_device_write_resp of <pyvisa-py.protocols.vxi11.Vxi11Unpacker object at 0x7fa58ce45c50>>
DEBUG:pyvisa:Sending record through <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('10.54.78.177', 52660), raddr=('10.54.230.109', 16198)>: b"\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x02\x00\x06\x07\xaf\x00\x00\x00\x01\x00\x00\x00\x0b\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x0f\x00\x00\x07\xd0\x00\x00'\x10\x00\x00\x00\x88\x00\x00\x00\x0fINIT:CONT OFF\r\n\x00"
DEBUG:pyvisa:Received record through <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('10.54.78.177', 52660), raddr=('10.54.230.109', 16198)>: bytearray(b'\x00\x00\x00\x03\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x0f')
DEBUG:pyvisa:Make call 11, (15, 2000, 10000, 136, b'INIT;*WAI\r\n'), <bound method Vxi11Packer.pack_device_write_parms of <pyvisa-py.protocols.vxi11.Vxi11Packer object at 0x7fa58ce45be0>>, <bound method Vxi11Unpacker.unpack_device_write_resp of <pyvisa-py.protocols.vxi11.Vxi11Unpacker object at 0x7fa58ce45c50>>
DEBUG:pyvisa:Sending record through <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('10.54.78.177', 52660), raddr=('10.54.230.109', 16198)>: b"\x00\x00\x00\x04\x00\x00\x00\x00\x00\x00\x00\x02\x00\x06\x07\xaf\x00\x00\x00\x01\x00\x00\x00\x0b\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x0f\x00\x00\x07\xd0\x00\x00'\x10\x00\x00\x00\x88\x00\x00\x00\x0bINIT;*WAI\r\n\x00"
DEBUG:pyvisa:Received record through <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('10.54.78.177', 52660), raddr=('10.54.230.109', 16198)>: bytearray(b'\x00\x00\x00\x04\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x0b')
DEBUG:pyvisa:Make call 11, (15, 2000, 10000, 136, b'TRACE1:DATA? TRACE1\r\n'), <bound method Vxi11Packer.pack_device_write_parms of <pyvisa-py.protocols.vxi11.Vxi11Packer object at 0x7fa58ce45be0>>, <bound method Vxi11Unpacker.unpack_device_write_resp of <pyvisa-py.protocols.vxi11.Vxi11Unpacker object at 0x7fa58ce45c50>>
DEBUG:pyvisa:Sending record through <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('10.54.78.177', 52660), raddr=('10.54.230.109', 16198)>: b"\x00\x00\x00\x05\x00\x00\x00\x00\x00\x00\x00\x02\x00\x06\x07\xaf\x00\x00\x00\x01\x00\x00\x00\x0b\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x0f\x00\x00\x07\xd0\x00\x00'\x10\x00\x00\x00\x88\x00\x00\x00\x15TRACE1:DATA? TRACE1\r\n\x00\x00\x00"
DEBUG:pyvisa:Received record through <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('10.54.78.177', 52660), raddr=('10.54.230.109', 16198)>: bytearray(b'\x00\x00\x00\x05\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x15')
DEBUG:pyvisa:TCPIP::10.54.230.109::INSTR - reading 20480 bytes (last status <StatusCode.success_max_count_read: 1073676294>)
DEBUG:pyvisa:Make call 12, (15, 4096, 2000, 10000, 0, 0), <bound method Vxi11Packer.pack_device_read_parms of <pyvisa-py.protocols.vxi11.Vxi11Packer object at 0x7fa58ce45be0>>, <bound method Vxi11Unpacker.unpack_device_read_resp of <pyvisa-py.protocols.vxi11.Vxi11Unpacker object at 0x7fa58ce45c50>>
DEBUG:pyvisa:Sending record through <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('10.54.78.177', 52660), raddr=('10.54.230.109', 16198)>: b"\x00\x00\x00\x06\x00\x00\x00\x00\x00\x00\x00\x02\x00\x06\x07\xaf\x00\x00\x00\x01\x00\x00\x00\x0c\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x0f\x00\x00\x10\x00\x00\x00\x07\xd0\x00\x00'\x10\x00\x00\x00\x00\x00\x00\x00\x00"
DEBUG:pyvisa:Time out encountered in <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('10.54.78.177', 52660), raddr=('10.54.230.109', 16198)>.Already receieved 3996 bytes. Last fragment is 140 bytes long and we were expecting 4
DEBUG:pyvisa:TCPIP::10.54.230.109::INSTR - exception while reading: VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.
Buffer content: bytearray(b'')
Traceback (most recent call last):
  File "traceminimal.py", line 10, in <module>
    scp.query("TRACE1:DATA? TRACE1")
  File "/home/test/visatest/env3/lib/python3.5/site-packages/pyvisa/resources/messagebased.py", line 569, in query
    return self.read()
  File "/home/test/visatest/env3/lib/python3.5/site-packages/pyvisa/resources/messagebased.py", line 413, in read
    message = self._read_raw().decode(enco)
  File "/home/test/visatest/env3/lib/python3.5/site-packages/pyvisa/resources/messagebased.py", line 386, in _read_raw
    chunk, status = self.visalib.read(self.session, size)
  File "/home/test/visatest/pyvisa-py/pyvisa-py/highlevel.py", line 350, in read
    raise errors.VisaIOError(ret[1])
pyvisa.errors.VisaIOError: VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.
DEBUG:pyvisa:TCPIP::10.54.230.109::INSTR - closing
DEBUG:pyvisa:Make call 23, 15, <bound method Vxi11Packer.pack_device_link of <pyvisa-py.protocols.vxi11.Vxi11Packer object at 0x7fa58ce45be0>>, <bound method Vxi11Unpacker.unpack_device_error of <pyvisa-py.protocols.vxi11.Vxi11Unpacker object at 0x7fa58ce45c50>>
DEBUG:pyvisa:Sending record through <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('10.54.78.177', 52660), raddr=('10.54.230.109', 16198)>: b'\x00\x00\x00\x07\x00\x00\x00\x00\x00\x00\x00\x02\x00\x06\x07\xaf\x00\x00\x00\x01\x00\x00\x00\x17\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x0f'
DEBUG:pyvisa:Received record through <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('10.54.78.177', 52660), raddr=('10.54.230.109', 16198)>: bytearray(b'\x00\x00\x00\x07\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00')
DEBUG:pyvisa:RawTCPClient: closing socket
DEBUG:pyvisa:TCPIP::10.54.230.109::INSTR - is closed
DEBUG:pyvisa:Closing ResourceManager (session: 9997676)
MatthieuDartiailh commented 6 years ago

Thanks for the detailed report. This looks a lot like https://github.com/pyvisa/pyvisa/issues/316 that was never really resolved but since I never managed to reproduce and I did not get any answer I stopped looking. Could you post the output of python -m visa info ? Also can you confirm that for both versions of pyvisa-py you use the same version of pyvisa ?

jake42 commented 6 years ago 
$ python -m visa info
Machine Details:
   Platform ID:    Linux-4.4.0-135-generic-x86_64-with-Ubuntu-16.04-xenial
   Processor:      x86_64

Python:
   Implementation: CPython
   Executable:     /home/test/visatest/env3/bin/python
   Version:        3.5.2
   Compiler:       GCC 5.4.0 20160609
   Bits:           64bit
   Build:          Nov 23 2017 16:37:01 (#default)
   Unicode:        UCS4

PyVISA Version: 1.9.1

Backends:
   ni:
      Version: 1.9.1 (bundled with PyVISA)
      #1: /usr/lib/x86_64-linux-gnu/libvisa.so.0.0.0:
         found by: auto
         bitness: 64
         Could not get more info:
            VI_ERROR_NSUP_ATTR (-1073807331): The specified attribute is not defined or supported by the referenced object.
   py:
      Version: 0.3.dev0
      GPIB INSTR:
         Please install linux-gpib to use this resource type.
         No module named 'gpib'
      TCPIP SOCKET: Available
      TCPIP INSTR: Available
      USB INSTR: Available via PyUSB (1.0.2). Backend: libusb1
      ASRL INSTR:
         Please install PySerial (>=3.0) to use this resource type.
         No module named 'serial'
      USB RAW: Available via PyUSB (1.0.2). Backend: libusb1

They should be using the same pyvisa version, as I only did a git checkout 0.2 or agit checkout master in an inplace pyvisa-py (pip install -e) and anything else stayed the same.

I looked more into it and the variable last (in _recvrecord() in rpc.py) is never updated after first setting it and if it's initialy False it results in a timeout. This seems to be different behavior than in 0.2 where on every fragment the header is parsed and last is updated. Atleast that's what I gathered so far as I have no clue about the protocol.

jake42 commented 6 years ago

My conclusion seems to be wrong. Because wait_header is set True and then it would update last again.

MatthieuDartiailh commented 6 years ago

I do not have time right now to look into more details, but if you can, continue experimenting. In particular, try to play with the chunk_size. I am curious to see if it depends on it or not.

jake42 commented 6 years ago

It depends on chunk_size. Adding the following to the script above:

for chunk in range(256, 10240+256, 256):
    scp.chunk_size = chunk
    try:
        scp.query("TRACE1:DATA? TRACE1")
        print(chunk)
    except pyvisa.errors.VisaIOError:
        pass

Outputs:

256
512
768
1024
1280
1536
1792
2048
2304
2560
2816
3072
3328
3584
3840
4864
5376
5888
6144
6912
7936
8448
9216
9984
MatthieuDartiailh commented 6 years ago

Thanks. At least you have a workaround for now.

khoazero1192 commented 5 years ago

This also happens with (":MMEM:TRANS") or probably any query commands that returns a chunk of data.

khoazero1192 commented 5 years ago

Works perfectly in 2.0

khoazero1192 commented 5 years ago

Here's my traceback. Pretty similar to jake42 Traceback (most recent call last): File "/usr/local/lib/python2.7/dist-packages/FeedMeasurement/feed_measurement_gui.py", line 388, in _feed_meas_task self.fm_routine.s_parm_routine(pattern_rows, save_dir) File "/usr/local/lib/python2.7/dist-packages/FeedMeasurement/feed_measurement_routine.py", line 288, in s_parm_routine self.vna_interface.save_s2p(save_dir, s2p_file_name) File "/usr/local/lib/python2.7/dist-packages/FeedMeasurement/vna_interface.py", line 260, in save_s2p content = self.vna.ask(':MMEM:TRAN? \"%s/%s\"' % (PNA_DEFAULT_DIR, filename)) File "/usr/local/lib/python2.7/dist-packages/umbriel/instruments/visaConn.py", line 35, in newFunction return f(*args, **kw) File "/usr/local/lib/python2.7/dist-packages/umbriel/instruments/visaConn.py", line 82, in ask recv=self.visa.ask(visaCmd) File "/usr/local/lib/python2.7/dist-packages/pyvisa/resources/messagebased.py", line 574, in ask return self.query(message, delay) File "/usr/local/lib/python2.7/dist-packages/pyvisa/resources/messagebased.py", line 569, in query return self.read() File "/usr/local/lib/python2.7/dist-packages/pyvisa/resources/messagebased.py", line 413, in read message = self._read_raw().decode(enco) File "/usr/local/lib/python2.7/dist-packages/pyvisa/resources/messagebased.py", line 386, in _read_raw chunk, status = self.visalib.read(self.session, size) File "/usr/local/lib/python2.7/dist-packages/pyvisa-py/highlevel.py", line 350, in read raise errors.VisaIOError(ret[1]) VisaIOError: VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.

pablob127 commented 5 years ago

I think I hit something related to this trying to download a waveform from a Tektronix scope (using CURV?). If the waveform has 1000 points, it gets downloaded quickly with no issues. If it has 10000 it takes a bit longer (it could be 10x, but it is still fast enough), but still works. With 100000, instead of just taking 10x longer than 10000, it just seems to hang there forever. Interestingly, I tried to set a 60 second timeout and it did not seem to timeout. WIth no timeout, after a very long time (which I did not time) it seems it finally finishes. Setting a small chunk size did not seem to have a significant difference. I will try to see if I can connect to the scope using USB and see if the same happens.

ssouffri commented 4 years ago

I also hit this bug in version 1.10.1 and can confirmed that the workaround works 👍. I discovered that the default chunk_size appears to be 20480 and wonder if this is a typo and was meant to be 2048?