IPython tab-complete executes __get__ of all properties/facets

[NitramC]

Happend to notice that tab-completion in IPython will get the value of all facets in an instrument instance. This appears to be somewhat expected behavior: ipython/ipython#9094. So far it is harmless, but it does spam the instrument with a lot of requests. I guess you wouldn't normally tab-complete enough for it to be a problem...

Steps to see the problem:
import logging
from instrumental.log import log_to_screen
log_to_screen(level=logging.DEBUG
myinst.<TAB>

[natezb]

Thanks for the report. Would you mind posting some log output that you get? I don't have access to any instruments at the moment.

If I recall correctly, I think we cache the output of dir() on remote objects to try to mitigate this kind of issue, but apparently it's a more complicated problem.

[NitramC]

At the moment I do not have access to any instruments with published drivers, but here is the log output for something I am currently working on (I trimmed it, but it goes through all the facets):

Python 3.8.3 (default, Jul  2 2020, 17:30:36) [MSC v.1916 64 bit (AMD64)]
Type 'copyright', 'credits' or 'license' for more information
IPython 7.16.1 -- An enhanced Interactive Python. Type '?' for help.

In [1]: from instrumental.drivers.lockins import signal_recovery

In [2]: lck = signal_recovery.SR7265()

In [3]: import logging

In [4]: from instrumental.log import log_to_screen

In [5]: log_to_screen(level=logging.DEBUG)
Out[5]: <RootLogger root (DEBUG)>

In [6]: lck.[   DEBUG]2021-01-02 19:46:46,993 parso.python.diff: diff parser start
[   DEBUG]2021-01-02 19:46:46,993 parso.python.diff: line_lengths old: 1; new: 1
[   DEBUG]2021-01-02 19:46:46,993 parso.python.diff: -> code[replace] old[1:1] new[1:1]
[   DEBUG]2021-01-02 19:46:46,993 parso.python.diff: parse_part from 1 to 1 (to 0 in part parser)
[   DEBUG]2021-01-02 19:46:46,993 parso.python.diff: diff parser end
[   DEBUG]2021-01-02 19:46:47,033 parso.cache: pickle loaded: M:\code\dtu\instrumental\instrumental\drivers\lockins\signal_recovery.py
[   DEBUG]2021-01-02 19:46:47,093 parso.cache: pickle loaded: C:\ProgramData\Anaconda3\lib\site-packages\jedi\third_party\typeshed\stdlib\2and3\builtins.pyi
[   DEBUG]2021-01-02 19:46:47,093 parso.cache: pickle loaded: M:\code\dtu\instrumental\instrumental\__init__.py
[   DEBUG]2021-01-02 19:46:47,143 parso.cache: pickle loaded: M:\code\dtu\instrumental\instrumental\drivers\__init__.py
[   DEBUG]2021-01-02 19:46:47,153 parso.cache: pickle loaded: M:\code\dtu\instrumental\instrumental\drivers\lockins\__init__.py
[   DEBUG]2021-01-02 19:46:47,188 instrumental.drivers.facet: Getting value of facet adc1
[   DEBUG]2021-01-02 19:46:47,193 pyvisa: viWrite(2, b'ADC. 1?', 7, 'c_ulong(7)') -> 0
[   DEBUG]2021-01-02 19:46:47,193 pyvisa: GPIB0::2::INSTR - reading 65536 bytes (last status <StatusCode.success_max_count_read: 1073676294>)
[   DEBUG]2021-01-02 19:46:47,203 pyvisa: viRead(2, <ctypes.c_char_Array_65536 object at 0x000001F2045DB740>, 65536, 'c_ulong(12)') -> 0
[   DEBUG]2021-01-02 19:46:47,203 instrumental.drivers.facet: Facet value was -1.171 volt
[   DEBUG]2021-01-02 19:46:47,203 instrumental.drivers.facet: Getting value of facet adc2
[   DEBUG]2021-01-02 19:46:47,203 pyvisa: viWrite(2, b'ADC. 2?', 7, 'c_ulong(7)') -> 0
[   DEBUG]2021-01-02 19:46:47,213 pyvisa: GPIB0::2::INSTR - reading 65536 bytes (last status <StatusCode.success_max_count_read: 1073676294>)
[   DEBUG]2021-01-02 19:46:47,213 pyvisa: viRead(2, <ctypes.c_char_Array_65536 object at 0x000001F2045DB9C0>, 65536, 'c_ulong(9)') -> 0
[   DEBUG]2021-01-02 19:46:47,213 instrumental.drivers.facet: Facet value was 0.001 volt
[   DEBUG]2021-01-02 19:46:47,213 instrumental.drivers.facet: Getting value of facet adc3
[   DEBUG]2021-01-02 19:46:47,213 pyvisa: viWrite(2, b'ADC. 3?', 7, 'c_ulong(7)') -> 0
[   DEBUG]2021-01-02 19:46:47,223 pyvisa: GPIB0::2::INSTR - reading 65536 bytes (last status <StatusCode.success_max_count_read: 1073676294>)
[   DEBUG]2021-01-02 19:46:47,223 pyvisa: viRead(2, <ctypes.c_char_Array_65536 object at 0x000001F2045DB740>, 65536, 'c_ulong(5)') -> 0
[   DEBUG]2021-01-02 19:46:47,223 instrumental.drivers.facet: Facet value was 471
[   DEBUG]2021-01-02 19:46:47,223 instrumental.drivers.facet: Getting value of facet adc3_time
[   DEBUG]2021-01-02 19:46:47,233 pyvisa: viWrite(2, b'ADC3TIME?', 9, 'c_ulong(9)') -> 0
[   DEBUG]2021-01-02 19:46:47,233 pyvisa: GPIB0::2::INSTR - reading 65536 bytes (last status <StatusCode.success_max_count_read: 1073676294>)
[   DEBUG]2021-01-02 19:46:47,233 pyvisa: viRead(2, <ctypes.c_char_Array_65536 object at 0x000001F2045DB9C0>, 65536, 'c_ulong(6)') -> 0
[   DEBUG]2021-01-02 19:46:47,233 instrumental.drivers.facet: Facet value was 1000
[   DEBUG]2021-01-02 19:46:47,243 instrumental.drivers.facet: Getting value of facet adc_burst_tpp
[   DEBUG]2021-01-02 19:46:47,243 pyvisa: viWrite(2, b'BURSTTPP?', 9, 'c_ulong(9)') -> 0
[   DEBUG]2021-01-02 19:46:47,243 pyvisa: GPIB0::2::INSTR - reading 65536 bytes (last status <StatusCode.success_max_count_read: 1073676294>)
[   DEBUG]2021-01-02 19:46:47,243 pyvisa: viRead(2, <ctypes.c_char_Array_65536 object at 0x000001F2045DB740>, 65536, 'c_ulong(4)') -> 0
[   DEBUG]2021-01-02 19:46:47,243 instrumental.drivers.facet: Facet value was 56
In [6]:

[natezb]

Yeah, this is unfortunate behavior, given how facets work. I'm not sure there's much we can do about this on the Instrumental end of things.

Some of those threads claim that the reintroduction of jedi and a jedi bugfix resolved the issue, but the completion engine still runs __get__ on properties for me.

Python: 3.8.5
IPython: 7.17.0
jedi: 0.17.0

[NitramC]

Agreed, hopefully someone up stream makes a fix! Should I close this issue or leave it open?

Funnily enough, I just noticed 'bilderbuchi' (a pymeasure developer) in the thread I linked to above. Looks like the issue is particulary annoying for instrument drivers :)

[natezb]

I'd say leave it open.

From what I can tell, it unfortunately looks like the issue was fixed, but later explicitly reverted (davidhalter/jedi#1063 (comment), davidhalter/jedi#1299).

I understand why __get__ needs to be called to complete on top of a property access, but not why it's necessary to complete the property itself.