Interestingly enough, someone once posted an issue that they have around slow key exchange for SSH, which then reminded me of this tweet I posted in 2017 here.
When you need to audit SFTP (or SSH, or even FTP) transactions, add the -vvv
option and this will provide you with further levels of verbosity in the output.
Below is an example with some dummy data (ie for the port, host, folders, username, folders, etc):
$ sftp -vvv -oPort=1033 admin@sftp_server
OpenSSH_7.6p1, LibreSSL 2.6.2
debug1: Reading configuration data /Users/Admin/.ssh/config
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 48: Applying options for *
debug2: ssh_connect_direct: needpriv 0
debug1: Connecting to sftp_server port 1033.
debug1: Connection established.
debug1: identity file /Users/Admin/.ssh/id_rsa type 0
debug1: key_load_public: No such file or directory
debug1: identity file /Users/Admin/.ssh/id_rsa-cert type -1
debug1: key_load_public: No such file or directory
debug1: identity file /Users/Admin/.ssh/id_dsa type -1
debug1: key_load_public: No such file or directory
debug1: identity file /Users/Admin/.ssh/id_dsa-cert type -1
debug1: key_load_public: No such file or directory
debug1: identity file /Users/Admin/.ssh/id_ecdsa type -1
debug1: key_load_public: No such file or directory
debug1: identity file /Users/Admin/.ssh/id_ecdsa-cert type -1
debug1: key_load_public: No such file or directory
debug1: identity file /Users/Admin/.ssh/id_ed25519 type -1
debug1: key_load_public: No such file or directory
debug1: identity file /Users/Admin/.ssh/id_ed25519-cert type -1
debug1: Local version string SSH-2.0-OpenSSH_7.6
debug1: Remote protocol version 2.0, remote software version SFTP_Server_Software
debug1: no match: SFTP_Server_Software
debug3: fd 6 is O_NONBLOCK
debug1: Authenticating to sftp_server:1033 as 'user'
debug3: put_host_port: [sftp_server]:1033
debug3: hostkeys_foreach: reading file "/Users/Admin/.ssh/known_hosts"
debug3: record_hostkey: found key type RSA in file /Users/Admin/.ssh/known_hosts:8
debug3: load_hostkeys: loaded 1 keys from [sftp_server]:1033
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,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha256,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
debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
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-group1-sha1,diffie-hellman-group14-sha1
debug2: host key algorithms: ssh-dss,ssh-rsa
debug2: ciphers ctos: aes256-ctr,aes256-cbc,aes192-ctr,aes192-cbc,aes128-ctr,aes128-cbc,3des-ctr,3des-cbc
debug2: ciphers stoc: aes256-ctr,aes256-cbc,aes192-ctr,aes192-cbc,aes128-ctr,aes128-cbc,3des-ctr,3des-cbc
debug2: MACs ctos: hmac-sha2-256,hmac-sha1
debug2: MACs stoc: hmac-sha2-256,hmac-sha1
debug2: compression ctos: none,zlib
debug2: compression stoc: none,zlib
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: hmac-sha2-256 compression: none
debug1: kex: client->server cipher: aes128-ctr MAC: hmac-sha2-256 compression: none
debug3: send packet: type 34
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(2048<8192<8192) sent
debug3: receive packet: type 31
debug1: got SSH2_MSG_KEX_DH_GEX_GROUP
debug2: bits set: 4092/8192
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:Up6KjbnEV4Hgfo75YM393QdQsK3Z0aTNBz0DoirrW+c
debug3: put_host_port: [127.0.0.1]:1033
debug3: put_host_port: [sftp_server]:1033
debug3: hostkeys_foreach: reading file "/Users/Admin/.ssh/known_hosts"
debug3: record_hostkey: found key type RSA in file /Users/Admin/.ssh/known_hosts:8
debug3: load_hostkeys: loaded 1 keys from [sftp_server]:1033
debug1: Host '[sftp_server]:1033' is known and matches the RSA host key.
debug1: Found key in /Users/Admin/.ssh/known_hosts:8
debug2: bits set: 4057/8192
debug3: send packet: type 21
debug2: set_newkeys: mode 1
debug1: rekey after 4197753996 blocks
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug3: receive packet: type 21
debug1: SSH2_MSG_NEWKEYS received
debug2: set_newkeys: mode 0
debug1: rekey after 4197853996 blocks
debug2: key: /Users/Admin/.ssh/id_rsa (0x7fabb9d13fg1)
debug2: key: /Users/Admin/.ssh/id_dsa (0x0)
debug2: key: /Users/Admin/.ssh/id_ecdsa (0x0)
debug2: key: /Users/Admin/.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: password,publickey
debug3: start over, passed a different list password,publickey
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 public key: RSA SHA256:Dp6PojkEV4Lbfo75YM024QdKsK2Z0aWPBz7DjiyyW+c /Users/Admin/.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 51
debug1: Authentications that can continue: password,publickey
debug1: Trying private key: /Users/Admin/.ssh/id_dsa
debug3: no such identity: /Users/Admin/.ssh/id_dsa: No such file or directory
debug1: Trying private key: /Users/Admin/.ssh/id_ecdsa
debug3: no such identity: /Users/Admin/.ssh/id_ecdsa: No such file or directory
debug1: Trying private key: /Users/Admin/.ssh/id_ed25519
debug3: no such identity: /Users/Admin/.ssh/id_ed25519: No such file or directory
debug2: we did not send a packet, disable method
debug3: authmethod_lookup password
debug3: remaining preferred: ,password
debug3: authmethod_is_enabled password
debug1: Next authentication method: password
user@sftp_server's password:
debug3: send packet: type 50
debug2: we sent a password packet, wait for reply
debug3: receive packet: type 52
debug1: Authentication succeeded (password).
Authenticated to sftp_server ([127.0.0.1]:1033).
debug2: fd 7 setting O_NONBLOCK
debug3: fd 8 is O_NONBLOCK
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug2: channel 0: send open
debug3: send packet: type 90
debug1: Entering interactive session.
debug1: pledge: network
debug3: receive packet: type 91
debug2: channel_input_open_confirmation: channel 0: callback start
debug2: fd 6 setting TCP_NODELAY
debug3: ssh_packet_set_tos: set IP_TOS 0x08
debug2: client_session2_setup: id 0
debug1: Sending environment.
debug3: Ignored env rvm_bin_path
debug3: Ignored env TERM_PROGRAM
debug3: Ignored env GEM_HOME
debug3: Ignored env SHELL
debug3: Ignored env TERM
debug3: Ignored env IRBRC
debug3: Ignored env TMPDIR
debug3: Ignored env Apple_PubSub_Socket_Render
debug3: Ignored env TERM_PROGRAM_VERSION
debug3: Ignored env MY_RUBY_HOME
debug3: Ignored env TERM_SESSION_ID
debug3: Ignored env USER
debug3: Ignored env _system_type
debug3: Ignored env rvm_path
debug3: Ignored env SSH_AUTH_SOCK
debug3: Ignored env rvm_prefix
debug3: Ignored env PATH
debug3: Ignored env PWD
debug1: Sending env LANG = en_CA.UTF-8
debug2: channel 0: request env confirm 0
debug3: send packet: type 98
debug3: Ignored env _system_arch
debug3: Ignored env XPC_FLAGS
debug3: Ignored env _system_version
debug3: Ignored env XPC_SERVICE_NAME
debug3: Ignored env rvm_version
debug3: Ignored env SHLVL
debug3: Ignored env HOME
debug3: Ignored env LOGNAME
debug3: Ignored env GEM_PATH
debug3: Ignored env DISPLAY
debug3: Ignored env RUBY_VERSION
debug3: Ignored env _system_name
debug3: Ignored env _
debug3: Ignored env __CF_USER_TEXT_ENCODING
debug1: Sending subsystem: sftp
debug2: channel 0: request subsystem confirm 1
debug3: send packet: type 98
debug2: channel_input_open_confirmation: channel 0: callback done
debug2: channel 0: open confirm rwindow 131072 rmax 32768
debug3: receive packet: type 99
debug2: channel_input_status_confirm: type 99 id 0
debug2: subsystem request accepted on channel 0
debug2: Remote version: 3
Connected to sftp_server.
debug3: Sent message fd 3 T:16 I:1
debug3: SSH_FXP_REALPATH . -> / size 0
sftp> dir
debug3: Sending SSH2_FXP_READDIR I:3
debug3: Received reply T:104 I:3
debug3: Received 9 SSH2_FXP_NAME responses
debug3: Sending SSH2_FXP_READDIR I:4
debug3: Received reply T:101 I:4
debug3: Received SSH2_FXP_STATUS 1
debug3: Sent message SSH2_FXP_CLOSE I:5
debug3: SSH2_FXP_STATUS 0
image.jpg sub1
sub2
sftp> debug2: client_check_window_change: changed
debug2: client_check_window_change: changed
debug3: receive packet: type 1
Received disconnect from 127.0.0.1 port 1033:10: Client connection idle time out.
Disconnected from 127.0.0.1 port 1033
As one goes line by line on a debug, one can start obtaining potential clues. Keeping note of the problem in the first is a good way to not be distracted by all the additional details of a verbose output.