TCP Socket connection: Issuing a query after a query that has timed out causes the previous result to be returned
DareDevilDenis opened this issue · 35 comments
If I issue a query that times out, and then issue a second query, that second query incorrectly returns the result from the first (timedout) query. The same test works fine when using the Keysight IVI backend.
To reproduce:
- Set instrument timeout to 5 seconds
*RST*OPC?<-- The *RST takes about 10 seconds so *OPC? times out after 5 seconds as expected- Wait 20 seconds to ensure that the *RST has completed
IDN?
The problem is that *IDN? returns '1' which is the result from the *OPC? query.
When using the Keysight IVI backend the *IDN? correctly returns 'Keysight Technologies,C8700200A Test Application Framework,US12345678,20.90.0.9010'
Instrument details:
- Keysight 5GNR Test Application Framework
- Communication: TCP Socket
Code:
from datetime import datetime
import time
import pyvisa
def debug(*args):
print(datetime.now(), *args)
rm = pyvisa.ResourceManager('@py') # If I remove '@py' then it works i.e. *IDN? returns the instrument name
instrument = rm.open_resource('TCPIP0::127.0.0.1::5125::SOCKET')
instrument.timeout = 5000 # Small value to make *OPC? timeout
instrument.read_termination = '\n'
try:
debug('Calling *RST')
instrument.write('*RST')
debug('Calling *OPC?')
instrument.query('*OPC?')
except Exception as ex:
debug(ex)
time.sleep(20)
debug('Calling *IDN?')
result = instrument.query('*IDN?')
debug('Result:', result)Incorrect result using pyvisa-py backend:
2023-06-05 09:48:28.934000 Calling *RST
2023-06-05 09:48:28.934000 Calling *OPC?
2023-06-05 09:48:33.989677 VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.
2023-06-05 09:48:53.993221 Calling *IDN?
2023-06-05 09:48:53.995160 Result: 1
Correct result using Keysight IVI backend (simply removing '@py' from the ResourceManager constructor):
2023-06-05 09:55:28.857054 Calling *RST
2023-06-05 09:55:28.858046 Calling *OPC?
2023-06-05 09:55:33.881024 VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.
2023-06-05 09:55:53.892010 Calling *IDN?
2023-06-05 09:55:53.894488 Result: Keysight Technologies,C8700200A Test Application Framework,US12345678,20.90.0.9010
Output of pyvisa-info
Machine Details:
Platform ID: Windows-10-10.0.19044-SP0
Processor: Intel64 Family 6 Model 141 Stepping 1, GenuineIntel
Python:
Implementation: CPython
Executable: C:\Program Files\Python38\python.exe
Version: 3.8.16
Compiler: MSC v.1900 64 bit (AMD64)
Bits: 64bit
Build: Dec 20 2022 23:15:53 (#default)
Unicode: UCS4
PyVISA Version: 1.13.0
Backends:
ivi:
Version: 1.13.0 (bundled with PyVISA)
#1: C:\Windows\system32\visa32.dll:
found by: auto
bitness: 64
Vendor: Keysight Technologies
Impl. Version: 1377199637
Spec. Version: 5244928
#2: C:\Windows\system32\visa64.dll:
found by: auto
bitness: 64
Vendor: Keysight Technologies
Impl. Version: 1377199637
Spec. Version: 5244928
py:
Version: 0.7.0
TCPIP INSTR: Available
Resource discovery:
- VXI-11: partial (psutil not installed)
- hislip: disabled (zeroconf not installed)
TCPIP SOCKET: Available
ASRL INSTR:
Please install PySerial (>=3.0) to use this resource type.
No module named 'serial'
USB INSTR:
Please install PyUSB to use this resource type.
No module named 'usb'
USB RAW:
Please install PyUSB to use this resource type.
No module named 'usb'
VICP INSTR:
Please install PyVICP to use this resource type.
GPIB INSTR:
Please install linux-gpib (Linux) or gpib-ctypes (Windows, Linux) to use this resource type. Note that installing gpib-ctypes will give you access to a broader range of functionalities.
No module named 'gpib'
GPIB INTFC:
Please install linux-gpib (Linux) or gpib-ctypes (Windows, Linux) to use this resource type. Note that installing gpib-ctypes will give you access to a broader range of functionalities.
No module named 'gpib'
ty for a detailed bug report!
I think I saw similar behaviour with other transports as well.
Wouldn’t it be caused by the result of OPC? still being in the output queue? I imagine capturing pcaps for each case will help a lot, but unfortunately I won’t have access to my lab for a couple more weeks.
@arr-ee, wow, that was a quick response! By 'pcaps', do you mean a Wireshark packet capture?
Yup
Ok, here's the packet capture for the working and non-working cases: packet_capture.zip
In wireshark use filter: tcp.port == 5125
[I've edited the comments below for clarity]
In both case, we can see that over the wire the result of *OPC? is the expected "Keysight Technologies,C8700200A Test Application Framework,US12345678,20.90.0.9010", however when using pyvisa-py, the value returned from the instrument.query('*IDN?') method call is '1' which I beleve is the result of the *OPC?
Would've been nice if I read the issue more thoroughly before jumping in — I assumed it's an LXI connection and not a raw socket. Good thing packet captures confirmed that at least network side is identical.
Currently pyvisa-py is only reading data from the socket once a read method is called, so we end up reading both responses and dropping the second one (or, rather, everything after first one's termination character) on the floor. You can verify this by unsetting read termination and swapping query with write + read(16) or smth.
I'm not terribly experienced with handling sockets, but I'm pretty sure this is not ideal. I imagine VISA drivers are always polling the socket, and just dismiss the (timed out) message, allowing us to read the correct one when we get to reading (or querying). Unfortunately, I don't think pyvisa-py is well equipped to run in a similar manner at this point (@MatthieuDartiailh to correct me.)
The easiest workaround while still using pyvisa-py would be switching to VXI/LXI, we do implement message sequencing there which should help with cases like this one. Are there any reasons for not using them in your case?
I checked the packets and I agree with @arr-ee that it would be hard to do anything meaningful to mitigate the issue.
Raw socket do not allow us to track which reply corresponds to which query and as a consequence discarding a message based on a timestamp seems to be the only feasible solution. However to do so would require to run a background thread continuously polling the socket and enqueuing valid messages. While feasible I am concerned about the overhead it would add to normal operation.
As an experiment I would be curious to know what happens, using Keysight VISA, if you query *IDN? before getting the response to *OPC? get sent but in such a way that the read does not time out. I have a feeling that in such a case you would also get a mangled response and if that is true the added complexity of a possible solution would be even less appealing.
My instrument (Keysight C8700200A https://www.keysight.com/us/en/product/C8700200A/uxm-5g-test-application-software.html) supports socket connections and HiSLIP connections so I don't think I have the option of switching to VXI/LXI. Since pyvisa-py doesn't support HiSLIP I think the only option I have is a socket connection.
As a workaround for this issue I'm catching the timeout exception and closing and re-opening the connection. I think this is quite an ugly workaround - do you guys have a better idea?
from datetime import datetime
import time
import pyvisa
def debug(*args):
print(datetime.now(), *args)
def connect():
instrument = rm.open_resource('TCPIP0::127.0.0.1::5125::SOCKET')
instrument.timeout = 5000 # Small value to make *OPC? timeout
instrument.read_termination = '\n'
return instrument
rm = pyvisa.ResourceManager('@py')
instrument = connect()
debug('Calling *RST')
instrument.write('*RST')
debug('Calling *OPC?')
try:
instrument.query('*OPC?')
except pyvisa.errors.VisaIOError as ex:
debug('Something went wrong!', ex)
# Workaround to ensure that the next query is ok <------------
instrument.close()
instrument = connect()
time.sleep(20)
debug('Calling *IDN?')
result = instrument.query('*IDN?')
debug('Result:', result)As an experiment I would be curious to know what happens, using Keysight VISA, if you query *IDN? before getting the response to *OPC? get sent but in such a way that the read does not time out.
I'm happy to do this, but I didn't quite understand how I should do it. The *OPC? query will be blocking so how do I perform a *IDN? during this time? Do you mean that I should do it in another thread?
PyVISA-py does support HiSLIP (added in the last release) so you can try that.
Regarding the test my idea was simply to reduce the wait time before issuing the IDN query so that the instrument has not yet answered to the OPC when we start reading.
Yeah I had a look at the instrument you're using, but found precious little info about it. Guess I need to get a platinum account with Keysight :)
Since pyvisa-py doesn't support HiSLIP I think the only option I have is a socket connection.
pyvisa-py does support hislip:
Lines 79 to 80 in 00535d5
As a workaround for this issue I'm catching the timeout exception and closing and re-opening the connection. I think this is quite an ugly workaround - do you guys have a better idea?
For cases where you know you might time out, a write & catch + read loop might help, but it's not ideal also.
I'm happy to do this, but I didn't quite understand how I should do it. The *OPC? query will be blocking so how do I perform a *IDN? during this time? Do you mean that I should do it in another thread?
I think something like
instrument.write('*RST')
try:
instrument.query('OPC?')
except pyvisa.errors.VisaIOError as ex:
debug('Something went wrong!', ex)
sleep(3) # 5 sec timeout + 3 sec sleep < ~9 sec reset time
instrument.query('*IDN?')might do the trick, with OPC? response and subsequent *IDN? response arriving into the buffer at about the same time.
Oh, I didn't realise that pyvisa-py supported HiSLIP - stupid me for missing that!
I ran my original script from the top of this discussion, this time using HiSLIP:
instrument = rm.open_resource('TCPIP0::127.0.0.1::hislip2::INSTR')However, it gave the same result i.e. *IDN? still returned '1'. Would you have expected this to work?
(I tried it both with and without zeroconf installed)
Regarding the test my idea was simply to reduce the wait time before issuing the IDN query so that the instrument has not yet answered to the OPC when we start reading.
and @arr-ee's code: Now I understand :). I swiched to the Keysight IVI backend and changed the delay between *OPC? and *IDN? to 3 seconds, The result was that *IDN? returned '1'.
re: @arr-ee
Yeah I had a look at the instrument you're using, but found precious little info about it. Guess I need to get a platinum account with Keysight :)
I work for Keysight 😃. I can help where I can, but I need to be careful not to share anything that is internal only.
So there is no weird dark magic at work to miraculously fix things for SOCKET, that's good to know.
For HiSLIP, my first question would to try to reproduce using Keyisght so that we get an idea of where we stand. If Keysight behaves in a nicer fashion (which I would expect), we will have to dive into hislip support...
We are supposed to be checking message ids and discarding stale responses:
pyvisa-py/pyvisa_py/protocols/hislip.py
Lines 547 to 560 in 00535d5
Unfortunately, hislip implementation has no debug logging, which makes this a bit tricky.
I agree that verifying Keysight VISA behaving better should be the first step, if it does we can sprinkle some logging around.
This issue's making a good case for test coverage, I'll try to look into it when I have more time.
I ran it with hislip and Keysight backend. Here's the full script:
from datetime import datetime
import time
import pyvisa
def debug(*args):
print(datetime.now(), *args)
rm = pyvisa.ResourceManager() # <---- So that it selects Keysight backend
instrument = rm.open_resource('TCPIP0::127.0.0.1::hislip2::INSTR')
instrument.timeout = 5000 # Small value to make *OPC? timeout
instrument.read_termination = '\n'
try:
debug('Calling *RST')
instrument.write('*RST')
debug('Calling *OPC?')
instrument.query('*OPC?')
except Exception as ex:
debug(ex)
time.sleep(20)
debug('Calling *IDN?')
result = instrument.query('*IDN?')
debug('Result:', result)It worked. Here's the output:
2023-06-07 09:48:00.440992 Calling *RST
2023-06-07 09:48:00.441992 Calling *OPC?
2023-06-07 09:48:05.471065 VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.
2023-06-07 09:48:25.486525 Calling *IDN?
2023-06-07 09:48:25.487630 Result: Keysight Technologies,C8700200A Test Application Framework,US12345678,20.90.0.9010
By the way (separate subject), I noticed that the example at https://pyvisa.readthedocs.io/projects/pyvisa-py/en/latest/index.html has import visa. Shouldn't it be import pyvisa ?
It should
To be honest I am underwater ATM so I won't have time to dive into the hislip code. I think adding some debug logging as suggested by @arr-ee is the most reasonable point at which to start an investigation.
@DareDevilDenis would you mind capturing packets for hislip as well? I hope it will be enough to repro in a test, and should introduce less back and forth with logging (although I will add some).
Also ty for pointing out the old module name — good example of selective blindness :)
Sure @arr-ee, here you go:
packet_capture_keysight_backend_hislip.zip
Let me know if I can help further.
And:
packet_capture_pyvisa-py_backend_hislip.zip
Output:
2023-06-09 14:03:01.537317 Calling *RST
2023-06-09 14:03:01.538305 Calling *OPC?
2023-06-09 14:03:06.539939 VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.
2023-06-09 14:03:26.541905 Calling *IDN?
2023-06-09 14:03:26.543428 Result: 1
Awesome, I managed to reproduce it locally and track down (one of the) issue(s). If you could give arr-ee@94c6be8#diff-16c2fd9245259a2996f77bbe2e2427d0b37ac828ea66dc972b74619ba8a2ca85 a whirl (modify your local install or run pip install git+https://github.com/arr-ee/pyvisa-py.git@376-hislip-caught-slippin in the venv you're running pyvisa from) I would appreciate it.
As mentioned in the commit, this is by no means a solution (it's barely a repro hahah), but might let you move forward for now and/or help find more issues. I'll try to come up with a better testsuite and state machine-based protocol handler in a week or two.
I ran the test with your commit (installed with the pip install link that you gave) but it gave the same result as before i.e. *IDN? returned '1'.
For completeness, here's the script:
from datetime import datetime
import time
import pyvisa
def debug(*args):
print(datetime.now(), *args)
rm = pyvisa.ResourceManager('@py')
instrument = rm.open_resource('TCPIP0::127.0.0.1::hislip2::INSTR')
instrument.timeout = 5000 # Small value to make *OPC? timeout
instrument.read_termination = '\n'
try:
debug('Calling *RST')
instrument.write('*RST')
debug('Calling *OPC?')
instrument.query('*OPC?')
except Exception as ex:
debug(ex)
time.sleep(20)
debug('Calling *IDN?')
result = instrument.query('*IDN?')
debug('Result:', result)Output:
2023-06-10 15:46:03.699280 Calling *RST
2023-06-10 15:46:03.699518 Calling *OPC?
2023-06-10 15:46:08.703645 VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.
2023-06-10 15:46:28.713017 Calling *IDN?
2023-06-10 15:46:28.713938 Result: 1
Packet capture: 2023_06_10_packet_capture_hislip_pyvisa-py_backend_arr-ee_commit_376-hislip-caught-slippin.zip
Checking the pyvisa-py version:
> py -m pip show pyvisa-py
Name: PyVISA-py
Version: 0.6.4.dev13+g94c6be8
Summary: Pure Python implementation of a VISA library.
Home-page:
Author:
Author-email: "Hernan E. Grecco" <hernan.grecco@gmail.com>
License: The MIT License
Copyright (c) 2014 PyVISA-py Authors and contributors. See AUTHORS
Permission is hereby granted, free of charge, to any person obtaining a copy of
this software and associated documentation files (the "Software"), to deal in
the Software without restriction, including without limitation the rights to
use, copy, modify, merge, publish, distribute, sublicense, and/or sell copies
of the Software, and to permit persons to whom the Software is furnished to do
so, subject to the following conditions:
The above copyright notice and this permission notice shall be included in all
copies or substantial portions of the Software.
THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
SOFTWARE.
Location: c:\program files\python38\lib\site-packages
Requires: pyvisa, typing-extensions
Required-by:
Do you need any more information from me, or is there anything I can do to help?
Hey Vince, apologies for lack of updates.
I went down a rabbit hole of adding hislip support to Scapy to make working with captures a bit less tedious (and because I wanted to), and that + travel got me bogged down for now.
Additionally, I am back in my homelab, and I found a hislip-enabled device here. It's an R&S NGE100B, so very different class of instrument, but a) better than nothing, and b) R&S folks have done a lot of work around LXI and hislip, including being one of the certifying bodies in the EU IIRC, so I can only hope their implementation is correct.
I'll try reproducing the issue on actual hardware while continuing debugging the test case, and will update next week. If you don't hear anything from me please do not hesitate to ping.
Ty for your assistance and patience.
quick update: with pyvisa_py==0.7.0 I see a different issue with hislip that I think ultimately comes from the same source. I also saw similar behaviour with USBTMC on other instruments but need to verify with data capture.
The "patch" I provided above fixes this behaviour, and I am able to start receiving messages after read timeout. Digging further.
pyvisa session:
Python 3.10.10 (main, Mar 23 2023, 17:56:17) [GCC 10.2.1 20210110] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import pyvisa
>>> rm = pyvisa.ResourceManager()
>>> i = rm.open_resource('TCPIP::192.168.111.103::hislip0::INSTR')
>>> i.query('*IDN?')
'Rohde&Schwarz,NGE103B,5601.3800k03/100545,1.55\n'
>>> i.query(':READ?')
...
pyvisa.errors.VisaIOError: VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.
>>> i.query(':SYST:ERR?')
...
pyvisa.errors.VisaIOError: VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.
>>> i.query('*IDN?')
...
pyvisa.errors.VisaIOError: VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.As can be seen in the dump, instrument responds as expected yet those responses never make it to the caller.
@DareDevilDenis I pushed another update to the branch mentioned above, this one just adds a bunch of logging around hislip socket operations. If you could run it I'd appreciate it.
I fail to reproduce these issues locally with the (initial) fix from my branch applied, but I also don't have such long-running operations on my instrument, so.
@arr-ee, I repeated the test and got the same result. I see that you've added some logging using structlog. I ran my script from a normal Windows command window but strangely I didn't see any logging come out. I'm not familiar with structlog so not sure why.
Just to prove that your code was being run, I uncommented your print statement in hislip.py
def send(self, data: bytes) -> int:
"""Send the data on the synchronous channel.
More than one packet may be necessary in order
to not exceed max_payload_size.
"""
print(f"send({data=})") # uncomment for debugging
log.debug("hislip.send")And the prints came out as expected:
2023-06-20 15:51:15.968591 Calling *RST
send(data=b'*RST\r\n')
2023-06-20 15:51:15.969626 Calling *OPC?
send(data=b'*OPC?\r\n')
2023-06-20 15:51:20.980215 VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.
2023-06-20 15:51:40.980817 Calling *IDN?
send(data=b'*IDN?\r\n')
2023-06-20 15:51:40.983765 Result: 1
Any idea how to get the structlog logging?
You don't get any logging because it's not enabled — same reason you don't see pyvisa logs.
Adding logging.basicConfig(level=logging.DEBUG) to the beginning of your script should do the trick. It's a bit annoying, but libraries are not supposed to log stuff unless told to :) Making this a bit more user-friendly is on my list (and structlog was one of the possible options, but I think sticking to stdlib logging would be best overall)
You can use pyvisa.log_to_screen to redirect the pyvisa logger to stdout.
You can use pyvisa.log_to_screen to redirect the pyvisa logger to stdout.
This might not work for logging calls that do not use pyvisa's logger instance, which I am not doing here (which is a mistake on my part tbh, although I realised now I have not noticed everything importing the logger from pyvisa itself)
Thanks for explaining the logging. I added the following to the top of the script:
logging.basicConfig(level=logging.DEBUG)
pyvisa.log_to_screen()Output:
DEBUG:pyvisa:SerialSession was not imported No module named 'serial'.
2023-06-22 09:42:25,960 - pyvisa - DEBUG - USBSession and USBRawSession were not imported No module named 'usb'.
DEBUG:pyvisa:USBSession and USBRawSession were not imported No module named 'usb'.
2023-06-22 09:42:25,968 - pyvisa - DEBUG - TCPIPSession was correctly imported.
DEBUG:pyvisa:TCPIPSession was correctly imported.
2023-06-22 09:42:25,970 - pyvisa - DEBUG - GPIBSession was not imported No module named 'gpib'.
DEBUG:pyvisa:GPIBSession was not imported No module named 'gpib'.
2023-06-22 09:42:25,972 - pyvisa - DEBUG - Created library wrapper for py
DEBUG:pyvisa:Created library wrapper for py
2023-06-22 09:42:25,975 - pyvisa - DEBUG - Created ResourceManager with session 9743154
DEBUG:pyvisa:Created ResourceManager with session 9743154
2023-06-22 09:42:25,976 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - opening ...
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - opening ...
2023-06-22 09:42:25,980 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - is open with session 2038837
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - is open with session 2038837
2023-06-22 09:42:25.980420 Calling *RST
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-22T08:42:25.981416Z' logger='pyvisa_py.protocols.hislip' event='hislip.send'
2023-06-22 09:42:25.981416 Calling *OPC?
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-22T08:42:25.981416Z' logger='pyvisa_py.protocols.hislip' event='hislip.send'
2023-06-22 09:42:25,981 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - reading 20480 bytes (last status <StatusCode.success_max_count_read: 1073676294>)
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - reading 20480 bytes (last status <StatusCode.success_max_count_read: 1073676294>)
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-22T08:42:25.982416Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive' expected_message_id=None last_message_id=4294967042 message_id=4294967044 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-22T08:42:25.982416Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive: adjust ids' expected_message_id=4294967042 last_message_id=4294967042 message_id=4294967044 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-22T08:42:25.983494Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive: loop iteration start' bytes_recvd=0 expected_message_id=4294967042 last_message_id=4294967042 message_id=4294967044 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-22T08:42:25.988800Z' logger='pyvisa_py.protocols.hislip' event='hislip._next_data_header: loop iteration start' bytes_recvd=0 expected_message_id=4294967042 last_message_id=4294967042 message_id=4294967044 msg_type='' payload_remaining=0
2023-06-22 09:42:31,005 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - exception while reading: VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.
Buffer content: bytearray(b'')
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - exception while reading: VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.
Buffer content: bytearray(b'')
2023-06-22 09:42:31.006234 VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.
2023-06-22 09:42:51.016830 Calling *IDN?
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-22T08:42:51.017005Z' logger='pyvisa_py.protocols.hislip' event='hislip.send' bytes_recvd=0 expected_message_id=4294967042 last_message_id=4294967042 message_id=4294967044 msg_type='' payload_remaining=0
2023-06-22 09:42:51,020 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - reading 20480 bytes (last status <StatusCode.success_max_count_read: 1073676294>)
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - reading 20480 bytes (last status <StatusCode.success_max_count_read: 1073676294>)
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-22T08:42:51.024227Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive' expected_message_id=4294967042 last_message_id=4294967044 message_id=4294967046 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-22T08:42:51.024227Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive: loop iteration start' bytes_recvd=0 expected_message_id=4294967042 last_message_id=4294967044 message_id=4294967046 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-22T08:42:51.024227Z' logger='pyvisa_py.protocols.hislip' event='hislip._next_data_header: loop iteration start' bytes_recvd=0 expected_message_id=4294967042 last_message_id=4294967044 message_id=4294967046 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-22T08:42:51.026746Z' logger='pyvisa_py.protocols.hislip' event='hislip._next_data_header' bytes_recvd=0 expected_message_id=4294967042 header={'header': bytearray(b'HS\x07\x00\xff\xff\xff\x02\x00\x00\x00\x00\x00\x00\x00\x02'), 'control_code': 0, 'message_parameter': 4294967042, 'payload_length': 2, 'msg_type': 'DataEnd', 'message_id': 4294967042} last_message_id=4294967044 message_id=4294967046 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-22T08:42:51.027754Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive: data header received' bytes_recvd=0 expected_message_id=4294967042 last_message_id=4294967044 message_id=4294967046 msg_type='DataEnd' payload_remaining=2
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-22T08:42:51.030742Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive: loop iteration start' bytes_recvd=2 expected_message_id=4294967042 last_message_id=4294967044 message_id=4294967046 msg_type='DataEnd' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-22T08:42:51.030742Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive: check for RMT' bytes_recvd=2 expected_message_id=4294967042 last_message_id=4294967044 message_id=4294967046 msg_type='DataEnd' payload_remaining=0
2023-06-22 09:42:51.030742 Result: 1
2023-06-22 09:42:51,031 - pyvisa - DEBUG - Closing ResourceManager (session: 9743154)
DEBUG:pyvisa:Closing ResourceManager (session: 9743154)
2023-06-22 09:42:51,031 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - closing
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - closing
2023-06-22 09:42:51,032 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - is closed
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - is closed
Packet capture:
2023_06_22_packet_capture.zip
Your log (abridged):
# write *IDN?
DEBUG:pyvisa_py.protocols.hislip:
level='debug'
timestamp='2023-06-22T08:42:51.017005Z'
logger='pyvisa_py.protocols.hislip'
event='hislip.send'
bytes_recvd=0
expected_message_id=4294967042
last_message_id=4294967042
message_id=4294967044
msg_type=''
payload_remaining=0
# read *IDN?
DEBUG:pyvisa_py.protocols.hislip:
level='debug'
timestamp='2023-06-22T08:42:51.024227Z'
logger='pyvisa_py.protocols.hislip'
event='hislip.receive'
===> expected_message_id=4294967042
last_message_id=4294967044
message_id=4294967046
msg_type=''
payload_remaining=0
test log:
DEBUG:pyvisa_py.protocols.hislip:
level='debug'
timestamp='2023-06-22T18:30:45.580628Z'
logger='pyvisa_py.protocols.hislip'
event='hislip.send'
bytes_recvd=0
expected_message_id=4294967042
last_message_id=4294967042
message_id=4294967044
msg_type=''
payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:
level='debug'
timestamp='2023-06-22T18:30:45.581698Z'
logger='pyvisa_py.protocols.hislip'
event='hislip.receive'
===> expected_message_id=None
last_message_id=4294967044
message_id=4294967046
msg_type=''
payload_remaining=0
So, arr-ee@94c6be8#diff-16c2fd9245259a2996f77bbe2e2427d0b37ac828ea66dc972b74619ba8a2ca85R516-R518 does not fire on your system for some reason, and I can only assume the reason is "different exceptions/timeout behaviours of sockets between macos and windows".
I'll try repro this on a windows system later, but in the meantime replacing block above with
except Exception as e:
log.debug(e)
if e.__class__ is TimeoutError:
self._expected_message_id = None
raise emight give more info?
Interesting that timeout appears to still be captured correctly further up the stack, even though it's supposed to be the same thing? So maybe catching that error will do the trick here.
I replaced the exception handler as you requested, plus printing the exception in full, and a few hacky prints:
except Exception as e:
print("DDD1")
traceback.print_exc()
log.debug(e)
print("DDD2")
if e.__class__ is TimeoutError:
print('DDD3')
self._expected_message_id = None
raise eResult:
2023-06-23 14:12:53,164 - pyvisa - DEBUG - SerialSession was not imported No module named 'serial'.
DEBUG:pyvisa:SerialSession was not imported No module named 'serial'.
2023-06-23 14:12:53,167 - pyvisa - DEBUG - USBSession and USBRawSession were not imported No module named 'usb'.
DEBUG:pyvisa:USBSession and USBRawSession were not imported No module named 'usb'.
2023-06-23 14:12:53,186 - pyvisa - DEBUG - TCPIPSession was correctly imported.
DEBUG:pyvisa:TCPIPSession was correctly imported.
2023-06-23 14:12:53,191 - pyvisa - DEBUG - GPIBSession was not imported No module named 'gpib'.
DEBUG:pyvisa:GPIBSession was not imported No module named 'gpib'.
2023-06-23 14:12:53,192 - pyvisa - DEBUG - Created library wrapper for py
DEBUG:pyvisa:Created library wrapper for py
2023-06-23 14:12:53,193 - pyvisa - DEBUG - Created ResourceManager with session 3392492
DEBUG:pyvisa:Created ResourceManager with session 3392492
2023-06-23 14:12:53,197 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - opening ...
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - opening ...
2023-06-23 14:12:53,202 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - is open with session 3094907
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - is open with session 3094907
2023-06-23 14:12:53.203470 Calling *RST
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T13:12:53.203970Z' logger='pyvisa_py.protocols.hislip' event='hislip.send'
2023-06-23 14:12:53.203970 Calling *OPC?
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T13:12:53.204976Z' logger='pyvisa_py.protocols.hislip' event='hislip.send'
2023-06-23 14:12:53,206 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - reading 20480 bytes (last status <StatusCode.success_max_count_read: 1073676294>)
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - reading 20480 bytes (last status <StatusCode.success_max_count_read: 1073676294>)
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T13:12:53.208559Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive' expected_message_id=None last_message_id=4294967042 message_id=4294967044 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T13:12:53.211390Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive: adjust ids' expected_message_id=4294967042 last_message_id=4294967042 message_id=4294967044 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T13:12:53.216805Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive: loop iteration start' bytes_recvd=0 expected_message_id=4294967042 last_message_id=4294967042 message_id=4294967044 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T13:12:53.218328Z' logger='pyvisa_py.protocols.hislip' event='hislip._next_data_header: loop iteration start' bytes_recvd=0 expected_message_id=4294967042 last_message_id=4294967042 message_id=4294967044 msg_type='' payload_remaining=0
DDD1
Traceback (most recent call last):
File "C:\Program Files\Python38\lib\site-packages\pyvisa_py\protocols\hislip.py", line 540, in receive
self._msg_type, self._payload_remaining = self._next_data_header()
File "C:\Program Files\Python38\lib\site-packages\pyvisa_py\protocols\hislip.py", line 595, in _next_data_header
header = RxHeader(self._sync)
File "C:\Program Files\Python38\lib\site-packages\pyvisa_py\protocols\hislip.py", line 213, in __init__
self.header = receive_exact(sock, HEADER_SIZE)
File "C:\Program Files\Python38\lib\site-packages\pyvisa_py\protocols\hislip.py", line 154, in receive_exact
receive_exact_into(sock, recv_buffer)
File "C:\Program Files\Python38\lib\site-packages\pyvisa_py\protocols\hislip.py", line 170, in receive_exact_into
data_len = sock.recv_into(view, request_size)
socket.timeout: timed out
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T13:12:58.252647Z' logger='pyvisa_py.protocols.hislip' event=timeout('timed out') bytes_recvd=0 expected_message_id=4294967042 last_message_id=4294967042 message_id=4294967044 msg_type='' payload_remaining=0
DDD2
2023-06-23 14:12:58,256 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - exception while reading: VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.
Buffer content: bytearray(b'')
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - exception while reading: VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.
Buffer content: bytearray(b'')
2023-06-23 14:12:58.258625 VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.
2023-06-23 14:13:18.267479 Calling *IDN?
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T13:13:18.267479Z' logger='pyvisa_py.protocols.hislip' event='hislip.send' bytes_recvd=0 expected_message_id=4294967042 last_message_id=4294967042 message_id=4294967044 msg_type='' payload_remaining=0
2023-06-23 14:13:18,280 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - reading 20480 bytes (last status <StatusCode.success_max_count_read: 1073676294>)
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - reading 20480 bytes (last status <StatusCode.success_max_count_read: 1073676294>)
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T13:13:18.285036Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive' expected_message_id=4294967042 last_message_id=4294967044 message_id=4294967046 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T13:13:18.287035Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive: loop iteration start' bytes_recvd=0 expected_message_id=4294967042 last_message_id=4294967044 message_id=4294967046 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T13:13:18.288035Z' logger='pyvisa_py.protocols.hislip' event='hislip._next_data_header: loop iteration start' bytes_recvd=0 expected_message_id=4294967042 last_message_id=4294967044 message_id=4294967046 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T13:13:18.290035Z' logger='pyvisa_py.protocols.hislip' event='hislip._next_data_header' bytes_recvd=0 expected_message_id=4294967042 header={'header': bytearray(b'HS\x07\x00\xff\xff\xff\x02\x00\x00\x00\x00\x00\x00\x00\x02'), 'control_code': 0, 'message_parameter': 4294967042, 'payload_length': 2, 'msg_type': 'DataEnd', 'message_id': 4294967042} last_message_id=4294967044 message_id=4294967046 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T13:13:18.291035Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive: data header received' bytes_recvd=0 expected_message_id=4294967042 last_message_id=4294967044 message_id=4294967046 msg_type='DataEnd' payload_remaining=2
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T13:13:18.292036Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive: loop iteration start' bytes_recvd=2 expected_message_id=4294967042 last_message_id=4294967044 message_id=4294967046 msg_type='DataEnd' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T13:13:18.292036Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive: check for RMT' bytes_recvd=2 expected_message_id=4294967042 last_message_id=4294967044 message_id=4294967046 msg_type='DataEnd' payload_remaining=0
2023-06-23 14:13:18.293035 Result: 1
2023-06-23 14:13:18,293 - pyvisa - DEBUG - Closing ResourceManager (session: 3392492)
DEBUG:pyvisa:Closing ResourceManager (session: 3392492)
2023-06-23 14:13:18,294 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - closing
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - closing
2023-06-23 14:13:18,295 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - is closed
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - is closed
Traceback:
socket.timeout: timed out
socket.timeout documentation:
Changed in version 3.10: This class was made an alias of
TimeoutError.
Your python: 3.8.16
My python: 3.11.2
silent scream.
It even reproduces locally. I should figure out a better way of running tests across python versions and platforms. Apologies for dragging this on for so long due to a silly mistake.
Replacing except TimeoutError as e: with except socket.timeout as e: should do the trick. I moved a (HOPEFULLY) working fix into https://github.com/arr-ee/pyvisa-py/tree/376-hislip-timeout-fix-clean without all the logging crud, and updated the original WIP branch as well.
Thanks @arr-ee
That worked 👍
Using the tip of 376-hislip-caught-slippin branch:
2023-06-23 16:21:54,140 - pyvisa - DEBUG - SerialSession was not imported No module named 'serial'.
DEBUG:pyvisa:SerialSession was not imported No module named 'serial'.
2023-06-23 16:21:54,142 - pyvisa - DEBUG - USBSession and USBRawSession were not imported No module named 'usb'.
DEBUG:pyvisa:USBSession and USBRawSession were not imported No module named 'usb'.
2023-06-23 16:21:54,150 - pyvisa - DEBUG - TCPIPSession was correctly imported.
DEBUG:pyvisa:TCPIPSession was correctly imported.
2023-06-23 16:21:54,152 - pyvisa - DEBUG - GPIBSession was not imported No module named 'gpib'.
DEBUG:pyvisa:GPIBSession was not imported No module named 'gpib'.
2023-06-23 16:21:54,154 - pyvisa - DEBUG - Created library wrapper for py
DEBUG:pyvisa:Created library wrapper for py
2023-06-23 16:21:54,154 - pyvisa - DEBUG - Created ResourceManager with session 4147854
DEBUG:pyvisa:Created ResourceManager with session 4147854
2023-06-23 16:21:54,154 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - opening ...
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - opening ...
2023-06-23 16:21:54,161 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - is open with session 4102967
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - is open with session 4102967
2023-06-23 16:21:54.163323 Calling *RST
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T15:21:54.163323Z' logger='pyvisa_py.protocols.hislip' event='hislip.send'
2023-06-23 16:21:54.164258 Calling *OPC?
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T15:21:54.164258Z' logger='pyvisa_py.protocols.hislip' event='hislip.send'
2023-06-23 16:21:54,167 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - reading 20480 bytes (last status <StatusCode.success_max_count_read: 1073676294>)
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - reading 20480 bytes (last status <StatusCode.success_max_count_read: 1073676294>)
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T15:21:54.169277Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive' expected_message_id=None last_message_id=4294967042 message_id=4294967044 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T15:21:54.173462Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive: adjust ids' expected_message_id=4294967042 last_message_id=4294967042 message_id=4294967044 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T15:21:54.175462Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive: loop iteration start' bytes_recvd=0 expected_message_id=4294967042 last_message_id=4294967042 message_id=4294967044 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T15:21:54.188138Z' logger='pyvisa_py.protocols.hislip' event='hislip._next_data_header: loop iteration start' bytes_recvd=0 expected_message_id=4294967042 last_message_id=4294967042 message_id=4294967044 msg_type='' payload_remaining=0
2023-06-23 16:21:59,199 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - exception while reading: VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.
Buffer content: bytearray(b'')
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - exception while reading: VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.
Buffer content: bytearray(b'')
2023-06-23 16:21:59.200192 VI_ERROR_TMO (-1073807339): Timeout expired before operation completed.
2023-06-23 16:22:19.202684 Calling *IDN?
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T15:22:19.202890Z' logger='pyvisa_py.protocols.hislip' event='hislip.send' bytes_recvd=0 expected_message_id=4294967042 last_message_id=4294967042 message_id=4294967044 msg_type='' payload_remaining=0
2023-06-23 16:22:19,206 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - reading 20480 bytes (last status <StatusCode.success_max_count_read: 1073676294>)
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - reading 20480 bytes (last status <StatusCode.success_max_count_read: 1073676294>)
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T15:22:19.209110Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive' expected_message_id=None last_message_id=4294967044 message_id=4294967046 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T15:22:19.210105Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive: adjust ids' expected_message_id=4294967044 last_message_id=4294967044 message_id=4294967046 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T15:22:19.210105Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive: loop iteration start' bytes_recvd=0 expected_message_id=4294967044 last_message_id=4294967044 message_id=4294967046 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T15:22:19.211061Z' logger='pyvisa_py.protocols.hislip' event='hislip._next_data_header: loop iteration start' bytes_recvd=0 expected_message_id=4294967044 last_message_id=4294967044 message_id=4294967046 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T15:22:19.211061Z' logger='pyvisa_py.protocols.hislip' event='hislip._next_data_header' bytes_recvd=0 expected_message_id=4294967044 header={'header': bytearray(b'HS\x07\x00\xff\xff\xff\x02\x00\x00\x00\x00\x00\x00\x00\x02'), 'control_code': 0, 'message_parameter': 4294967042, 'payload_length': 2, 'msg_type': 'DataEnd', 'message_id': 4294967042} last_message_id=4294967044 message_id=4294967046 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T15:22:19.222666Z' logger='pyvisa_py.protocols.hislip' event='hislip._next_data_header: flush message' bytes_recvd=0 expected_message_id=4294967044 last_message_id=4294967044 message_id=4294967046 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T15:22:19.225750Z' logger='pyvisa_py.protocols.hislip' event='hislip._next_data_header: loop iteration start' bytes_recvd=0 expected_message_id=4294967044 last_message_id=4294967044 message_id=4294967046 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T15:22:19.226676Z' logger='pyvisa_py.protocols.hislip' event='hislip._next_data_header' bytes_recvd=0 expected_message_id=4294967044 header={'header': bytearray(b'HS\x07\x00\xff\xff\xff\x04\x00\x00\x00\x00\x00\x00\x00S'), 'control_code': 0, 'message_parameter': 4294967044, 'payload_length': 83, 'msg_type': 'DataEnd', 'message_id': 4294967044} last_message_id=4294967044 message_id=4294967046 msg_type='' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T15:22:19.230691Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive: data header received' bytes_recvd=0 expected_message_id=4294967044 last_message_id=4294967044 message_id=4294967046 msg_type='DataEnd' payload_remaining=83
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T15:22:19.231673Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive: loop iteration start' bytes_recvd=83 expected_message_id=4294967044 last_message_id=4294967044 message_id=4294967046 msg_type='DataEnd' payload_remaining=0
DEBUG:pyvisa_py.protocols.hislip:level='debug' timestamp='2023-06-23T15:22:19.231673Z' logger='pyvisa_py.protocols.hislip' event='hislip.receive: check for RMT' bytes_recvd=83 expected_message_id=4294967044 last_message_id=4294967044 message_id=4294967046 msg_type='DataEnd' payload_remaining=0
2023-06-23 16:22:19.232770 Result: Keysight Technologies,C8700200A Test Application Framework,US12345678,20.90.0.9010
2023-06-23 16:22:19,233 - pyvisa - DEBUG - Closing ResourceManager (session: 4147854)
DEBUG:pyvisa:Closing ResourceManager (session: 4147854)
2023-06-23 16:22:19,234 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - closing
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - closing
2023-06-23 16:22:19,235 - pyvisa - DEBUG - TCPIP0::127.0.0.1::hislip2::INSTR - is closed
DEBUG:pyvisa:TCPIP0::127.0.0.1::hislip2::INSTR - is closed
2023_06_23__1622_packet_capture.zip
Note that I didn't do any in-depth testing.
By the way, there's really no need to appologise - I appreciate all your help on this. Have a nice weekend 🙂
One question, do you have any idea when the fix might make it into an official release?
I'll open a PR with the current fix, and there is another unreleased feature already but I'm not in charge or release schedule so it's up to Matthieu.