search

pyvisa / pyvisa-py

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

How to reset the communication after RPCError without release/re-open the device #172

Closed ldpgh closed 5 years ago

ldpgh commented 5 years ago

By accident a "?" was missing in the query string ("output?" vs "output"). It creates a timeout error ... which is OK, but afterwards each query returns with an RPCError.

What needs to be issued fix this communication issue?

'''

python Python 2.7.15 |Anaconda, Inc.| (default, May 1 2018, 18:37:09) [MSC v.1500 64 bit (AMD64)] on win32 Type "help", "copyright", "credits" or "license" for more information.

import visa rm=visa.ResourceManager("@py") fg=rm.open_resource("TCPIP::fg42") print fg.query("*IDN?") Agilent Technologies,33220A

print fg.query("output?") 0

print fg.query("output") Traceback (most recent call last): File "", line 1, in File "C:\ProgramData\A2\lib\site-packages\pyvisa\resources\messagebased.py", line 569, in query return self.read() File "C:\ProgramData\A2\lib\site-packages\pyvisa\resources\messagebased.py", line 413, in read message = self._read_raw().decode(enco) File "C:\ProgramData\A2\lib\site-packages\pyvisa\resources\messagebased.py", line 386, in _read_raw chunk, status = self.visalib.read(self.session, size) File "C:\ProgramData\A2\lib\site-packages\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.

print fg.query("output?") Traceback (most recent call last): File "", line 1, in File "C:\ProgramData\A2\lib\site-packages\pyvisa\resources\messagebased.py", line 563, in query self.write(message) File "C:\ProgramData\A2\lib\site-packages\pyvisa\resources\messagebased.py", line 223, in write count = self.write_raw(message.encode(enco)) File "C:\ProgramData\A2\lib\site-packages\pyvisa\resources\messagebased.py", line 201, in write_raw return self.visalib.write(self.session, message) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\highlevel.py", line 368, in write ret = self.sessions[session].write(data) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\tcpip.py", line 182, in write flags, block) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\protocols\vxi11.py", line 215, in device_write self.unpacker.unpack_device_write_resp) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\protocols\rpc.py", line 452, in make_call unpack_func) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\protocols\rpc.py", line 252, in make_call self.do_call() File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\protocols\rpc.py", line 477, in do_call raise RPCError(msg.format(xid, self.lastxid)) pyvisa-py.protocols.rpc.RPCError: wrong xid in reply 7 instead of 8

print fg.query("*IDN?") Traceback (most recent call last): File "", line 1, in File "C:\ProgramData\A2\lib\site-packages\pyvisa\resources\messagebased.py", line 563, in query self.write(message) File "C:\ProgramData\A2\lib\site-packages\pyvisa\resources\messagebased.py", line 223, in write count = self.write_raw(message.encode(enco)) File "C:\ProgramData\A2\lib\site-packages\pyvisa\resources\messagebased.py", line 201, in write_raw return self.visalib.write(self.session, message) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\highlevel.py", line 368, in write ret = self.sessions[session].write(data) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\tcpip.py", line 182, in write flags, block) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\protocols\vxi11.py", line 215, in device_write self.unpacker.unpack_device_write_resp) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\protocols\rpc.py", line 452, in make_call unpack_func) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\protocols\rpc.py", line 252, in make_call self.do_call() File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\protocols\rpc.py", line 477, in do_call raise RPCError(msg.format(xid, self.lastxid)) pyvisa-py.protocols.rpc.RPCError: wrong xid in reply 8 instead of 9

fg.read() Traceback (most recent call last): File "", line 1, in File "C:\ProgramData\A2\lib\site-packages\pyvisa\resources\messagebased.py", line 413, in read message = self._read_raw().decode(enco) File "C:\ProgramData\A2\lib\site-packages\pyvisa\resources\messagebased.py", line 386, in _read_raw chunk, status = self.visalib.read(self.session, size) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\highlevel.py", line 345, in read ret = self.sessions[session].read(count) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\tcpip.py", line 132, in read self.lock_timeout, flags, term_char) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\protocols\vxi11.py", line 226, in device_read self.unpacker.unpack_device_read_resp) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\protocols\rpc.py", line 452, in make_call unpack_func) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\protocols\rpc.py", line 252, in make_call self.do_call() File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\protocols\rpc.py", line 477, in do_call raise RPCError(msg.format(xid, self.lastxid)) pyvisa-py.protocols.rpc.RPCError: wrong xid in reply 9 instead of 10 fg.read() Traceback (most recent call last): File "", line 1, in File "C:\ProgramData\A2\lib\site-packages\pyvisa\resources\messagebased.py", line 413, in read message = self._read_raw().decode(enco) File "C:\ProgramData\A2\lib\site-packages\pyvisa\resources\messagebased.py", line 386, in _read_raw chunk, status = self.visalib.read(self.session, size) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\highlevel.py", line 345, in read ret = self.sessions[session].read(count) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\tcpip.py", line 132, in read self.lock_timeout, flags, term_char) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\protocols\vxi11.py", line 226, in device_read self.unpacker.unpack_device_read_resp) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\protocols\rpc.py", line 452, in make_call unpack_func) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\protocols\rpc.py", line 252, in make_call self.do_call() File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\protocols\rpc.py", line 477, in do_call raise RPCError(msg.format(xid, self.lastxid)) pyvisa-py.protocols.rpc.RPCError: wrong xid in reply 10 instead of 11 fg.read() Traceback (most recent call last): File "", line 1, in File "C:\ProgramData\A2\lib\site-packages\pyvisa\resources\messagebased.py", line 413, in read message = self._read_raw().decode(enco) File "C:\ProgramData\A2\lib\site-packages\pyvisa\resources\messagebased.py", line 386, in _read_raw chunk, status = self.visalib.read(self.session, size) File "C:\ProgramData\A2\lib\site-packages\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.

print fg.query("*IDN?") Traceback (most recent call last): File "", line 1, in File "C:\ProgramData\A2\lib\site-packages\pyvisa\resources\messagebased.py", line 563, in query self.write(message) File "C:\ProgramData\A2\lib\site-packages\pyvisa\resources\messagebased.py", line 223, in write count = self.write_raw(message.encode(enco)) File "C:\ProgramData\A2\lib\site-packages\pyvisa\resources\messagebased.py", line 201, in write_raw return self.visalib.write(self.session, message) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\highlevel.py", line 368, in write ret = self.sessions[session].write(data) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\tcpip.py", line 182, in write flags, block) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\protocols\vxi11.py", line 215, in device_write self.unpacker.unpack_device_write_resp) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\protocols\rpc.py", line 452, in make_call unpack_func) File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\protocols\rpc.py", line 252, in make_call self.do_call() File "C:\ProgramData\A2\lib\site-packages\pyvisa-py\protocols\rpc.py", line 477, in do_call raise RPCError(msg.format(xid, self.lastxid)) pyvisa-py.protocols.rpc.RPCError: wrong xid in reply 11 instead of 13

visa.version '1.9.1'

quit() Error closing VISA link: wrong xid in reply 12 instead of 14

'''

MatthieuDartiailh commented 5 years ago

It looks like you have hit a bug. The quick workaround for now is to do the following after a timeout:

rm.visalib.sessions[fg.session].interface.lastxid -= 1

The key issue here is that the xid is always incremented but if we attempt to communicate with the instrument at the wrong time (when we are not supposed to), the instrument does not internally increment the xid which leads to discrepancies. I will look at how to cleanly fix this and hopefully I will have a patch next week.

MatthieuDartiailh commented 5 years ago

Closed by #173

ianccole commented 4 years ago

So, I'm seeing the same IOError from a Agilent N9020A after in excess of 5 million successful peak reads.

02:08:59: Error closing VISA link: wrong xid in reply 5391675 instead of 5391676

I'm using OPC? to ensure that I wait for a measurement trace to complete before calculating and returning the peak value. It's the OPC? command that fails.

PyVISA==1.9.1 PyVISA-py==0.3.1

I note that the final message is 'Error closing VISA link' presumably from tcpip.py line 92 so it's likely that the session/link is actually closed at this point? So decrementing lastxid is unlikely to help?

What should I do to prevent this error or recover from it? Does it have anything to do with timeouts?

Any guidance here would be gratefully received!

MatthieuDartiailh commented 4 years ago

Could you post the full traceback and log ? Also do you see this on current master ?

ianccole commented 4 years ago

Here's the traceback. Initial event seemed to be a timeout.

I've not tried the current master - this event seems to take anything between a few hours to 2 days to manifest itself.

The comment in rpc.py '# Can't really happen since this is TCP...' seems correct to me. Any reply is likely to have a correctly incremented xid. No reply is a hard timeout.

The xid error seems to occur during the shutdown. But I expect at this point that if I handled the timeout by retrying I might see it here too?

1:29:29: VI_ERROR_TMO (-1073807339): Timeout expired before operation completed. 21:29:29: Traceback (most recent call last): 21:29:29: File "/home/pfr347/work/projects/antenna2/antennaTest.py", line 884, in 21:29:29: main() 21:29:29: File "/home/pfr347/work/projects/antenna2/antennaTest.py", line 875, in main 21:29:29: test.runScript('_Radio') 21:29:29: File "/home/pfr347/work/projects/antenna2/antennaTest.py", line 359, in runScript 21:29:29: getattr(self, cmd[0])(args) 21:29:29: File "/home/pfr347/work/projects/antenna2/antennaTest.py", line 469, in radioTest 21:29:29: self.measure(peakType, freqOffset, self.config['freqList'], radio, radioConfigPerPosition) 21:29:29: File "/home/pfr347/work/projects/antenna2/antennaTest.py", line 583, in measure 21:29:29: self.raw = self.capture.peak 21:29:29: File "/home/pfr347/work/projects/antenna2/mxa.py", line 50, in peak 21:29:29: val = self.calcMarkMax() 21:29:29: File "/home/pfr347/work/projects/antenna2/mxa.py", line 68, in calcMarkMax 21:29:29: self.opc 21:29:29: File "/home/pfr347/work/projects/dvt-common/Agilent.py", line 65, in opc 21:29:29: self.opcText = self.query("OPC?") 21:29:29: File "/home/pfr347/work/projects/dvt-common/Agilent.py", line 131, in query 21:29:29: raise IOError('GPIB failed to read') 21:29:29: IOError: GPIB failed to read 2019-11-29 21:29:29,547 - main - INFO - OnProcessEnded, pid:8167, exitCode: 1 21:29:29: Error closing VISA link: wrong xid in reply 836276 instead of 836277

ianccole commented 4 years ago

I wonder if catching rpc.RPCError and decrementing lastxid might be a workaround?

MatthieuDartiailh commented 4 years ago

The fixes of #173 are only available on master so it would be great if you could test on master.

ianccole commented 4 years ago

Ah OK. I'll clone master and try that out. Should be doing another long run this weekend.

Thanks for the update.

ianccole commented 4 years ago

Ok xid failure while running on master

pip install git+https://github.com/pyvisa/pyvisa.git pip install git+https://github.com/pyvisa/pyvisa-py.git

pyvisa Log if it helps:

6:20:58: 2019-12-11 16:20:58,623:Agilent:DEBUG:GPIB Write Tx: FREQ:CENT 4498750000.0 Hz;WAI 16:20:58: 2019-12-11 16:20:58,624:pyvisa:DEBUG:Make call 11, (11727344, 5000, 10000, 136, 'FREQ:CENT 4498750000.0 Hz;WAI\r\n'), <bound method Vxi11Packer.pack_device_write_parms of <pyvisa-py.protocols.vxi11.Vxi11Packer instance at 0x7f416fe77d88>>, <bound method Vxi11Unpacker.unpack_device_write_resp of <pyvisa-py.protocols.vxi11.Vxi11Unpacker instance at 0x7f416fe77dd0>> 16:20:58: 2019-12-11 16:20:58,624:pyvisa:DEBUG:Sending record through <socket._socketobject object at 0x7f416feecfa0>: "\x00\td\x1f\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\xb2\xf1\xf0\x00\x00\x13\x88\x00\x00'\x10\x00\x00\x00\x88\x00\x00\x00 FREQ:CENT 4498750000.0 Hz;WAI\r\n" 16:20:58: 2019-12-11 16:20:58,626:pyvisa:DEBUG:Received record through <socket._socketobject object at 0x7f416feecfa0>: bytearray(b'\x00\td\x1f\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 ') 16:20:58: 2019-12-11 16:20:58,626:Agilent:DEBUG:GPIB Write Rx: (32, <StatusCode.success: 0>) 16:20:58: 2019-12-11 16:20:58,626:pyvisa:DEBUG:Make call 11, (0, 2000, 10000, 136, 'FREQ:FIX 9690000000.0 HZ\r\n'), <bound method Vxi11Packer.pack_device_write_parms of <pyvisa-py.protocols.vxi11.Vxi11Packer instance at 0x7f416fe8b368>>, <bound method Vxi11Unpacker.unpack_device_write_resp of <pyvisa-py.protocols.vxi11.Vxi11Unpacker instance at 0x7f416fe8b3b0>> 16:20:58: 2019-12-11 16:20:58,627:pyvisa:DEBUG:Sending record through <socket._socketobject object at 0x7f416fea2de0>: "\x00\x001\x19\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\x00\x00\x00\x07\xd0\x00\x00'\x10\x00\x00\x00\x88\x00\x00\x00\x1aFREQ:FIX 9690000000.0 HZ\r\n\x00\x00" 16:20:58: 2019-12-11 16:20:58,630:pyvisa:DEBUG:Received record through <socket._socketobject object at 0x7f416fea2de0>: bytearray(b'\x00\x001\x19\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\x1a') 16:20:58: 2019-12-11 16:20:58,731:Agilent:DEBUG:GPIB Write Tx: :INIT:IMM 16:20:58: 2019-12-11 16:20:58,731:pyvisa:DEBUG:Make call 11, (11727344, 5000, 10000, 136, ':INIT:IMM\r\n'), <bound method Vxi11Packer.pack_device_write_parms of <pyvisa-py.protocols.vxi11.Vxi11Packer instance at 0x7f416fe77d88>>, <bound method Vxi11Unpacker.unpack_device_write_resp of <pyvisa-py.protocols.vxi11.Vxi11Unpacker instance at 0x7f416fe77dd0>> 16:20:58: 2019-12-11 16:20:58,731:pyvisa:DEBUG:Sending record through <socket._socketobject object at 0x7f416feecfa0>: "\x00\td \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\xb2\xf1\xf0\x00\x00\x13\x88\x00\x00'\x10\x00\x00\x00\x88\x00\x00\x00\x0b:INIT:IMM\r\n\x00" 16:20:58: 2019-12-11 16:20:58,732:pyvisa:DEBUG:Received record through <socket._socketobject object at 0x7f416feecfa0>: bytearray(b'\x00\td \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') 16:20:58: 2019-12-11 16:20:58,732:Agilent:DEBUG:GPIB Write Rx: (11, <StatusCode.success: 0>) 16:20:58: 2019-12-11 16:20:58,733:Agilent:DEBUG:GPIB query Tx: OPC? 16:20:58: 2019-12-11 16:20:58,733:pyvisa:DEBUG:Make call 11, (11727344, 5000, 10000, 136, 'OPC?\r\n'), <bound method Vxi11Packer.pack_device_write_parms of <pyvisa-py.protocols.vxi11.Vxi11Packer instance at 0x7f416fe77d88>>, <bound method Vxi11Unpacker.unpack_device_write_resp of <pyvisa-py.protocols.vxi11.Vxi11Unpacker instance at 0x7f416fe77dd0>> 16:20:58: 2019-12-11 16:20:58,733:pyvisa:DEBUG:Sending record through <socket._socketobject object at 0x7f416feecfa0>: "\x00\td!\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\xb2\xf1\xf0\x00\x00\x13\x88\x00\x00'\x10\x00\x00\x00\x88\x00\x00\x00\x07OPC?\r\n\x00" 16:20:58: 2019-12-11 16:20:58,734:pyvisa:DEBUG:Received record through <socket._socketobject object at 0x7f416feecfa0>: bytearray(b'\x00\td!\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\x07') 16:20:58: 2019-12-11 16:20:58,734:pyvisa:DEBUG:TCPIP::10.10.10.58 - reading 20480 bytes (last status <StatusCode.success_max_count_read: 1073676294>) 16:20:58: 2019-12-11 16:20:58,734:pyvisa:DEBUG:Make call 12, (11727344, 20480, 5000, 10000, 0, 0), <bound method Vxi11Packer.pack_device_read_parms of <pyvisa-py.protocols.vxi11.Vxi11Packer instance at 0x7f416fe77d88>>, <bound method Vxi11Unpacker.unpack_device_read_resp of <pyvisa-py.protocols.vxi11.Vxi11Unpacker instance at 0x7f416fe77dd0>> 16:20:58: 2019-12-11 16:20:58,734:pyvisa:DEBUG:Sending record through <socket._socketobject object at 0x7f416feecfa0>: '\x00\td"\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\xb2\xf1\xf0\x00\x00P\x00\x00\x00\x13\x88\x00\x00\'\x10\x00\x00\x00\x00\x00\x00\x00\x00' 16:21:04: 2019-12-11 16:21:04,790:pyvisa:DEBUG:Time out encountered in <socket._socketobject object at 0x7f416feecfa0>.Already receieved 0 bytes. Last fragment is 0 bytes long and we were expecting 4 16:21:04: 2019-12-11 16:21:04,791:pyvisa:DEBUG:TCPIP::10.10.10.58 - exception while reading: VI_ERROR_IO (-1073807298): Could not perform operation because of I/O error.