Ubuntu
python-serial package

RFC2217 connections always fail

Bug #1349525 reported by TJ on 2014-07-28

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	pyserial	Fix Released	Undecided	Unassigned
	python-serial (Ubuntu)	Triaged	Medium	Unassigned

Bug Description

Trying to connect to an RFC2217 access server:

$ python -m serial.tools.miniterm -D rfc2217://10.254.1.143:4001/logging=debug
DEBUG:pySerial.rfc2217:enabled logging
INFO:pySerial.rfc2217:NOTIFY_MODEMSTATE: 30
could not open port 'rfc2217://10.254.1.143:4001/logging=debug': Remote does not seem to support RFC2217 or BINARY mode [we-BINARY:False(INACTIVE), we-RFC2217:True(ACTIVE)]

Examining the code it seems that RFC2217Serial.open() has an incorrect test for connection completion.

        # negotiate Telnet/RFC 2217 -> send initial requests
        for option in self._telnet_options:
            if option.state is REQUESTED:
                self.telnetSendOption(option.send_yes, option.option)
        # now wait until important options are negotiated
        timeout_time = time.time() + self._network_timeout
        while time.time() < timeout_time:
            time.sleep(0.05) # prevent 100% CPU load
            if sum(o.active for o in mandadory_options) == len(mandadory_options):
                break
        else:
            raise SerialException("Remote does not seem to support RFC2217 or BINARY mode %r" % mandadory_options)

The problem is the " == len(mandadory_options)" test. The mandadory_options array has 2 elements, but since only state == REQUESTED will be sent in the prior 'for' loop one of them remains INACTIVE and therefore active == False, but the test compares against a count of the active options which reduces to

if 1 == 2

which will therefore always fall through to the SerialException.

summing on options that are not INACTIVE allows the connection to be established:

if sum(o.active for o in mandadory_options) == sum(o.state != INACTIVE for o in mandadory_options):

$ python -m serial.tools.miniterm -D rfc2217://10.254.1.143:4001/logging=debug
DEBUG:pySerial.rfc2217:enabled logging
INFO:pySerial.rfc2217:NOTIFY_MODEMSTATE: 30
DEBUG:pySerial.rfc2217:ENTER process_incoming( ECHO REQUESTED 0)
DEBUG:pySerial.rfc2217:LEAVE process_incoming( ECHO INACTIVE 0)
DEBUG:pySerial.rfc2217:ENTER process_incoming( we-SGA REQUESTED 0)
DEBUG:pySerial.rfc2217:LEAVE process_incoming( we-SGA INACTIVE 0)
DEBUG:pySerial.rfc2217:ENTER process_incoming( they-SGA REQUESTED 0)
DEBUG:pySerial.rfc2217:LEAVE process_incoming( they-SGA REQUESTED 0)
DEBUG:pySerial.rfc2217:ENTER process_incoming( we-SGA INACTIVE 0)
DEBUG:pySerial.rfc2217:LEAVE process_incoming( we-SGA INACTIVE 0)
DEBUG:pySerial.rfc2217:ENTER process_incoming( they-SGA REQUESTED 0)
DEBUG:pySerial.rfc2217:LEAVE process_incoming( they-SGA INACTIVE 0)
DEBUG:pySerial.rfc2217:ENTER process_incoming( they-RFC2217 REQUESTED 0)
DEBUG:pySerial.rfc2217:LEAVE process_incoming( they-RFC2217 ACTIVE 1)
DEBUG:pySerial.rfc2217:ENTER process_incoming( we-RFC2217 REQUESTED 0)
DEBUG:pySerial.rfc2217:LEAVE process_incoming( we-RFC2217 REQUESTED 0)
DEBUG:pySerial.rfc2217:ENTER process_incoming( they-RFC2217 ACTIVE 1)
DEBUG:pySerial.rfc2217:LEAVE process_incoming( they-RFC2217 ACTIVE 1)
DEBUG:pySerial.rfc2217:ENTER process_incoming( we-RFC2217 REQUESTED 0)
DEBUG:pySerial.rfc2217:LEAVE process_incoming( we-RFC2217 ACTIVE 1)
INFO:pySerial.rfc2217:Negotiated options: [ECHO:False(INACTIVE), we-SGA:False(INACTIVE), they-SGA:False(INACTIVE), they-BINARY:False(INACTIVE), they-RFC2217:True(ACTIVE), we-BINARY:False(INACTIVE), we-RFC2217:True(ACTIVE)]
DEBUG:pySerial.rfc2217:SB Requesting baudrate -> '\x00\x00%\x80'
DEBUG:pySerial.rfc2217:SB Requesting datasize -> '\x08'
DEBUG:pySerial.rfc2217:SB Requesting parity -> '\x01'
DEBUG:pySerial.rfc2217:SB Requesting stopsize -> '\x01'
DEBUG:pySerial.rfc2217:Negotiating settings: [stopsize:REQUESTED, parity:REQUESTED, baudrate:REQUESTED, datasize:REQUESTED]
DEBUG:pySerial.rfc2217:SB Answer baudrate -> '\x00\x00%\x80' -> ACTIVE
DEBUG:pySerial.rfc2217:SB Answer datasize -> '\x08' -> ACTIVE
DEBUG:pySerial.rfc2217:SB Answer parity -> '\x01' -> ACTIVE
DEBUG:pySerial.rfc2217:SB Answer stopsize -> '\x01' -> ACTIVE
INFO:pySerial.rfc2217:Negotiated settings: [stopsize:ACTIVE, parity:ACTIVE, baudrate:ACTIVE, datasize:ACTIVE]
DEBUG:pySerial.rfc2217:SB Requesting control -> '\x01'
DEBUG:pySerial.rfc2217:SB Answer control -> '\x01' -> ACTIVE
INFO:pySerial.rfc2217:NOTIFY_MODEMSTATE: 1
INFO:pySerial.rfc2217:set RTS to active
DEBUG:pySerial.rfc2217:SB Requesting control -> '\x0b'
DEBUG:pySerial.rfc2217:SB Answer control -> '\x0b' -> ACTIVE
INFO:pySerial.rfc2217:set DTR to active
DEBUG:pySerial.rfc2217:SB Requesting control -> '\x08'
DEBUG:pySerial.rfc2217:SB Answer control -> '\x08' -> ACTIVE
DEBUG:pySerial.rfc2217:SB Requesting purge -> '\x01'
DEBUG:pySerial.rfc2217:SB Answer purge -> '\x01' -> ACTIVE
DEBUG:pySerial.rfc2217:SB Requesting purge -> '\x02'
DEBUG:pySerial.rfc2217:SB Answer purge -> '\x02' -> ACTIVE
--- Miniterm on rfc2217://10.254.1.143:4001/logging=debug: 9600,8,N,1 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---