search

scrapli / scrapli_netconf

Fast and flexible Python 3.7+ netconf client specifically for network devices
https://scrapli.github.io/scrapli_netconf/
MIT License
92 stars 6 forks source link

ScrapliConnectionError while get diff for big template #138

Closed RomainGuilloux closed 6 months ago

RomainGuilloux commented 1 year ago

Describe the bug Timeout error even if scrapli timeouts are set when trying to get the diff of big template to Juniper MX with rpcs.

To Reproduce Steps to reproduce the behavior:

  1. script

    my_device = {
    "host": DEVICE_PARAMS['host'],
    "auth_username": DEVICE_PARAMS['username'],
    "auth_password": DEVICE_PARAMS['password'],
    "auth_strict_key": False,
    "port": int(DEVICE_PARAMS['port']),
    'transport': 'ssh2',
    'timeout_socket': 180,
    'timeout_transport': 180,
    'timeout_ops': 180
}

conn = NetconfDriver(**my_device)
print('open conf')
conn.open()
print('start load')
f = open(TEMPLATE_FILENAME, "r")
LOAD_RPC = f"""
<load-configuration format="xml">
    {f.read()}
</load-configuration>
"""
response = conn.rpc(filter_=LOAD_RPC)
pprint(response.__dict__)
print(response)

print('start diff')
DIFF_COMMIT_FILTER = """
<get-configuration compare="rollback" database="candidate" format="set"/>
"""
response = conn.rpc(filter_=DIFF_COMMIT_FILTER)
pprint(response.__dict__)
print(response)
  2. Remote devices are Juniper MX480, version 19.4R2-S3.2 with 280k lines of configurations (display set).
  3. The template pushed is an xml file with 10k lines of configurations with 9k static routes.
  4. Load configuratio is working well
  5. Logs 
    
'elapsed_time': 3.843117,
'error_messages': [],
'failed': False,
'failed_when_contains': [b'</rpc-error>',
                      b'</rpc-errors>',
                      b'<rpc-error>',
                      b'<rpc-errors>'],
'finish_time': datetime.datetime(2023, 6, 26, 9, 4, 25, 220373),
'genie_platform': '',
'host': 'x.y.z.w',
'netconf_version': <NetconfVersion.VERSION_1_0: '1.0'>,
'raw_result': b'\n<rpc-reply xmlns:junos="http://xml.juniper.net/junos/19.4R0'
           b'/junos" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" mess'
           b'age-id="101">\n<load-configuration-results>\n<ok/>\n</load-'
           b'configuration-results>\n</rpc-reply>\n]]>]]>\n',
'result': '<rpc-reply xmlns:junos="http://xml.juniper.net/junos/19.4R0/junos" '
       'xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="101">\n'
       '  <load-configuration-results>\n'
       '    <ok/>\n'
       '  </load-configuration-results>\n'
       '</rpc-reply>\n',
'start_time': datetime.datetime(2023, 6, 26, 9, 4, 21, 377256),
'strip_namespaces': False,
'textfsm_platform': '',
'xml_input': <Element {urn:ietf:params:xml:ns:netconf:base:1.0}rpc at 0x7f2c9b1c9c80>,
'xml_result': <Element {urn:ietf:params:xml:ns:netconf:base:1.0}rpc-reply at 0x7f2c96638e40>}
NetconfResponse <Success: True>
start diff

Traceback (most recent call last): File "/opt/customs-envs/venv-netconf-console/lib/python3.9/site-packages/scrapli/transport/plugins/ssh2/transport.py", line 257, in read _, buf = self.session_channel.read(65535) File "ssh2/channel.pyx", line 134, in ssh2.channel.Channel.read File "ssh2/channel.pyx", line 162, in ssh2.channel.Channel.read_ex File "ssh2/utils.pyx", line 106, in ssh2.utils.handle_error_codes ssh2.exceptions.Timeout

The above exception was the direct cause of the following exception:

Traceback (most recent call last): File "/var/lib/awx/projects/diff.py", line 217, in main() File "/var/lib/awx/projects/diff.py", line 213, in main with_scrapli() File "/var/lib/awx/projects/diff.py", line 203, in withscrapli response = conn.rpc(filter=DIFF_COMMIT_FILTER) File "/opt/customs-envs/venv-netconf-console/lib/python3.9/site-packages/scrapli_netconf/driver/sync_driver.py", line 330, in rpc raw_response = self.channel.send_input_netconf(response.channel_input) File "/opt/customs-envs/venv-netconf-console/lib/python3.9/site-packages/scrapli_netconf/channel/sync_channel.py", line 284, in send_input_netconf buf = self._read_until_prompt(buf=buf) File "/opt/customs-envs/venv-netconf-console/lib/python3.9/site-packages/scrapli/channel/sync_channel.py", line 137, in _read_until_prompt read_buf.write(self.read()) File "/opt/customs-envs/venv-netconf-console/lib/python3.9/site-packages/scrapli_netconf/channel/sync_channel.py", line 214, in read return super().read() File "/opt/customs-envs/venv-netconf-console/lib/python3.9/site-packages/scrapli/channel/sync_channel.py", line 69, in read buf = self.transport.read() File "/opt/customs-envs/venv-netconf-console/lib/python3.9/site-packages/scrapli/transport/plugins/ssh2/transport.py", line 264, in read raise ScrapliConnectionError(msg) from exc scrapli.exceptions.ScrapliConnectionError: encountered EOF reading from transport; typically means the device closed the connection


**Expected behavior**
I expect to have the get diff rpc response like: 
```json
{'netconf_version': <NetconfVersion.VERSION_1_0: '1.0'>, 'xml_input': <Element {urn:ietf:params:xml:ns:netconf:base:1.0}rpc at 0x7fe95d8ebb40>, 'strip_namespaces': False, 'host': 'x.y.z.w', 'start_time': datetime.datetime(2023, 6, 26, 8, 43, 16, 252383), 'finish_time': datetime.datetime(2023, 6, 26, 8, 43, 46, 989905), 'elapsed_time': 30.737522, 'channel_input': '<?xml version=\'1.0\' encoding=\'utf-8\'?>\n<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="101"><get-configuration compare="rollback" database="candidate" format="set"/></rpc>]]>]]>', 'textfsm_platform': '', 'genie_platform': '', 'raw_result': b'\n<rpc-reply xmlns:junos="http://xml.juniper.net/junos/19.4R0/junos" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="101">\n<configuration-information>\n<configuration-output>\n</configuration-output>\n</configuration-information>\n</rpc-reply>\n]]>]]>\n', 'result': '<rpc-reply xmlns:junos="http://xml.juniper.net/junos/19.4R0/junos" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="101">\n  <configuration-information>\n    <configuration-output>\n</configuration-output>\n  </configuration-information>\n</rpc-reply>\n', 'failed_when_contains': [b'</rpc-error>', b'</rpc-errors>', b'<rpc-error>', b'<rpc-errors>'], 'failed': False, 'error_messages': [], 'xml_result': <Element {urn:ietf:params:xml:ns:netconf:base:1.0}rpc-reply at 0x7fe95b643900>}
NetconfResponse <Success: True>

OS (please complete the following information):

Thanks for your help.

carlmontanari commented 1 year ago

280k lines of configurations

that escalated quickly :)

is that timeout happening at 180s or something else? can you try disabling transport timeout by setting that to 0 to see if that works? I think logs with timestamps may be helpful for just figuring out the interval it's crapping out at then we can go from there.

thanks for raising this!

RomainGuilloux commented 1 year ago

Do you have a method to activate debug logs of scrapli netconf please ?

I will try to set timeout to 0

I would say the timeout happen at 35-40 seconds.

carlmontanari commented 1 year ago

sure, just like this should do the trick! if its 30 or so seconds then we may just have not properly set the timeout somewhere... my guess would be in ssh2 transport since I know system and asyncssh get a lot more use -- if you could try w/ system transport as well that would be great!

thanks!

RomainGuilloux commented 1 year ago
  1. transport system is not working on my environment OSError: [Errno 5] Input/output error scrapli.exceptions.ScrapliConnectionError: encountered EOF reading from transport; typically means the device closed the connection
  2. setting transport timeout to 0 doesn't changes the behaviour
  3. Here is the trace of rpc get-configuration only 
    ID    | TIMESTAMP               | LEVEL    | (UID:)HOST:PORT           | MESSAGE
1     | 2023-06-27 17:08:06,295 | DEBUG    | x.y.z.w:830          | setting 'server_capabilities' value to '[]'
2     | 2023-06-27 17:08:06,296 | INFO     | x.y.z.w:830          | opening connection to 'x.y.z.w' on port '830'
3     | 2023-06-27 17:08:06,296 | DEBUG    | x.y.z.w:830          | opening transport connection to 'x.y.z.w' on port '830'
4     | 2023-06-27 17:08:06,296 | DEBUG    | x.y.z.w:830          | opening socket connection to 'x.y.z.w' on port '830'
5     | 2023-06-27 17:08:06,309 | DEBUG    | x.y.z.w:830          | opened socket connection to 'x.y.z.w' on port '830' successfully
6     | 2023-06-27 17:08:06,784 | DEBUG    | x.y.z.w:830          | transport connection to 'x.y.z.w' on port '830' opened successfully
7     | 2023-06-27 17:08:07,095 | DEBUG    | x.y.z.w:830          | read : b'<!-- No zombies were killed during the creation of this user int
erface -->\n<!-- user GEN-USR-R_W, class j-GEN-PROF-R_W -->\n<hello xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">\n  <capabilities>\n    <capab
ility>urn:ietf:params:netconf:base:1.0</capability>\n    <capability>urn:ietf:params:netconf:capability:candidate:1.0</capability>\n    <capabilit
y>urn:ietf:params:netconf:capability:confirmed-commit:1.0</capability>\n    <capability>urn:ietf:params:netconf:capability:validate:1.0</capabilit
y>\n    <capability>urn:ietf:params:netconf:capability:url:1.0?scheme=http,ftp,file</capability>\n    <capability>urn:ietf:params:xml:ns:netconf:b
ase:1.0</capability>\n    <capability>urn:ietf:params:xml:ns:netconf:capability:candidate:1.0</capability>\n    <capability>urn:ietf:params:xml:ns
:netconf:capability:confirmed-commit:1.0</capability>\n    <capability>urn:ietf:params:xml:ns:netconf:capability:validate:1.0</capability>\n    <c
apability>urn:ietf:params:xml:ns:netconf:capability:url:1.0?scheme=http,ftp,file</capability>\n    <capability>urn:ietf:params:xml:ns:yang:ietf-ne
tconf-monitoring</capability>\n    <capability>http://xml.juniper.net/netconf/junos/1.0</capability>\n    <capability>http://xml.juniper.net/dmi/s
ystem/1.0</capability>\n  </capabilities>\n  <session-id>34203</session-id>\n</hello>\n]]>]]>\n'
8     | 2023-06-27 17:08:07,102 | DEBUG    | x.y.z.w:830          | received raw server capabilities: b'<!-- No zombies were killed during th
e creation of this user interface -->\n<!-- user GEN-USR-R_W, class j-GEN-PROF-R_W -->\n<hello xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">\n
<capabilities>\n    <capability>urn:ietf:params:netconf:base:1.0</capability>\n    <capability>urn:ietf:params:netconf:capability:candidate:1.0</
capability>\n    <capability>urn:ietf:params:netconf:capability:confirmed-commit:1.0</capability>\n    <capability>urn:ietf:params:netconf:capabil
ity:validate:1.0</capability>\n    <capability>urn:ietf:params:netconf:capability:url:1.0?scheme=http,ftp,file</capability>\n    <capability>urn:i
etf:params:xml:ns:netconf:base:1.0</capability>\n    <capability>urn:ietf:params:xml:ns:netconf:capability:candidate:1.0</capability>\n    <capabi
lity>urn:ietf:params:xml:ns:netconf:capability:confirmed-commit:1.0</capability>\n    <capability>urn:ietf:params:xml:ns:netconf:capability:valida
te:1.0</capability>\n    <capability>urn:ietf:params:xml:ns:netconf:capability:url:1.0?scheme=http,ftp,file</capability>\n    <capability>urn:ietf
:params:xml:ns:yang:ietf-netconf-monitoring</capability>\n    <capability>http://xml.juniper.net/netconf/junos/1.0</capability>\n    <capability>h
ttp://xml.juniper.net/dmi/system/1.0</capability>\n  </capabilities>\n  <session-id>34203</session-id>\n</hello>\n'
9     | 2023-06-27 17:08:07,103 | INFO     | x.y.z.w:830          | server capabilities received and parsed: ['urn:ietf:params:netconf:base:1
.0', 'urn:ietf:params:netconf:capability:candidate:1.0', 'urn:ietf:params:netconf:capability:confirmed-commit:1.0', 'urn:ietf:params:netconf:capab
ility:validate:1.0', 'urn:ietf:params:netconf:capability:url:1.0?scheme=http,ftp,file', 'urn:ietf:params:xml:ns:netconf:base:1.0', 'urn:ietf:param
s:xml:ns:netconf:capability:candidate:1.0', 'urn:ietf:params:xml:ns:netconf:capability:confirmed-commit:1.0', 'urn:ietf:params:xml:ns:netconf:capa
bility:validate:1.0', 'urn:ietf:params:xml:ns:netconf:capability:url:1.0?scheme=http,ftp,file', 'urn:ietf:params:xml:ns:yang:ietf-netconf-monitori
ng', 'http://xml.juniper.net/netconf/junos/1.0', 'http://xml.juniper.net/dmi/system/1.0']
10    | 2023-06-27 17:08:07,103 | INFO     | x.y.z.w:830          | sending client capabilities
11    | 2023-06-27 17:08:07,104 | DEBUG    | x.y.z.w:830          | attempting to send capabilities: NetconfClientCapabilities.CAPABILITIES_1
_0
12    | 2023-06-27 17:08:07,104 | DEBUG    | x.y.z.w:830          | write: '\n<?xml version="1.0" encoding="utf-8"?>\n    <hello xmlns="urn:i
etf:params:xml:ns:netconf:base:1.0">\n        <capabilities>\n            <capability>urn:ietf:params:netconf:base:1.0</capability>\n        </cap
abilities>\n</hello>]]>]]>'
13    | 2023-06-27 17:08:07,104 | DEBUG    | x.y.z.w:830          | write: '\n'
14    | 2023-06-27 17:08:07,104 | INFO     | x.y.z.w:830          | connection to 'x.y.z.w' on port '830' opened successfully
15    | 2023-06-27 17:08:07,104 | DEBUG    | x.y.z.w:830          | Building payload for 'rpc' operation.
16    | 2023-06-27 17:08:07,104 | DEBUG    | x.y.z.w:830          | Building base element for message id 101
17    | 2023-06-27 17:08:07,105 | DEBUG    | x.y.z.w:830          | Built payload for 'rpc' operation. Payload: <?xml version='1.0' encoding=
'utf-8'?>
<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="101"><get-configuration compare="rollback" database="candidate" format="set"/></r
pc>]]>]]>
18    | 2023-06-27 17:08:07,105 | INFO     | x.y.z.w:830          | sending channel input: <?xml version='1.0' encoding='utf-8'?>
<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="101"><get-configuration compare="rollback" database="candidate" format="set"/></r
pc>]]>]]>; strip_prompt: False; eager: True
19    | 2023-06-27 17:08:07,105 | DEBUG    | x.y.z.w:830          | write: '<?xml version=\'1.0\' encoding=\'utf-8\'?>\n<rpc xmlns="urn:ietf:
params:xml:ns:netconf:base:1.0" message-id="101"><get-configuration compare="rollback" database="candidate" format="set"/></rpc>]]>]]>'
20    | 2023-06-27 17:08:07,105 | DEBUG    | x.y.z.w:830          | write: '\n'
21    | 2023-06-27 17:08:07,222 | DEBUG    | x.y.z.w:830          | read : b'<rpc-reply xmlns:junos="http://xml.juniper.net/junos/19.4R0/juno
s" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="101">\n<configuration-information>\n<configuration-output>\n</configuration-output>
\n</configuration-information>\n</rpc-reply>\n]]>]]>\n'
22    | 2023-06-27 17:08:37,415 | DEBUG    | x.y.z.w:830          | server echo is unset, determining if server echoes inputs now
23    | 2023-06-27 17:08:37,415 | DEBUG    | x.y.z.w:830          | server does *not* echo inputs, setting _server_echo to 'false'
24    | 2023-06-27 17:08:37,416 | INFO     | x.y.z.w:830          | closing connection to 'x.y.z.w' on port '830'
25    | 2023-06-27 17:08:37,416 | DEBUG    | x.y.z.w:830          | closing transport connection to 'x.y.z.w' on port '830'
26    | 2023-06-27 17:08:37,426 | DEBUG    | x.y.z.w:830          | closing socket connection to 'x.y.z.w' on port '830'
27    | 2023-06-27 17:08:37,426 | DEBUG    | x.y.z.w:830          | closed socket connection to 'x.y.z.w' on port '830' successfully
28    | 2023-06-27 17:08:37,426 | DEBUG    | x.y.z.w:830          | transport connection to 'x.y.z.w' on port '830' closed successfully
29    | 2023-06-27 17:08:37,426 | INFO     | x.y.z.w:830          | connection to 'x.y.z.w' on port '830' closed successfully
  4. Here is the log with 2 rpcs : load-configuration + get-configuration 
    ID    | TIMESTAMP               | LEVEL    | (UID:)HOST:PORT           | MESSAGE
1     | 2023-06-27 18:00:03,834 | DEBUG    | x.y.z.w:830          | setting 'server_capabilities' value to '[]'
2     | 2023-06-27 18:00:03,835 | INFO     | x.y.z.w:830          | opening connection to 'x.y.z.w' on port '830'
3     | 2023-06-27 18:00:03,835 | DEBUG    | x.y.z.w:830          | opening transport connection to 'x.y.z.w' on port '830'
4     | 2023-06-27 18:00:03,835 | DEBUG    | x.y.z.w:830          | opening socket connection to 'x.y.z.w' on port '830'
5     | 2023-06-27 18:00:03,847 | DEBUG    | x.y.z.w:830          | opened socket connection to 'x.y.z.w' on port '830' successfully
6     | 2023-06-27 18:00:04,313 | DEBUG    | x.y.z.w:830          | transport connection to 'x.y.z.w' on port '830' opened successfully
7     | 2023-06-27 18:00:04,624 | DEBUG    | x.y.z.w:830          | read : b'<!-- No zombies were killed during the creation of this user interface -->\n<!-- user GEN-USR-R_W, class j-GEN-PROF-R_W -->\n<hello xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">\n  <capabilities>\n    <capability>urn:ietf:params:netconf:base:1.0</capability>\n    <capability>urn:ietf:params:netconf:capability:candidate:1.0</capability>\n    <capability>urn:ietf:params:netconf:capability:confirmed-commit:1.0</capability>\n    <capability>urn:ietf:params:netconf:capability:validate:1.0</capability>\n    <capability>urn:ietf:params:netconf:capability:url:1.0?scheme=http,ftp,file</capability>\n    <capability>urn:ietf:params:xml:ns:netconf:base:1.0</capability>\n    <capability>urn:ietf:params:xml:ns:netconf:capability:candidate:1.0</capability>\n    <capability>urn:ietf:params:xml:ns:netconf:capability:confirmed-commit:1.0</capability>\n    <capability>urn:ietf:params:xml:ns:netconf:capability:validate:1.0</capability>\n    <capability>urn:ietf:params:xml:ns:netconf:capability:url:1.0?scheme=http,ftp,file</capability>\n    <capability>urn:ietf:params:xml:ns:yang:ietf-netconf-monitoring</capability>\n    <capability>http://xml.juniper.net/netconf/junos/1.0</capability>\n    <capability>http://xml.juniper.net/dmi/system/1.0</capability>\n  </capabilities>\n  <session-id>35046</session-id>\n</hello>\n]]>]]>\n'
8     | 2023-06-27 18:00:04,632 | DEBUG    | x.y.z.w:830          | received raw server capabilities: b'<!-- No zombies were killed during the creation of this user interface -->\n<!-- user GEN-USR-R_W, class j-GEN-PROF-R_W -->\n<hello xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">\n  <capabilities>\n    <capability>urn:ietf:params:netconf:base:1.0</capability>\n    <capability>urn:ietf:params:netconf:capability:candidate:1.0</capability>\n    <capability>urn:ietf:params:netconf:capability:confirmed-commit:1.0</capability>\n    <capability>urn:ietf:params:netconf:capability:validate:1.0</capability>\n    <capability>urn:ietf:params:netconf:capability:url:1.0?scheme=http,ftp,file</capability>\n    <capability>urn:ietf:params:xml:ns:netconf:base:1.0</capability>\n    <capability>urn:ietf:params:xml:ns:netconf:capability:candidate:1.0</capability>\n    <capability>urn:ietf:params:xml:ns:netconf:capability:confirmed-commit:1.0</capability>\n    <capability>urn:ietf:params:xml:ns:netconf:capability:validate:1.0</capability>\n    <capability>urn:ietf:params:xml:ns:netconf:capability:url:1.0?scheme=http,ftp,file</capability>\n    <capability>urn:ietf:params:xml:ns:yang:ietf-netconf-monitoring</capability>\n    <capability>http://xml.juniper.net/netconf/junos/1.0</capability>\n    <capability>http://xml.juniper.net/dmi/system/1.0</capability>\n  </capabilities>\n  <session-id>35046</session-id>\n</hello>\n'
9     | 2023-06-27 18:00:04,633 | INFO     | x.y.z.w:830          | server capabilities received and parsed: ['urn:ietf:params:netconf:base:1.0', 'urn:ietf:params:netconf:capability:candidate:1.0', 'urn:ietf:params:netconf:capability:confirmed-commit:1.0', 'urn:ietf:params:netconf:capability:validate:1.0', 'urn:ietf:params:netconf:capability:url:1.0?scheme=http,ftp,file', 'urn:ietf:params:xml:ns:netconf:base:1.0', 'urn:ietf:params:xml:ns:netconf:capability:candidate:1.0', 'urn:ietf:params:xml:ns:netconf:capability:confirmed-commit:1.0', 'urn:ietf:params:xml:ns:netconf:capability:validate:1.0', 'urn:ietf:params:xml:ns:netconf:capability:url:1.0?scheme=http,ftp,file', 'urn:ietf:params:xml:ns:yang:ietf-netconf-monitoring', 'http://xml.juniper.net/netconf/junos/1.0', 'http://xml.juniper.net/dmi/system/1.0']
10    | 2023-06-27 18:00:04,633 | INFO     | x.y.z.w:830          | sending client capabilities
11    | 2023-06-27 18:00:04,633 | DEBUG    | x.y.z.w:830          | attempting to send capabilities: NetconfClientCapabilities.CAPABILITIES_1_0
12    | 2023-06-27 18:00:04,633 | DEBUG    | x.y.z.w:830          | write: '\n<?xml version="1.0" encoding="utf-8"?>\n    <hello xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">\n        <capabilities>\n            <capability>urn:ietf:params:netconf:base:1.0</capability>\n        </capabilities>\n</hello>]]>]]>'
13    | 2023-06-27 18:00:04,633 | DEBUG    | x.y.z.w:830          | write: '\n'
14    | 2023-06-27 18:00:04,633 | INFO     | x.y.z.w:830          | connection to 'x.y.z.w' on port '830' opened successfully
15    | 2023-06-27 18:00:04,637 | DEBUG    | x.y.z.w:830          | Building payload for 'rpc' operation.
16    | 2023-06-27 18:00:04,637 | DEBUG    | x.y.z.w:830          | Building base element for message id 101
17    | 2023-06-27 18:00:04,684 | DEBUG    | x.y.z.w:830          | Built payload for 'rpc' operation. Payload: <?xml version='1.0' encoding='utf-8'?>
<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="101"><load-configuration format="xml"><configuration><routing-options operation="merge"><static operation="replace">...</routing-instances></configuration></load-configuration></rpc>]]>]]>
18    | 2023-06-27 18:00:04,691 | INFO     | x.y.z.w:830          | sending channel input: <?xml version='1.0' encoding='utf-8'?>
<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="101"><load-configuration format="xml"><configuration><routing-options operation="merge"><static operation="replace">...</routing-instances></configuration></load-configuration></rpc>]]>]]>; strip_prompt: False; eager: True
19    | 2023-06-27 18:00:04,703 | DEBUG    | x.y.z.w:830          | write: '<?xml version=\'1.0\' encoding=\'utf-8\'?>\n<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="101"><load-configuration format="xml"><configuration><routing-options operation="merge"><static operation="replace">...</routing-instances></configuration></load-configuration></rpc>]]>]]>'
20    | 2023-06-27 18:00:04,756 | DEBUG    | x.y.z.w:830          | write: '\n'
21    | 2023-06-27 18:00:04,756 | DEBUG    | x.y.z.w:830          | read : b'<rpc-reply xmlns:junos="http://xml.juniper.net/junos/19.4R0/junos" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="101">\n<load-configuration-results>\n<ok/>\n</load-configuration-results>\n</rpc-reply>\n]]>]]>\n'
22    | 2023-06-27 18:00:08,566 | DEBUG    | x.y.z.w:830          | server echo is unset, determining if server echoes inputs now
23    | 2023-06-27 18:00:08,566 | DEBUG    | x.y.z.w:830          | server does *not* echo inputs, setting _server_echo to 'false'
24    | 2023-06-27 18:00:08,627 | DEBUG    | x.y.z.w:830          | Building payload for 'rpc' operation.
25    | 2023-06-27 18:00:08,627 | DEBUG    | x.y.z.w:830          | Building base element for message id 102
26    | 2023-06-27 18:00:08,627 | DEBUG    | x.y.z.w:830          | Built payload for 'rpc' operation. Payload: <?xml version='1.0' encoding='utf-8'?>
<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="102"><get-configuration compare="rollback" database="candidate" format="set"/></rpc>]]>]]>
27    | 2023-06-27 18:00:08,627 | INFO     | x.y.z.w:830          | sending channel input: <?xml version='1.0' encoding='utf-8'?>
<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="102"><get-configuration compare="rollback" database="candidate" format="set"/></rpc>]]>]]>; strip_prompt: False; eager: True
28    | 2023-06-27 18:00:08,627 | DEBUG    | x.y.z.w:830          | write: '<?xml version=\'1.0\' encoding=\'utf-8\'?>\n<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="102"><get-configuration compare="rollback" database="candidate" format="set"/></rpc>]]>]]>'
29    | 2023-06-27 18:00:08,628 | DEBUG    | x.y.z.w:830          | write: '\n'
30    | 2023-06-27 18:00:08,637 | DEBUG    | x.y.z.w:830          | read : b'<rpc-reply xmlns:junos="http://xml.juniper.net/junos/19.4R0/junos" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="102">\n'
31    | 2023-06-27 18:01:08,653 | CRITICAL | x.y.z.w:830          | encountered EOF reading from transport; typically means the device closed the connection
32    | 2023-06-27 18:01:08,654 | INFO     | x.y.z.w:830          | closing connection to 'x.y.z.w' on port '830'
33    | 2023-06-27 18:01:08,654 | DEBUG    | x.y.z.w:830          | closing transport connection to 'x.y.z.w' on port '830'

    On the Juniper I have also activated netconf logs, everything looks good:

Jun 27 18:00:04 [NETCONF] - [96114] Outgoing: <ok/>
Jun 27 18:00:04 [NETCONF] - [96114] Outgoing: </load-configuration-results>
Jun 27 18:00:04 [NETCONF] - [96114] Outgoing: </rpc-reply>
Jun 27 18:00:04 [NETCONF] - [96114] Outgoing: ]]>]]>
Jun 27 18:00:04 [NETCONF] - [96114] Incoming: <?xml version="1.0" encoding="UTF-8"?><nc:rpc xmlns:nc="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="urn:uuid:9a49c834-e5f5-4007-9e9a-4b177f35b4de"><nc:get-configuration compare="rollback" format="text" rollback="0"/></nc:rpc>]]>]]>
Jun 27 18:00:04 [NETCONF] - [96114] Outgoing: <rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" xmlns:junos="http://xml.juniper.net/junos/19.4R0/junos" xmlns:nc="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="urn:uuid:9a49c834-e5f5-4007-9e9a-4b177f35b4de">
Jun 27 18:37:04  [NETCONF] - [96114] Outgoing: <configuration-information>
Jun 27 18:37:16 [NETCONF] - [96114] Outgoing: <configuration-output>
Jun 27 18:37:23 [NETCONF] - [96114] Outgoing: [edit routing-options rib inet6.0 static]
...
Jun 27 18:37:30 [NETCONF] - [96114] Outgoing: </configuration-output>
Jun 27 18:37:30 [NETCONF] - [96114] Outgoing: </configuration-information>
Jun 27 18:37:31 [NETCONF] - [96114] Outgoing: </rpc-reply>
Jun 27 18:37:31 [NETCONF] - [96114] Outgoing: ]]>]]>

I will try with asyncssh too.

carlmontanari commented 1 year ago

awesome thanks for grabbing that! ill try to take a peak this weekend and get back to ya!

RomainGuilloux commented 1 year ago

Hi, I've tried with asyncssh, it works like a charm !

carlmontanari commented 1 year ago

great! thank you for confirming! will figure out where / why the timeout gets dropped this weekend!

carlmontanari commented 1 year ago

hmm ok i spent a little time poking around and didnt find anything totally obvious

i dropped a sleep down in scrapli core for 90s and then set timeout to 180s like you've got and things worked as expected (no timeout), and if i slept like 200s then of course id hit a timeout. tried this with a netconf driver as well as just regular scrapli/ssh bits.

could you maybe drop a breakpoint or a print before the diff rpc call with this: conn.transport.session.get_timeout() just to confirm its getting set to what we think it should be (this is in ms).

could you also try to do timeouts like this to just totally disable/rule out the other possible timeouts:

   dev = {
        "host": "xyz",
        "transport": "ssh2",
        'timeout_socket': 0,
        'timeout_transport': 0,
        'timeout_ops': 0
    }

will try to take a further look with some fresh eyes later in the weekend too, but nothing obvious is jumping out at me. I did notice that you're using ssh2-python3 (vs ssh2-python) so I tried that as well and that seemed to work the same -- and looking at the fork it did nothing different for timeouts as far as I saw.

carlmontanari commented 6 months ago

hey there, im going to close this out for now just for housekeeping reasons. feel free to reopen if we need to dig back into this. thanks!