SFTP timeout but SSH works fine

Question

I am unable to sftp (or scp) into my server setup but am able to ssh just fine. I am using key authentication for both.

When I sftp it just hangs forever and doesn't give me the sftp prompt.

Here is the output from my verbose sftp run.

$ sftp -vvv dev@server
OpenSSH_5.9p1 Debian-5ubuntu1, OpenSSL 1.0.1 14 Mar 2012
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 19: Applying options for *
debug2: ssh_connect: needpriv 0
debug1: Connecting to server [ipaddress] port 22.
debug1: Connection established.
debug3: Incorrect RSA1 identifier
debug3: Could not load "/home/vagrant/.ssh/id_rsa" as a RSA1 public key
debug1: identity file /home/vagrant/.ssh/id_rsa type 1
debug1: Checking blacklist file /usr/share/ssh/blacklist.RSA-2048
debug1: Checking blacklist file /etc/ssh/blacklist.RSA-2048
debug1: identity file /home/vagrant/.ssh/id_rsa-cert type -1
debug1: identity file /home/vagrant/.ssh/id_dsa type -1
debug1: identity file /home/vagrant/.ssh/id_dsa-cert type -1
debug1: identity file /home/vagrant/.ssh/id_ecdsa type -1
debug1: identity file /home/vagrant/.ssh/id_ecdsa-cert type -1
debug1: Remote protocol version 2.0, remote software version OpenSSH_5.9p1 Debian-5ubuntu1.4
debug1: match: OpenSSH_5.9p1 Debian-5ubuntu1.4 pat OpenSSH*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_5.9p1 Debian-5ubuntu1
debug2: fd 3 setting O_NONBLOCK
debug3: load_hostkeys: loading entries for host "server" from file "/home/vagrant/.ssh/known_hosts"
debug3: load_hostkeys: found key type ECDSA in file /home/vagrant/.ssh/known_hosts:42
debug3: load_hostkeys: loaded 1 keys
debug3: order_hostkeyalgs: prefer hostkeyalgs: [email protected],[email protected],[email protected],ecdsa-sha2-nistp256
,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug2: kex_parse_kexinit: ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffi
e-hellman-group1-sha1
debug2: kex_parse_kexinit: [email protected],[email protected],[email protected],ecdsa-sha2-nistp256,ecdsa-sha2-nistp384
,ecdsa-sha2-nistp521,[email protected],[email protected],[email protected],[email protected],ssh-rsa,ssh-dss
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,[email protected]
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,[email protected]
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,[email protected],hmac-sha2-256,hmac-sha2-256-96,hmac-sha2-512,hmac-sha2-512-96,hmac-ripemd160,[email protected],hmac-sha1-96,hmac-m
d5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,[email protected],hmac-sha2-256,hmac-sha2-256-96,hmac-sha2-512,hmac-sha2-512-96,hmac-ripemd160,[email protected],hmac-sha1-96,hmac-m
d5-96
debug2: kex_parse_kexinit: none,[email protected],zlib
debug2: kex_parse_kexinit: none,[email protected],zlib
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: kex_parse_kexinit: ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffi
e-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,[email protected]
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,[email protected]
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,[email protected],hmac-sha2-256,hmac-sha2-256-96,hmac-sha2-512,hmac-sha2-512-96,hmac-ripemd160,[email protected],hmac-sha1-96,hmac-m
d5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,[email protected],hmac-sha2-256,hmac-sha2-256-96,hmac-sha2-512,hmac-sha2-512-96,hmac-ripemd160,[email protected],hmac-sha1-96,hmac-m
d5-96
debug2: kex_parse_kexinit: none,[email protected]
debug2: kex_parse_kexinit: none,[email protected]
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: mac_setup: found hmac-md5
debug1: kex: server->client aes128-ctr hmac-md5 none
debug2: mac_setup: found hmac-md5
debug1: kex: client->server aes128-ctr hmac-md5 none
debug1: sending SSH2_MSG_KEX_ECDH_INIT
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug1: Server host key: ECDSA fd:e1:ab:e1:03:4d:1e:80:ba:76:4e:4a:8a:57:e1:d6
debug3: load_hostkeys: loading entries for host "server" from file "/home/vagrant/.ssh/known_hosts"
debug3: load_hostkeys: found key type ECDSA in file /home/vagrant/.ssh/known_hosts:42
debug3: load_hostkeys: loaded 1 keys
debug3: load_hostkeys: loading entries for host "ipaddress" from file "/home/vagrant/.ssh/known_hosts"
debug3: load_hostkeys: found key type ECDSA in file /home/vagrant/.ssh/known_hosts:43
debug3: load_hostkeys: loaded 1 keys
debug1: Host 'server' is known and matches the ECDSA host key.
debug1: Found key in /home/vagrant/.ssh/known_hosts:42
debug1: ssh_ecdsa_verify: signature correct
debug2: kex_derive_keys
debug2: set_newkeys: mode 1
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug2: set_newkeys: mode 0
debug1: SSH2_MSG_NEWKEYS received
debug1: Roaming not allowed by server
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug2: key: /home/vagrant/.ssh/id_rsa (0xb7954db8)
debug2: key: /home/vagrant/.ssh/id_dsa ((nil))
debug2: key: /home/vagrant/.ssh/id_ecdsa ((nil))
debug1: 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: Offering RSA public key: /home/vagrant/.ssh/id_rsa
debug3: send_pubkey_test
debug2: we sent a publickey packet, wait for reply
debug1: Server accepts key: pkalg ssh-rsa blen 279
debug2: input_userauth_pk_ok: fp c6:c6:df:44:89:bf:1e:da:fe:89:d7:3c:36:69:ef:94
debug3: sign_and_send_pubkey: RSA c6:c6:df:44:89:bf:1e:da:fe:89:d7:3c:36:69:ef:94
debug1: read PEM private key done: type RSA
debug1: Authentication succeeded (publickey).
Authenticated to server ([ipaddress]:22).
debug2: fd 4 setting O_NONBLOCK
debug3: fd 5 is O_NONBLOCK
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug2: channel 0: send open
debug1: Requesting [email protected]
debug1: Entering interactive session.
debug1: Remote: Forced command.
debug1: Remote: Forced command.
debug2: callback start
debug2: client_session2_setup: id 0
debug2: fd 3 setting TCP_NODELAY
debug1: Sending environment.
debug3: Ignored env TMUX_GIT_LASTREPO
debug3: Ignored env TERM
debug3: Ignored env SHELL
debug3: Ignored env SSH_CLIENT
debug3: Ignored env SSH_TTY
debug1: Sending env LC_ALL = en_US
debug2: channel 0: request env confirm 0
debug3: Ignored env USER
debug3: Ignored env LS_COLORS
debug3: Ignored env TODOTXT_DEFAULT_ACTION
debug3: Ignored env TMUX
debug3: Ignored env PATH
debug3: Ignored env MAIL
debug3: Ignored env PWD
debug3: Ignored env EDITOR
debug1: Sending env LANG = en_US
debug2: channel 0: request env confirm 0
debug3: Ignored env NODE_PATH
debug3: Ignored env TMUX_PANE
debug3: Ignored env SHLVL
debug3: Ignored env HOME
debug3: Ignored env GOROOT
debug3: Ignored env LOGNAME
debug3: Ignored env SSH_CONNECTION
debug3: Ignored env LESSOPEN
debug3: Ignored env GOPATH
debug3: Ignored env LESSCLOSE
debug3: Ignored env _
debug1: Sending subsystem: sftp
debug2: channel 0: request subsystem confirm 1
debug2: callback done
debug2: channel 0: open confirm rwindow 0 rmax 32768
debug2: channel 0: rcvd adjust 2097152
debug2: channel_input_status_confirm: type 99 id 0
debug2: subsystem request accepted on channel 0
debug2: client_check_window_change: changed
debug2: client_check_window_change: changed
debug2: client_check_window_change: changed
^Cdebug1: channel 0: free: client-session, nchannels 1
debug3: channel 0: status: The following connections are open:
  #0 client-session (t4 r0 i0/0 o0/0 fd 4/5 cc -1)

debug1: fd 0 clearing O_NONBLOCK
debug3: fd 1 is not O_NONBLOCK
debug1: Killed by signal 15.

And here is our sshd_config

Port 22
Port 2222

AcceptEnv LANG LC_*
ChallengeResponseAuthentication no
HostKey /etc/ssh/ssh_host_rsa_key
HostKey /etc/ssh/ssh_host_dsa_key
HostKey /etc/ssh/ssh_host_ecdsa_key
HostbasedAuthentication no
IgnoreRhosts yes
KeyRegenerationInterval 3600
LogLevel INFO
LoginGraceTime 120
PermitEmptyPasswords no
PermitRootLogin no
PrintLastLog yes
PrintMotd no
Protocol 2
PubkeyAuthentication yes
RSAAuthentication yes
RhostsRSAAuthentication no
ServerKeyBits 768
StrictModes yes
Subsystem sftp /usr/lib/openssh/sftp-server
SyslogFacility AUTH
TCPKeepAlive yes
UsePAM yes
UsePrivilegeSeparation yes
X11DisplayOffset 10
X11Forwarding yes

The subsystem is being sent but still am not getting any prompt...any ideas?

EDIT

---

Everything works just fine when I add

Forcecommand inetrnal-sftp

But obviously this breaks regular ssh for me.

---

Solution 1

Okay after much digging we discovered that the problem was how our ssh keys were being added to our server.

There was a command being set from the key itself preventing us from getting to the sftp prompt, Thanks to everyone who attempted to help!

command=/bin/bash ssh-rsa ...

Solution 2

As per my comment, I replicated your setup and it works flawlessly in OpenSSH_6.0p1.

I diffed the output I got , the only noticeable differences in your output were the lines 113 / 114: debug1: Remote: Forced command. in your output, unfortunately the part about which command was forced is missing.

To get this working using a (somewhat ugly) workaround, you could use a different local port for sftp and use a Match block that matches on said LocalPort, limiting the execution of Forcecommand internal-sftp to clients connecting to that port...

Comments

[Jetson Earth]

I have exactly the same config on my home server (bare the ecdsa key), and I can not reproduce the issue using OpenSSH_6.0p1. Can you install a more recent version and try again?

[Jared Meyering]

Were using sftp from terminal. No gui or other clients involved in this transaction.

[Jared Meyering]

Thanks for the suggestion, sadly it didn't fix my problem.

[Jared Meyering]

Yeah, thanks for your comment. I'm running 5.9p1 at the moment and may try an upgrade to see if that works. The biggest thing I'm running into is that the deploy tool that I'm using deploys using sftp, which I can get working using a match user block. However I also have post deploy commands that it needs to trigger from straight ssh and therein lies the rub. I need sftp but cant use the ugly hack because I also want ssh for the same user sigh This is quite frustrating. I have suspicions that the problem lies not necessarially in the sshd_config...but where i don't know.

[Jetson Earth]

If you could make the deploy tool use different ports for ssh and sftp, then this hack would permit the same user to use both ssh and `sftp.

[Jared Meyering]

This did not work

[John Smith Optional]

Could you explain a bit more what you mean by "There was a command being set from the key itself preventing us from getting to the sftp prompt". I don't understand what you mean. How did you solve the problem?

[Jared Meyering]

in our authorized_keys file the key was sending a command to the client to be executed. See my comment for an example. A Line in our authorized_keys would start with command=...