classification
Title: telnetlib Telnet.expect fails with timeout=0
Type: behavior Stage: resolved
Components: Library (Lib) Versions: Python 2.7
process
Status: closed Resolution: out of date
Dependencies: Superseder:
Assigned To: Nosy List: Joel.Lovinger, ZackerySpytz, iritkatriel, jackdied, r.david.murray
Priority: normal Keywords:

Created on 2012-04-12 01:20 by Joel.Lovinger, last changed 2020-11-30 10:07 by iritkatriel. This issue is now closed.

Messages (7)
msg158096 - (view) Author: Joel Lovinger (Joel.Lovinger) Date: 2012-04-12 01:20
In Python 2.4.3 a Telnet.expect with timeout=0 would always make at least one call to Telnet.fill_rawq if a match couldn't be found and the connection was open.

In Python 2.7.1/2.7.3 Telnet.expect with timeout=0 breaks before any call to Telnet.fill_rawq if a match isn't found in already read raw/cooked data. Expected behavior is that on timeout=0 at least one non-blocking attempt should be made to read from the connection when necessary to fulfill a match.

From code inspection (including Python 2.7.3) timeout behavior was modified to provide an overall elapsed timeout instead of passing unmodified timeout to each select resulting in the failure.


Python 2.7.1 (r271:86832, Nov 27 2010, 18:30:46) [MSC v.1500 32 bit (Intel)] on
win32
Type "help", "copyright", "credits" or "license" for more information.
>>> from telnetlib import Telnet
>>> import time
>>> tn = Telnet("scn.org", 23)
>>> time.sleep(5) # short wait for data to be available
>>> tn.expect(['.{16}'], 0)
(-1, None, '')
>>>

Python 2.4.3 (#69, Mar 29 2006, 17:35:34) [MSC v.1310 32 bit (Intel)] on win32
Type "help", "copyright", "credits" or "license" for more information.
>>> from telnetlib import Telnet
>>> import time
>>> tn = Telnet("scn.org", 23)
>>> time.sleep(5) # short wait for data to be available
>>> tn.expect(['.{16}'], 0)
(0, <_sre.SRE_Match object at 0x01752410>, '\r\nSeattle Communit')
>>>
msg158098 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2012-04-12 01:33
Can you point to the changes you think are at issue?  That might help us track down why the change was made.  This isn't necessarily a bug, but even if it isn't, the behavior should probably be explicitly documented.
msg158102 - (view) Author: Joel Lovinger (Joel.Lovinger) Date: 2012-04-12 03:37
Quick response!

Based on review of Telnet.expect in Python 2.4.3 and Python 2.7.1/2.7.3.  

In Python 2.4.3 the timeout is passed unmodified on each loop iteration to the underlying select to get more data for a potential match. Iteration only ends on EOF, select timeout with no rx, or match. A timeout=0 received data, without blocking, until no more data or a match was found. 

Unfortunately this implementation can extend the timeout indeterminately if the connection consistently has data for each select but no match is made.

Imagine with timeout=10 and a byte coming in every 5 seconds. Select will always succeed and continue to iterate.

Could even happen with timeout=0 if match processing takes long enough for each iteration (high system load, long input buffer, complicated reg ex, etc).

Python 2.7.1 keeps track of overall elapsed time in Telnet.expect itself and explicitly drops out when it exceeds the timeout. Further passes (timeout-elapsed) as the timeout to select.

Works to ensure an expect never exceeds its timeout, but breaks the case where timeout=0 can read non-blocking to find a match.
msg158126 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2012-04-12 13:04
Ah, so there are actually two timeouts of interest.  One is "time out if there is no more data for X seconds", and the other is "time out if there is no match for X seconds".  It used to do the former, now it does the latter.

I think you get the former by calling socket.settimeout() and then using a blocking call for the expect.
msg158161 - (view) Author: Joel Lovinger (Joel.Lovinger) Date: 2012-04-12 18:55
2.4 behavior, "time out if there is no more data for X seconds", only worked as expected in the case of timeout=0. Any other timeout could result in indefinite extension and needed fixing.

2.7 behavior, "time out if there is no match for X seconds" fixes timeout!=0 cases while breaking for timeout=0.

Can't get former behavior on timeout=0 in 2.7 using socket.settimeout(). Call to socket.recv() then throws a timeout exception which isn't caught by Telnet.expect.

I think fixing timeout=0 will require a patch to Telnet.expect. The simplest would likely be to insert a "very eager" type read to grab all data without blocking before entering the match loop. Won't need to modify existing timeout logic and sidesteps any new corner cases on select/recv iteration.

The only functional side effect (other than moving storage in some cases from the socket to the Telnet object) is on greedy RE that will have more data to match. Documentation already warns against greedy RE as non-deterministic so hopefully not an issue.
msg379563 - (view) Author: Zackery Spytz (ZackerySpytz) * (Python triager) Date: 2020-10-25 04:59
Python 2.7 is no longer supported, so I think this issue should be closed.
msg382135 - (view) Author: Irit Katriel (iritkatriel) * (Python committer) Date: 2020-11-30 10:07
This has been fixed by now:

Running Release|x64 interpreter...
Python 3.10.0a2+ (heads/bpo-42482:920f808f50, Nov 29 2020, 23:02:47) [MSC v.1916 64 bit (AMD64)] on win32
Type "help", "copyright", "credits" or "license" for more information.
>>> from telnetlib import Telnet
>>> import time
>>> tn = Telnet("scn.org", 23)
>>> time.sleep(5) # short wait for data to be available
>>> tn.expect(['.{16}'], 0)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "C:\Users\User\src\cpython\lib\telnetlib.py", line 622, in expect
    m = list[i].search(self.cookedq)
TypeError: cannot use a string pattern on a bytes-like object
>>> tn.expect([b'.{16}'], 0)
(0, <re.Match object; span=(2, 18), match=b'Seattle Communit'>, b'\r\nSeattle Communit')
>>>
History
Date User Action Args
2020-11-30 10:07:00iritkatrielsetstatus: open -> closed

nosy: + iritkatriel
messages: + msg382135

resolution: out of date
stage: resolved
2020-10-25 04:59:38ZackerySpytzsetnosy: + ZackerySpytz
messages: + msg379563
2012-04-12 18:55:29Joel.Lovingersetmessages: + msg158161
2012-04-12 13:04:13r.david.murraysetmessages: + msg158126
2012-04-12 03:37:05Joel.Lovingersetmessages: + msg158102
2012-04-12 01:33:26r.david.murraysetnosy: + jackdied, r.david.murray
messages: + msg158098
2012-04-12 01:20:16Joel.Lovingercreate