search

netfishers-onl / Netshot

Network Configuration and Compliance Management
http://www.netfishers.onl/netshot
242 stars 57 forks source link

unable to backup cisco ncs ios xr #250

Closed Godfather133th closed 10 months ago

Godfather133th commented 1 year ago

Hi,

I'm trying to backup cisco router ncs ios xr and the backup failed for below reason, so appreciate your support to solve it

note: I can login to the device from server cli by using ssh command

2023-02-14 18:45:59,443 WARN [NetshotRunnerScheduler_Worker-1] TaskJob: Running the task 24621 of type onl.netfishers.netshot.work.tasks.TakeSnapshotTask 2023-02-14 18:46:04,870 WARN [NetshotRunnerScheduler_Worker-1] CliScript: Unable to open an SSH connection to ipx:0. java.io.IOException: Session.connect: java.net.SocketTimeoutException: Read timed out at onl.netfishers.netshot.device.access.Ssh.connect(Ssh.java:304) at onl.netfishers.netshot.device.script.CliScript.connectRun(CliScript.java:253) at onl.netfishers.netshot.device.script.CliScript.connectRun(CliScript.java:205) at onl.netfishers.netshot.work.tasks.TakeSnapshotTask.run(TakeSnapshotTask.java:211) at onl.netfishers.netshot.work.TaskJob.execute(TaskJob.java:95) at org.quartz.core.JobRunShell.run(JobRunShell.java:202) at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) Caused by: com.jcraft.jsch.JSchException: Session.connect: java.net.SocketTimeoutException: Read timed out at com.jcraft.jsch.Session.connect(Session.java:568) at onl.netfishers.netshot.device.access.Ssh.connect(Ssh.java:297) ... 6 common frames omitted Caused by: java.net.SocketTimeoutException: Read timed out at java.base/java.net.SocketInputStream.socketRead0(Native Method) at java.base/java.net.SocketInputStream.socketRead(SocketInputStream.java:115) at java.base/java.net.SocketInputStream.read(SocketInputStream.java:168) at java.base/java.net.SocketInputStream.read(SocketInputStream.java:140) at com.jcraft.jsch.IO.getByte(IO.java:82) at com.jcraft.jsch.Session.read(Session.java:1070) at com.jcraft.jsch.Session.connect(Session.java:326) ... 7 common frames omitted

SCadilhac commented 1 year ago

Hello, can you start the snapshot in debug mode (https://github.com/netfishers-onl/Netshot/wiki/Snapshot-troubleshooting) and check the logs?

clockwe commented 1 year ago

Hello, Same problem here... But working fine on NCS and failing on ASR9K. Device logs says this : SECURITY-SSHD-3-ERR_GENERAL : Error in receiving key exchange packet

ssh server debug : RP/0/RSP0/CPU0:Apr 26 12:10:39.802 CEST: SSHD[1293]: elapsed:426505.812500, msecs:1000.000000, count:1 RP/0/RSP0/CPU0:Apr 26 12:10:39.802 CEST: SSHD[1293]: Empty free list, allocating from history RP/0/RSP0/CPU0:Apr 26 12:10:39.802 CEST: SSHD[1293]: Free index from history 22 RP/0/RSP0/CPU0:Apr 26 12:10:39.802 CEST: SSHD[1293]: Next free index 101 RP/0/RSP0/CPU0:Apr 26 12:10:39.802 CEST: SSHD[1293]: Last history index 2 RP/0/RSP0/CPU0:Apr 26 12:10:39.802 CEST: SSHD[1293]: Kex algo list is RP/0/RSP0/CPU0:Apr 26 12:10:39.802 CEST: SSHD[1293]: Cipher algo list is aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com RP/0/RSP0/CPU0:Apr 26 12:10:39.802 CEST: SSHD[1293]: Fips mode is: OFF RP/0/RSP0/CPU0:Apr 26 12:10:39.802 CEST: SSHD_[1293]: sshd_connhandler:1272 type: 1, port: 22 RP/0/RSP0/CPU0:Apr 26 12:10:39.802 CEST: SSHD[1293]: port forwarding 0 RP/0/RSP0/CPU0:Apr 26 12:10:39.802 CEST: SSHD[1293]: 0 count RP/0/RSP0/CPU0:Apr 26 12:10:39.805 CEST: SSHD[1293]: Spawned new child process 2117, active clients=2, session count=2 RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD_[67653]: Inside initttylist FUNC RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: initttylist: Created/Opened the Semaphore %pid:2117 SEM Value:1: RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: (sshd_shm_lock_init) shm path:/sshd_lock22 RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: (sshd_shm_lock_init): shared memory truncated file:/sshd_lock22, fd:102, size:12 RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: (sshd_shm_lock_init): shared memory mmaped ptr:0x7fd4f4037000, file:/sshd_lock22, fd:102, size:12 RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: Host certificate Trustpoint present = 0 RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: User-tp-count:=0 RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: User-tp:= RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: username mask:=1 RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: Client sockfd 3 RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD_[67653]: SSH path/dev/ssh_pulse2117 RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: SSH ltraceindex 22 RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: SSH port forwarding 0 RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: Fips mode OFF RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: Enable doxml 0 RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: Old ciphers enabled - 0 RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: Disabled hmac mask 0 RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: kex algo list is RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: ssh type 1 RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: ssh type 1 : NIN : 4 RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: ssh version is 2 RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: ssh srvr logging is 1 RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: ssh server cipher list - aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com RP/0/RSP0/CPU0:Apr 26 12:10:40.404 CEST: SSHD[67653]: Port on which service running 22 RP/0/RSP0/CPU0:Apr 26 12:10:40.405 CEST: SSHD_[67653]: Setting IPTOS value:64 RP/0/RSP0/CPU0:Apr 26 12:10:40.405 CEST: SSHD[67653]: After setting socket options, sndbuf65536, rcvbuf - 65536 RP/0/RSP0/CPU0:Apr 26 12:10:40.405 CEST: SSHD[67653]: vrf id socket 6000000f RP/0/RSP0/CPU0:Apr 26 12:10:40.405 CEST: SSHD[67653]: Connection from A.B.C.D port 20701 RP/0/RSP0/CPU0:Apr 26 12:10:40.405 CEST: SSHD_[67653]: (update_sshd_session_details) addrem: 0 channel_id: 1, tty:XXXXX, session_state: 1 channelstate:1 user: connection RP/0/RSP0/CPU0:Apr 26 12:10:40.405 CEST: SSHD[67653]: Session id 22373 RP/0/RSP0/CPU0:Apr 26 12:10:40.405 CEST: SSHD[67653]: Exchanging versions RP/0/RSP0/CPU0:Apr 26 12:10:40.406 CEST: SSHD_[67653]: ssh_version_exchange : client_str = SSH-2.0-JSCH0.2.7 (len = 18) RP/0/RSP0/CPU0:Apr 26 12:10:40.406 CEST: SSHD[67653]: Remote protocol version 2.0, remote software version JSCH0.2.7 RP/0/RSP0/CPU0:Apr 26 12:10:40.406 CEST: SSHD[67653]: main, Rekey Interval = 3600 , Rekey Datasize = 1073741824 RP/0/RSP0/CPU0:Apr 26 12:10:40.406 CEST: SSHD_[67653]: (update_sshd_session_details) addrem: 3 channel_id: 1, tty:XXXXX, session_state: 2 channelstate:1 user: connection RP/0/RSP0/CPU0:Apr 26 12:10:40.406 CEST: SSHD[67653]: In Key exchange RP/0/RSP0/CPU0:Apr 26 12:10:40.406 CEST: SSHD[67653]: ecdsa256:=0, ecdsa384:=0, ecdsa521:=0, rsa:=0, dsa:=0, x509v3-rsa:=0, ed25519:=0, rsa521:=0, rsa256:=0, ssh-rsa:=0 RP/0/RSP0/CPU0:Apr 26 12:10:40.407 CEST: SSHD_[67653]: Inside (sshd_get_alglistkeys) The algorithm list(ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,ssh-ds RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Padlen = 15, Packlen = 1116 RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Calling Receive kexinit 10 RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD_[67653]: (sshd_kexinitreceived:1184) setting alarm to 60 secs RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: sshd_kexinitreceived: BEGIN KEX INIT RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Peer Proposal : diffie-hellman-group18-sha512,diffie-hellman-group16-sha512,diffie-hellman-group14-sha256,diffie-hel,diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1,ext-info-c RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Peer Proposal : rsa-sha2-256,rsa-sha2-512,ssh-rsa,ssh-dss RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Peer Proposal : aes128-gcm@openssh.com,aes128-ctr,aes128-cbc,3des-ctr,3des-cbc,blowfish-cbc,aes192-ctr,aes192-cbc,ae RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Peer Proposal : hmac-md5-etm@openssh.com,hmac-sha1-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@om@openssh.com,hmac-md5,hmac-sha1,hmac-sha2-256,hmac-sha2-512,hmac-sha1-96,hmac-md5-96 RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Peer Proposal : none RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Peer Proposal : RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Peer Proposal first_kexfollows : 0 RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Negotiated Alg : diffie-hellman-group14-sha1 RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Publickey Alg = rsa-sha2-256 RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Incoming cipher = aes128-gcm@openssh.com RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Outgoing cipher = aes128-gcm@openssh.com RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Incoming mac = aes-gcm RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Outgoing mac = aes-gcm RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Keylen Reqd = 16 RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Incoming mac's key length = 0 RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Outgoing mac's key length = 0 RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Incoming cipher's key length = 16 RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Outgoing cipher's key length = 16 RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Incoming cipher's block size = 16 RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Outgoing cipher's block size = 16 RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD_[67653]: (update_sshd_kexinfo_details) sessionid: 22373, kexname:diffie-hellman-group14-sha1, hostkeyalg: rsa-sha2-256 incipsh.com inmac: aes-gcm, outmac:aes-gcm RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: sshd_kexinit_received: keytype: 9 RP/0/RSP0/CPU0:Apr 26 12:10:40.769 CEST: SSHD[67653]: Waiting for KEXDHINIT RP/0/RSP0/CPU0:Apr 26 12:10:40.772 CEST: SSHD[67653]: Padlen = 13, Packlen = 276 RP/0/RSP0/CPU0:Apr 26 12:10:40.772 CEST: SSHD[67653]: Received KEXDHINIT RP/0/RSP0/CPU0:Apr 26 12:10:40.772 CEST: SSHD[67653]: Calling DH algorithm setting with group14 RP/0/RSP0/CPU0:Apr 26 12:10:40.772 CEST: SSHD[67653]: After geting the parameter we are calling the first phase of DH RP/0/RSP0/CPU0:Apr 26 12:10:40.862 CEST: SSHD[67167]: Padlen = 18, Packlen = 28 RP/0/RSP0/CPU0:Apr 26 12:10:40.862 CEST: SSHD[67167]: Received Win_adjust 8387, rwin = 15530 RP/0/RSP0/CPU0:Apr 26 12:10:42.652 CEST: SSHD[67653]: sshd_kexinit_received: Selected keytype: RSA RP/0/RSP0/CPU0:Apr 26 12:10:42.652 CEST: SSHD[67653]: Extracting RSA pubkey from crypto engine RP/0/RSP0/CPU0:Apr 26 12:10:42.652 CEST: SSHD[67653]: Retreiving 2048 bit RSA host key-pair RP/0/RSP0/CPU0:Apr 26 12:10:42.652 CEST: SSHD[67653]: bloblen = 284 RP/0/RSP0/CPU0:Apr 26 12:10:42.652 CEST: SSHD[67653]: exponent = 3, modulus = 257 RP/0/RSP0/CPU0:Apr 26 12:10:42.652 CEST: SSHD[67653]: Host key blob len = 284 RP/0/RSP0/CPU0:Apr 26 12:10:42.652 CEST: SSHD_[67653]: Calculating kex =hash with client_str = SSH-2.0-JSCH0.2.7 (len = 18) RP/0/RSP0/CPU0:Apr 26 12:10:42.652 CEST: SSHD[67653]: serverstr = SSH-2.0-Cisco-2.0 (len = 17) RP/0/RSP0/CPU0:Apr 26 12:10:42.652 CEST: SSHD[67653]: The Hash Algorithm is:2 Digest Size is:20 RP/0/RSP0/CPU0:Apr 26 12:10:42.652 CEST: SSHD[67653]: hash level : 2 used for digesting data RP/0/RSP0/CPU0:Apr 26 12:10:42.652 CEST: SSHD[67653]: Dumping the Session Id: RP/0/RSP0/CPU0:Apr 26 12:10:42.653 CEST: SSHD[67653]: 0000 - 92 ac 16 40 d9 c8 a6 06-7b 20 e9 a2 84 81 94 66 ...@....{ .....f RP/0/RSP0/CPU0:Apr 26 12:10:42.653 CEST: SSHD[67653]: 0010 - 41 52 85 84 AR.. RP/0/RSP0/CPU0:Apr 26 12:10:42.660 CEST: SSHD_[67653]: Sending KEXDHREPLY RP/0/RSP0/CPU0:Apr 26 12:10:42.660 CEST: SSHD[67653]: Inside (sshd_kexinitreceived) Hash Type:2 Digest:20 RP/0/RSP0/CPU0:Apr 26 12:10:42.660 CEST: SSHD[67653]: Sending NEWKEYS RP/0/RSP0/CPU0:Apr 26 12:10:42.660 CEST: SSHD[67653]: Waiting for NEWKEYS RP/0/RSP0/CPU0:Apr 26 12:10:42.665 CEST: SSHD[67653]: Padlen = 8, Packlen = 68 RP/0/RSP0/CPU0:Apr 26 12:10:42.665 CEST: SSHD[67653]: ssh_receive - MSGDISCONNECT - Received reason code 3 RP/0/RSP0/CPU0:Apr 26 12:10:42.666 CEST: SSHD[67653]: [TID=2117] In cleanup code, pid:2117, sig rcvd:0, state:4 RP/0/RSP0/CPU0:Apr 26 12:10:42.666 CEST: SSHD_[67653]: (sshcleanup:900) clearing alarm. Remaining 58 secs RP/0/RSP0/CPU0:Apr 26 12:10:42.666 CEST: SSHD[67653]: ssh Cleanup: No open Channels to close RP/0/RSP0/CPU0:Apr 26 12:10:42.666 CEST: SSHD[67653]: [TID=2117] Closing connection to A.B.C.D RP/0/RSP0/CPU0:Apr 26 12:10:42.666 CEST: SSHD[67653]: [TID=2117] Inside ttylistcleanup FUNC RP/0/RSP0/CPU0:Apr 26 12:10:42.680 CEST: SSHD[1293]: Proces with pid: 2117 exited with waitpid exitstat=0x0 RP/0/RSP0/CPU0:Apr 26 12:10:42.680 CEST: SSHD[1293]: CLNT SES REL: Active Entries=2, Client PID=2117 RP/0/RSP0/CPU0:Apr 26 12:10:42.680 CEST: SSHD[1293]: Releasing client Session id: 22373,index=22 RP/0/RSP0/CPU0:Apr 26 12:10:42.680 CEST: SSHD[1293]: Not freeing first entry, freeing last entry RP/0/RSP0/CPU0:Apr 26 12:10:42.680 CEST: SSHD[1293]: Non-NULL Last History entry RP/0/RSP0/CPU0:Apr 26 12:10:42.680 CEST: SSHD[1293]: SIGCHLD: Active clients=1, session count=1 RP/0/RSP0/CPU0:Apr 26 12:10:42.680 CEST: SSHD[1293]: Exit status of the process pid 2117 : 0 RP/0/RSP0/CPU0:Apr 26 12:11:11.330 CEST: SSHD[67167]: Padlen = 6, Packlen = 12 RP/0/RSP0/CPU0:Apr 26 12:11:11.330 CEST: SSHD[67167]: ignore message received

From netshot.log: 2023-04-26 12:10:51,083 WARN [NetshotRunnerScheduler_Worker-1] CliScript: Unable to open an SSH connection to E.F.G.H:0. java.io.IOException: verify: false at onl.netfishers.netshot.device.access.Ssh.connect(Ssh.java:490) at onl.netfishers.netshot.device.script.CliScript.connectRun(CliScript.java:256) at onl.netfishers.netshot.device.script.CliScript.connectRun(CliScript.java:205) at onl.netfishers.netshot.work.tasks.TakeSnapshotTask.run(TakeSnapshotTask.java:212) at onl.netfishers.netshot.work.TaskJob.execute(TaskJob.java:96) at org.quartz.core.JobRunShell.run(JobRunShell.java:202) at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) Caused by: com.jcraft.jsch.JSchException: verify: false at com.jcraft.jsch.Session.connect(Session.java:340) at onl.netfishers.netshot.device.access.Ssh.connect(Ssh.java:477) ... 6 common frames omitted 2023-04-26 12:10:51,085 ERROR [NetshotRunnerScheduler_Worker-1] TakeSnapshotTask: Task 899. Error while taking the snapshot. java.io.IOException: Couldn't open either SSH or Telnet socket with the device. at onl.netfishers.netshot.device.script.CliScript.connectRun(CliScript.java:482) at onl.netfishers.netshot.device.script.CliScript.connectRun(CliScript.java:205) at onl.netfishers.netshot.work.tasks.TakeSnapshotTask.run(TakeSnapshotTask.java:212) at onl.netfishers.netshot.work.TaskJob.execute(TaskJob.java:96) at org.quartz.core.JobRunShell.run(JobRunShell.java:202)

File from debug comes empty !

SCadilhac commented 10 months ago

I've tested with quite some different XR versions on both NCS and ASR9k, with Netshot 0.19 (running on GraalVM GraalVM 17.0.8+9.1) and all worked. If the problem is still present, please provide the precise XR version, along with full logs (https://github.com/netfishers-onl/Netshot/wiki/Snapshot-troubleshooting).