BaseConnection.find_prompt() logic appears to be incorrect

[anmcn]

Description of Issue/Question

BaseConnection.find_prompt() gets out of sync if pattern is not specified and the initial response takes more than 25ms.

With fast_cli=True being the default, select_delay_factor() returns 0.1, setting the initial sleep_time to 0.025 (25ms).

RETURN is sent, then we sleep for sleep_time (25ms) and read the connection. If no response is received in that time, we send another RETURN and sleep another 25ms, then we read the channel again and this time we see the prompt response from the first RETURN (but not the second). The while loop exits and the function returns, but some time later, the response to the second RETURN is received. When we now call send_command(), we immediately find the previously received buffered prompt and think that the send_command() returned nothing.

Setup

Needs a device that takes more than 25ms to respond to a prompt.

Netmiko version

netmiko==4.3.0

Netmiko device_type (if relevant to the issue)

Not relevant, but nokia_sros

Steps to Reproduce the Issue

See python code below. Run the dummy router with the time.sleep() uncommented, connect with netmiko.

Error Traceback

No traceback.

Relevant Python code

Dummy router, uncomment the time.sleep(0.26) to demonstrate the problem.

import os
import time
import socket

s = socket.socket()
s.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
s.bind(('0.0.0.0', 54321))
s.listen(1)

while True:
    c, _ = s.accept()
    if not os.fork():
        pid = os.getpid()
        print(f'{pid} accept')
        c.send(b'Hello\r\nlogin:')
        c.recv(8192)
        c.send(b'Password:')
        c.recv(8192)
        while True:
            c.send(b'Prompt> ')
            cmd = c.recv(8192)
            print(f'{pid} recv: {cmd!r}')
            if not cmd:
                break
            cmd = cmd.strip()
            # XXX - Uncomment this to demonstrate problem
            # time.sleep(0.26)
            if cmd:
                c.send(cmd+b'\r\nCommand goes bing!\r\n')
        c.close()
        os._exit(0)

>>> import netmiko, logging
>>> logging.basicConfig(level=logging.DEBUG)
>>> c=netmiko.ConnectHandler(device_type='nokia_sros_telnet', ip='127.0.0.1', port=54321, username='x', password='x', session_log='netmiko.log')
>>> c.send_command('foo')
DEBUG:netmiko:read_channel: foo
Command goes bing!
Prompt> 
DEBUG:netmiko:Clear buffer detects data in the channel
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:write_channel: b'\r\n'
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:write_channel: b'\r\n'
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:write_channel: b'\r\n'
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:write_channel: b'\r\n'
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:write_channel: b'\r\n'
DEBUG:netmiko:read_channel: Prompt> 
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:[find_prompt()]: prompt is Prompt>
DEBUG:netmiko:write_channel: b'foo\r\n'
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: 
DEBUG:netmiko:read_channel: Prompt> 
''

[ktbyers]

Probably need to set fast_cli=False if the device is slower (i.e doesn't respond in the 25mS).

[anmcn]

Certainly that will help, but I think the logic is still incorrect.

[ktbyers]

What you reference here:

The while loop exits and the function returns, but some time later, the response to the 
second RETURN is received. When we now call send_command(), we immediately find the 
previously received buffered prompt and think that the send_command() returned nothing.

Generally doesn't happen as Netmiko's cmd_verify mechanism will read the data until the command is properly echoed. So it would read all of the enters/prompts before the command echo (up to and including the command echo). send_command would then only read the proper output as it would match on the next prompt.

Nokia SROS is a special case (as there are other things about this SROS platform that cause it to break cmd_verify).

https://github.com/ktbyers/netmiko/blob/develop/netmiko/nokia/nokia_sros.py#L57

There are other workarounds with Nokia SROS i.e. you could call send_command with an expect_string (or you could adjust fast_cli/global_delay_factor).

Anyways the logic you reference above is working the way it is supposed to (when coupled with cmd_verify).

This is part of the big difficulty inherent in screen-scraping (i.e. we don't really know when commands are done so we try to put the best mechanisms we can to reliably ensure things are done while also executing reasonably fast).