telnetlib several times slower than the one from stdlib

[robgom]

Hi all,
with upcoming planned deletion of telnetlib from stdlib (https://peps.python.org/pep-0594/#telnetlib) I wanted to try out using any replacement. telnetlib3 was too complicated to be used, so I wanted to use Exscript.
The interface was very similar to stdlib version, with the exception of replacing byte strings with strings in some places.
So I went ahead and replaced the code.
After the change and adjusting my calls I have discovered that the code works several times slower.
Sample code connecting to Cisco IOS which originally took 4 seconds, now takes roughly 40 seconds to finish.
My code uses only open_connection, write and read_until.
It seems that there's additional unexpected 3 seconds delay at the end of write.

13:29:26.79 .......... self = <Exscript.protocols.telnetlib.Telnet object at 0x0229DA48>
13:29:26.79 .......... buffer = b'terminal length 0\n'
13:29:26.79 .......... len(buffer) = 18
13:29:26.79  313 |     def write(self, buffer):
13:29:26.79  320 |         if type(buffer) == type(0):
13:29:26.80  322 |         elif not isinstance(buffer, bytes):
13:29:26.80  324 |         if IAC in buffer:
13:29:26.80  326 |         self.msg("send %s", repr(buffer))
13:29:26.80  327 |         self.sock.send(buffer)
13:29:26.80 <<< Return value from Telnet.write: None
reply=b'terminal length 0\r\nTB-1B#'
13:29:29.81 >>> Call to Telnet.write in File "C:\Users\r\telnetlib\lib\site-packages\Exscript\protocols\telnetlib.py", line 313
13:29:29.81 .......... self = <Exscript.protocols.telnetlib.Telnet object at 0x0229DA48>
13:29:29.81 .......... buffer = b'ping 10.192.71.122 repeat 1\n'
13:29:29.81 .......... len(buffer) = 28
13:29:29.81  313 |     def write(self, buffer):
13:29:29.81  320 |         if type(buffer) == type(0):
13:29:29.81  322 |         elif not isinstance(buffer, bytes):
13:29:29.81  324 |         if IAC in buffer:
13:29:29.82  326 |         self.msg("send %s", repr(buffer))
13:29:29.82  327 |         self.sock.send(buffer)
13:29:29.82 <<< Return value from Telnet.write: None

Python version: 3.8-32
OS: Windows

Imports:

from Exscript.protocols.telnetlib import Telnet

Reproducible: always

If there's an incentive in debugging and fixing that, I can provide more debugs and stripped down code, right now it's a part of more complex tool.

>python -m pip freeze
asn1crypto==1.5.1
astroid==3.1.0
asttokens==2.4.1
async-timeout==4.0.3
attrs==23.2.0
bcrypt==4.1.2
beautifulsoup4==4.12.3
blinker==1.7.0
certifi==2024.2.2
cffi==1.16.0
charset-normalizer==3.3.2
cheap-repr==0.5.1
click==8.1.7
colorama==0.4.6
configparser==6.0.1
cryptography==42.0.5
dictdiffer==0.9.0
dill==0.3.8
distlib==0.3.8
dnslib==0.9.24
docutils==0.20.1
exceptiongroup==1.2.0
executing==2.0.1
Exscript==2.6.28
filelock==3.13.4
Flask==3.0.3
ftputil==5.1.0
future==1.0.0
idna==3.7
ifaddr==0.2.0
importlib_metadata==7.1.0
isort==5.13.2
itsdangerous==2.1.2
Jinja2==3.1.3
lxml==5.2.1
markdown-it-py==3.0.0
MarkupSafe==2.1.5
marrydoc==0.2.0
mccabe==0.7.0
mdurl==0.1.2
outcome==1.3.0.post0
paramiko==3.4.0
pipdeptree==2.16.1
platformdirs==3.11.0
plum-py==0.8.7
ply==3.11
polling==0.3.2
pyasn1==0.6.0
pycodestyle==2.11.1
pycparser==2.22
pycryptodomex==3.20.0
Pygments==2.17.2
pylint==3.1.0
PyNaCl==1.5.0
pyOpenSSL==24.1.0
pyopenssl-psk==1.0.0
pypiwin32==223
pysmi==0.3.4
pysnmp==4.4.12
pysnmp-mibs==0.1.6
python-dateutil==2.9.0.post0
pywin32==306
pywinauto==0.5.2
pywincffi==0.5.0
requests==2.31.0
rich==13.7.1
ruamel.yaml==0.18.6
ruamel.yaml.clib==0.2.8
scapy==2.5.0
scapy-ssl-tls==2.0.0.post1+ra3
simplejson==3.19.2
six==1.16.0
sniffio==1.3.1
snoop==0.4.3
sortedcontainers==2.4.0
soupsieve==2.5
telnetlib3==2.0.4
tinyec==0.4.0
tomli==2.0.1
tomlkit==0.12.4
trio==0.25.0
typing_extensions==4.11.0
urllib3==2.2.1
virtualenv==20.21.1
Werkzeug==3.0.2
xmltodict==0.13.0
zeroconf==0.132.0
zipp==3.18.1

[robgom]

And some debugs from read_until:

13:44:01.39 .......... timeout = 10
13:44:01.39  330 |     def read_until(self, match, timeout=None):
13:44:01.39  336 |         n = len(match)
13:44:01.39 .............. n = 1
13:44:01.39  337 |         self.process_rawq()
13:44:01.39  338 |         i = self.rawq.find(match)
13:44:01.39 .............. i = -1
13:44:01.39  339 |         if i >= 0:
13:44:01.39  344 |         if timeout is not None:
13:44:01.40  345 |             deadline = _time() + timeout
13:44:01.40 .................. deadline = 1104632.625
13:44:01.40  346 |         with _TelnetSelector() as selector:
13:44:01.41 .............. selector = <selectors.SelectSelector object at 0x04E5FCA0>
13:44:01.41  347 |             selector.register(self, selectors.EVENT_READ)
13:44:01.41  348 |             while not self.eof:
13:44:01.41  349 |                 if selector.select(timeout):
13:44:01.41  350 |                     i = max(0, len(self.rawq)-n)
13:44:01.41 .......................... i = 0
13:44:01.41  351 |                     self.fill_rawq()
13:44:01.41  352 |                     self.process_rawq()
13:44:01.42  353 |                     i = self.rawq.find(match, i)
13:44:01.42 .......................... i = -1
13:44:01.42  354 |                     if i >= 0:
13:44:01.42  359 |                 if timeout is not None:
13:44:01.42  360 |                     timeout = deadline - _time()
13:44:01.42 .......................... timeout = 9.985000000102445
13:44:01.42  361 |                     if timeout < 0:
13:44:01.42  348 |             while not self.eof:
13:44:01.43  349 |                 if selector.select(timeout):
13:44:11.43  359 |                 if timeout is not None:
13:44:11.43  360 |                     timeout = deadline - _time()
13:44:11.44 .......................... timeout = -0.04600000008940697
13:44:11.44  361 |                     if timeout < 0:
13:44:11.45  362 |                         break
13:44:11.45  363 |         return self.read_very_lazy()

[robgom]

From what I can see, read_until has been added in a different way than in stdlib version (rawq vs. cookedq), I suspect that's the culprit.