openssh sftp fails to start a session

Wed Jun 2 13:16:21 EST 2010

Hi,

I am having trouble running sftp from the openssh package openssh-5.5p1. There seems to
be an authentication problem.

This is what happens:
$ sftp -o "Port 2022" testu at localhost
testu at localhost's password:
Connection closed

QUESTION:
Can someone spot the problem please? How do I fix this?

FURTHER INFORMATION
I can run openssh's ssh:
$ ./ssh -p 2022 testu at localhost
testu at localhost's password:
Last login: Wed Jun  2 12:55:01 2010 from localhost.localdomain

I have run sshd in debug mode and the output is at the bottom of this email.

There is nothing wrong with testu's password as I can run sftp (the standard one on Redhat) OK:
$ sftp testu at localhost
Connecting to localhost...
testu at localhost's password:
sftp>

I am compiling and running openssh on Redhat 4.

I compile it with:
./configure --prefix=/home/myuser/openssh --sysconfdir=/home/myuser/openssh/ssh --enable-pam --disable-privsep

The sshd_config file is:
Port 2022
PasswordAuthentication yes
ChallengeResponseAuthentication yes
X11Forwarding yes
Protocol 2

The pam config it is using is /etc/pam.d/sshd:
#%PAM-1.0
auth       required     pam_stack.so service=system-auth
auth       required     pam_nologin.so
account    required     pam_stack.so service=system-auth
password   required     pam_stack.so service=system-auth
session    required     pam_stack.so service=system-auth
session    required     pam_loginuid.so

The trace does say that it cannot stat /home/myuser/openssh/libexec/sftp-server but the executable has
r-x for "others" and that goes for all directories above it.

=============================================================================================
debug2: load_server_config: filename /home/myuser/openssh/ssh/sshd_config
debug2: load_server_config: done config len = 300
debug2: parse_server_config: config /home/myuser/openssh/ssh/sshd_config len 300
debug3: /home/myuser/openssh/ssh/sshd_config:13 setting Port 2022
debug3: /home/myuser/openssh/ssh/sshd_config:19 setting Protocol 2
debug3: /home/myuser/openssh/ssh/sshd_config:33 setting SyslogFacility AUTH
debug3: /home/myuser/openssh/ssh/sshd_config:34 setting LogLevel INFO
debug3: /home/myuser/openssh/ssh/sshd_config:59 setting PasswordAuthentication yes
debug3: /home/myuser/openssh/ssh/sshd_config:63 setting ChallengeResponseAuthentication yes
debug3: /home/myuser/openssh/ssh/sshd_config:90 setting X11Forwarding yes
debug3: /home/myuser/openssh/ssh/sshd_config:112 setting Subsystem sftp    /home/myuser/openssh/libexec/sftp-server
debug1: sshd version OpenSSH_5.5p1
debug3: Not a RSA1 key file /home/myuser/openssh/ssh/ssh_host_rsa_key.
debug1: read PEM private key done: type RSA
debug1: private host key: #0 type 1 RSA
debug3: Not a RSA1 key file /home/myuser/openssh/ssh/ssh_host_dsa_key.
debug1: read PEM private key done: type DSA
debug1: private host key: #1 type 2 DSA
debug1: rexec_argv[0]='/home/myuser/openssh/sbin/sshd'
debug1: rexec_argv[1]='-d'
debug1: rexec_argv[2]='-d'
debug1: rexec_argv[3]='-d'
debug1: rexec_argv[4]='-f'
debug1: rexec_argv[5]='/home/myuser/openssh/ssh/sshd_config'
debug3: oom_adjust_setup
debug2: fd 3 setting O_NONBLOCK
debug1: Bind to port 2022 on 0.0.0.0.
Server listening on 0.0.0.0 port 2022.
socket: Address family not supported by protocol
debug3: fd 4 is not O_NONBLOCK
debug1: Server will not fork when running in debugging mode.
debug3: send_rexec_state: entering fd = 7 config len 300
debug3: ssh_msg_send: type 0
debug3: send_rexec_state: done
debug1: rexec start in 4 out 4 newsock 4 pipe -1 sock 7
debug1: inetd sockets after dupping: 3, 3
Connection from 127.0.0.1 port 34117
debug1: Client protocol version 2.0; client software version OpenSSH_5.5
debug1: match: OpenSSH_5.5 pat OpenSSH*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_5.5
debug2: fd 3 setting O_NONBLOCK
debug3: privsep user:group 74:74
debug1: permanently_set_uid: 74/74
debug1: list_hostkey_types: ssh-rsa,ssh-dss
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug2: Network child is on pid 18299
debug3: preauth child monitor started
debug3: mm_request_receive entering
debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha256,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,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc at lysator.liu.se
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,rijndael-cbc at lysator.liu.se
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64 at openssh.com,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64 at openssh.com,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib at openssh.com
debug2: kex_parse_kexinit: none,zlib at openssh.com
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: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa-cert-v00 at openssh.com,ssh-dss-cert-v00 at openssh.com,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,rijndael-cbc at lysator.liu.se
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,rijndael-cbc at lysator.liu.se
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64 at openssh.com,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64 at openssh.com,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib at openssh.com,zlib
debug2: kex_parse_kexinit: none,zlib at openssh.com,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_setup: found hmac-md5
debug1: kex: client->server aes128-ctr hmac-md5 none
debug2: mac_setup: found hmac-md5
debug1: kex: server->client aes128-ctr hmac-md5 none
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST received
debug3: mm_request_send entering: type 0
debug3: monitor_read: checking request 0
debug3: mm_answer_moduli: got parameters: 1024 1024 8192
debug3: mm_choose_dh: waiting for MONITOR_ANS_MODULI
debug3: mm_request_receive_expect entering: type 1
debug3: mm_request_receive entering
debug3: mm_request_send entering: type 1
debug2: monitor_read: 0 used once, disabling now
debug3: mm_request_receive entering
debug3: mm_choose_dh: remaining 0
debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent
debug2: dh_gen_key: priv key bits set: 121/256
debug2: bits set: 491/1024
debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT
debug2: bits set: 525/1024
debug3: mm_key_sign entering
debug3: mm_request_send entering: type 4
debug3: mm_key_sign: waiting for MONITOR_ANS_SIGN
debug3: monitor_read: checking request 4
debug3: mm_answer_sign
debug3: mm_request_receive_expect entering: type 5
debug3: mm_request_receive entering
debug3: mm_answer_sign: signature 0x88d08b0(271)
debug3: mm_request_send entering: type 5
debug2: monitor_read: 4 used once, disabling now
debug3: mm_request_receive entering
debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent
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: KEX done
debug1: userauth-request for user testu service ssh-connection method none
debug1: attempt 0 failures 0
debug3: mm_getpwnamallow entering
debug3: mm_request_send entering: type 6
debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM
debug3: mm_request_receive_expect entering: type 7
debug3: mm_request_receive entering
debug3: monitor_read: checking request 6
debug3: mm_answer_pwnamallow
debug3: Trying to reverse map address 127.0.0.1.
debug2: parse_server_config: config reprocess config len 300
debug3: auth_shadow_acctexpired: today 14762 sp_expire -1 days left -14763
debug3: account expiration disabled
debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
debug3: mm_request_send entering: type 7
debug2: monitor_read: 6 used once, disabling now
debug3: mm_request_receive entering
debug2: input_userauth_request: setting up authctxt for testu
debug3: mm_inform_authserv entering
debug3: mm_request_send entering: type 3
debug2: input_userauth_request: try method none
debug3: mm_auth_password entering
debug3: mm_request_send entering: type 10
debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD
debug3: mm_request_receive_expect entering: type 11
debug3: mm_request_receive entering
debug3: monitor_read: checking request 3
debug3: mm_answer_authserv: service=ssh-connection, style=
debug2: monitor_read: 3 used once, disabling now
debug3: mm_request_receive entering
debug3: monitor_read: checking request 10
debug3: mm_answer_authpassword: sending result 0
debug3: mm_request_send entering: type 11
Failed none for testu from 127.0.0.1 port 34117 ssh2
debug3: mm_request_receive entering
debug3: mm_auth_password: user not authenticated
debug1: userauth-request for user testu service ssh-connection method publickey
debug1: attempt 1 failures 0
debug2: input_userauth_request: try method publickey
debug1: test whether pkalg/pkblob are acceptable
debug3: mm_key_allowed entering
debug3: mm_request_send entering: type 20
debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED
debug3: mm_request_receive_expect entering: type 21
debug3: mm_request_receive entering
debug3: monitor_read: checking request 20
debug3: mm_answer_keyallowed entering
debug3: mm_answer_keyallowed: key_from_blob: 0x88c7648
debug1: temporarily_use_uid: 502/502 (e=0/0)
debug1: trying public key file /home/testu/.ssh/authorized_keys
debug1: restore_uid: 0/0
debug1: temporarily_use_uid: 502/502 (e=0/0)
debug1: trying public key file /home/testu/.ssh/authorized_keys2
debug1: restore_uid: 0/0
Failed publickey for testu from 127.0.0.1 port 34117 ssh2
debug3: mm_answer_keyallowed: key 0x88c7648 is not allowed
debug3: mm_request_send entering: type 21
debug3: mm_request_receive entering
debug2: userauth_pubkey: authenticated 0 pkalg ssh-rsa
debug1: userauth-request for user testu service ssh-connection method keyboard-interactive
debug1: attempt 2 failures 1
debug2: input_userauth_request: try method keyboard-interactive
debug1: keyboard-interactive devs
debug1: auth2_challenge: user=testu devs=
debug1: kbdint_alloc: devices ''
debug2: auth2_challenge_start: devices
debug1: userauth-request for user testu service ssh-connection method password
debug1: attempt 3 failures 2
debug2: input_userauth_request: try method password
debug3: mm_auth_password entering
debug3: mm_request_send entering: type 10
debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD
debug3: mm_request_receive_expect entering: type 11
debug3: mm_request_receive entering
debug3: monitor_read: checking request 10
debug3: auth_shadow_pwexpired: today 14762 sp_lstchg 14714 sp_max 99999
debug3: mm_answer_authpassword: sending result 1
debug3: mm_request_send entering: type 11
Accepted password for testu from 127.0.0.1 port 34117 ssh2
debug1: monitor_child_preauth: testu has been authenticated by privileged process
debug3: mm_get_keystate: Waiting for new keys
debug3: mm_request_receive_expect entering: type 24
debug3: mm_request_receive entering
debug3: mm_auth_password: user authenticated
debug3: mm_send_keystate: Sending new keys: 0x88d0860 0x88c79d0
debug3: mm_newkeys_to_blob: converting 0x88d0860
debug3: mm_newkeys_to_blob: converting 0x88c79d0
debug3: mm_send_keystate: New keys have been sent
debug3: mm_send_keystate: Sending compression state
debug3: mm_request_send entering: type 24
debug3: mm_send_keystate: Finished sending state
debug3: mm_newkeys_from_blob: 0x88d0e50(118)
debug2: mac_setup: found hmac-md5
debug3: mm_get_keystate: Waiting for second key
debug3: mm_newkeys_from_blob: 0x88d0e50(118)
debug2: mac_setup: found hmac-md5
debug3: mm_get_keystate: Getting compression state
debug3: mm_get_keystate: Getting Network I/O buffers
debug3: mm_share_sync: Share sync
debug3: mm_share_sync: Share sync end
debug1: permanently_set_uid: 502/502
debug2: set_newkeys: mode 0
debug2: set_newkeys: mode 1
debug1: Entering interactive session for SSH2.
debug2: fd 5 setting O_NONBLOCK
debug2: fd 6 setting O_NONBLOCK
debug1: server_init_dispatch_20
debug1: server_input_channel_open: ctype session rchan 0 win 2097152 max 32768
debug1: input_session_request
debug1: channel 0: new [server-session]
debug2: session_new: allocate (allocated 0 max 10)
debug3: session_unused: session id 0 unused
debug1: session_new: session 0
debug1: session_open: channel 0
debug1: session_open: session 0: link with channel 0
debug1: server_input_channel_open: confirm session
debug1: server_input_global_request: rtype no-more-sessions at openssh.com want_reply 0
User child is on pid 18300
debug3: mm_request_receive entering
debug1: server_input_channel_req: channel 0 request subsystem reply 1
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req subsystem
subsystem request for sftp
debug1: subsystem: cannot stat /home/myuser/openssh/libexec/sftp-server: Permission denied
debug1: subsystem: exec() /home/myuser/openssh/libexec/sftp-server
debug2: fd 3 setting TCP_NODELAY
debug2: fd 9 setting O_NONBLOCK
debug2: fd 8 setting O_NONBLOCK
debug2: channel 0: read<=0 rfd 9 len 0
debug2: channel 0: read failed
debug2: channel 0: close_read
debug2: channel 0: input open -> drain
debug2: channel 0: ibuf empty
debug2: channel 0: send eof
debug2: channel 0: input drain -> closed
debug2: notify_done: reading
debug1: Received SIGCHLD.
debug1: session_by_pid: pid 18301
debug1: session_exit_message: session 0 channel 0 pid 18301
debug2: channel 0: request exit-signal confirm 0
debug1: session_exit_message: release channel 0
debug2: channel 0: write failed
debug2: channel 0: close_write
debug2: channel 0: send eow
debug2: channel 0: output open -> closed
debug2: channel 0: send close
debug3: channel 0: will not send data after close
debug2: channel 0: rcvd close
Received disconnect from 127.0.0.1: 11: disconnected by user
debug1: do_cleanup
debug1: do_cleanup

***************************************************************
This message is intended for the addressee named and may contain confidential information. If you are not the intended recipient, please delete it and notify the sender. Views expressed in this message are those of the individual sender, and are not necessarily the views of the Land and Property Management Authority. This email message has been swept by MIMEsweeper for the presence of computer viruses.
***************************************************************
Please consider the environment before printing this email.