search

hierynomus / sshj

ssh, scp and sftp for java
Apache License 2.0
2.51k stars 601 forks source link

why sshj clinet cost too long time to connect? #388

Closed scuhzq closed 6 years ago

scuhzq commented 6 years ago

long time1 = System.currentTimeMillis(); ssh = new SSHClient(); ssh.loadKnownHosts(); KeyProvider keyProvider = ssh.loadKeys("/Users/hzq/.ssh/id_rsa", "123".toCharArray()); ssh.connect("192.168.0.44", 22); ssh.authPublickey("zhanqi", keyProvider); long time2 = System.currentTimeMillis(); System.out.println(time2 - time1);

log is 4602ms this usage is not suittable?

and I use jsch long time1 = System.currentTimeMillis(); JSch jsch = new JSch(); jsch.addIdentity("/Users/hzq/.ssh/id_rsa", "xxx".getBytes()); session =jsch.getSession("zhanqi", "xx", xx); java.util.Properties config = new java.util.Properties(); config.put("StrictHostKeyChecking", "no"); session.setConfig(config); session.connect();

    long time2 = System.currentTimeMillis();
    System.out.println(time2 - time1);

log is 2079ms

hierynomus commented 6 years ago

Which version? What is the trace logging? Are you running in a low entropy system such as a vm?

scuhzq commented 6 years ago

thanks for you reply. the version is compile group: 'com.hierynomus', name: 'sshj', version: '0.23.0' I am running at local, and connect remote server(when I use ssh in iterm，is very fast)。 the log is ...

16:00:59.142 [main] INFO net.schmizz.sshj.transport.TransportImpl - Client identity string: SSH-2.0-SSHJ_0.23.0 16:00:59.152 [main] INFO net.schmizz.sshj.transport.TransportImpl - Server identity string: SSH-2.0-OpenSSH_5.3 16:00:59.152 [main] DEBUG net.schmizz.concurrent.Promise - Setting <> to null 16:00:59.152 [main] DEBUG net.schmizz.sshj.transport.KeyExchanger - Sending SSH_MSG_KEXINIT 16:00:59.157 [main] DEBUG net.schmizz.concurrent.Promise - Setting <> to SOME 16:00:59.158 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Received SSH_MSG_KEXINIT 16:00:59.159 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <> 16:00:59.160 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Negotiated algorithms: [ kex=diffie-hellman-group-exchange-sha256; sig=ssh-rsa; c2sCipher=aes128-cbc; s2cCipher=aes128-cbc; c2sMAC=hmac-sha1; s2cMAC=hmac-sha1; c2sComp=none; s2cComp=none ] 16:00:59.170 [reader] DEBUG net.schmizz.sshj.transport.kex.DHGexSHA256 - Sending KEX_DH_GEX_REQUEST 16:00:59.212 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Received kex followup data 16:00:59.212 [reader] DEBUG net.schmizz.sshj.transport.kex.DHGexSHA256 - Got message KEXDH_31 16:00:59.212 [reader] DEBUG net.schmizz.sshj.transport.kex.DHGexSHA256 - Received server p bitlength 2048 16:00:59.281 [reader] DEBUG net.schmizz.sshj.transport.kex.DHGexSHA256 - Sending KEX_DH_GEX_INIT 16:00:59.290 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Received kex followup data 16:00:59.291 [reader] DEBUG net.schmizz.sshj.transport.kex.DHGexSHA256 - Got message KEX_DH_GEX_REPLY 16:00:59.372 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Trying to verify host key with net.schmizz.sshj.transport.verification.OpenSSHKnownHosts@2101513b 16:00:59.379 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Sending SSH_MSG_NEWKEYS 16:00:59.380 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Received SSH_MSG_NEWKEYS 16:00:59.382 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <> to null 16:00:59.382 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <> to SOME 16:00:59.382 [main] DEBUG net.schmizz.sshj.SSHClient - Key exchange took 0.23 seconds 16:00:59.385 [main] DEBUG net.schmizz.concurrent.Promise - Setting <> to null 16:00:59.385 [main] DEBUG net.schmizz.sshj.transport.TransportImpl - Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth 16:00:59.386 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <> 16:00:59.432 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <> to SOME 16:00:59.433 [main] DEBUG net.schmizz.sshj.transport.TransportImpl - Setting active service to ssh-userauth 16:00:59.433 [main] DEBUG net.schmizz.concurrent.Promise - Setting <> to null 16:00:59.434 [main] DEBUG net.schmizz.sshj.userauth.UserAuthImpl - Trying publickey auth... 16:00:59.434 [main] DEBUG net.schmizz.sshj.userauth.method.AuthPublickey - Attempting authentication using PKCS8KeyFile{resource=[PrivateKeyFileResource] /Users/hzq/.ssh/id_rsa} 16:00:59.435 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <> 16:00:59.444 [reader] DEBUG net.schmizz.sshj.userauth.UserAuthImpl - Asking publickey method to handle USERAUTH_60 packet 16:00:59.444 [reader] DEBUG net.schmizz.sshj.userauth.method.AuthPublickey - Key acceptable, sending signed request 16:00:59.444 [reader] DEBUG net.schmizz.sshj.userauth.method.AuthPublickey - Attempting authentication using PKCS8KeyFile{resource=[PrivateKeyFileResource] /Users/hzq/.ssh/id_rsa} 16:01:00.380 [reader] DEBUG net.schmizz.sshj.transport.TransportImpl - Setting active service to ssh-connection 16:01:00.380 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <> to true 16:01:00.381 [main] DEBUG net.schmizz.sshj.userauth.UserAuthImpl - publickey auth successful 3960

scuhzq commented 6 years ago

I found session.exec if very fast. but load is slow...

long time1 = System.currentTimeMillis(); ssh = new SSHClient(); long time2 = System.currentTimeMillis(); System.out.println(time2 - time1);// 2626 ssh.loadKnownHosts(); long time3 = System.currentTimeMillis(); System.out.println(time3 - time2);//594 KeyProvider keyProvider = ssh.loadKeys("/Users/hzq/.ssh/id_rsa", "xxx".toCharArray()); ssh.connect(ip, port); ssh.authPublickey("zhanqi", keyProvider); long time4 = System.currentTimeMillis(); System.out.println(time4 - time3);//594

scuhzq commented 6 years ago

16:04:40.496 [main] INFO net.schmizz.sshj.transport.random.BouncyCastleRandom - Generating random seed from SecureRandom. 16:04:40.505 [main] DEBUG net.schmizz.sshj.transport.random.BouncyCastleRandom - Creating random seed took 1 ms 16:04:40.773 [main] WARN net.schmizz.sshj.DefaultConfig - Illegal key size 16:04:40.773 [main] WARN net.schmizz.sshj.DefaultConfig - Illegal key size 16:04:40.774 [main] WARN net.schmizz.sshj.DefaultConfig - Illegal key size 16:04:40.775 [main] WARN net.schmizz.sshj.DefaultConfig - Illegal key size 16:04:40.780 [main] WARN net.schmizz.sshj.DefaultConfig - Illegal key size 16:04:40.845 [main] WARN net.schmizz.sshj.DefaultConfig - Illegal key size 16:04:40.845 [main] WARN net.schmizz.sshj.DefaultConfig - Illegal key size 16:04:40.845 [main] WARN net.schmizz.sshj.DefaultConfig - Illegal key size 16:04:40.845 [main] WARN net.schmizz.sshj.DefaultConfig - Illegal key size 16:04:40.877 [main] WARN net.schmizz.sshj.DefaultConfig - Illegal key size 16:04:40.878 [main] WARN net.schmizz.sshj.DefaultConfig - Illegal key size 16:04:40.880 [main] WARN net.schmizz.sshj.DefaultConfig - Illegal key size 16:04:40.880 [main] WARN net.schmizz.sshj.DefaultConfig - Illegal key size 16:04:40.881 [main] WARN net.schmizz.sshj.DefaultConfig - Illegal key size 16:04:40.885 [main] WARN net.schmizz.sshj.DefaultConfig - Illegal key size or default parameters 16:04:40.885 [main] WARN net.schmizz.sshj.DefaultConfig - Disabling high-strength ciphers: cipher strengths apparently limited by JCE policy 16:04:40.885 [main] DEBUG net.schmizz.sshj.DefaultConfig - Available cipher factories: [aes128-cbc, aes128-ctr, blowfish-cbc, cast128-cbc, cast128-ctr, idea-cbc, idea-ctr, serpent128-cbc, serpent128-ctr, 3des-cbc, 3des-ctr, twofish128-cbc, twofish128-ctr, arcfour, arcfour128] 2626 // this is the ssh = new SSHClient(); cost time

hierynomus commented 6 years ago

Initializing a new DefaultConfig takes time as it builds up all the factories. The trick is that you can reuse the config across different SSHClients.

Does this answer your question?

hierynomus commented 6 years ago

@scuhzq Did that answer your question?

scuhzq commented 6 years ago

I init a sshClient before executing commands, so the program is not sensitive to the Initializing process.