sftp/scp hangs at connection, but ssh is OK

Thu Nov 3 02:38:28 EST 2005

On 2005-10-30 16:46:11 +0100, Martin Schröder wrote:
> I've read the FAQ and googled, but I'm still stymied:
> ssh localhost works, but scp and sftp both hang.
> 
> ssh is OpenSSH_4.2p1, OpenSSL 0.9.6c [engine] 21 dec 2001
> 
> The last lines of an "scp -4 -vvv .bashrc localhost:/tmp/" are:
> ----------------------------------
> debug2: mac_init: found hmac-ripemd160
> debug1: kex: server->client aes128-cbc hmac-ripemd160 zlib at openssh.com
> debug2: mac_init: found hmac-ripemd160
> debug1: kex: client->server aes128-cbc hmac-ripemd160 zlib at openssh.com
> debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<2048<8192) sent
> debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
> debug2: dh_gen_key: priv key bits set: 152/320
> debug2: bits set: 1606/3191
> debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
> debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
> debug3: check_host_in_hostfile: filename /home/ms/.ssh/known_hosts
> debug3: key_read: type mismatch
> debug3: check_host_in_hostfile: match line 15
> debug1: Host 'localhost' is known and matches the RSA host key.
> debug1: Found key in /home/ms/.ssh/known_hosts:15
> debug2: bits set: 1587/3191
> debug1: ssh_rsa_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: SSH2_MSG_SERVICE_REQUEST sent
> debug2: service_accept: ssh-userauth
> debug1: SSH2_MSG_SERVICE_ACCEPT received
> debug2: key: /home/ms/.ssh/id_dsa (0x809ad70)
> debug2: key: /home/ms/.ssh/id_rsa ((nil))
> debug1: Authentications that can continue: publickey,password
> debug3: start over, passed a different list publickey,password
> 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: /home/ms/.ssh/id_dsa
> debug3: send_pubkey_test
> debug2: we sent a publickey packet, wait for reply
> debug1: Server accepts key: pkalg ssh-dss blen 432
> debug2: input_userauth_pk_ok: fp 20:e2:42:bb:b2:48:6a:07:db:5c:99:5f:28:1c:17:88
> debug3: sign_and_send_pubkey
> debug1: Enabling compression at level 6.
> debug1: Authentication succeeded (publickey).
> debug2: fd 6 setting O_NONBLOCK
> debug2: fd 9 setting O_NONBLOCK
> debug1: channel 0: new [client-session]
> debug3: ssh_session2_open: channel_new: 0
> debug2: channel 0: send open
> debug1: Entering interactive session.
> debug2: callback start
> debug2: client_session2_setup: id 0
> debug1: Sending command: scp -v -t /tmp/
> debug2: channel 0: request exec confirm 0
> debug2: callback done
> debug2: channel 0: open confirm rwindow 0 rmax 32768
> debug2: channel 0: rcvd adjust 131072
> ----------------------------------
> The sshd (running with DEBUG3) produces this:
> ----------------------------------
> Oct 30 16:23:13 dream sshd[2122]: Found matching DSA key: 20:e2:42:bb:b2:48:6a:07:db:5c:99:5f:28:1c:17:88
> Oct 30 16:23:13 dream sshd[2122]: debug1: restore_uid: 0/0
> Oct 30 16:23:13 dream sshd[2122]: debug3: mm_answer_keyallowed: key 0x80a3d70 is allowed
> Oct 30 16:23:13 dream sshd[2122]: debug3: mm_request_send entering: type 21
> Oct 30 16:23:13 dream sshd[2122]: debug3: mm_request_receive entering
> Oct 30 16:23:13 dream sshd[2122]: debug3: monitor_read: checking request 22
> Oct 30 16:23:13 dream sshd[2122]: debug1: ssh_dss_verify: signature correct
> Oct 30 16:23:13 dream sshd[2122]: debug3: mm_answer_keyverify: key 0x809ac58 signature verified
> Oct 30 16:23:13 dream sshd[2122]: debug3: mm_request_send entering: type 23
> Oct 30 16:23:13 dream sshd[2122]: Accepted publickey for ms from 127.0.0.1 port 32838 ssh2
> Oct 30 16:23:13 dream sshd[2122]: debug1: monitor_child_preauth: ms has been authenticated by privileged process
> Oct 30 16:23:13 dream sshd[2122]: debug3: mm_get_keystate: Waiting for new keys
> Oct 30 16:23:13 dream sshd[2122]: debug3: mm_request_receive_expect entering: type 24
> Oct 30 16:23:13 dream sshd[2122]: debug3: mm_request_receive entering
> Oct 30 16:23:13 dream sshd[2122]: debug3: mm_newkeys_from_blob: 0x809aaa0(140)
> Oct 30 16:23:13 dream sshd[2122]: debug2: mac_init: found hmac-ripemd160
> Oct 30 16:23:13 dream sshd[2122]: debug3: mm_get_keystate: Waiting for second key
> Oct 30 16:23:13 dream sshd[2122]: debug3: mm_newkeys_from_blob: 0x809aaa0(140)
> Oct 30 16:23:13 dream sshd[2122]: debug2: mac_init: found hmac-ripemd160
> Oct 30 16:23:13 dream sshd[2122]: debug3: mm_get_keystate: Getting compression state
> Oct 30 16:23:13 dream sshd[2122]: debug3: mm_get_keystate: Getting Network I/O buffers
> Oct 30 16:23:13 dream sshd[2122]: debug3: mm_share_sync: Share sync
> Oct 30 16:23:13 dream sshd[2122]: debug3: mm_share_sync: Share sync end
> Oct 30 16:23:13 dream sshd[2124]: debug1: permanently_set_uid: 500/100
> Oct 30 16:23:13 dream sshd[2124]: debug2: set_newkeys: mode 0
> Oct 30 16:23:13 dream sshd[2124]: debug2: set_newkeys: mode 1
> Oct 30 16:23:13 dream sshd[2124]: debug1: Entering interactive session for SSH2.
> Oct 30 16:23:13 dream sshd[2124]: debug2: fd 5 setting O_NONBLOCK
> Oct 30 16:23:13 dream sshd[2124]: debug2: fd 6 setting O_NONBLOCK
> Oct 30 16:23:13 dream sshd[2124]: debug1: server_init_dispatch_20
> Oct 30 16:23:13 dream sshd[2124]: debug1: server_input_channel_open: ctype session rchan 0 win 131072 max 32768
> Oct 30 16:23:13 dream sshd[2124]: debug1: input_session_request
> Oct 30 16:23:13 dream sshd[2124]: debug1: channel 0: new [server-session]
> Oct 30 16:23:13 dream sshd[2124]: debug1: session_new: init
> Oct 30 16:23:13 dream sshd[2124]: debug1: session_new: session 0
> Oct 30 16:23:13 dream sshd[2124]: debug1: session_open: channel 0
> Oct 30 16:23:13 dream sshd[2124]: debug1: session_open: session 0: link with channel 0
> Oct 30 16:23:13 dream sshd[2124]: debug1: server_input_channel_open: confirm session
> Oct 30 16:23:13 dream sshd[2124]: debug1: server_input_channel_req: channel 0 request exec reply 0
> Oct 30 16:23:13 dream sshd[2124]: debug1: session_by_channel: session 0 channel 0
> Oct 30 16:23:13 dream sshd[2124]: debug1: session_input_channel_req: session 0 req exec
> Oct 30 16:23:13 dream sshd[2125]: debug3: channel 0: close_fds r -1 w -1 e -1 c -1
> Oct 30 16:23:13 dream sshd[2124]: debug2: fd 8 setting O_NONBLOCK
> Oct 30 16:23:13 dream sshd[2124]: debug3: fd 8 is O_NONBLOCK
> Oct 30 16:23:13 dream sshd[2124]: debug2: fd 10 setting O_NONBLOCK
> Oct 30 16:23:13 dream sshd[2122]: debug2: User child is on pid 2124
> Oct 30 16:23:13 dream sshd[2122]: debug3: mm_request_receive entering
> ----------------------------------
> After an Ctrl-C scp exits with
> ----------------------------------
> debug1: 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 6/9 cfd -1)
> 
> debug3: channel 0: close_fds r 6 w 9 e 10 c -1
> debug1: fd 0 clearing O_NONBLOCK
> debug1: fd 1 clearing O_NONBLOCK
> Killed by signal 2.
> ----------------------------------
> And the sshd logs
> ----------------------------------
> Oct 30 16:26:09 dream sshd[2124]: Connection closed by 127.0.0.1
> Oct 30 16:26:09 dream sshd[2124]: debug1: channel 0: free: server-session, nchannels 1
> Oct 30 16:26:09 dream sshd[2124]: debug3: channel 0: status: The following connections are open:\r\n  #0 server-session (t4 r0 i0/0 o0/0 fd 8/8 cfd -1)\r\n
> Oct 30 16:26:09 dream sshd[2124]: debug3: channel 0: close_fds r 8 w 8 e 10 c -1
> Oct 30 16:26:09 dream sshd[2124]: debug1: session_close: session 0 pid 2125
> Oct 30 16:26:09 dream sshd[2124]: debug1: do_cleanup
> Oct 30 16:26:09 dream sshd[2124]: Closing connection to 127.0.0.1
> Oct 30 16:26:09 dream sshd[2124]: debug3: mm_request_send entering: type 58
> Oct 30 16:26:09 dream sshd[2122]: debug3: monitor_read: checking request 58
> Oct 30 16:26:09 dream sshd[2122]: debug3: mm_answer_term: tearing down sessions
> ----------------------------------
> 
> The system is a Suse 8.0 (Linux 2.4.18).
> 
> Any idea how to fix this?

I tried this on secureshell, but got only garbage or pointers to
the FAQ. The FAQ doesn't help:
-------------
> echo +`ssh localhost /bin/true`+
++
-------------

Thanks in advance
    Martin
-- 
                    http://www.tm.oneiros.de