sftp connection hungs, vvv mode did not helped...

[kashyap1983]

Hi all,

I am facing issue with sftp where i am making several connection to a remote server via automated process and some of them hangs
without any error message or code but rest are working ok..

out of 50 connections i make about 6-7 are stuck in hung state.

Sftp verbose mode also
have not given much useful information or i am not able to understand it thoroughly

I am using ssh key based authentication. But some simultaneously process going in hung state.
Can you please help me in digging out the issue.?
sftp -vvv logs are pasted below.

While process going in hung state:-
============================

Connecting to xxxx.server.com ...
Sun_SSH_1.1.4, SSH protocols 1.5/2.0, OpenSSL 0x0090704f
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: Rhosts Authentication disabled, originating port will not be trusted.
debug1: ssh_connect: needpriv 0
debug1: Connecting to xxxx.server.com [150.xxx.xxx.xxx] port 22.
debug1: Connection established.
debug3: Not a RSA1 key file /cdunix/appl/user/.ssh/id_rsa.
debug2: key_type_from_name: unknown key type '-----BEGIN'
debug3: key_read: no key found
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug2: key_type_from_name: unknown key type '-----END'
debug3: key_read: no key found
debug1: identity file /cdunix/appl/user/.ssh/id_rsa type 1
debug3: Not a RSA1 key file /cdunix/appl/user/.ssh/id_dsa.
debug2: key_type_from_name: unknown key type '-----BEGIN'
debug3: key_read: no key found
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug2: key_type_from_name: unknown key type '-----END'
debug3: key_read: no key found
debug1: identity file /cdunix/appl/user/.ssh/id_dsa type -1
debug1: Logging to host: xxxx.xxx.com
debug1: Local user: cduser Remote user: 700000035

This is the place where is hangs
=========================================================



While process successfully completed:-

Connecting to xxxx.xxx.com
Sun_SSH_1.1.4, SSH protocols 1.5/2.0, OpenSSL 0x0090704f
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: Rhosts Authentication disabled, originating port will not be trusted.
debug1: ssh_connect: needpriv 0
debug1: Connecting to xxxx.xxx.com[150.xxx.xxx.xx] port 22.
debug1: Connection established.
debug3: Not a RSA1 key file /cdunix/appl/user/.ssh/id_rsa.
debug2: key_type_from_name: unknown key type '-----BEGIN'
debug3: key_read: no key found
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug2: key_type_from_name: unknown key type '-----END'
debug3: key_read: no key found
debug1: identity file /cdunix/appl/user/.ssh/id_rsa type 1
debug3: Not a RSA1 key file /cdunix/appl/user/.ssh/id_dsa.
debug2: key_type_from_name: unknown key type '-----BEGIN'
debug3: key_read: no key found
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug2: key_type_from_name: unknown key type '-----END'
debug3: key_read: no key found
debug1: identity file /cdunix/appl/user/.ssh/id_dsa type -1
debug1: Logging to host: xxxx.xxx.com
debug1: Local user: cduser Remote user: 700000035
debug1: Remote protocol version 2.0, remote software version SecureLink SSH Server (Version 3.2.1.142)
debug1: no match: SecureLink SSH Server (Version 3.2.1.142)
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-Sun_SSH_1.1.4
debug1: use_engine is 'yes'
debug1: pkcs11 engine initialized, now setting it as default for RSA, DSA, and symmetric ciphers
debug1: pkcs11 engine initialization complete
debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
debug2: kex_parse_kexinit: aes128-ctr,aes128-cbc,arcfour,3des-cbc,blowfish-cbc,aes192-ctr,aes192-cbc,aes256-ctr,aes256-cbc
debug2: kex_parse_kexinit: aes128-ctr,aes128-cbc,arcfour,3des-cbc,blowfish-cbc,aes192-ctr,aes192-cbc,aes256-ctr,aes256-cbc
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib
debug2: kex_parse_kexinit: none,zlib
debug2: kex_parse_kexinit: i-default
debug2: kex_parse_kexinit: i-default
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug1: Failed to acquire GSS-API credentials for any mechanisms (No credentials were supplied, or the credentials were unavailable or inaccessible
Unknown code 0
)
debug1: SSH2_MSG_KEXINIT sent
debug3: kex_reset_dispatch -- should we dispatch_set(KEXINIT) here? 0 && !0
debug1: SSH2_MSG_KEXINIT received
debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
debug2: kex_parse_kexinit: aes128-ctr,aes128-cbc,arcfour,3des-cbc,blowfish-cbc,aes192-ctr,aes192-cbc,aes256-ctr,aes256-cbc
debug2: kex_parse_kexinit: aes128-ctr,aes128-cbc,arcfour,3des-cbc,blowfish-cbc,aes192-ctr,aes192-cbc,aes256-ctr,aes256-cbc
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib
debug2: kex_parse_kexinit: none,zlib
debug2: kex_parse_kexinit: i-default
debug2: kex_parse_kexinit: i-default
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: kex_parse_kexinit: diffie-hellman-group1-sha1,diffie-hellman-group14-sha1
debug2: kex_parse_kexinit: ssh-rsa
debug2: kex_parse_kexinit: aes128-cbc,arcfour256,aes192-ctr,twofish192-cbc,cast128-cbc,twofish256-cbc,aes128-ctr,twofish128-cbc,3des-cbc,blowfish-cbc,arcfour128,arcfour,aes256-cbc,aes256-ctr,aes192-cbc
debug2: kex_parse_kexinit: aes128-cbc,arcfour256,aes192-ctr,twofish192-cbc,cast128-cbc,twofish256-cbc,aes128-ctr,twofish128-cbc,3des-cbc,blowfish-cbc,arcfour128,arcfour,aes256-cbc,aes256-ctr,aes192-cbc
debug2: kex_parse_kexinit: hmac-sha1,hmac-md5-96,hmac-md5,hmac-sha1-96,hmac-ripemd160
debug2: kex_parse_kexinit: hmac-sha1,hmac-md5-96,hmac-md5,hmac-sha1-96,hmac-ripemd160
debug2: kex_parse_kexinit: none,zlib
debug2: kex_parse_kexinit: none,zlib
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: mac_init: found hmac-md5
debug1: kex: server->client aes128-ctr hmac-md5 none
debug2: mac_init: found hmac-md5
debug1: kex: client->server aes128-ctr hmac-md5 none
debug1: Peer sent proposed langtags, ctos:
debug1: Peer sent proposed langtags, stoc:
debug1: We proposed langtags, ctos: i-default
debug1: We proposed langtags, stoc: i-default
debug1: dh_gen_key: priv key bits set: 135/256
debug1: bits set: 1043/2048
debug1: sending SSH2_MSG_KEXDH_INIT
debug1: expecting SSH2_MSG_KEXDH_REPLY
debug3: check_host_in_hostfile: filename /cdunix/appl/user/.ssh/known_hosts
debug3: check_host_in_hostfile: match line 32
debug3: check_host_in_hostfile: filename /cdunix/appl/user/.ssh/known_hosts
debug3: check_host_in_hostfile: match line 32
debug1: Host 'xxxx.xxx.com' is known and matches the RSA host key.
debug1: Found key in /cdunix/appl/user/.ssh/known_hosts:32
debug1: bits set: 1050/2048
debug1: ssh_rsa_verify: signature correct
debug2: kex_derive_keys
debug3: kex_reset_dispatch -- should we dispatch_set(KEXINIT) here? 0 && !0
debug1: newkeys: mode 1
debug1: set_newkeys: setting new keys for 'out' mode
debug3: aes-128-ctr NID found
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug1: newkeys: mode 0
debug1: set_newkeys: setting new keys for 'in' mode
debug3: aes-128-ctr NID found
debug1: SSH2_MSG_NEWKEYS received
debug1: done: ssh_kex2.
debug1: send SSH2_MSG_SERVICE_REQUEST
debug2: service_accept: ssh-userauth
debug1: got SSH2_MSG_SERVICE_ACCEPT
debug3: input_userauth_banner
sftp.gatewaydebug1: Authentications that can continue: publickey,password
debug3: start over, passed a different list publickey,password
debug3: preferred gssapi-keyex,gssapi-with-mic,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: Trying public key: /cdunix/appl/user/.ssh/id_rsa
debug3: send_pubkey_test
debug2: we sent a publickey packet, wait for reply
debug1: Server accepts key: pkalg ssh-rsa blen 149 lastkey 6f1f8 hint 0
debug2: input_userauth_pk_ok: fp f8:d2:f2:e0:e9:a1:a5:92:a9:a4:cb:c5:c8:0d:ed:ff
debug3: sign_and_send_pubkey
debug1: read PEM private key done: type RSA
debug1: Authentication succeeded (publickey)
debug1: fd 6 setting O_NONBLOCK
debug2: fd 7 is O_NONBLOCK
debug1: fd 8 setting O_NONBLOCK
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug1: send channel open 0
debug1: Entering interactive session.
debug2: callback start
debug1: ssh_session2_setup: id 0
debug1: channel request 0: env
debug2: Sent request for environment variable LC_CTYPE=en_US.ISO8859-1
debug1: channel request 0: env
debug2: Sent request for environment variable LC_COLLATE=en_US.ISO8859-1
debug1: channel request 0: env
debug2: Sent request for environment variable LC_TIME=en_US.ISO8859-1
debug1: channel request 0: env
debug2: Sent request for environment variable LC_NUMERIC=en_US.ISO8859-1
debug1: channel request 0: env
debug2: Sent request for environment variable LC_MONETARY=en_US.ISO8859-1
debug1: channel request 0: env
debug2: Sent request for environment variable LC_MESSAGES=C
debug1: Sending subsystem: sftp
debug1: channel request 0: subsystem
debug2: callback done
debug1: channel 0: open confirm rwindow 0 rmax 34000
debug2: channel 0: rcvd adjust 131072
debug2: Remote version: 3
debug3: Sent message fd 6 T:16 I:1
debug3: SSH_FXP_REALPATH . -> /home/700000035
sftp> put /push/snd/OUT100000157152.INT.sch /home/700000035/tovan/OUT100000157152.INT.wrk
debug3: Looking up /cust01/dellinvs/edi_prod/push/snd/OUT100000157152.INT.sch
debug3: Sent message fd 6 T:17 I:2
debug3: Received stat reply T:101 I:2
debug1: Couldn't stat remote file: No such file or directory
Uploading /push/snd/OUT100000157152.INT.sch to /home/700000035/tovan/OUT100000157152.INT.wrk
debug3: Sent message SSH2_FXP_OPEN I:3 P:/home/700000035/tovan/OUT100000157152.INT.wrk
debug3: Sent message SSH2_FXP_WRITE I:4 O:0 S:564
debug3: SSH2_FXP_STATUS 0
debug3: In write loop, ack for 4 564 bytes at 0
debug3: Sent message SSH2_FXP_CLOSE I:4
debug3: SSH2_FXP_STATUS 0
sftp> rename /home/700000035/tovan/OUT100000157152.INT.wrk /home/700000035/tovan/OUT100000157152.INT
debug3: Sent message SSH2_FXP_RENAME "/home/700000035/tovan/OUT100000157152.INT.wrk" -> "/home/700000035/tovan/OUT100000157152.INT"
debug3: SSH2_FXP_STATUS 0
sftp> quit
debug1: channel 0: read<=0 rfd 6 len 0
debug1: channel 0: read failed
debug1: channel 0: close_read
debug1: channel 0: input open -> drain
debug1: channel 0: ibuf empty
debug1: channel 0: send eof
debug1: channel 0: input drain -> closed
debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
debug1: channel 0: rcvd close
debug1: channel 0: output open -> drain
debug3: channel 0: will not send data after close
debug1: channel 0: obuf empty
debug1: channel 0: close_write
debug1: channel 0: output drain -> closed
debug1: channel 0: almost dead
debug1: channel 0: gc: notify user
debug1: channel 0: gc: user detached
debug1: channel 0: send close
debug1: channel 0: is dead
debug1: channel 0: garbage collecting
debug1: channel_free: channel 0: client-session, nchannels 1
debug3: channel_free: status: The following connections are open:
#0 client-session (t4 r0 i3/0 o3/0 fd -1/-1)

debug3: channel_close_fds: channel 0: r -1 w -1 e 8
debug1: fd 0 clearing O_NONBLOCK
debug2: fd 1 is not O_NONBLOCK
debug1: fd 2 clearing O_NONBLOCK
debug1: Transferred: stdin 0, stdout 0, stderr 0 bytes in 1.9 seconds
debug1: Bytes per second: stdin 0.0, stdout 0.0, stderr 0.0
debug1: Exit status 0
ssh_exchange_identification: read: Connection timed out
debug1: Calling cleanup 0x34d88(0x0)
Connection closed
=======================================================================

 

[sbrews]

What is your MaxSessions set to in your sshd_config file? If not defined, its default value is 10. You mention that you do 50 connections - is that 50 sequential or 50 concurrent? If concurrent, then you likely have the MaxSessions value defined at X and you are hitting that limit.

On the other hand, if these are sequential and MaxSessions is not defined, you may still be hitting its upper (default) limit if previous sftp connections have not finished/terminated before you kick off a new one.