Closed sincerywaing closed 7 years ago
weird, it happened couple of times then it disappears... under what circumstance would this happens? local host will initialize a new scp? how can the code prevent this from happening?
@sincerywaing Is the file transfer completing? Do you see a file named merge_config.txt
in flash:
or bootflash:
? You might need to use dir
to get the name of the file system it is using.
How big is the config.txt
file?
How long does it take before the SSHException appears?
Thanks Kirk.
No there is no file in flash. Usually around 10s. config file is very small like 4 lines.
It is not 100% reproducible, just wondering if there is any way we can retry?
Sent from my iPhone
On 24 Jun 2017, at 12:37 AM, Kirk Byers notifications@github.com wrote:
@sincerywaing Is the file transfer completing? Do you see a file named merge_config.txt in flash: or bootflash:? You might need to use dir to get the name of the file system it is using.
How big is the config.txt file?
How long does it take before the SSHException appears?
— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.
What does SSH debugging on the router/switch show when you do this (i.e. when the failure happens).
Also can you enable logging and see if that gives us more information:
import logging
logging.basicConfig(filename='test.log', level=logging.DEBUG)
logger = logging.getLogger("netmiko")
Thanks Kirk. I'll see if I can reproduce this.
Sent from my iPhone
On 25 Jun 2017, at 3:47 AM, Kirk Byers notifications@github.com wrote:
What does SSH debugging on the router/switch show when you do this (i.e. when the failure happens).
Also can you enable logging and see if that gives us more information:
import logging logging.basicConfig(filename='test.log', level=logging.DEBUG) logger = logging.getLogger("netmiko") — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.
Here is the debug log. config txt file has only 2 lines. it seems file is never scp'ed to switch. junos works with same code. the device is not pre-configured with scp but it seems will be auto configured during the loading.
code
===================
`def connect_host(device, username, password): # prepare to open connection`
` driver = get_network_driver(device['os'])`
` conn = driver(device['hostname'], username, password, optional_args=device['option'])`
` return conn`
`def load_config_bot(device): # automatically load config`
` connection = connect_host(device, username, password)`
` try:`
` print '\nConnecting to %s...' % device['hostname']`
` connection.open()`
` connection.load_merge_candidate(filename=os.path.expanduser('~/Desktop/' + project_name + '/config/') + device['config_file'])`
` connection.commit_config()`
` print '\n%s is implemented.' % device['hostname']`
` connection.close()`
` print '\n'`
` print '=' * 80`
` except:`
` with open(os.path.expanduser('~/Desktop/' + project_name + '/fail.log'), 'a') as f:`
` f.write('\nDeployment to %s fails.' % device['hostname'])`
=========================
DEBUG:paramiko.transport:starting thread (client mode): 0x84865d10L
DEBUG:paramiko.transport:Local version/idstring: SSH-2.0-paramiko_2.2.1
DEBUG:paramiko.transport:Remote version/idstring: SSH-2.0-Cisco-1.25
INFO:paramiko.transport:Connected (version 2.0, client Cisco-1.25)
DEBUG:paramiko.transport:kex algos:[u'diffie-hellman-group-exchange-sha1', u'diffie-hellman-group14-sha1', u'diffie-hellman-group1-sha1'] server key:[u'ssh-rsa'] client encrypt:[u'aes128-ctr', u'aes192-ctr', u'aes256-ctr', u'aes128-cbc', u'3des-cbc', u'aes192-cbc', u'aes256-cbc'] server encrypt:[u'aes128-ctr', u'aes192-ctr', u'aes256-ctr', u'aes128-cbc', u'3des-cbc', u'aes192-cbc', u'aes256-cbc'] client mac:[u'hmac-sha1', u'hmac-sha1-96'] server mac:[u'hmac-sha1', u'hmac-sha1-96'] client compress:[u'none'] server compress:[u'none'] client lang:[u''] server lang:[u''] kex follows?False
DEBUG:paramiko.transport:Kex agreed: diffie-hellman-group-exchange-sha1
DEBUG:paramiko.transport:HostKey agreed: ssh-rsa
DEBUG:paramiko.transport:Cipher agreed: aes128-ctr
DEBUG:paramiko.transport:MAC agreed: hmac-sha1
DEBUG:paramiko.transport:Compression agreed: none
DEBUG:paramiko.transport:Got server p (2048 bits)
DEBUG:paramiko.transport:kex engine KexGex specified hash_algo
INFO:paramiko.transport:Authentication (password) successful! DEBUG:paramiko.transport:[chan 0] Max packet in: 32768 bytes DEBUG:paramiko.transport:[chan 0] Max packet out: 4096 bytes DEBUG:paramiko.transport:Secsh channel 0 opened. DEBUG:paramiko.transport:[chan 0] Sesch channel 0 request ok DEBUG:paramiko.transport:[chan 0] Sesch channel 0 request ok DEBUG:netmiko:read_channel: This is banner!!!
access-switch1# DEBUG:netmiko:read_channel: DEBUG:netmiko:read_channel: DEBUG:netmiko:read_channel: DEBUG:netmiko:write_channel:
DEBUG:netmiko:read_channel: access-switch1# DEBUG:netmiko:read_channel: DEBUG:netmiko:read_channel: DEBUG:netmiko:write_channel: terminal length 0
DEBUG:netmiko:_read_channel_expect read_data: terminal length 0 access-switch1# DEBUG:netmiko:write_channel: terminal width 511
DEBUG:netmiko:_read_channel_expect read_data: terminal width 511 access-switch1# DEBUG:netmiko:read_channel: DEBUG:netmiko:write_channel:
DEBUG:netmiko:_read_channel_expect read_data: access-switch1# DEBUG:netmiko:read_channel: DEBUG:netmiko:write_channel:
DEBUG:netmiko:read_channel:
DEBUG:netmiko:read_channel: access-switch1# DEBUG:netmiko:read_channel: DEBUG:netmiko:read_channel: DEBUG:netmiko:write_channel: dir
DEBUG:netmiko:read_channel: DEBUG:netmiko:read_channel: dir Directory of flash:/
579 -rwx 2072 Jun 20 2017 13:01:37 -07:00 multiple-fs 2 -rwx 796 Jun 20 2017 13:01:32 -07:00 vlan.dat 3 drwx 512 Feb 28 2017 15:48:55 -08:00 c3560cx-universalk9-mz.152-3.E1 574 drwx 512 Feb 28 2017 15:48:55 -08:00 dc_profile_dir 576 -rwx 1918 Feb 28 2017 16:42:15 -08:00 private-config.text 578 -rwx 9185 Feb 28 2017 16:42:15 -08:00 config.text
122185728 bytes total (96306176 bytes free) access-switch1# DEBUG:netmiko:read_channel: DEBUG:netmiko:write_channel:
DEBUG:netmiko:read_channel: access-switch1# DEBUG:netmiko:read_channel: DEBUG:netmiko:read_channel: DEBUG:netmiko:write_channel: dir flash:
DEBUG:netmiko:read_channel: DEBUG:netmiko:read_channel: dir flash: Directory of flash:/
579 -rwx 2072 Jun 20 2017 13:01:37 -07:00 multiple-fs 2 -rwx 796 Jun 20 2017 13:01:32 -07:00 vlan.dat 3 drwx 512 Feb 28 2017 15:48:55 -08:00 c3560cx-universalk9-mz.152-3.E1 574 drwx 512 Feb 28 2017 15:48:55 -08:00 dc_profile_dir 576 -rwx 1918 Feb 28 2017 16:42:15 -08:00 private-config.text 578 -rwx 9185 Feb 28 2017 16:42:15 -08:00 config.text
122185728 bytes total (96306176 bytes free)
access-switch1#
DEBUG:paramiko.transport:starting thread (client mode): 0x764a9050L
DEBUG:paramiko.transport:Local version/idstring: SSH-2.0-paramiko_2.2.1
DEBUG:paramiko.transport:Remote version/idstring: SSH-2.0-Cisco-1.25
INFO:paramiko.transport:Connected (version 2.0, client Cisco-1.25)
DEBUG:paramiko.transport:kex algos:[u'diffie-hellman-group-exchange-sha1', u'diffie-hellman-group14-sha1', u'diffie-hellman-group1-sha1'] server key:[u'ssh-rsa'] client encrypt:[u'aes128-ctr', u'aes192-ctr', u'aes256-ctr', u'aes128-cbc', u'3des-cbc', u'aes192-cbc', u'aes256-cbc'] server encrypt:[u'aes128-ctr', u'aes192-ctr', u'aes256-ctr', u'aes128-cbc', u'3des-cbc', u'aes192-cbc', u'aes256-cbc'] client mac:[u'hmac-sha1', u'hmac-sha1-96'] server mac:[u'hmac-sha1', u'hmac-sha1-96'] client compress:[u'none'] server compress:[u'none'] client lang:[u''] server lang:[u''] kex follows?False
DEBUG:paramiko.transport:Kex agreed: diffie-hellman-group-exchange-sha1
DEBUG:paramiko.transport:HostKey agreed: ssh-rsa
DEBUG:paramiko.transport:Cipher agreed: aes128-ctr
DEBUG:paramiko.transport:MAC agreed: hmac-sha1
DEBUG:paramiko.transport:Compression agreed: none
DEBUG:paramiko.transport:Got server p (2048 bits)
DEBUG:paramiko.transport:kex engine KexGex specified hash_algo
INFO:paramiko.transport:Authentication (password) successful! DEBUG:netmiko:read_channel: DEBUG:netmiko:write_channel:
DEBUG:netmiko:read_channel: access-switch1# DEBUG:netmiko:read_channel: DEBUG:netmiko:read_channel: DEBUG:netmiko:write_channel: dir flash:/merge_config.txt
DEBUG:netmiko:read_channel: DEBUG:netmiko:read_channel: dir flash:/merge_config.txt %Error opening flash:/merge_config.txt (No such file or directory) access-switch1# DEBUG:netmiko:read_channel: DEBUG:netmiko:write_channel:
DEBUG:netmiko:read_channel: access-switch1# DEBUG:netmiko:read_channel: DEBUG:netmiko:read_channel: DEBUG:netmiko:write_channel: dir flash:
DEBUG:netmiko:read_channel: DEBUG:netmiko:read_channel: dir flash: Directory of flash:/
579 -rwx 2072 Jun 20 2017 13:01:37 -07:00 multiple-fs 2 -rwx 796 Jun 20 2017 13:01:32 -07:00 vlan.dat 3 drwx 512 Feb 28 2017 15:48:55 -08:00 c3560cx-universalk9-mz.152-3.E1 574 drwx 512 Feb 28 2017 15:48:55 -08:00 dc_profile_dir 576 -rwx 1918 Feb 28 2017 16:42:15 -08:00 private-config.text 578 -rwx 9185 Feb 28 2017 16:42:15 -08:00 config.text
122185728 bytes total (96306176 bytes free) access-switch1# DEBUG:netmiko:write_channel:
DEBUG:netmiko:_read_channel_expect read_data: access-switch1# DEBUG:netmiko:write_channel: config term
DEBUG:netmiko:_read_channel_expect read_data: config term Enter configuration commands, one per line. End with CNTL/Z. access-switch1(config)# DEBUG:netmiko:write_channel:
DEBUG:netmiko:_read_channel_expect read_data: access-switch1(config)# DEBUG:netmiko:write_channel: ip scp server enable
DEBUG:netmiko:read_channel: ip scp server enable access-switch1(config)# DEBUG:netmiko:read_channel: DEBUG:paramiko.transport:EOF in transport thread DEBUG:netmiko:read_channel: DEBUG:netmiko:write_channel:
DEBUG:netmiko:_read_channel_expect read_data: access-switch1(config)# DEBUG:netmiko:write_channel: end
DEBUG:netmiko:_read_channel_expect read_data: end access-switch1# DEBUG:netmiko:write_channel:
DEBUG:netmiko:_read_channel_expect read_data: access-switch1# DEBUG:netmiko:write_channel:
DEBUG:netmiko:_read_channel_expect read_data: access-switch1# DEBUG:netmiko:write_channel: exit
DEBUG:paramiko.transport:EOF in transport thread
so if you keep show ssh - you will find the user did have two sessions - but the second one is Authenticated. comparing debug log, the second one looks like the one doing dir flash:merge_config. so why scp did not happen?
Connection Version Mode Encryption Hmac State Username
1 2.0 IN aes128-ctr hmac-sha1 Session started ttt 1 2.0 OUT aes128-ctr hmac-sha1 Session started ttt 2 2.0 IN aes128-ctr hmac-sha1 Authenticated ttt 2 2.0 OUT aes128-ctr hmac-sha1 Authenticated ttt
Then the second one disappears - with exception -
Connection Version Mode Encryption Hmac State Username
1 2.0 IN aes128-ctr hmac-sha1 Session started ttt 1 2.0 OUT aes128-ctr hmac-sha1 Session started ttt
Traceback (most recent call last):
File "push.py", line 48, in
Also as you can see I used multiprocessing (futures), but it should not be relevant?
if I open a python interaction >>>, same code works fine, without define functions.
looks like this
I don't know why but once I added 'inline_transfer': True to optional_args, everything starts working...
inline_transfer
doesn't use SCP; it uses a TCL-based file transfer completely inside the SSH session.
Leave this issue open so I can see if I can figure out any reason why the SCP transfer wasn't working.
Thanks Kirk.
Would it make any difference if we use inline transfer? what is the advantage and disadvantages against SCP?
I'd assume my code should not have issue, however you can try to increase latency to 300ms -400ms and put global_delay_factor=4 see if you can reproduce.
Sent from my iPhone
On 30 Jun 2017, at 2:55 AM, Kirk Byers notifications@github.com wrote:
inline_transfer doesn't use SCP; it uses a TCL-based file transfer completely inside the SSH session.
Leave this issue open so I can see if I can figure out any reason why the SCP transfer wasn't working.
— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.
inline transfer
is very slow for larger config files (not even all that large). I am not sure why this is.
Inline transfer also might run into some issues with special characters in the config. I know there is one open issue on this (I think in napalm-ios).
I can see ip scp server is enabled so until line 502 the code should be good. It's just tranfer_file not working. is it possible that global_delay_factor could cause this?
Another thought would be - if scp needs to establish a new ssh session, is it possible that the new session is never established if we use self.device?
@sincerywaing I don't think you would see the error that you see if the issue was with global_delay_factor.
Can you expand on this?
Another thought would be - if scp needs to establish a new ssh session, is it possible that the new session is never established if we use self.device?
The SCP operation of NAPALM generally works (i.e. it is used on a lot of IOS devices). So it is not a matter of referencing the wrong thing.
What do you see if you debug ip ssh
on the Cisco side?
@ktbyers I think I can reproduce the issue, it looks purely latency related:
if latency <150ms, there is no issue.
if latency is >300ms or even >350ms, there are various errors. changing global_delay_factor does not help.
An error occurred in dynamically determining remote file system: dir -sw1#
dis-sw1#
dis-sw1#
or
Unexpected output from check_file_exists
Also during transfer, the transfer class will configure 'ip scp server enable'; but it won't disable it. Can we put 'no ip scp server enable' after transfer finish? Do you want me to open another issue as enhancement?
The original issue of 'SSH session inactive' probably due to vty 5 15 configuration issue. I'll close this one first and open a new one on this latency issue.
reopen this one to properly track the issue as it seems even increased global_delay_factor can't fix it. I encountered another one during a push.
fail.txt here is the debug ip ssh from the router it seems both logins are successful, however the scp fails due to session already closed due to 0x12
I compared a working instance and non-working instance, the nonworking instance does not have below log:
dis-sw1(config)# DEBUG:netmiko:read_channel: DEBUG:netmiko:read_channel: DEBUG:netmiko:write_channel:
DEBUG:netmiko:_read_channel_expect read_data: dis-sw1(config)# DEBUG:netmiko:write_channel: end
DEBUG:netmiko:_read_channel_expect read_data: end dis-sw1# DEBUG:netmiko:write_channel:
DEBUG:netmiko:_read_channel_expect read_data:
DEBUG:netmiko:_read_channel_expect read_data: dis-sw1# DEBUG:paramiko.transport:[chan 0] Max packet in: 32768 bytes DEBUG:paramiko.transport:[chan 0] Max packet out: 4096 bytes DEBUG:paramiko.transport:Secsh channel 0 opened. DEBUG:paramiko.transport:[chan 0] Sesch channel 0 request ok DEBUG:paramiko.transport:[chan 0] EOF sent (0)
DEBUG:netmiko:read_channel: dis-sw1# DEBUG:netmiko:read_channel: DEBUG:netmiko:read_channel: DEBUG:netmiko:write_channel: verify /md5 flash:merge_config.txt
DEBUG:netmiko:read_channel: DEBUG:netmiko:read_channel: verify /md5 flash:merge_config.txt .Done! verify /md5 (flash:merge_config.txt) = 1b8087aa8604e540a385c70ca542ac68
dis-sw1# DEBUG:netmiko:read_channel: DEBUG:netmiko:write_channel:
DEBUG:netmiko:read_channel: dis-sw1# DEBUG:netmiko:read_channel: DEBUG:netmiko:read_channel: DEBUG:netmiko:write_channel: show archive config incremental-diffs flash:/merge_config.txt ignorecase
DEBUG:netmiko:read_channel: DEBUG:netmiko:read_channel: show archive config incremental-diffs flash:/merge_c DEBUG:netmiko:read_channel: DEBUG:netmiko:read_channel: onfig.txt ignorecase
DEBUG:netmiko:read_channel: DEBUG:netmiko:read_channel: DEBUG:netmiko:read_channel: !List of Commands: int tun 1 description test1 int tun 2 description test2 end
dis-sw1# DEBUG:netmiko:write_channel:
I think the ssh session was closed due to below when I take a look at the fail debug:
DEBUG:paramiko.transport:EOF in transport thread
Above is the last line of debug.
it seems after sending 'ip scp server enable', the program somehow read EOF so the channel is closed:
lab1-rtr2(config)#
DEBUG:netmiko:write_channel: ip scp server enable
DEBUG:netmiko:read_channel: ip scp server enable
lab1-rtr2(config)#
DEBUG:netmiko:read_channel:
DEBUG:netmiko:read_channel:
DEBUG:netmiko:write_channel:
DEBUG:netmiko:_read_channel_expect read_data:
lab1-rtr2(config)#
DEBUG:netmiko:write_channel: end
DEBUG:netmiko:_read_channel_expect read_data: end
lab1-rtr2#
DEBUG:netmiko:write_channel:
DEBUG:netmiko:_read_channel_expect read_data:
lab1-rtr2#
DEBUG:paramiko.transport:[chan 0] Max packet in: 32768 bytes
DEBUG:paramiko.transport:EOF in transport thread
@ktbyers I think I can reproduce the issue.
on my devices I configure below:
ip ssh time-out 15
it seems if you configure global_delay_factor
large value, or latency is high, the ssh session might got closed.
if I configure
ip ssh time-out 120
The issue never re-occured.
I tried keepalive
= 1 but it does not help.
@krbyers it seems you partially rewrited scp in scp_handler for netmiko. is it possible to add a keepalive function to prevent it from closing :-)?
@sincerywaing So my read of the above is:
This is the router closing the session (for some reason):
DEBUG:paramiko.transport:[chan 0] Max packet in: 32768 bytes
DEBUG:paramiko.transport:EOF in transport thread
So ip ssh time-out
defaults to 120 seconds. You are setting this lower which is causing SSH negotiation to fail for slow links.
On this question:
it seems you partially rewrited scp in scp_handler for netmiko. is it possible to
add a keepalive function to prevent it from closing :-)?
The router is closing the SSH session. The easy fix is for you to go back to the default ip ssh time-out 120
. In other words, you have put an aggressive setting here and it is causing the SSH negotiation to fail.
@ktbyers yes I agree. The weird part is that why the negotiation can't be done in 15s. Just wondering if there is somewhere we can improve the efficiency, as the scp process should be another ssh session so it should not be affected by global_delay_factor but only latency and code efficency I guess?
Why not just set your Cisco devices back to the 120s default and be done with it?
My point is Cisco defaulted this to 120s for some reason. We are seeing strange behavior from the Cisco device when we set the timer to 15s (i.e. Cisco disconnects the session at a lower time than we would expect). This makes me believe there is more nuance to this timer on the Cisco side.
I guess it has something to do with PCI DSS. Anyways inline_transfer works even with low timeout value. I'll close it for now if we don't have plan to further investigate. Thanks @ktbyers.
@sincerywaing That is a bummer...FWIW I don't think that is real. In other words, I don't think PCI actually requires that. So I would probably push back on your auditors on that.
You could also try to see if there are any bugs in Cisco IOS pertaining to this timer.
You could also see if negotiation is actually taking 15 seconds i.e. I wouldn't think our negotiation is taking 15 seconds. If it is failing and not taking 15 seconds, then that is very likely a Cisco issue.
I am reluctant to try to do things on my side as it really is a Cisco issue.
But if you see clear things I am doing wrong, feel free to submit a PR on it.
Description of Issue/Question
dev.open() dev.load_merge_candidate(filename='config.txt') then it will throw 'SSH session not active'
Did you follow the steps from https://github.com/napalm-automation/napalm#faq
Setup
napalm-ios version
(Paste verbatim output from
pip freeze | grep napalm-ios
between quotes below)napalm-ios==0.6.2 napalm-iosxr==0.5.0
IOS version
(Paste verbatim output from
show version
between quotes below)Steps to Reproduce the Issue
Error Traceback
(Paste the complete traceback of the exception between quotes below)
dev.open() dev.load_merge_candidate(filename='config.txt') Traceback (most recent call last): File "", line 1, in
File "/usr/local/lib/python2.7/dist-packages/napalm_ios/ios.py", line 223, in load_merge_candidate
file_system=self.dest_file_system)
File "/usr/local/lib/python2.7/dist-packages/napalm_ios/ios.py", line 193, in _load_candidate_wrapper
file_system=file_system)
File "/usr/local/lib/python2.7/dist-packages/napalm_ios/ios.py", line 430, in _scp_file
file_system=file_system, TransferClass=FileTransfer)
File "/usr/local/lib/python2.7/dist-packages/napalm_ios/ios.py", line 481, in _xfer_file
return (False, '')
File "/usr/local/lib/python2.7/dist-packages/netmiko/scp_handler.py", line 87, in exit
raise exc_type(exc_value)
paramiko.ssh_exception.SSHException: SSH session not active