search

ronf / asyncssh

AsyncSSH is a Python package which provides an asynchronous client and server implementation of the SSHv2 protocol on top of the Python asyncio framework.
Eclipse Public License 2.0
1.55k stars 151 forks source link

5 seconds delay #249

Closed horseinthesky closed 4 years ago

horseinthesky commented 4 years ago

Hello. I'm trying out the library against Huawei CE switches. It seems to work just great but there is a weird 5 seconds timeout between asyncssh starts handling the device RPC reply.

Here is manual interaction with the device:

<hello xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
    <capabilities>
        <capability>urn:ietf:params:netconf:base:1.0</capability>
    </capabilities>
</hello>
]]>]]>
<rpc message-id="1" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <edit-config>
    <target>
      <running/>
    </target>
      <config xmlns:xc="urn:ietf:params:xml:ns:netconf:base:1.0">
  <ethernet xmlns="http://www.huawei.com/netconf/vrp/huawei-ethernet">
    <ethernetIfs>
       <ethernetIf>
         <ifName>25GE1/0/10</ifName>
         <l2Enable>enable</l2Enable>
         <l2Attribute>
           <linkType>access</linkType>
           <pvid>126</pvid>
           <taggedPacketDiscard>false</taggedPacketDiscard>
           <portBridgEnable>false</portBridgEnable>
         </l2Attribute>
       </ethernetIf>
    </ethernetIfs>
  </ethernet>
</config>
  </edit-config>
</rpc>
]]>]]>
<?xml version="1.0" encoding="UTF-8"?>
<rpc-reply message-id="1" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <ok/>
</rpc-reply>
]]>]]>
<rpc message-id="1024" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <get>
    <filter type="subtree">
      <devm xmlns="http://www.huawei.com/netconf/vrp/huawei-devm">
        <cpuInfos>
          <cpuInfo>
            <systemCpuUsage></systemCpuUsage>
          </cpuInfo>
        </cpuInfos>
      </devm>
    </filter>
  </get>
</rpc>
]]>]]>
<?xml version="1.0" encoding="UTF-8"?>
<rpc-reply message-id="1024" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <data>
    <devm xmlns="http://www.huawei.com/netconf/vrp/huawei-devm">
      <cpuInfos>
        <cpuInfo>
          <position>1</position>
          <systemCpuUsage>10</systemCpuUsage>
        </cpuInfo>
      </cpuInfos>
    </devm>
  </data>
</rpc-reply>]]>]]>

there is no timestamps but it always replies almost instantly (milliseconds).

How here is my script which send 2 RPCs:

import asyncssh
import asyncio
import xmltodict
import json
import logging
logging.basicConfig(level=logging.DEBUG, format="%(asctime)s - %(filename)s:%(lineno)d - %(funcName)s() - %(levelname)s - %(message)s")

hello = '''
<hello xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
    <capabilities>
        <capability>urn:ietf:params:netconf:base:1.0</capability>
    </capabilities>
</hello>
]]>]]>
'''
get = '''
<rpc message-id="1024" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <get>
    <filter type="subtree">
      {}
    </filter>
  </get>
</rpc>
]]>]]>
'''
edit = '''
<rpc message-id="1" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <edit-config>
    <target>
      <running/>
    </target>
    <config xmlns:xc="urn:ietf:params:xml:ns:netconf:base:1.0">
      {}
    </config>
  </edit-config>
</rpc>
]]>]]>
'''
cpu_rpc = '''<devm xmlns="http://www.huawei.com/netconf/vrp/huawei-devm">
        <cpuInfos>
          <cpuInfo>
            <systemCpuUsage></systemCpuUsage>
          </cpuInfo>
        </cpuInfos>
      </devm>'''
intf_rpc = '''<ethernet xmlns="http://www.huawei.com/netconf/vrp/huawei-ethernet">
        <ethernetIfs>
           <ethernetIf>
             <ifName>25GE1/0/11</ifName>
             <l2Enable>enable</l2Enable>
             <l2Attribute>
               <linkType>trunk</linkType>
               <pvid>106</pvid>
               <trunkVlans>4,5,6,104,106</trunkVlans>
               <taggedPacketDiscard>false</taggedPacketDiscard>
               <portBridgEnable>false</portBridgEnable>
             </l2Attribute>
           </ethernetIf>
        </ethernetIfs>
      </ethernet>'''

class NetconfConnection:
    def __init__(self, ip):
        self.ip = ip

    async def __aenter__(self):
        await self.connect()
        return self

    async def __aexit__(self, *exception):
        self.conn.close()

    async def connect(self):
        self.conn, _ = await asyncssh.create_connection(None, self.ip, known_hosts=None)
        self.writer, self.reader, _ = await self.conn.open_session(subsystem='netconf')
        self.caps = await self.read()
        self.write(hello)

    async def read(self):
        data = await self.reader.readuntil(']]>]]>')
        logging.debug("read %s", data)
        return data[:-6]

    def write(self, data):
        self.writer.write(data)
        logging.debug("write %s", data)

    async def get(self, data):
        self.write(get.format(data))
        data = await self.read()
        return data

    async def edit(self, data):
        self.write(edit.format(data))
        await self.read()
        # self.write(commit)
        # data = await self.read()
        return data

async def get_data(device):
    async with NetconfConnection(device) as nc:
        intf_rpc_reply = await nc.edit(intf_rpc)
        data = xmltodict.parse(intf_rpc_reply)
        print(json.dumps(data, indent=2))
        cpu_rpc_reply = await nc.get(cpu_rpc)
        data = xmltodict.parse(cpu_rpc_reply)
        print(json.dumps(data, indent=2))

loop = asyncio.get_event_loop()
loop.run_until_complete(get_data('<device_hostname>'))

And here is the log:

2020-01-29 13:32:56,226 - test3.py:87 - write() - DEBUG - write 
<hello xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
    <capabilities>
        <capability>urn:ietf:params:netconf:base:1.0</capability>
    </capabilities>
</hello>
]]>]]>

2020-01-29 13:32:56,226 - test3.py:87 - write() - DEBUG - write 
<rpc message-id="1" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <edit-config>
    <target>
      <running/>
    </target>
    <config xmlns:xc="urn:ietf:params:xml:ns:netconf:base:1.0">
      <ethernet xmlns="http://www.huawei.com/netconf/vrp/huawei-ethernet">
        <ethernetIfs>
           <ethernetIf>
             <ifName>25GE1/0/11</ifName>
             <l2Enable>enable</l2Enable>
             <l2Attribute>
               <linkType>trunk</linkType>
               <pvid>106</pvid>
               <trunkVlans>4,5,6,104,106</trunkVlans>
               <taggedPacketDiscard>false</taggedPacketDiscard>
               <portBridgEnable>false</portBridgEnable>
             </l2Attribute>
           </ethernetIf>
        </ethernetIfs>
      </ethernet>
    </config>
  </edit-config>
</rpc>
]]>]]>

2020-01-29 13:33:01,267 - test3.py:82 - read() - DEBUG - read <?xml version="1.0" encoding="UTF-8"?>
<rpc-reply message-id="1" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <ok/>
</rpc-reply>
]]>]]>
{
  "ethernet": {
    "@xmlns": "http://www.huawei.com/netconf/vrp/huawei-ethernet",
    "ethernetIfs": {
      "ethernetIf": {
        "ifName": "25GE1/0/11",
        "l2Enable": "enable",
        "l2Attribute": {
          "linkType": "trunk",
          "pvid": "106",
          "trunkVlans": "4,5,6,104,106",
          "taggedPacketDiscard": "false",
          "portBridgEnable": "false"
        }
      }
    }
  }
}
2020-01-29 13:33:01,269 - test3.py:87 - write() - DEBUG - write 
<rpc message-id="1024" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <get>
    <filter type="subtree">
      <devm xmlns="http://www.huawei.com/netconf/vrp/huawei-devm">
        <cpuInfos>
          <cpuInfo>
            <systemCpuUsage></systemCpuUsage>
          </cpuInfo>
        </cpuInfos>
      </devm>
    </filter>
  </get>
</rpc>
]]>]]>

2020-01-29 13:33:01,289 - test3.py:82 - read() - DEBUG - read <?xml version="1.0" encoding="UTF-8"?>
<rpc-reply message-id="1024" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <data>
    <devm xmlns="http://www.huawei.com/netconf/vrp/huawei-devm">
      <cpuInfos>
        <cpuInfo>
          <position>1</position>
          <systemCpuUsage>15</systemCpuUsage>
        </cpuInfo>
      </cpuInfos>
    </devm>
  </data>
</rpc-reply>]]>]]>
{
  "rpc-reply": {
    "@message-id": "1024",
    "@xmlns": "urn:ietf:params:xml:ns:netconf:base:1.0",
    "data": {
      "devm": {
        "@xmlns": "http://www.huawei.com/netconf/vrp/huawei-devm",
        "cpuInfos": {
          "cpuInfo": {
            "position": "1",
            "systemCpuUsage": "15"
          }
        }
      }
    }
  }
}
2020-01-29 13:33:01,290 - logging.py:71 - log() - INFO - [conn=0] Closing connection
2020-01-29 13:33:01,291 - logging.py:71 - log() - INFO - [conn=0, chan=0] Closing channel
2020-01-29 13:33:01,293 - logging.py:71 - log() - INFO - [conn=0] Sending disconnect: Disconnected by application (11)
2020-01-29 13:33:01,294 - logging.py:71 - log() - INFO - [conn=0] Connection closed
2020-01-29 13:33:01,294 - logging.py:71 - log() - INFO - [conn=0, chan=0] Closing channel due to connection close
2020-01-29 13:33:01,295 - logging.py:71 - log() - INFO - [conn=0, chan=0] Channel closed

There is always scrict 5 seconds delay between write and read for the first RPC. Where it comes from and how to avoid it?

ronf commented 4 years ago

Nothing obvious is jumping out at me here, but you might try turning on asyncssh debugging so you can see when the actual packets are being sent at the SSH level. A debug level of 2 should give you enough to see when data packets are sent/received and how long they are. If you want to see the actual dump of the data being transferred, you can increase it to level 3 (but be careful if you are sending any passwords over the channel, as they will show up in the debug output).

See https://asyncssh.readthedocs.io/en/latest/api.html#set-debug-level for more info on setting the asyncssh debug level. Normally, you'd also need to add code to initialize logging and set its level to DEBUG, but I see you're already doing that here.

horseinthesky commented 4 years ago

This just got a little bit weirder =)

Level 2 has this 5 sec delay:

2020-01-30 13:11:39,651 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Sending 178 data bytes
2020-01-30 13:11:39,652 - test.py:91 - write() - DEBUG - write 
<hello xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
    <capabilities>
        <capability>urn:ietf:params:netconf:base:1.0</capability>
    </capabilities>
</hello>
]]>]]>

2020-01-30 13:11:39,652 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Sending 808 data bytes
2020-01-30 13:11:39,652 - test.py:91 - write() - DEBUG - write 
<rpc message-id="1" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <edit-config>
    <target>
      <running/>
    </target>
    <config xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
      <ethernet xmlns="http://www.huawei.com/netconf/vrp/huawei-ethernet">
        <ethernetIfs>
           <ethernetIf>
             <ifName>25GE1/0/11</ifName>
             <l2Enable>enable</l2Enable>
             <l2Attribute>
               <linkType>trunk</linkType>
               <pvid>106</pvid>
               <trunkVlans>4,5,6,104,106</trunkVlans>
               <taggedPacketDiscard>false</taggedPacketDiscard>
               <portBridgEnable>false</portBridgEnable>
             </l2Attribute>
           </ethernetIf>
        </ethernetIfs>
      </ethernet>
    </config>
  </edit-config>
</rpc>
]]>]]>

2020-01-30 13:11:44,701 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Received 141 data bytes
2020-01-30 13:11:44,701 - test.py:86 - read() - DEBUG - read <?xml version="1.0" encoding="UTF-8"?>
<rpc-reply message-id="1" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <ok/>
</rpc-reply>
]]>]]>
{
  "@message-id": "1",
  "@xmlns": "urn:ietf:params:xml:ns:netconf:base:1.0",
  "ok": null
}
2020-01-30 13:11:44,702 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Sending 353 data bytes
2020-01-30 13:11:44,703 - test.py:91 - write() - DEBUG - write 
<rpc message-id="1024" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <get>
    <filter type="subtree">
      <devm xmlns="http://www.huawei.com/netconf/vrp/huawei-devm">
        <cpuInfos>
          <cpuInfo>
            <systemCpuUsage></systemCpuUsage>
          </cpuInfo>
        </cpuInfos>
      </devm>
    </filter>
  </get>
</rpc>
]]>]]>

2020-01-30 13:11:44,732 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Received 382 data bytes
2020-01-30 13:11:44,733 - test.py:86 - read() - DEBUG - read <?xml version="1.0" encoding="UTF-8"?>
<rpc-reply message-id="1024" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <data>
    <devm xmlns="http://www.huawei.com/netconf/vrp/huawei-devm">
      <cpuInfos>
        <cpuInfo>
          <position>1</position>
          <systemCpuUsage>15</systemCpuUsage>
        </cpuInfo>
      </cpuInfos>
    </devm>
  </data>
</rpc-reply>]]>]]>
{
  "@message-id": "1024",
  "@xmlns": "urn:ietf:params:xml:ns:netconf:base:1.0",
  "data": {
    "devm": {
      "@xmlns": "http://www.huawei.com/netconf/vrp/huawei-devm",
      "cpuInfos": {
        "cpuInfo": {
          "position": "1",
          "systemCpuUsage": "15"
        }
      }
    }
  }
}
2020-01-30 13:11:44,734 - logging.py:71 - log() - INFO - [conn=0] Closing connection
2020-01-30 13:11:44,734 - logging.py:71 - log() - INFO - [conn=0, chan=0] Closing channel
2020-01-30 13:11:44,735 - logging.py:71 - log() - INFO - [conn=0] Sending disconnect: Disconnected by application (11)
2020-01-30 13:11:44,736 - logging.py:71 - log() - INFO - [conn=0] Connection closed
2020-01-30 13:11:44,736 - logging.py:71 - log() - INFO - [conn=0, chan=0] Closing channel due to connection close
2020-01-30 13:11:44,737 - logging.py:71 - log() - INFO - [conn=0, chan=0] Channel closed
python3 test.py  0.42s user 0.39s system 8% cpu 9.940 total

and level 3 does not:

2020-01-30 13:12:23,213 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Sending 178 data bytes
2020-01-30 13:12:23,214 - logging.py:71 - log() - DEBUG - [conn=0, pktid=15] Sent MSG_IGNORE (2), 5 bytes
  00000000: 02 00 00 00 00                                   .....
2020-01-30 13:12:23,215 - logging.py:71 - log() - DEBUG - [conn=0, chan=0, pktid=16] Sent MSG_CHANNEL_DATA (94), 187 bytes
  00000000: 5e 00 00 00 01 00 00 00 b2 0a 3c 68 65 6c 6c 6f  ^.........<hello
  00000010: 20 78 6d 6c 6e 73 3d 22 75 72 6e 3a 69 65 74 66   xmlns="urn:ietf
  00000020: 3a 70 61 72 61 6d 73 3a 78 6d 6c 3a 6e 73 3a 6e  :params:xml:ns:n
  00000030: 65 74 63 6f 6e 66 3a 62 61 73 65 3a 31 2e 30 22  etconf:base:1.0"
  00000040: 3e 0a 20 20 20 20 3c 63 61 70 61 62 69 6c 69 74  >.    <capabilit
  00000050: 69 65 73 3e 0a 20 20 20 20 20 20 20 20 3c 63 61  ies>.        <ca
  00000060: 70 61 62 69 6c 69 74 79 3e 75 72 6e 3a 69 65 74  pability>urn:iet
  00000070: 66 3a 70 61 72 61 6d 73 3a 6e 65 74 63 6f 6e 66  f:params:netconf
  00000080: 3a 62 61 73 65 3a 31 2e 30 3c 2f 63 61 70 61 62  :base:1.0</capab
  00000090: 69 6c 69 74 79 3e 0a 20 20 20 20 3c 2f 63 61 70  ility>.    </cap
  000000a0: 61 62 69 6c 69 74 69 65 73 3e 0a 3c 2f 68 65 6c  abilities>.</hel
  000000b0: 6c 6f 3e 0a 5d 5d 3e 5d 5d 3e 0a                 lo>.]]>]]>.
2020-01-30 13:12:23,226 - test.py:91 - write() - DEBUG - write 
<hello xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
    <capabilities>
        <capability>urn:ietf:params:netconf:base:1.0</capability>
    </capabilities>
</hello>
]]>]]>

2020-01-30 13:12:23,226 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Sending 808 data bytes
2020-01-30 13:12:23,227 - logging.py:71 - log() - DEBUG - [conn=0, pktid=17] Sent MSG_IGNORE (2), 5 bytes
  00000000: 02 00 00 00 00                                   .....
2020-01-30 13:12:23,229 - logging.py:71 - log() - DEBUG - [conn=0, chan=0, pktid=18] Sent MSG_CHANNEL_DATA (94), 817 bytes
  00000000: 5e 00 00 00 01 00 00 03 28 0a 3c 72 70 63 20 6d  ^.......(.<rpc m
  00000010: 65 73 73 61 67 65 2d 69 64 3d 22 31 22 20 78 6d  essage-id="1" xm
  00000020: 6c 6e 73 3d 22 75 72 6e 3a 69 65 74 66 3a 70 61  lns="urn:ietf:pa
  00000030: 72 61 6d 73 3a 78 6d 6c 3a 6e 73 3a 6e 65 74 63  rams:xml:ns:netc
  00000040: 6f 6e 66 3a 62 61 73 65 3a 31 2e 30 22 3e 0a 20  onf:base:1.0">. 
  00000050: 20 3c 65 64 69 74 2d 63 6f 6e 66 69 67 3e 0a 20   <edit-config>. 
  00000060: 20 20 20 3c 74 61 72 67 65 74 3e 0a 20 20 20 20     <target>.    
  00000070: 20 20 3c 72 75 6e 6e 69 6e 67 2f 3e 0a 20 20 20    <running/>.   
  00000080: 20 3c 2f 74 61 72 67 65 74 3e 0a 20 20 20 20 3c   </target>.    <
  00000090: 63 6f 6e 66 69 67 20 78 6d 6c 6e 73 3d 22 75 72  config xmlns="ur
  000000a0: 6e 3a 69 65 74 66 3a 70 61 72 61 6d 73 3a 78 6d  n:ietf:params:xm
  000000b0: 6c 3a 6e 73 3a 6e 65 74 63 6f 6e 66 3a 62 61 73  l:ns:netconf:bas
  000000c0: 65 3a 31 2e 30 22 3e 0a 20 20 20 20 20 20 3c 65  e:1.0">.      <e
  000000d0: 74 68 65 72 6e 65 74 20 78 6d 6c 6e 73 3d 22 68  thernet xmlns="h
  000000e0: 74 74 70 3a 2f 2f 77 77 77 2e 68 75 61 77 65 69  ttp://www.huawei
  000000f0: 2e 63 6f 6d 2f 6e 65 74 63 6f 6e 66 2f 76 72 70  .com/netconf/vrp
  00000100: 2f 68 75 61 77 65 69 2d 65 74 68 65 72 6e 65 74  /huawei-ethernet
  00000110: 22 3e 0a 20 20 20 20 20 20 20 20 3c 65 74 68 65  ">.        <ethe
  00000120: 72 6e 65 74 49 66 73 3e 0a 20 20 20 20 20 20 20  rnetIfs>.       
  00000130: 20 20 20 20 3c 65 74 68 65 72 6e 65 74 49 66 3e      <ethernetIf>
  00000140: 0a 20 20 20 20 20 20 20 20 20 20 20 20 20 3c 69  .             <i
  00000150: 66 4e 61 6d 65 3e 32 35 47 45 31 2f 30 2f 31 31  fName>25GE1/0/11
  00000160: 3c 2f 69 66 4e 61 6d 65 3e 0a 20 20 20 20 20 20  </ifName>.      
  00000170: 20 20 20 20 20 20 20 3c 6c 32 45 6e 61 62 6c 65         <l2Enable
  00000180: 3e 65 6e 61 62 6c 65 3c 2f 6c 32 45 6e 61 62 6c  >enable</l2Enabl
  00000190: 65 3e 0a 20 20 20 20 20 20 20 20 20 20 20 20 20  e>.             
  000001a0: 3c 6c 32 41 74 74 72 69 62 75 74 65 3e 0a 20 20  <l2Attribute>.  
  000001b0: 20 20 20 20 20 20 20 20 20 20 20 20 20 3c 6c 69               <li
  000001c0: 6e 6b 54 79 70 65 3e 74 72 75 6e 6b 3c 2f 6c 69  nkType>trunk</li
  000001d0: 6e 6b 54 79 70 65 3e 0a 20 20 20 20 20 20 20 20  nkType>.        
  000001e0: 20 20 20 20 20 20 20 3c 70 76 69 64 3e 31 30 36         <pvid>106
  000001f0: 3c 2f 70 76 69 64 3e 0a 20 20 20 20 20 20 20 20  </pvid>.        
  00000200: 20 20 20 20 20 20 20 3c 74 72 75 6e 6b 56 6c 61         <trunkVla
  00000210: 6e 73 3e 34 2c 35 2c 36 2c 31 30 34 2c 31 30 36  ns>4,5,6,104,106
  00000220: 3c 2f 74 72 75 6e 6b 56 6c 61 6e 73 3e 0a 20 20  </trunkVlans>.  
  00000230: 20 20 20 20 20 20 20 20 20 20 20 20 20 3c 74 61               <ta
  00000240: 67 67 65 64 50 61 63 6b 65 74 44 69 73 63 61 72  ggedPacketDiscar
  00000250: 64 3e 66 61 6c 73 65 3c 2f 74 61 67 67 65 64 50  d>false</taggedP
  00000260: 61 63 6b 65 74 44 69 73 63 61 72 64 3e 0a 20 20  acketDiscard>.  
  00000270: 20 20 20 20 20 20 20 20 20 20 20 20 20 3c 70 6f               <po
  00000280: 72 74 42 72 69 64 67 45 6e 61 62 6c 65 3e 66 61  rtBridgEnable>fa
  00000290: 6c 73 65 3c 2f 70 6f 72 74 42 72 69 64 67 45 6e  lse</portBridgEn
  000002a0: 61 62 6c 65 3e 0a 20 20 20 20 20 20 20 20 20 20  able>.          
  000002b0: 20 20 20 3c 2f 6c 32 41 74 74 72 69 62 75 74 65     </l2Attribute
  000002c0: 3e 0a 20 20 20 20 20 20 20 20 20 20 20 3c 2f 65  >.           </e
  000002d0: 74 68 65 72 6e 65 74 49 66 3e 0a 20 20 20 20 20  thernetIf>.     
  000002e0: 20 20 20 3c 2f 65 74 68 65 72 6e 65 74 49 66 73     </ethernetIfs
  000002f0: 3e 0a 20 20 20 20 20 20 3c 2f 65 74 68 65 72 6e  >.      </ethern
  00000300: 65 74 3e 0a 20 20 20 20 3c 2f 63 6f 6e 66 69 67  et>.    </config
  00000310: 3e 0a 20 20 3c 2f 65 64 69 74 2d 63 6f 6e 66 69  >.  </edit-confi
  00000320: 67 3e 0a 3c 2f 72 70 63 3e 0a 5d 5d 3e 5d 5d 3e  g>.</rpc>.]]>]]>
  00000330: 0a                                               .
2020-01-30 13:12:23,235 - test.py:91 - write() - DEBUG - write 
<rpc message-id="1" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <edit-config>
    <target>
      <running/>
    </target>
    <config xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
      <ethernet xmlns="http://www.huawei.com/netconf/vrp/huawei-ethernet">
        <ethernetIfs>
           <ethernetIf>
             <ifName>25GE1/0/11</ifName>
             <l2Enable>enable</l2Enable>
             <l2Attribute>
               <linkType>trunk</linkType>
               <pvid>106</pvid>
               <trunkVlans>4,5,6,104,106</trunkVlans>
               <taggedPacketDiscard>false</taggedPacketDiscard>
               <portBridgEnable>false</portBridgEnable>
             </l2Attribute>
           </ethernetIf>
        </ethernetIfs>
      </ethernet>
    </config>
  </edit-config>
</rpc>
]]>]]>

2020-01-30 13:12:23,273 - logging.py:71 - log() - DEBUG - [conn=0, chan=0, pktid=12] Received MSG_CHANNEL_DATA (94), 150 bytes
  00000000: 5e 00 00 00 00 00 00 00 8d 3c 3f 78 6d 6c 20 76  ^........<?xml v
  00000010: 65 72 73 69 6f 6e 3d 22 31 2e 30 22 20 65 6e 63  ersion="1.0" enc
  00000020: 6f 64 69 6e 67 3d 22 55 54 46 2d 38 22 3f 3e 0a  oding="UTF-8"?>.
  00000030: 3c 72 70 63 2d 72 65 70 6c 79 20 6d 65 73 73 61  <rpc-reply messa
  00000040: 67 65 2d 69 64 3d 22 31 22 20 78 6d 6c 6e 73 3d  ge-id="1" xmlns=
  00000050: 22 75 72 6e 3a 69 65 74 66 3a 70 61 72 61 6d 73  "urn:ietf:params
  00000060: 3a 78 6d 6c 3a 6e 73 3a 6e 65 74 63 6f 6e 66 3a  :xml:ns:netconf:
  00000070: 62 61 73 65 3a 31 2e 30 22 3e 0a 20 20 3c 6f 6b  base:1.0">.  <ok
  00000080: 2f 3e 0a 3c 2f 72 70 63 2d 72 65 70 6c 79 3e 0a  />.</rpc-reply>.
  00000090: 5d 5d 3e 5d 5d 3e                                ]]>]]>
2020-01-30 13:12:23,273 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Received 141 data bytes
2020-01-30 13:12:23,273 - test.py:86 - read() - DEBUG - read <?xml version="1.0" encoding="UTF-8"?>
<rpc-reply message-id="1" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <ok/>
</rpc-reply>
]]>]]>
{
  "@message-id": "1",
  "@xmlns": "urn:ietf:params:xml:ns:netconf:base:1.0",
  "ok": null
}
2020-01-30 13:12:23,276 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Sending 353 data bytes
2020-01-30 13:12:23,276 - logging.py:71 - log() - DEBUG - [conn=0, pktid=19] Sent MSG_IGNORE (2), 5 bytes
  00000000: 02 00 00 00 00                                   .....
2020-01-30 13:12:23,279 - logging.py:71 - log() - DEBUG - [conn=0, chan=0, pktid=20] Sent MSG_CHANNEL_DATA (94), 362 bytes
  00000000: 5e 00 00 00 01 00 00 01 61 0a 3c 72 70 63 20 6d  ^.......a.<rpc m
  00000010: 65 73 73 61 67 65 2d 69 64 3d 22 31 30 32 34 22  essage-id="1024"
  00000020: 20 78 6d 6c 6e 73 3d 22 75 72 6e 3a 69 65 74 66   xmlns="urn:ietf
  00000030: 3a 70 61 72 61 6d 73 3a 78 6d 6c 3a 6e 73 3a 6e  :params:xml:ns:n
  00000040: 65 74 63 6f 6e 66 3a 62 61 73 65 3a 31 2e 30 22  etconf:base:1.0"
  00000050: 3e 0a 20 20 3c 67 65 74 3e 0a 20 20 20 20 3c 66  >.  <get>.    <f
  00000060: 69 6c 74 65 72 20 74 79 70 65 3d 22 73 75 62 74  ilter type="subt
  00000070: 72 65 65 22 3e 0a 20 20 20 20 20 20 3c 64 65 76  ree">.      <dev
  00000080: 6d 20 78 6d 6c 6e 73 3d 22 68 74 74 70 3a 2f 2f  m xmlns="http://
  00000090: 77 77 77 2e 68 75 61 77 65 69 2e 63 6f 6d 2f 6e  www.huawei.com/n
  000000a0: 65 74 63 6f 6e 66 2f 76 72 70 2f 68 75 61 77 65  etconf/vrp/huawe
  000000b0: 69 2d 64 65 76 6d 22 3e 0a 20 20 20 20 20 20 20  i-devm">.       
  000000c0: 20 3c 63 70 75 49 6e 66 6f 73 3e 0a 20 20 20 20   <cpuInfos>.    
  000000d0: 20 20 20 20 20 20 3c 63 70 75 49 6e 66 6f 3e 0a        <cpuInfo>.
  000000e0: 20 20 20 20 20 20 20 20 20 20 20 20 3c 73 79 73              <sys
  000000f0: 74 65 6d 43 70 75 55 73 61 67 65 3e 3c 2f 73 79  temCpuUsage></sy
  00000100: 73 74 65 6d 43 70 75 55 73 61 67 65 3e 0a 20 20  stemCpuUsage>.  
  00000110: 20 20 20 20 20 20 20 20 3c 2f 63 70 75 49 6e 66          </cpuInf
  00000120: 6f 3e 0a 20 20 20 20 20 20 20 20 3c 2f 63 70 75  o>.        </cpu
  00000130: 49 6e 66 6f 73 3e 0a 20 20 20 20 20 20 3c 2f 64  Infos>.      </d
  00000140: 65 76 6d 3e 0a 20 20 20 20 3c 2f 66 69 6c 74 65  evm>.    </filte
  00000150: 72 3e 0a 20 20 3c 2f 67 65 74 3e 0a 3c 2f 72 70  r>.  </get>.</rp
  00000160: 63 3e 0a 5d 5d 3e 5d 5d 3e 0a                    c>.]]>]]>.
2020-01-30 13:12:23,282 - test.py:91 - write() - DEBUG - write 
<rpc message-id="1024" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <get>
    <filter type="subtree">
      <devm xmlns="http://www.huawei.com/netconf/vrp/huawei-devm">
        <cpuInfos>
          <cpuInfo>
            <systemCpuUsage></systemCpuUsage>
          </cpuInfo>
        </cpuInfos>
      </devm>
    </filter>
  </get>
</rpc>
]]>]]>

2020-01-30 13:12:23,299 - logging.py:71 - log() - DEBUG - [conn=0, chan=0, pktid=13] Received MSG_CHANNEL_DATA (94), 391 bytes
  00000000: 5e 00 00 00 00 00 00 01 7e 3c 3f 78 6d 6c 20 76  ^.......~<?xml v
  00000010: 65 72 73 69 6f 6e 3d 22 31 2e 30 22 20 65 6e 63  ersion="1.0" enc
  00000020: 6f 64 69 6e 67 3d 22 55 54 46 2d 38 22 3f 3e 0a  oding="UTF-8"?>.
  00000030: 3c 72 70 63 2d 72 65 70 6c 79 20 6d 65 73 73 61  <rpc-reply messa
  00000040: 67 65 2d 69 64 3d 22 31 30 32 34 22 20 78 6d 6c  ge-id="1024" xml
  00000050: 6e 73 3d 22 75 72 6e 3a 69 65 74 66 3a 70 61 72  ns="urn:ietf:par
  00000060: 61 6d 73 3a 78 6d 6c 3a 6e 73 3a 6e 65 74 63 6f  ams:xml:ns:netco
  00000070: 6e 66 3a 62 61 73 65 3a 31 2e 30 22 3e 0a 20 20  nf:base:1.0">.  
  00000080: 3c 64 61 74 61 3e 0a 20 20 20 20 3c 64 65 76 6d  <data>.    <devm
  00000090: 20 78 6d 6c 6e 73 3d 22 68 74 74 70 3a 2f 2f 77   xmlns="http://w
  000000a0: 77 77 2e 68 75 61 77 65 69 2e 63 6f 6d 2f 6e 65  ww.huawei.com/ne
  000000b0: 74 63 6f 6e 66 2f 76 72 70 2f 68 75 61 77 65 69  tconf/vrp/huawei
  000000c0: 2d 64 65 76 6d 22 3e 0a 20 20 20 20 20 20 3c 63  -devm">.      <c
  000000d0: 70 75 49 6e 66 6f 73 3e 0a 20 20 20 20 20 20 20  puInfos>.       
  000000e0: 20 3c 63 70 75 49 6e 66 6f 3e 0a 20 20 20 20 20   <cpuInfo>.     
  000000f0: 20 20 20 20 20 3c 70 6f 73 69 74 69 6f 6e 3e 31       <position>1
  00000100: 3c 2f 70 6f 73 69 74 69 6f 6e 3e 0a 20 20 20 20  </position>.    
  00000110: 20 20 20 20 20 20 3c 73 79 73 74 65 6d 43 70 75        <systemCpu
  00000120: 55 73 61 67 65 3e 31 35 3c 2f 73 79 73 74 65 6d  Usage>15</system
  00000130: 43 70 75 55 73 61 67 65 3e 0a 20 20 20 20 20 20  CpuUsage>.      
  00000140: 20 20 3c 2f 63 70 75 49 6e 66 6f 3e 0a 20 20 20    </cpuInfo>.   
  00000150: 20 20 20 3c 2f 63 70 75 49 6e 66 6f 73 3e 0a 20     </cpuInfos>. 
  00000160: 20 20 20 3c 2f 64 65 76 6d 3e 0a 20 20 3c 2f 64     </devm>.  </d
  00000170: 61 74 61 3e 0a 3c 2f 72 70 63 2d 72 65 70 6c 79  ata>.</rpc-reply
  00000180: 3e 5d 5d 3e 5d 5d 3e                             >]]>]]>
2020-01-30 13:12:23,299 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Received 382 data bytes
2020-01-30 13:12:23,299 - test.py:86 - read() - DEBUG - read <?xml version="1.0" encoding="UTF-8"?>
<rpc-reply message-id="1024" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <data>
    <devm xmlns="http://www.huawei.com/netconf/vrp/huawei-devm">
      <cpuInfos>
        <cpuInfo>
          <position>1</position>
          <systemCpuUsage>15</systemCpuUsage>
        </cpuInfo>
      </cpuInfos>
    </devm>
  </data>
</rpc-reply>]]>]]>
{
  "@message-id": "1024",
  "@xmlns": "urn:ietf:params:xml:ns:netconf:base:1.0",
  "data": {
    "devm": {
      "@xmlns": "http://www.huawei.com/netconf/vrp/huawei-devm",
      "cpuInfos": {
        "cpuInfo": {
          "position": "1",
          "systemCpuUsage": "15"
        }
      }
    }
  }
}
2020-01-30 13:12:23,299 - logging.py:71 - log() - INFO - [conn=0] Closing connection
2020-01-30 13:12:23,299 - logging.py:71 - log() - INFO - [conn=0, chan=0] Closing channel
2020-01-30 13:12:23,300 - logging.py:71 - log() - DEBUG - [conn=0, pktid=21] Sent MSG_IGNORE (2), 5 bytes
  00000000: 02 00 00 00 00                                   .....
2020-01-30 13:12:23,300 - logging.py:71 - log() - DEBUG - [conn=0, chan=0, pktid=22] Sent MSG_CHANNEL_CLOSE (97), 5 bytes
  00000000: 61 00 00 00 01                                   a....
2020-01-30 13:12:23,300 - logging.py:71 - log() - INFO - [conn=0] Sending disconnect: Disconnected by application (11)
2020-01-30 13:12:23,300 - logging.py:71 - log() - DEBUG - [conn=0, pktid=23] Sent MSG_IGNORE (2), 5 bytes
  00000000: 02 00 00 00 00                                   .....
2020-01-30 13:12:23,301 - logging.py:71 - log() - DEBUG - [conn=0, pktid=24] Sent MSG_DISCONNECT (1), 45 bytes
  00000000: 01 00 00 00 0b 00 00 00 1b 44 69 73 63 6f 6e 6e  .........Disconn
  00000010: 65 63 74 65 64 20 62 79 20 61 70 70 6c 69 63 61  ected by applica
  00000020: 74 69 6f 6e 00 00 00 05 65 6e 2d 55 53           tion....en-US
2020-01-30 13:12:23,301 - logging.py:71 - log() - INFO - [conn=0] Connection closed
2020-01-30 13:12:23,301 - logging.py:71 - log() - INFO - [conn=0, chan=0] Closing channel due to connection close
2020-01-30 13:12:23,301 - logging.py:71 - log() - INFO - [conn=0, chan=0] Channel closed
python3 test.py  0.36s user 0.50s system 19% cpu 4.478 total
horseinthesky commented 4 years ago

Actually no. Sometimes level 2 debug runs without this delay too. But level 3, for now, runs without it always.

horseinthesky commented 4 years ago

In addition to the current description: if I do infinite loop there is no delay between sending and receiving RPC:

async def get_data(device):
    async with NetconfConnection(device) as nc:
        while True:
            intf_rpc_reply = await nc.edit(intf_rpc)
            print(json.dumps(intf_rpc_reply, indent=2))
            cpu_rpc_reply = await nc.get(cpu_rpc)
            print(json.dumps(cpu_rpc_reply, indent=2))
            await asyncio.sleep(5)

logs:

2020-01-31 11:19:08,616 - test.py:90 - write() - DEBUG - write 
<hello xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
    <capabilities>
        <capability>urn:ietf:params:netconf:base:1.0</capability>
    </capabilities>
</hello>
]]>]]>

2020-01-31 11:19:08,616 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Sending 178 data bytes
2020-01-31 11:19:08,617 - test.py:90 - write() - DEBUG - write 
<rpc message-id="1" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <edit-config>
    <target>
      <running/>
    </target>
    <config xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
      <ethernet xmlns="http://www.huawei.com/netconf/vrp/huawei-ethernet">
        <ethernetIfs>
           <ethernetIf>
             <ifName>25GE1/0/11</ifName>
             <l2Enable>enable</l2Enable>
             <l2Attribute>
               <linkType>trunk</linkType>
               <pvid>106</pvid>
               <trunkVlans>4,5,6,104,106</trunkVlans>
               <taggedPacketDiscard>false</taggedPacketDiscard>
               <portBridgEnable>false</portBridgEnable>
             </l2Attribute>
           </ethernetIf>
        </ethernetIfs>
      </ethernet>
    </config>
  </edit-config>
</rpc>
]]>]]>

2020-01-31 11:19:08,617 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Sending 808 data bytes
2020-01-31 11:19:08,661 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Received 141 data bytes
2020-01-31 11:19:08,661 - test.py:86 - read() - DEBUG - read <?xml version="1.0" encoding="UTF-8"?>
<rpc-reply message-id="1" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <ok/>
</rpc-reply>
]]>]]>
{
  "@message-id": "1",
  "@xmlns": "urn:ietf:params:xml:ns:netconf:base:1.0",
  "ok": null
}
2020-01-31 11:19:08,662 - test.py:90 - write() - DEBUG - write 
<rpc message-id="1024" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <get>
    <filter type="subtree">
      <devm xmlns="http://www.huawei.com/netconf/vrp/huawei-devm">
        <cpuInfos>
          <cpuInfo>
            <systemCpuUsage></systemCpuUsage>
          </cpuInfo>
        </cpuInfos>
      </devm>
    </filter>
  </get>
</rpc>
]]>]]>

2020-01-31 11:19:08,662 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Sending 353 data bytes
2020-01-31 11:19:08,682 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Received 382 data bytes
2020-01-31 11:19:08,683 - test.py:86 - read() - DEBUG - read <?xml version="1.0" encoding="UTF-8"?>
<rpc-reply message-id="1024" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <data>
    <devm xmlns="http://www.huawei.com/netconf/vrp/huawei-devm">
      <cpuInfos>
        <cpuInfo>
          <position>1</position>
          <systemCpuUsage>15</systemCpuUsage>
        </cpuInfo>
      </cpuInfos>
    </devm>
  </data>
</rpc-reply>]]>]]>
{
  "@message-id": "1024",
  "@xmlns": "urn:ietf:params:xml:ns:netconf:base:1.0",
  "data": {
    "devm": {
      "@xmlns": "http://www.huawei.com/netconf/vrp/huawei-devm",
      "cpuInfos": {
        "cpuInfo": {
          "position": "1",
          "systemCpuUsage": "15"
        }
      }
    }
  }
}
2020-01-31 11:19:13,685 - test.py:90 - write() - DEBUG - write 
<rpc message-id="1" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <edit-config>
    <target>
      <running/>
    </target>
    <config xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
      <ethernet xmlns="http://www.huawei.com/netconf/vrp/huawei-ethernet">
        <ethernetIfs>
           <ethernetIf>
             <ifName>25GE1/0/11</ifName>
             <l2Enable>enable</l2Enable>
             <l2Attribute>
               <linkType>trunk</linkType>
               <pvid>106</pvid>
               <trunkVlans>4,5,6,104,106</trunkVlans>
               <taggedPacketDiscard>false</taggedPacketDiscard>
               <portBridgEnable>false</portBridgEnable>
             </l2Attribute>
           </ethernetIf>
        </ethernetIfs>
      </ethernet>
    </config>
  </edit-config>
</rpc>
]]>]]>

2020-01-31 11:19:13,685 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Sending 808 data bytes
2020-01-31 11:19:13,746 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Received 141 data bytes
2020-01-31 11:19:13,746 - test.py:86 - read() - DEBUG - read <?xml version="1.0" encoding="UTF-8"?>
<rpc-reply message-id="1" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <ok/>
</rpc-reply>
]]>]]>
{
  "@message-id": "1",
  "@xmlns": "urn:ietf:params:xml:ns:netconf:base:1.0",
  "ok": null
}
2020-01-31 11:19:13,747 - test.py:90 - write() - DEBUG - write 
<rpc message-id="1024" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <get>
    <filter type="subtree">
      <devm xmlns="http://www.huawei.com/netconf/vrp/huawei-devm">
        <cpuInfos>
          <cpuInfo>
            <systemCpuUsage></systemCpuUsage>
          </cpuInfo>
        </cpuInfos>
      </devm>
    </filter>
  </get>
</rpc>
]]>]]>

2020-01-31 11:19:13,747 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Sending 353 data bytes
2020-01-31 11:19:13,768 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Received 382 data bytes
2020-01-31 11:19:13,769 - test.py:86 - read() - DEBUG - read <?xml version="1.0" encoding="UTF-8"?>
<rpc-reply message-id="1024" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <data>
    <devm xmlns="http://www.huawei.com/netconf/vrp/huawei-devm">
      <cpuInfos>
        <cpuInfo>
          <position>1</position>
          <systemCpuUsage>15</systemCpuUsage>
        </cpuInfo>
      </cpuInfos>
    </devm>
  </data>
</rpc-reply>]]>]]>
{
  "@message-id": "1024",
  "@xmlns": "urn:ietf:params:xml:ns:netconf:base:1.0",
  "data": {
    "devm": {
      "@xmlns": "http://www.huawei.com/netconf/vrp/huawei-devm",
      "cpuInfos": {
        "cpuInfo": {
          "position": "1",
          "systemCpuUsage": "15"
        }
      }
    }
  }
}
^C
ronf commented 4 years ago

It's very odd that adding extra log output would affect anything on the SSH connection. However, I'm wondering if perhaps the issue is that the device can't handle multiple SSH requests open at the same time. While you are closing the connection after each request, you're not waiting for the close to complete, and perhaps that means there's a race condition where you might open a new SSH connection before the previous one has finished closing.

Try adding an "await self.conn.wait_closed()" after the "self.conn.close()" in aexit and see if that makes any difference. That should make sure that the connection is fully closed before you begin opening a new connection.

horseinthesky commented 4 years ago

I've already tried this but this changes nothing. I am not closing the connecting after each request but send both of them in one with block. You can see there is crypto key negotiation happening only once in logs.

This is my current version:

import asyncssh
import asyncio
import xmltodict
import json
import logging

from exceptions import RPCError
asyncssh.set_debug_level(2)

logging.basicConfig(level=logging.DEBUG, format="%(asctime)s - %(filename)s:%(lineno)d - %(funcName)s() - %(levelname)s - %(message)s")

hello = '''
<hello xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
    <capabilities>
        <capability>urn:ietf:params:netconf:base:1.0</capability>
    </capabilities>
</hello>
]]>]]>
'''
close = '''
<rpc message-id="1024" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <close-session/>
</rpc>
]]>]]>
'''
get = '''
<rpc message-id="1024" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <get>
    <filter type="subtree">
      {}
    </filter>
  </get>
</rpc>
]]>]]>
'''
edit = '''
<rpc message-id="1" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <edit-config>
    <target>
      <running/>
    </target>
    <config xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
      {}
    </config>
  </edit-config>
</rpc>
]]>]]>
'''
cpu_rpc = '''<devm xmlns="http://www.huawei.com/netconf/vrp/huawei-devm">
        <cpuInfos>
          <cpuInfo>
            <systemCpuUsage></systemCpuUsage>
          </cpuInfo>
        </cpuInfos>
      </devm>'''
intf_rpc = '''<ethernet xmlns="http://www.huawei.com/netconf/vrp/huawei-ethernet">
        <ethernetIfs>
           <ethernetIf>
             <ifName>25GE1/0/11</ifName>
             <l2Enable>enable</l2Enable>
             <l2Attribute>
               <linkType>trunk</linkType>
               <pvid>106</pvid>
               <trunkVlans>4,5,6,104,106</trunkVlans>
               <taggedPacketDiscard>false</taggedPacketDiscard>
               <portBridgEnable>false</portBridgEnable>
             </l2Attribute>
           </ethernetIf>
        </ethernetIfs>
      </ethernet>'''

class NetconfConnection:
    def __init__(self, ip):
        self.ip = ip

    async def __aenter__(self):
        await self.connect()
        return self

    async def __aexit__(self, *exception):
        self.write(close)
        await self.conn.wait_closed()

    async def connect(self):
        self.conn, _ = await asyncssh.create_connection(None, self.ip, known_hosts=None)
        self.writer, self.reader, _ = await self.conn.open_session(subsystem='netconf')
        self.caps = await self.read()
        self.write(hello)

    async def read(self):
        data = await self.reader.readuntil(']]>]]>')
        logging.debug("read %s", data)
        return data[:-6]

    def write(self, data):
        logging.debug("write %s", data)
        self.writer.write(data)

    async def get(self, data):
        self.write(get.format(data))
        rpc_reply = await self.read()
        data = xmltodict.parse(rpc_reply)['rpc-reply']
        if 'rpc-error' in data:
            raise RPCError(data['rpc-error']['error-message']['#text'])
        return data

    async def edit(self, data):
        self.write(edit.format(data))
        rpc_reply = await self.read()
        data = xmltodict.parse(rpc_reply)['rpc-reply']
        if 'rpc-error' in data:
            raise RPCError(data['rpc-error']['error-message']['#text'])
        # self.write(commit)
        # data = await self.read()
        return data

async def get_data(device):
    async with NetconfConnection(device) as nc:
        intf_rpc_reply = await nc.edit(intf_rpc)
        print(json.dumps(intf_rpc_reply, indent=2))
        cpu_rpc_reply = await nc.get(cpu_rpc)
        print(json.dumps(cpu_rpc_reply, indent=2))

loop = asyncio.get_event_loop()
loop.run_until_complete(get_data('hostname'))

Logs

    <capability>urn:ietf:params:xml:ns:yang:ietf-yang-library?module=ietf-yang-library&amp;revision=2016-06-21</capability>
    <capability>urn:ietf:params:xml:ns:yang:ietf-yang-metadata?module=ietf-yang-metadata&amp;revision=2014-09-11</capability>
    <capability>urn:ietf:params:xml:ns:yang:ietf-yang-types?module=ietf-yang-types&amp;revision=2013-07-15</capability>
  </capabilities>
  <session-id>18174</session-id>
</hello>
]]>]]>
2020-02-03 12:31:11,970 - test.py:97 - write() - DEBUG - write 
<hello xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
    <capabilities>
        <capability>urn:ietf:params:netconf:base:1.0</capability>
    </capabilities>
</hello>
]]>]]>

2020-02-03 12:31:11,971 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Sending 178 data bytes
2020-02-03 12:31:11,972 - test.py:97 - write() - DEBUG - write 
<rpc message-id="1" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <edit-config>
    <target>
      <running/>
    </target>
    <config xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
      <ethernet xmlns="http://www.huawei.com/netconf/vrp/huawei-ethernet">
        <ethernetIfs>
           <ethernetIf>
             <ifName>25GE1/0/11</ifName>
             <l2Enable>enable</l2Enable>
             <l2Attribute>
               <linkType>trunk</linkType>
               <pvid>106</pvid>
               <trunkVlans>4,5,6,104,106</trunkVlans>
               <taggedPacketDiscard>false</taggedPacketDiscard>
               <portBridgEnable>false</portBridgEnable>
             </l2Attribute>
           </ethernetIf>
        </ethernetIfs>
      </ethernet>
    </config>
  </edit-config>
</rpc>
]]>]]>

2020-02-03 12:31:11,972 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Sending 808 data bytes
2020-02-03 12:31:17,066 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Received 141 data bytes
2020-02-03 12:31:17,067 - test.py:93 - read() - DEBUG - read <?xml version="1.0" encoding="UTF-8"?>
<rpc-reply message-id="1" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <ok/>
</rpc-reply>
]]>]]>
{
  "@message-id": "1",
  "@xmlns": "urn:ietf:params:xml:ns:netconf:base:1.0",
  "ok": null
}
2020-02-03 12:31:17,069 - test.py:97 - write() - DEBUG - write 
<rpc message-id="1024" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <get>
    <filter type="subtree">
      <devm xmlns="http://www.huawei.com/netconf/vrp/huawei-devm">
        <cpuInfos>
          <cpuInfo>
            <systemCpuUsage></systemCpuUsage>
          </cpuInfo>
        </cpuInfos>
      </devm>
    </filter>
  </get>
</rpc>
]]>]]>

2020-02-03 12:31:17,070 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Sending 353 data bytes
2020-02-03 12:31:17,109 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Received 382 data bytes
2020-02-03 12:31:17,110 - test.py:93 - read() - DEBUG - read <?xml version="1.0" encoding="UTF-8"?>
<rpc-reply message-id="1024" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <data>
    <devm xmlns="http://www.huawei.com/netconf/vrp/huawei-devm">
      <cpuInfos>
        <cpuInfo>
          <position>1</position>
          <systemCpuUsage>16</systemCpuUsage>
        </cpuInfo>
      </cpuInfos>
    </devm>
  </data>
</rpc-reply>]]>]]>
{
  "@message-id": "1024",
  "@xmlns": "urn:ietf:params:xml:ns:netconf:base:1.0",
  "data": {
    "devm": {
      "@xmlns": "http://www.huawei.com/netconf/vrp/huawei-devm",
      "cpuInfos": {
        "cpuInfo": {
          "position": "1",
          "systemCpuUsage": "16"
        }
      }
    }
  }
}
2020-02-03 12:31:17,111 - test.py:97 - write() - DEBUG - write 
<rpc message-id="1024" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <close-session/>
</rpc>
]]>]]>

2020-02-03 12:31:17,111 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Sending 106 data bytes
2020-02-03 12:31:17,124 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Received 144 data bytes
2020-02-03 12:31:18,119 - logging.py:71 - log() - INFO - [conn=0, chan=0] Received channel close
2020-02-03 12:31:18,120 - logging.py:71 - log() - INFO - [conn=0, chan=0] Channel closed
2020-02-03 12:31:18,130 - logging.py:71 - log() - DEBUG - [conn=0] Received disconnect: The connection is closed by SSH Server
 (2)
2020-02-03 12:31:18,130 - logging.py:71 - log() - INFO - [conn=0] Connection lost: Disconnect Error: The connection is closed by SSH Server
horseinthesky commented 4 years ago

I wonder if I use readuntil in an inappropriate way? Some details of what I want to achieve: 1) I use NETCONF protocol which in turn uses SSH transport; 2) the client wraps every message (called RPC) in <rpc> tag and server wraps reply in <rpc-reply> tag; 3) both a client and a server must put a special sequence of symbols ]]>]]> to the end of the message indicating that this is the end of it's message. 4) This particular (on this type of device) implementation of NETCONF can put ]]>]]> exactly to the end of the message:

...
    </devm>
  </data>
</rpc-reply>]]>]]>

or after \n:

    </devm>
  </data>
</rpc-reply>]]>]]>

which shouldn't be a problem.

No matter what RPC (interface or cpu) I send the first this is where delay appears. The second RPC is handled immediately.

horseinthesky commented 4 years ago

I am just guessing but it seems like readuntil can't find the string I gave (]]>]]>) and wait for a timeout of 5 sec but I couldn't find any timeouts in https://github.com/ronf/asyncssh/blob/780e542a82df804492bc56523562e12b4786fa80/asyncssh/stream.py

ronf commented 4 years ago

That's right - there are no timeouts in readuntil(). So, it wouldn't return at all if it didn't match whatever string you pass into it.

Looking at the level 2 logs, the response from the server comes in AFTER the 5 seconds, suggesting the delay may be something happening on the remote system, but I'm not really sure what that could be. From the AsyncSSH logs, all we know is that you wrote a request successfully to the SSH connection and then didn't hear a response for 5 seconds. As soon as that came in, though it got returned immediately to your application code.

You could try doing a packet capture to confirm that there's no buffering happening at the TCP level, but I doubt that would tell you any more than this does.

Can you reproduce this problem even if you only make one connection and don't actually close that connection? It sounds like you can. I'm thinking it would be good to just strip out as much code as possible to see if that helps to narrow things down.

horseinthesky commented 4 years ago

I've found the solution: NETCONF server will not communicate with the client until it gets a hello message with the client's capabilities; I was sending RPCs just after sending my (client's) hello and it turned out that it was too fast for the NETCONF server (device).

Putting just a tiny sleep after hello message solves this issue:

    async def connect(self):                                                            
        self.conn, _ = await asyncssh.create_connection(None, self.ip, known_hosts=None)
        self.writer, self.reader, _ = await self.conn.open_session(subsystem='netconf') 
        self.caps = await self.read()                                                   
        self.write(hello)                                                               
        await asyncio.sleep(.1)

My silly mistake.

horseinthesky commented 4 years ago

You said there is no timeout for awaiting the response. Why is that so? Are you going to add it? I assume it could be useful if there are some issues with the server or network.

horseinthesky commented 4 years ago

Also SSH negotiation is kind of slow ~ 2.5 seconds:

2020-02-04 11:27:44,296 - selector_events.py:65 - __init__() - DEBUG - Using selector: EpollSelector
2020-02-04 11:27:44,298 - logging.py:71 - log() - INFO - Opening SSH connection to <hostname>, port 22
2020-02-04 11:27:44,344 - logging.py:71 - log() - INFO - [conn=0] Connection to <hostname>, port 22 succeeded
2020-02-04 11:27:44,344 - logging.py:71 - log() - INFO - [conn=0]   Local address: <ip>, port 60308
2020-02-04 11:27:44,355 - logging.py:71 - log() - DEBUG - [conn=0] Requesting key exchange
2020-02-04 11:27:44,356 - logging.py:71 - log() - DEBUG - [conn=0] Received key exchange request
/usr/local/lib/python3.6/dist-packages/asyncssh/crypto/ec.py:168: CryptographyDeprecationWarning: encode_point has been deprecated on EllipticCurvePublicNumbers and will be removed in a future version. Please use EllipticCurvePublicKey.public_bytes to obtain both compressed and uncompressed point encoding.
  return pub.encode_point()
2020-02-04 11:27:44,359 - logging.py:71 - log() - DEBUG - [conn=0] Beginning key exchange
/usr/local/lib/python3.6/dist-packages/asyncssh/crypto/ec.py:174: CryptographyDeprecationWarning: Support for unsafe construction of public numbers from encoded data will be removed in a future version. Please use EllipticCurvePublicKey.from_encoded_point
  self._priv_key.curve, peer_public).public_key(backend)
/usr/local/lib/python3.6/dist-packages/asyncssh/crypto/ec.py:136: CryptographyDeprecationWarning: Support for unsafe construction of public numbers from encoded data will be removed in a future version. Please use EllipticCurvePublicKey.from_encoded_point
  public_value)
2020-02-04 11:27:46,725 - logging.py:71 - log() - DEBUG - [conn=0] Completed key exchange
2020-02-04 11:27:46,738 - logging.py:71 - log() - INFO - [conn=0] Beginning auth for user horseinthesky
2020-02-04 11:27:46,750 - logging.py:71 - log() - DEBUG - [conn=0] Received authentication banner
2020-02-04 11:27:46,751 - logging.py:71 - log() - DEBUG - [conn=0] Trying public key auth with ssh-rsa key
2020-02-04 11:27:46,762 - logging.py:71 - log() - DEBUG - [conn=0] Signing request with ssh-rsa key
2020-02-04 11:27:46,775 - logging.py:71 - log() - INFO - [conn=0] Auth for user horseinthesky succeeded
2020-02-04 11:27:46,776 - logging.py:71 - log() - DEBUG - [conn=0, chan=0] Set write buffer limits: low-water=16384, high-water=65536
2020-02-04 11:27:46,776 - logging.py:71 - log() - INFO - [conn=0, chan=0] Requesting new SSH session
2020-02-04 11:27:46,786 - logging.py:71 - log() - INFO - [conn=0, chan=0]   Subsystem: netconf
2020-02-04 11:27:46,804 - test.py:94 - read() - DEBUG - read <?xml version="1.0" encoding="UTF-8"?>
<hello xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <capabilities>
  ...

I have another implementation of my script done with ncclient (uses pamamiko to establish SSH connection) and this is much quicker:

2020-02-04 12:25:08,769 DEBUG: [host None session 0x7f2a04786978] <SSHSession(session, initial daemon)> created: client_capabilities=<dict_keyiterator object at 0x7f2a04792cc8>
2020-02-04 12:25:08,790 DEBUG: starting thread (client mode): 0x47c09e8
2020-02-04 12:25:08,791 DEBUG: Local version/idstring: SSH-2.0-paramiko_2.7.1
2020-02-04 12:25:08,798 DEBUG: Remote version/idstring: SSH-2.0--
2020-02-04 12:25:08,798 INFO: Connected (version 2.0, client -)
2020-02-04 12:25:08,808 DEBUG: kex algos:['diffie-hellman-group-exchange-sha256', 'ecdh-sha2-nistp521', 'ecdh-sha2-nistp384', 'ecdh-sha2-nistp256', 'diffie-hellman-group-exchange-sha1', 'sm2kep-sha2-nistp256'] server key:['ssh-dss', 'ssh-rsa', 'ecdsa-sha2-nistp521'] client encrypt:['aes256-ctr', 'aes128-ctr'] server encrypt:['aes256-ctr', 'aes128-ctr'] client mac:['hmac-sha2-256', 'hmac-sha2-256-96', 'hmac-sha1-96'] server mac:['hmac-sha2-256', 'hmac-sha2-256-96', 'hmac-sha1-96'] client compress:['none', 'zlib'] server compress:['none', 'zlib'] client lang:[''] server lang:[''] kex follows?False
2020-02-04 12:25:08,809 DEBUG: Kex agreed: ecdh-sha2-nistp256
2020-02-04 12:25:08,809 DEBUG: HostKey agreed: ecdsa-sha2-nistp521
2020-02-04 12:25:08,809 DEBUG: Cipher agreed: aes128-ctr
2020-02-04 12:25:08,810 DEBUG: MAC agreed: hmac-sha2-256
2020-02-04 12:25:08,810 DEBUG: Compression agreed: none
2020-02-04 12:25:09,630 DEBUG: kex engine KexNistp256 specified hash_algo <built-in function openssl_sha256>
2020-02-04 12:25:09,631 DEBUG: Switch to new keys ...
2020-02-04 12:25:09,650 DEBUG: [host <hostname> session 0x7f2a04786978] Trying key b'67c9aba344384dcf30e11a50f566907c' from <key_path>
2020-02-04 12:25:09,700 DEBUG: userauth is OK
2020-02-04 12:25:09,720 INFO: Auth banner: b'\r\n<hostname>\r\n'
2020-02-04 12:25:09,723 INFO: Authentication (publickey) successful!
...
ronf commented 4 years ago

I've found the solution: NETCONF server will not communicate with the client until it gets a hello message with the client's capabilities; I was sending RPCs just after sending my (client's) hello and it turned out that it was too fast for the NETCONF server (device).

Is there any response that the server sends to the hello that you could wait for, rather than putting in an arbitrary delay?

You said there is no timeout for awaiting the response. Why is that so? Are you going to add it? I assume it could be useful if there are some issues with the server or network.

See the discussion in #21 here. You can use the asyncio wait_for() call to put a timeout around your reads if you like, or any other async call where you want to limit the amount of time it waits.

Also SSH negotiation is kind of slow ~ 2.5 seconds:

2020-02-04 11:27:44,359 - logging.py:71 - log() - DEBUG - [conn=0] Beginning key exchange 2020-02-04 11:27:46,725 - logging.py:71 - log() - DEBUG - [conn=0] Completed key exchange

If you increase the debug level, can you see if the same algorithms are being chosen? Depending on algorithm choice and key sizes, it's not unusual for older devices in particular to take a long time to perform some of the operations.

Also, which version of AsyncSSH are you using? From the deprecation warnings, I'm guessing it is a bit old, as I fixed those warnings a year or so ago. If the algorithms are the same in the two cases, you might want to try updating to a newer version of AsyncSSH and/or the cryptography package (which is what actually provides the crypto functions) to see if that helps. I haven't seen any cases where the negotiation take multiple seconds, but I'm usually testing on fairly modern hosts.

horseinthesky commented 4 years ago

Is there any response that the server sends to the hello that you could wait for, rather than putting in an arbitrary delay?

When the client opens a connection, the server instantly sends its hello (I omitted it because it's quite long). Then the client needs to send it's hello (to describe it's capabilities) to which the server is not responding with anything. After this the client may start send RPCs.

Also, which version of AsyncSSH are you using? From the deprecation warnings, I'm guessing it is a bit old, as I fixed those warnings a year or so ago. If the algorithms are the same in the two cases, you might want to try updating to a newer version of AsyncSSH and/or the cryptography package (which is what actually provides the crypto functions) to see if that helps. I haven't seen any cases where the negotiation take multiple seconds, but I'm usually testing on fairly modern hosts.

Yes, my asyncssh was quite old -1.13.3. No deprecation warnings with the newest one. With the same crypto algs timings are pretty much close:

        self.conn, _ = await asyncssh.create_connection(None, self.ip, known_hosts=None,
                                                        kex_algs=['ecdh-sha2-nistp256'],
                                                        server_host_key_algs=['ecdsa-sha2-nistp521'],
                                                        encryption_algs=['aes128-ctr'],
                                                        mac_algs=['hmac-sha2-256'],
                                                        compression_algs=['none'])

asyncssh - ~0.8 secs

2020-02-05 14:55:23,127 - selector_events.py:65 - __init__() - DEBUG - Using selector: EpollSelector
2020-02-05 14:55:23,135 - logging.py:79 - log() - INFO - Opening SSH connection to <hostname>, port 22
2020-02-05 14:55:23,180 - logging.py:79 - log() - INFO - [conn=0] Connection to <hostname>, port 22 succeeded
2020-02-05 14:55:23,181 - logging.py:79 - log() - INFO - [conn=0]   Local address: <ip>, port 63131
2020-02-05 14:55:23,192 - logging.py:79 - log() - DEBUG - [conn=0] Requesting key exchange
2020-02-05 14:55:23,193 - logging.py:79 - log() - DEBUG - [conn=0] Received key exchange request
2020-02-05 14:55:23,197 - logging.py:79 - log() - DEBUG - [conn=0] Beginning key exchange
2020-02-05 14:55:23,905 - logging.py:79 - log() - DEBUG - [conn=0] Completed key exchange
2020-02-05 14:55:23,912 - logging.py:79 - log() - INFO - [conn=0] Beginning auth for user horseinthesky
2020-02-05 14:55:23,918 - logging.py:79 - log() - DEBUG - [conn=0] Received authentication banner
2020-02-05 14:55:23,920 - logging.py:79 - log() - DEBUG - [conn=0] Trying public key auth with ssh-rsa key
2020-02-05 14:55:23,926 - logging.py:79 - log() - DEBUG - [conn=0] Signing request with ssh-rsa key
2020-02-05 14:55:23,942 - logging.py:79 - log() - INFO - [conn=0] Auth for user horseinthesky succeeded
2020-02-05 14:55:23,943 - logging.py:79 - log() - DEBUG - [conn=0, chan=0] Set write buffer limits: low-water=16384, high-water=65536
2020-02-05 14:55:23,944 - logging.py:79 - log() - INFO - [conn=0, chan=0] Requesting new SSH session
2020-02-05 14:55:23,950 - logging.py:79 - log() - INFO - [conn=0, chan=0]   Subsystem: netconf

paramiko - ~0.9 secs

Btw why self.conn.wait_closed() takes a little bit more than a second?

    async def __aexit__(self, *exception):
        self.write(close)
        await self.conn.wait_closed()

logs

2020-02-05 13:59:41,888 - test.py:103 - write() - DEBUG - write 
<rpc message-id="1024" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <close-session/>
</rpc>
]]>]]>

2020-02-05 13:59:42,908 - logging.py:79 - log() - INFO - [conn=0, chan=0] Received channel close
2020-02-05 13:59:42,908 - logging.py:79 - log() - INFO - [conn=0, chan=0] Channel closed
2020-02-05 13:59:42,913 - logging.py:79 - log() - INFO - [conn=0] Connection lost
horseinthesky commented 4 years ago

Timeout works perfectly fine. Thank you for the tip!

ronf commented 4 years ago

Regarding wait_closed(), the fact that you called wait_closed() without calling close() first means that you will be waiting for the remote end of the SSH connection to close before it will return. In this case, that would mean the remote system would have to parse the "close" RPC, write its response if there is one (even though you aren't reading it), and then initiate a connection close at the SSH level. Only then would the AsyncSSH client code send a close in response and return from wait_closed().

If you call close() explicitly before wait_closed(), it should still do a clean close at the SSH level, but it wouldn't need to wait for the remote system to initiate the close.

horseinthesky commented 4 years ago

I've tested it with Huawei and Juniper devices and they implement close-session RPC:

<rpc message-id="1024" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <close-session/>
</rpc>
]]>]]>

differently.

Huawei is closing the connection from its side so I can do just wait_closed() and Juniper continues to keep the connection so I have to do close().

I just wanted to make sure I can do close() from my side to close the session correctly.

ronf commented 4 years ago

If you like, you can still write the RPC before calling close(), as long as you don't try to read anything further on the connection after that.

Alternately, you can write_eof() to trigger the other end to close the connection if the RPC alone doesn't do it. However, there might still be a delay in that case since you wouldn't close on your end until the other end sent a close request in response to the EOF.

horseinthesky commented 4 years ago

It says

AttributeError: 'SSHClientConnection' object has no attribute 'write_eof'

https://asyncssh.readthedocs.io/en/latest/api.html#sshclientconnection

But I am pretty much happy with the options I have. Thank you!

ronf commented 4 years ago

Just for clarity, the write_eof() call is like the regular write() call -- it would be on your "writer" object, not on the SSHClientConnection.

horseinthesky commented 4 years ago

Got it. And yes, this works. Thanks again.