Telnet Auto Negotiation Failure

[rumpadunk]

On certain devices (Fortinet) I experienced telnet auto negation failures for the telnet session.

Sample from this script:
attempting connection to 127.0.0.1:12123
connected to 127.0.0.1:12123

DO ECHO
DO SUPPRESS GO AHEAD
login: waiting for login prompt: login:
expect: watching for login:
< DO TERMINAL TYPE
WONT TERMINAL TYPE
< DO TSPEED
WONT TSPEED
< DO XDISPLOC
WONT XDISPLOC
< DO NEW-ENVIRON
WONT NEW-ENVIRON
< WILL ECHO
Enabling Remote Echo
< WILL SUPPRESS GO AHEAD
Enabling Suppress Go Ahead (SGA) on Receive
Enabling Suppress Go Ahead (SGA) on Transmit
WILL SUPPRESS GO AHEAD
< DO SUPPRESS GO AHEAD
< DO ECHO
Disabling Remote Echo to prevent Echo loop
DONT ECHO
Enabling Local Network Echo
WILL ECHO
< DO NAWS
WONT NAWS
< WILL STATUS
< DO LFLOW
WONT LFLOW

Sample from PuttyTel which works properly:
2016-03-09 14:02:35 Looking up host "127.0.0.1"
2016-03-09 14:02:35 Connecting to 127.0.0.1 port 12123
2016-03-09 14:02:35 client: WILL NAWS
2016-03-09 14:02:35 client: WILL TSPEED
2016-03-09 14:02:35 client: WILL TTYPE
2016-03-09 14:02:35 client: WILL NEW_ENVIRON
2016-03-09 14:02:35 client: DO ECHO
2016-03-09 14:02:35 client: WILL SGA
2016-03-09 14:02:35 client: DO SGA
2016-03-09 14:02:36 server: DO TTYPE
2016-03-09 14:02:36 server: DO TSPEED
2016-03-09 14:02:36 server: DO XDISPLOC
2016-03-09 14:02:36 client: WONT XDISPLOC
2016-03-09 14:02:36 server: DO NEW_ENVIRON
2016-03-09 14:02:36 server: DO NAWS
2016-03-09 14:02:36 client: SB NAWS 80,24
2016-03-09 14:02:36 server: WILL ECHO
2016-03-09 14:02:36 server: DO SGA
2016-03-09 14:02:36 server: WILL SGA
2016-03-09 14:02:36 server: SB TSPEED SEND
2016-03-09 14:02:36 client: SB TSPEED IS 38400,38400
2016-03-09 14:02:36 server: SB NEW_ENVIRON SEND
2016-03-09 14:02:36 client: SB NEW_ENVIRON IS
2016-03-09 14:02:36 server: SB TTYPE SEND
2016-03-09 14:02:36 client: SB TTYPE IS XTERM
2016-03-09 14:02:36 server: DO ECHO
2016-03-09 14:02:36 client: WONT ECHO
2016-03-09 14:02:36 server: WILL STATUS
2016-03-09 14:02:36 client: DONT STATUS
2016-03-09 14:02:36 server: DO LFLOW
2016-03-09 14:02:36 client: WONT LFLOW

The workaround that @jnorell came up with is as follows:

Edit Net/Telnet.php, line 983
right now has this:

       if ($this->mode['echo_remote']) {
           $this->debug("Disabling Remote Echo to prevent Echo loop");
           $this->mode['echo_remote'] = false;
           $this->send_telcmd(TEL_DONT, $opt);
       }

Change that to:

       if ($this->mode['echo_remote']) {
           $this->debug("Refusing to Echo");
               $this->send_telcmd(TEL_WONT, $opt);
               break;

               $this->debug("Disabling Remote Echo to prevent Echo loop");
      $this->mode['echo_remote'] = false;
      $this->send_telcmd(TEL_DONT, $opt);
   }

Which essentially sends a "TEL_WONT" instead of a "TEL_DONT" on in response to the DO ECHO.

After you change the code above, valid debug output looks as follows and the code worked properly:

attempting connection to 127.0.0.1:12123
connected to 127.0.0.1:12123

DO ECHO
DO SUPPRESS GO AHEAD
login: waiting for login prompt: login:
expect: watching for login:
< DO TERMINAL TYPE
WONT TERMINAL TYPE
< DO TSPEED
WONT TSPEED
< DO XDISPLOC
WONT XDISPLOC
< DO NEW-ENVIRON
WONT NEW-ENVIRON
< WILL ECHO
Enabling Remote Echo
< WILL SUPPRESS GO AHEAD
Enabling Suppress Go Ahead (SGA) on Receive
Enabling Suppress Go Ahead (SGA) on Transmit
WILL SUPPRESS GO AHEAD
< DO SUPPRESS GO AHEAD
< DO ECHO
Refusing to Echo
WONT ECHO
< DO NAWS
WONT NAWS
< WILL STATUS
< DO LFLOW
WONT LFLOW

Opening a bug just to track it should anyone else encounter a similar issue.