SOLVED: Newbie: SSH fails to connect; gives strange error message

From: Dan (daniel.j.botz_at_cummins.com)
Date: 01/20/04 

Date: 20 Jan 2004 12:26:19 -0800

daniel.j.botz@cummins.com (Dan) wrote in message news:<ffb05a35.0401200534.55d6ad4f@posting.google.com>...
> Darren Dunham <ddunham@redwood.taos.com> wrote in message news:<YJZOb.13213$Sd3.7376@newssvr25.news.prodigy.com>...
> > Dan <daniel.j.botz@cummins.com> wrote:
> >
> > > [host2.domain.com] /roothome # /usr/local/sbin/sshd -d -d -d -f
> > > /usr/local/etc/sshd_config <
> [snip]
> > > Bind to port 22 on 0.0.0.0 failed: Address already in use.
> > > Generating 768 bit RSA key.
> > > RSA key generation complete.
> >
> > You're attempting to run a debug SSHD, but there's still a copy running
> > on port 22, so this one doesn't bind. There's no output from a
> > connection here.
> >
> > you need to either kill the normal sshd first, or you need to run this
> > on another port and try to connect to that port from the client.
>
> I saw that too and thought it looked suspicious. But is seems to work
> with other User IDs. And when I do kill the SSHD, I don't see
> anything running on port 22.
>
> I've tried several other ports and got the same result with the user
> Id that keeps failing.
>
> Does anybody have any ideas?
>
> Thanks,
> Dan
>
>
> Here is output from a working User ID:
>
> CLIENT:
> user@host1.domain.com $ssh -v host2
> OpenSSH_3.4p1, SSH protocols 1.5/2.0, OpenSSL 0x0090603f
> debug1: Reading configuration data /usr/local/etc/ssh_config
> debug1: Rhosts Authentication disabled, originating port will not be
> trusted.
> debug1: ssh_connect: needpriv 0
> debug1: Connecting to host2 [XXX.XXX.XXX.XXX] port 22.
> debug1: Connection established.
> debug1: identity file /users/user/.ssh/identity type -1
> debug1: identity file /users/user/.ssh/id_rsa type 1
> debug1: identity file /users/user/.ssh/id_dsa type -1
> debug1: Remote protocol version 1.99, remote software version
> OpenSSH_3.4p1
> debug1: match: OpenSSH_3.4p1 pat OpenSSH*
> Enabling compatibility mode for protocol 2.0
> debug1: Local version string SSH-2.0-OpenSSH_3.4p1
> debug1: SSH2_MSG_KEXINIT sent
> debug1: SSH2_MSG_KEXINIT received
> debug1: kex: server->client aes128-cbc hmac-md5 none
> debug1: kex: client->server aes128-cbc hmac-md5 none
> debug1: SSH2_MSG_KEX_DH_GEX_REQUEST sent
> debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
> debug1: dh_gen_key: priv key bits set: 130/256
> debug1: bits set: 1607/3191
> debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
> debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
> debug1: Host 'host2' is known and matches the RSA host key.
> debug1: Found key in /users/user/.ssh/known_hosts:1
> debug1: bits set: 1622/3191
> debug1: ssh_rsa_verify: signature correct
> debug1: kex_derive_keys
> debug1: newkeys: mode 1
> debug1: SSH2_MSG_NEWKEYS sent
> debug1: waiting for SSH2_MSG_NEWKEYS
> debug1: newkeys: mode 0
> debug1: SSH2_MSG_NEWKEYS received
> debug1: done: ssh_kex2.
> debug1: send SSH2_MSG_SERVICE_REQUEST
> debug1: service_accept: ssh-userauth
> debug1: got SSH2_MSG_SERVICE_ACCEPT
> debug1: authentications that can continue:
> publickey,password,keyboard-interacti
> ve
> debug1: next auth method to try is publickey
> debug1: try privkey: /users/user/.ssh/identity
> debug1: try pubkey: /users/user/.ssh/id_rsa
> debug1: input_userauth_pk_ok: pkalg ssh-rsa blen 149 lastkey 14004ee40
> hint 1
> debug1: read PEM private key done: type RSA
> debug1: ssh-userauth2 successful: method publickey
> debug1: channel 0: new [client-session]
> debug1: send channel open 0
> debug1: Entering interactive session.
> debug1: ssh_session2_setup: id 0
> debug1: channel request 0: pty-req
> debug1: channel request 0: shell
> debug1: fd 3 setting TCP_NODELAY
> debug1: channel 0: open confirm rwindow 0 rmax 32768
> debug3: Trying to reverse map address ::ffff:146.91.128.222.
> Last login: Tue Jan 20 07:14:27 CST 2004 from host1.domain.com
> Compaq Tru64 UNIX V5.1A (Rev. 1885); Sun Oct 19 04:08:33 CDT 2003
>
> Environment:
> USER=user
> LOGNAME=user
> HOME=/users1/user
> PATH=/usr/bin:/bin:/usr/sbin:/sbin:/usr/local/bin
> MAIL=/var/spool/mail/user
> SHELL=/usr/bin/ksh
> SSH_CLIENT=::ffff:XXX.XXX.XXX.XXX 2318 22
> SSH_TTY=/dev/pts/31
> TERM=vt100
> debug3: channel_close_fds: channel 0: r -1 w -1 e -1
>
> SERVER:
> [host2] /roothome # /usr/local/sbin/sshd -d -d -d
> debug3: Seeding PRNG from /usr/local/libexec/ssh-rand-helper
> debug1: sshd version OpenSSH_3.4p1
> debug1: private host key: #0 type 0 RSA1
> debug3: Not a RSA1 key file /usr/local/etc/ssh_host_rsa_key.
> debug1: read PEM private key done: type RSA
> debug1: private host key: #1 type 1 RSA
> debug3: Not a RSA1 key file /usr/local/etc/ssh_host_dsa_key.
> debug1: read PEM private key done: type DSA
> debug1: private host key: #2 type 2 DSA
> debug1: Bind to port 22 on ::.
> Server listening on :: port 22.
> debug1: Bind to port 22 on 0.0.0.0.
> Bind to port 22 on 0.0.0.0 failed: Address already in use.
> Generating 768 bit RSA key.
> RSA key generation complete.
> debug1: Server will not fork when running in debugging mode.
> Connection from ::ffff:146.91.128.222 port 2318
> debug1: Client protocol version 2.0; client software version
> OpenSSH_3.4p1
> debug1: match: OpenSSH_3.4p1 pat OpenSSH*
> Enabling compatibility mode for protocol 2.0
> debug1: Local version string SSH-1.99-OpenSSH_3.4p1
> debug1: list_hostkey_types: ssh-rsa,ssh-dss
> debug1: SSH2_MSG_KEXINIT sent
> debug1: SSH2_MSG_KEXINIT received
> debug2: kex_parse_kexinit:
> diffie-hellman-group-exchange-sha1,diffie-hellman-gro
> up1-sha1
> debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
> debug2: kex_parse_kexinit:
> aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,
> aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se
> debug2: kex_parse_kexinit:
> aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,
> aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se
> debug2: kex_parse_kexinit:
> hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@open
> ssh.com,hmac-sha1-96,hmac-md5-96
> debug2: kex_parse_kexinit:
> hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@open
> ssh.com,hmac-sha1-96,hmac-md5-96
> 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: kex_parse_kexinit:
> diffie-hellman-group-exchange-sha1,diffie-hellman-gro
> up1-sha1
> debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
> debug2: kex_parse_kexinit:
> aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,
> aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se
> debug2: kex_parse_kexinit:
> aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,
> aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se
> debug2: kex_parse_kexinit:
> hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@open
> ssh.com,hmac-sha1-96,hmac-md5-96
> debug2: kex_parse_kexinit:
> hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@open
> ssh.com,hmac-sha1-96,hmac-md5-96
> debug2: kex_parse_kexinit: none
> debug2: kex_parse_kexinit: none
> 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: client->server aes128-cbc hmac-md5 none
> debug2: mac_init: found hmac-md5
> debug1: kex: server->client aes128-cbc hmac-md5 none
> debug1: SSH2_MSG_KEX_DH_GEX_REQUEST received
> debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent
> debug1: dh_gen_key: priv key bits set: 137/256
> debug1: bits set: 1622/3191
> debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT
> debug1: bits set: 1607/3191
> debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent
> debug1: kex_derive_keys
> debug1: newkeys: mode 1
> debug1: SSH2_MSG_NEWKEYS sent
> debug1: waiting for SSH2_MSG_NEWKEYS
> debug1: newkeys: mode 0
> debug1: SSH2_MSG_NEWKEYS received
> debug1: KEX done
> debug1: userauth-request for user cm008 service ssh-connection method
> none
> debug1: attempt 0 failures 0
> debug2: input_userauth_request: setting up authctxt for cm008
> debug2: input_userauth_request: try method none
> Failed none for user from ::ffff:XXX.XXX.XXX.XXX port 2318 ssh2
> debug1: userauth-request for user user service ssh-connection method
> publickey
> debug1: attempt 1 failures 1
> debug2: input_userauth_request: try method publickey
> debug1: test whether pkalg/pkblob are acceptable
> debug1: temporarily_use_uid: 7777/16 (e=0)
> debug1: trying public key file /users1/user/.ssh/authorized_keys
> debug3: secure_filename: checking '/users1/user/.ssh'
> debug3: secure_filename: checking '/users1/user'
> debug3: secure_filename: terminating check at '/users1/user'
> debug1: matching key found: file /users1/user/.ssh/authorized_keys,
> line 1
> Found matching RSA key:
> 6c:de:0e:d8:4b:22:46:27:01:e3:00:e2:74:fd:55:0b
> debug1: restore_uid
> debug2: userauth_pubkey: authenticated 0 pkalg ssh-rsa
> Postponed publickey for user from ::ffff:XXX.XXX.XXX.XXX port 2318
> ssh2
> debug1: userauth-request for user user service ssh-connection method
> publickey
> debug1: attempt 2 failures 1
> debug2: input_userauth_request: try method publickey
> debug1: temporarily_use_uid: 7777/16 (e=0)
> debug1: trying public key file /users1/user/.ssh/authorized_keys
> debug3: secure_filename: checking '/users1/user/.ssh'
> debug3: secure_filename: checking '/users1/user'
> debug3: secure_filename: terminating check at '/users1/user'
> debug1: matching key found: file /users1/user/.ssh/authorized_keys,
> line 1
> Found matching RSA key:
> 6c:de:0e:d8:4b:22:46:27:01:e3:00:e2:74:fd:55:0b
> debug1: restore_uid
> debug1: ssh_rsa_verify: signature correct
> debug2: userauth_pubkey: authenticated 1 pkalg ssh-rsa
> Accepted publickey for user from ::ffff:XXX.XXX.XXX.XXX port 2318 ssh2
> debug1: Entering interactive session for SSH2.
> debug1: fd 3 setting O_NONBLOCK
> debug1: fd 7 setting O_NONBLOCK
> debug1: server_init_dispatch_20
> debug1: server_input_channel_open: ctype session rchan 0 win 65536 max
> 16384
> debug1: input_session_request
> debug1: channel 0: new [server-session]
> debug1: session_new: init
> 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_channel_req: channel 0 request pty-req reply 0
> debug1: session_by_channel: session 0 channel 0
> debug1: session_input_channel_req: session 0 req pty-req
> debug1: Allocating pty.
> debug1: session_pty_req: session 0 alloc /dev/pts/31
> debug3: tty_parse_modes: SSH2 n_bytes 271
> debug3: tty_parse_modes: ospeed 9600
> debug3: tty_parse_modes: ispeed 9600
> debug3: tty_parse_modes: 1 3
> debug3: tty_parse_modes: 2 28
> debug3: tty_parse_modes: 3 127
> debug3: tty_parse_modes: 4 21
> debug3: tty_parse_modes: 5 4
> debug3: tty_parse_modes: 6 255
> debug3: tty_parse_modes: 7 255
> debug3: tty_parse_modes: 8 17
> debug3: tty_parse_modes: 9 19
> debug3: tty_parse_modes: 10 26
> debug3: tty_parse_modes: 11 25
> debug3: tty_parse_modes: 12 18
> debug3: tty_parse_modes: 13 23
> debug3: tty_parse_modes: 14 22
> debug3: tty_parse_modes: 15 15
> debug3: tty_parse_modes: 17 255
> debug3: tty_parse_modes: 18 15
> debug3: tty_parse_modes: 30 0
> debug3: tty_parse_modes: 31 0
> debug3: tty_parse_modes: 32 0
> debug3: tty_parse_modes: 33 0
> debug3: tty_parse_modes: 34 0
> debug3: tty_parse_modes: 35 0
> debug3: tty_parse_modes: 36 1
> debug3: tty_parse_modes: 37 0
> debug3: tty_parse_modes: 38 1
> debug3: tty_parse_modes: 39 0
> debug3: tty_parse_modes: 40 0
> debug3: tty_parse_modes: 41 1
> debug3: tty_parse_modes: 50 1
> debug3: tty_parse_modes: 51 1
> debug3: tty_parse_modes: 52 0
> debug3: tty_parse_modes: 53 1
> debug3: tty_parse_modes: 54 1
> debug3: tty_parse_modes: 55 0
> debug3: tty_parse_modes: 56 0
> debug3: tty_parse_modes: 57 0
> debug3: tty_parse_modes: 58 0
> debug3: tty_parse_modes: 59 1
> debug3: tty_parse_modes: 60 1
> debug3: tty_parse_modes: 61 1
> debug3: tty_parse_modes: 62 0
> debug3: tty_parse_modes: 70 1
> debug3: tty_parse_modes: 71 0
> debug3: tty_parse_modes: 72 1
> debug3: tty_parse_modes: 73 0
> debug3: tty_parse_modes: 74 0
> debug3: tty_parse_modes: 75 0
> debug3: tty_parse_modes: 90 1
> debug3: tty_parse_modes: 91 1
> debug3: tty_parse_modes: 92 0
> debug3: tty_parse_modes: 93 0
> debug1: server_input_channel_req: channel 0 request shell reply 0
> debug1: session_by_channel: session 0 channel 0
> debug1: session_input_channel_req: session 0 req shell
> debug1: fd 4 setting TCP_NODELAY
> debug1: channel 0: rfd 9 isatty
> debug1: fd 9 setting O_NONBLOCK
> debug2: fd 8 is O_NONBLOCK
> debug1: Setting controlling tty using TIOCSCTTY.

Well, I finally fingured it out. After running a trace on the ssh
command, I saw that ssh could not read the "etc/protocols" file. A
chmod on the file solved the problem and now ssh and me are happy.