Debug logging spits out each character individually

[dougthor42]

Debug logging prints every character individually, rather than just the sent command string:

INFO:root:Testing with simulated instrument.
DEBUG:pyvisa:Created library wrapper for mysim.yaml
DEBUG:pyvisa:Created ResourceManager with session 9128214
DEBUG:pyvisa:USB0::2391::35608::MY51144553::0::INSTR - opening ...
DEBUG:pyvisa:USB0::2391::35608::MY51144553::0::INSTR - is open with session 4172433
DEBUG:pyvisa:Writing into device input buffer: b':'
DEBUG:pyvisa:Writing into device input buffer: b'M'
DEBUG:pyvisa:Writing into device input buffer: b'E'
DEBUG:pyvisa:Writing into device input buffer: b'A'
DEBUG:pyvisa:Writing into device input buffer: b'S'
DEBUG:pyvisa:Writing into device input buffer: b'U'
DEBUG:pyvisa:Writing into device input buffer: b'R'
DEBUG:pyvisa:Writing into device input buffer: b'E'
DEBUG:pyvisa:Writing into device input buffer: b'?'
DEBUG:pyvisa:Writing into device input buffer: b'\r'
DEBUG:pyvisa:Writing into device input buffer: b'\n'
DEBUG:pyvisa:Found response in queries: b'1.23,2.34,3.45,4.56,5.67,6.78'
DEBUG:pyvisa:USB0::2391::35608::MY51144553::0::INSTR - reading 20480 bytes (last status <StatusCode.success_max_count_read: 1073676294>)
DEBUG:pyvisa:Closing ResourceManager (session: 9128214)
DEBUG:pyvisa:USB0::2391::35608::MY51144553::0::INSTR - closing
DEBUG:pyvisa:USB0::2391::35608::MY51144553::0::INSTR - is closed

Whereas running with a real instrument via the pyvisa-py backend logs nothing:

INFO:root:Testing with real instrument.
DEBUG:pyvisa:SerialSession was correctly imported.
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 py
DEBUG:pyvisa:Created ResourceManager with session 8612875
DEBUG:pyvisa:USB0::2391::35608::MY51144553::0::INSTR - opening ...
DEBUG:pyvisa:USB0::2391::35608::MY51144553::0::INSTR - is open with session 2142339
DEBUG:pyvisa:USB0::2391::35608::MY51144553::0::INSTR - reading 20480 bytes (last status <StatusCode.success_max_count_read: 1073676294>)
DEBUG:pyvisa:Closing ResourceManager (session: 8612875)
DEBUG:pyvisa:USB0::2391::35608::MY51144553::0::INSTR - closing
DEBUG:pyvisa:USB0::2391::35608::MY51144553::0::INSTR - is closed

Steps to Reproduce:

1. Create the mysim.yaml file and example.py files found below.
2. Run example.py
3. See the logs.

Actual Behavior

Each character is written in a separate log message.

Expected (Desired) Behavior

The full string is written in a single log message:

DEBUG:pyvisa:USB0::2391::35608::MY51144553::0::INSTR - is open with session 4172433
DEBUG:pyvisa:Writing into device input buffer: b':MEASURE?\r\n'
DEBUG:pyvisa:Found response in queries: b'1.23,2.34,3.45,4.56,5.67,6.78'

mysim.yaml

# mysim.yaml
---
spec: "1.1"

devices:
  # Keysight B2901A SMU
  SMU:
    eom:
      USB INSTR:
        q: "\r\n"
        r: "\n"
    dialogues:
      - q: "*IDN?"
        r: "Fake SMU"
      - q: ":MEASURE?"
        r: "1.23,2.34,3.45,4.56,5.67,6.78"

resources:
  "USB0::2391::35608::MY51144553::0::INSTR":
    device: "SMU"

example.py

import pyvisa

import logging

logging.basicConfig(level=logging.DEBUG)

addr = "USB0::2391::35608::MY51144553::0::INSTR"

logging.info("Testing with simulated instrument.")
rm = pyvisa.ResourceManager("mysim.yaml@sim")
instr = rm.open_resource(addr, read_termination="\n", write_termination="\r\n")
instr.query(":MEASURE?")
rm.close()

logging.info("")
logging.info("Testing with real instrument.")
rm = pyvisa.ResourceManager("@py")
instr = rm.open_resource(addr, read_termination="\n", write_termination="\r\n")
instr.query(":MEASURE?")
rm.close()

[dougthor42]

Hmm... I thought that this would just be a simple fix in logging, but it looks like it's more of an architectural decision.

The devices.Device.write method requires sending a single byte at a time: https://github.com/pyvisa/pyvisa-sim/blob/b0c22826ad506cc5c5acc155bdca3764dfe14f5e/pyvisa_sim/devices.py#L230-L238

And the session.usb.USBInstrumentSession.write method sends single bytes: https://github.com/pyvisa/pyvisa-sim/blob/b0c22826ad506cc5c5acc155bdca3764dfe14f5e/pyvisa_sim/sessions/usb.py#L63-L67

Same with the other session objects.

Is there a particular reason for this design choice? Would it be reasonable for me to switch things so that Device.write accepts bytes of any length?

[MatthieuDartiailh]

I have honestly no idea why @hgrecco went with this design. I am personally fine with writing larger chunks.

[dougthor42]

Neato burrito :burrito:. I'll try and find some time this week or weekend to make the change. I also notice a lot of code duplication with sessions.foo.FooSession.write, so I'll probably clean that up first.