stuck at the async with step

[afourmy]

Hello,

I am trying netdev with the following code:

async def task(param):
    print('before async with')
    async with netdev.create(**param) as ios:
        print('after async with')
        out = await ios.send_config_set([CONFIG])

async def run():
    devices = []
    for ip, driver in DISPATCHER:
        devices.append({
            'username': USERNAME,
            'password': PASSWORD,
            'device_type': driver,
            'host': ip
        })
    tasks = [task(dev) for dev in devices]
    await asyncio.wait(tasks)

loop = asyncio.get_event_loop()
loop.run_until_complete(run())

My issue is that I don't get past the "async with" step, i.e the print('before async with') is displayed, but not the print('after async with'). Netdev is connected to the device (ASK1K, IOS-XE 15.3(3)S3), because I see the VTY after starting the script, but the VTY / the script stays idle.

When I KeyboardInterrupt, it says the task is pending:

afourmy@afourmy-virtual-machine:~/automation$ python3.5 async_netmiko.py
before async with
^CTraceback (most recent call last):
  File "async_netmiko.py", line 34, in <module>
    loop.run_until_complete(run())
  File "/usr/lib/python3.5/asyncio/base_events.py", line 375, in run_until_complete
    self.run_forever()
  File "/usr/lib/python3.5/asyncio/base_events.py", line 345, in run_forever
    self._run_once()
  File "/usr/lib/python3.5/asyncio/base_events.py", line 1276, in _run_once
    event_list = self._selector.select(timeout)
  File "/usr/lib/python3.5/selectors.py", line 441, in select
    fd_event_list = self._epoll.poll(timeout, max_ev)
KeyboardInterrupt
Task was destroyed but it is pending!
task: <Task pending coro=<task() done, defined at async_netmiko.py:13> wait_for=<Future pending cb=[Task._wakeup()]> cb=[_wait.<locals>._on_completion() at /usr/lib/python3.5/asyncio/tasks.py:414]>

Environment: afourmy@afourmy-virtual-machine:~/automation$ uname -a Linux afourmy-virtual-machine 4.10.0-28-generic #32~16.04.2-Ubuntu SMP Thu Jul 20 10:19:48 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

Any idea what's wrong ?

Thanks

[selfuryon]

@afourmy Hello! Thanks for trying to use my library! It's the interesting situation because of your script didn't send any commands to a device so the problem is probably in connection. Can you enable logging and send me the output? You can enable it by this code:

import logging
import netdev

logging.basicConfig(level=logging.INFO)
netdev.logger.setLevel(logging.DEBUG)

And I also will try to reproduce this situation in my lab.

[afourmy]

Hello

Here are the logs:

afourmy@afourmy-virtual-machine:~/automation/netdev$ python3 async_netmiko.py
before async with
INFO:netdev:Host 192.168.243.115: Trying to connect to the device
INFO:netdev:Host 192.168.243.115: Establishing connection to port 22
INFO:asyncssh:Opening SSH connection to 192.168.243.115, port 22
INFO:asyncssh:[conn=0] Connection to 192.168.243.115, port 22 succeeded
INFO:asyncssh:[conn=0]   Local address: 192.168.243.13, port 38830
INFO:asyncssh:[conn=0] Beginning auth for user afourmy
INFO:asyncssh:[conn=0] Auth for user afourmy succeeded
INFO:asyncssh:[conn=0, chan=0] Requesting new SSH session
INFO:asyncssh:[conn=0, chan=0]   Interactive shell requested
INFO:netdev:Host 192.168.243.115: Connection is established
INFO:netdev:Host 192.168.243.115: Reading until pattern
DEBUG:netdev:Host 192.168.243.115: Reading pattern: \>|\#
DEBUG:netdev:Host 192.168.243.115: Reading pattern '\>|\#' was found: '......'
DEBUG:netdev:Host 192.168.243.115: Establish Connection Output: '......'
INFO:netdev:Host 192.168.243.115: Setting base prompt
INFO:netdev:Host 192.168.243.115: Finding prompt
INFO:netdev:Host 192.168.243.115: Reading until pattern
DEBUG:netdev:Host 192.168.243.115: Reading pattern: \>|\#
DEBUG:netdev:Host 192.168.243.115: Reading pattern '\>|\#' was found: 'C\r\n\r\n\r\n\r\nCCCC\r\n\r\n\r\n\r\n\r\n\r\n\r\n\r\n\r\n\r\nC\r\n       ________________________________________________________________\r\n      |                                                                |\r\n      |  Activity on this device is recorded and possibly monitored    |\r\n      |________________________________________________________________|\r\n\r\n\r\nBnet-I3#'
DEBUG:netdev:Host 192.168.243.115: Found Prompt: 'C\r\n\r\n\r\n\r\nCCCC\r\n\r\n\r\n\r\n\r\n\r\n\r\n\r\n\r\n\r\nC\r\n       ________________________________________________________________\r\n      |                                                                |\r\n      |  Activity on this device is recorded and possibly monitored    |\r\n      |________________________________________________________________|\r\n\r\n\r\nBnet-I3#'
DEBUG:netdev:Host 192.168.243.115: Base Prompt: C

CCCC

C
       ________________________________________________________________
      |                                                                |
      |  Activity on this device is recorded and possibly monitored    |
      |________________________________________________________________|

Bnet-I3
\EBUG:netdev:Host 192.168.243.115: Base Pattern: C\
\
\
\
CCC.*?(\(.*?\))?[\>|\#]
INFO:netdev:Host 192.168.243.115: Entering to privilege exec
INFO:netdev:Host 192.168.243.115: Checking privilege exec
INFO:netdev:Host 192.168.243.115: Reading until pattern
\EBUG:netdev:Host 192.168.243.115: Reading pattern: C\
\
\
\
CCC.*?(\(.*?\))?[\>|\#]

then it's stuck, until I KeyboardInterrupt looks like it expects a pattern that never shows up.

^CTraceback (most recent call last):
  File "async_netmiko.py", line 39, in <module>
    loop.run_until_complete(run())
  File "/usr/lib/python3.5/asyncio/base_events.py", line 375, in run_until_complete
    self.run_forever()
  File "/usr/lib/python3.5/asyncio/base_events.py", line 345, in run_forever
    self._run_once()
  File "/usr/lib/python3.5/asyncio/base_events.py", line 1276, in _run_once
    event_list = self._selector.select(timeout)
  File "/usr/lib/python3.5/selectors.py", line 441, in select
    fd_event_list = self._epoll.poll(timeout, max_ev)
KeyboardInterrupt
ERROR:asyncio:Task was destroyed but it is pending!
task: <Task pending coro=<task() done, defined at async_netmiko.py:18> wait_for=<Future pending cb=[Task._wakeup()]> cb=[_wait.<locals>._on_completion() at /usr/lib/python3.5/asyncio/tasks.py:414]>

when the script is stuck, netdev is using a VTY so the connection was successful:

Load for five secs: 1%/0%; one minute: 2%; five minutes: 2%
Time source is NTP, 07:17:13.269 UTC Mon Apr 9 2018

    Line       User       Host(s)              Idle       Location
*  2 vty 0     afourmy    idle                 00:00:00 192.168.243.1
   3 vty 1     afourmy    idle                 00:00:01 192.168.243.13

  Interface    User               Mode         Idle     Peer Address

Note: when logging in, we go directly into enable mode on this device, because of how privileges are configured.

Thanks

[selfuryon]

Oh, now I see that the problem is in the banner. Can you post here banner from your device and also hostname? I will try it in my lab to understand the reason.

[selfuryon]

I think that the problem in '>' symbol in the banner because netdev search '>' and '#' in prompt for understanding the end of prompt but in your case '>' are existed in banner. So netdev decide that prompt is all before '>' not 'Bnet-A4'. You should avoid using '>' and '#' symbols in banner. Can you test without it in the banner?

[afourmy]

Indeed, the problem comes from the > in the banner, thank you ! (note that with the same banner, netmiko works fine so there's probably a way around this)

[selfuryon]

The problem in this case netdev can receive characters from an ssh channel symbol by symbol in the worst case. The library should understand that it received all characters from the channel. We also know that the end for Cisco devices is # or > (delimiters). If you try to read the characters after the end - the script will stick in awaiting new characters but it never gets it because device wait for your commands So right now we have the two ways of getting it:

1. We wait X time for sure that buffer gets all characters in a channel and after that, we read the buffer and parse the output for searching the delimiters and prompt (netmiko way)
2. Reads until we get delimiters in output and after parse the prompt (my way).

My way is faster in several times but it can be unsuccessful if you have delimiter characters in a banner. I will think about adding some logic to it: maybe try to apply regexp in the output for the understanding prompt is that or not. In your case, it will be working solution but if you swap > and < symbols - it won't because the previous part may be correct for regex. So the simplest solution is to avoid these characters in banner. But I will think about it and try to make it works