[SOLVED] slow ssh log-in

Problem: Slow SSH log-in

Fractal is getting more and more troublesome recently... It has a hug lap for ssh and also su . It took me a while to debug. In the end, my labmate, Aravind, found the culprit -- log file explosion. Here's some symptons observed and the final solution offered by Aravind. :)

1. use "vvv" mode for ssh to show error information.

$ssh -vvv username@fractal.mit.edu
OpenSSH_7.2p2, LibreSSL 2.4.1
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 20: Applying options for *
debug2: resolving "fractal.mit.edu" port 22
debug2: ssh_connect_direct: needpriv 0
debug1: Connecting to fractal.mit.edu [18.53.0.111] port 22.
debug1: Connection established.
debug1: identity file /Users/leleslx/.ssh/id_rsa type 1
debug1: key_load_public: No such file or directory
debug1: identity file /Users/leleslx/.ssh/id_rsa-cert type -1
debug1: key_load_public: No such file or directory
debug1: identity file /Users/leleslx/.ssh/id_dsa type -1
debug1: key_load_public: No such file or directory
debug1: identity file /Users/leleslx/.ssh/id_dsa-cert type -1
debug1: key_load_public: No such file or directory
debug1: identity file /Users/leleslx/.ssh/id_ecdsa type -1
debug1: key_load_public: No such file or directory
debug1: identity file /Users/leleslx/.ssh/id_ecdsa-cert type -1
debug1: key_load_public: No such file or directory
debug1: identity file /Users/leleslx/.ssh/id_ed25519 type -1
debug1: key_load_public: No such file or directory
debug1: identity file /Users/leleslx/.ssh/id_ed25519-cert type -1
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_7.2
debug1: Remote protocol version 2.0, remote software version OpenSSH_5.3
debug1: match: OpenSSH_5.3 pat OpenSSH_5* compat 0x0c000000
debug2: fd 3 setting O_NONBLOCK
debug1: Authenticating to fractal.mit.edu:22 as 'leleslx'
debug3: hostkeys_foreach: reading file "/Users/leleslx/.ssh/known_hosts"
debug3: record_hostkey: found key type RSA in file /Users/leleslx/.ssh/known_hosts:5
debug3: load_hostkeys: loaded 1 keys from fractal.mit.edu
debug3: order_hostkeyalgs: prefer hostkeyalgs: ssh-rsa-cert-v01@openssh.com,rsa-sha2-512,rsa-sha2-256,ssh-rsa
debug3: send packet: type 20
debug1: SSH2_MSG_KEXINIT sent
debug3: receive packet: type 20
debug1: SSH2_MSG_KEXINIT received
debug2: local client KEXINIT proposal
debug2: KEX algorithms: curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,ext-info-c
debug2: host key algorithms: ssh-rsa-cert-v01@openssh.com,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-ed25519
debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,3des-cbc
debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,3des-cbc
debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: compression ctos: none,zlib@openssh.com,zlib
debug2: compression stoc: none,zlib@openssh.com,zlib
debug2: languages ctos: 
debug2: languages stoc: 
debug2: first_kex_follows 0 
debug2: reserved 0 
debug2: peer server KEXINIT proposal
debug2:
 KEX algorithms: 
diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: host key algorithms: ssh-rsa,ssh-dss
debug2:
 ciphers ctos: 
aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
debug2:
 ciphers stoc: 
aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
debug2: MACs ctos: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: MACs stoc: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: compression ctos: none,zlib@openssh.com
debug2: compression stoc: none,zlib@openssh.com
debug2: languages ctos: 
debug2: languages stoc: 
debug2: first_kex_follows 0 
debug2: reserved 0 
debug1: kex: algorithm: diffie-hellman-group-exchange-sha256
debug1: kex: host key algorithm: ssh-rsa
debug1: kex: server->client cipher: aes128-ctr MAC: umac-64@openssh.com compression: none
debug1: kex: client->server cipher: aes128-ctr MAC: umac-64@openssh.com compression: none
debug3: send packet: type 34
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(2048<3072<8192) sent
debug3: receive packet: type 31
debug1: got SSH2_MSG_KEX_DH_GEX_GROUP
debug2: bits set: 1517/3072
debug3: send packet: type 32
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug3: receive packet: type 33
debug1: got SSH2_MSG_KEX_DH_GEX_REPLY
debug1: Server host key: ssh-rsa SHA256:uBZfZxslLA4ck9fpckjUju27pN97ijtTKxSL+uubmSE
debug3: hostkeys_foreach: reading file "/Users/leleslx/.ssh/known_hosts"
debug3: record_hostkey: found key type RSA in file /Users/leleslx/.ssh/known_hosts:5
debug3: load_hostkeys: loaded 1 keys from fractal.mit.edu
debug3: hostkeys_foreach: reading file "/Users/leleslx/.ssh/known_hosts"
debug3: record_hostkey: found key type RSA in file /Users/leleslx/.ssh/known_hosts:18
debug3: load_hostkeys: loaded 1 keys from 18.53.0.111
debug1: Host 'fractal.mit.edu' is known and matches the RSA host key.
debug1: Found key in /Users/leleslx/.ssh/known_hosts:5
debug2: bits set: 1548/3072
debug3: send packet: type 21
debug2: set_newkeys: mode 1
debug1: rekey after 4294967296 blocks
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug3: receive packet: type 21
debug2: set_newkeys: mode 0
debug1: rekey after 4294967296 blocks
debug1: SSH2_MSG_NEWKEYS received
debug2: key: /Users/leleslx/.ssh/id_rsa (0x7fda8c700000)
debug2: key: /Users/leleslx/.ssh/id_dsa (0x0)
debug2: key: /Users/leleslx/.ssh/id_ecdsa (0x0)
debug2: key: /Users/leleslx/.ssh/id_ed25519 (0x0)
debug3: send packet: type 5
debug3: receive packet: type 6
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug3: send packet: type 50
debug3: receive packet: type 51
debug1: Authentications that can continue: publickey,gssapi-keyex,gssapi-with-mic,password,keyboard-interactive,hostbased
debug3: start over, passed a different list publickey,gssapi-keyex,gssapi-with-mic,password,keyboard-interactive,hostbased
debug3: preferred publickey,keyboard-interactive,password
debug3: authmethod_lookup publickey
debug3: remaining preferred: keyboard-interactive,password
debug3: authmethod_is_enabled publickey
debug1: Next authentication method: publickey
debug1: Offering RSA public key: /Users/leleslx/.ssh/id_rsa
debug3: send_pubkey_test
debug3: send packet: type 50
debug2: we sent a publickey packet, wait for reply
debug3: receive packet: type 60
debug1: Server accepts key: pkalg ssh-rsa blen 279
debug2: input_userauth_pk_ok: fp SHA256:v9xPHvCu/p1chlnt9zbt0KnSDfC8MGDPIT5ZiinR+7c
debug3: sign_and_send_pubkey: RSA SHA256:v9xPHvCu/p1chlnt9zbt0KnSDfC8MGDPIT5ZiinR+7c
debug2: storing passphrase in keychain
debug3: Search for existing item with query: {
    acct = "/Users/leleslx/.ssh/id_rsa";
    agrp = "com.apple.ssh.passphrases";
    class = genp;
    labl = "SSH: /Users/leleslx/.ssh/id_rsa";
    nleg = 1;
    "r_Ref" = 1;
    svce = OpenSSH;
}
debug3: Item already exists in the keychain, updating.
debug3: send packet: type 50
debug3: receive packet: type 52
debug1: Authentication succeeded (publickey).
Authenticated to fractal.mit.edu ([18.53.0.111]:22).
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug2: channel 0: send open
debug3: send packet: type 90
debug1: Requesting no-more-sessions@openssh.com
debug3: send packet: type 80
debug1: Entering interactive session.
debug1: pledge: network
debug3: receive packet: type 91
debug2: callback start
debug2: fd 3 setting TCP_NODELAY
debug3: ssh_packet_set_tos: set IP_TOS 0x10
debug2: client_session2_setup: id 0
debug2: channel 0: request pty-req confirm 1
debug3: send packet: type 98
debug1: Sending environment.
debug3: Ignored env TERM_PROGRAM
debug3: Ignored env SHELL
debug3: Ignored env TERM
debug3: Ignored env TMPDIR
debug3: Ignored env Apple_PubSub_Socket_Render
debug3: Ignored env TERM_PROGRAM_VERSION
debug3: Ignored env TERM_SESSION_ID
debug3: Ignored env USER
debug3: Ignored env SSH_AUTH_SOCK
debug3: Ignored env __CF_USER_TEXT_ENCODING
debug3: Ignored env PATH
debug3: Ignored env PWD
debug1: Sending env LANG = en_US.UTF-8
debug2: channel 0: request env confirm 0
debug3: send packet: type 98
debug3: Ignored env XPC_FLAGS
debug3: Ignored env XPC_SERVICE_NAME
debug3: Ignored env SHLVL
debug3: Ignored env HOME
debug3: Ignored env LOGNAME
debug3: Ignored env DISPLAY
debug3: Ignored env _
debug2: channel 0: request shell confirm 1
debug3: send packet: type 98
debug2: callback done
debug2: channel 0: open confirm rwindow 0 rmax 32768
debug3: receive packet: type 99
debug2: channel_input_status_confirm: type 99 id 0
debug2: PTY allocation request accepted on channel 0
debug2: channel 0: rcvd adjust 2097152
debug3: receive packet: type 99
debug2: channel_input_status_confirm: type 99 id 0
debug2: shell request accepted on channel 0
Last login: Sat Nov 26 16:15:52 2016 from dhcp-18-189-17-183.dyn.mit.edu
Rocks 6.1 (Emerald Boa)
Profile built 01:19 30-Apr-2013
Kickstarted 22:03 29-Apr-2013

It stuck at "debug1: pledge: network" for 45 seconds!! Meanwhile, pinging fractal works perfectly well.

$ping fractal.mit.eduPING fractal.mit.edu (18.53.0.111): 56 data bytes
64 bytes from 18.53.0.111: icmp_seq=0 ttl=61 time=1.594 ms
64 bytes from 18.53.0.111: icmp_seq=1 ttl=61 time=2.172 ms
64 bytes from 18.53.0.111: icmp_seq=2 ttl=61 time=1.656 ms

Solution:

Aravind solved it...

I noticed that I also had lots of lag in just su-ing to root, so I thought it wasn’t just a SSH issue. So, I checked out the /var filesystem to look at the logs. But nothing is being logged right now because the /var filesystem is 100% full. Usually that’s because the logfiles become too big, but this time the culprit was the /var/www/html/tripwire folder. Apparently, tripwire is some rocks service that runs in the background and logs any changes to system files. I removed most of the older log files (from 2013, 2014) and now /var has some free space left (300 MB or so). Since logging is now active, all your ssh logins should also become faster.

Follow up

I also checked the logfile. Most of the logfile is html, which should be compressible. So I tarball them into tar.gz file.

root# tar cvfz 2015.tar.gz *-2015

root# tar cvfz 2016-first-hafl.tar.gz Jan* ...

the compressed files are only ~300 MB large. So now /var has 3.9G free space. Should be enough for a while.

Lixin Sun :

Atomic simulation for energy solutions

[SOLVED] slow ssh log-in

Solution:

Follow up

Filter By

Contact

Blog posts by month