Hello all, I am running OpenSSH on OpenSuse Linux 10.0 using the included version: openssh-4.1p1-10.13 We've just enabled kerberos authentication for our system, authenticating against a Windows 2003 AD environment. Prior to doing this, our authentication over SSH has used public keys. We would like to continue to support key authentication in addition to username/password auth using our AD account. What I am finding is that, when I connect using Putty and my public key, there is an initial attempt at username authentication but no password sent over (no prompt provided). When this fails, it then searches for a key and succeeds. The end result is that the initial username/password attempt hits our AD, generates a kerberos pre-authentication failure and, if we try enough times, will lockout the account. What I can't tell is if I'm dealing with a client issue (putty) or server issue. I would love to be able to force the authentication to try the keypair first and, if that fails, try username/password. Can anyone point me in the right direction? My server debug3 is below: Jul 23 10:28:36 sshserver sshd[13957]: Received SIGHUP; restarting. Jul 23 10:28:36 sshserver sshd[14328]: debug2: fd 3 setting O_NONBLOCK Jul 23 10:28:36 sshserver sshd[14328]: debug1: Bind to port 22 on ::. Jul 23 10:28:36 sshserver sshd[14328]: Server listening on :: port 22. Jul 23 10:28:42 sshserver sshd[14328]: debug3: fd 4 is not O_NONBLOCK Jul 23 10:28:42 sshserver sshd[14329]: debug1: rexec start in 4 out 4 newsock 4 pipe 6 sock 7 Jul 23 10:28:42 sshserver sshd[14328]: debug1: Forked child 14329. Jul 23 10:28:42 sshserver sshd[14328]: debug3: send_rexec_state: entering fd = 7 config len 431 Jul 23 10:28:42 sshserver sshd[14328]: debug3: ssh_msg_send: type 0 Jul 23 10:28:42 sshserver sshd[14328]: debug3: send_rexec_state: done Jul 23 10:28:43 sshserver sshd[14329]: debug1: inetd sockets after dupping: 3, 3 Jul 23 10:28:43 sshserver sshd[14329]: debug3: Normalising mapped IPv4 in IPv6 address Jul 23 10:28:43 sshserver sshd[14329]: Connection from 192.168.0.196 port 2900 Jul 23 10:28:43 sshserver sshd[14329]: debug1: Client protocol version 2.0; client software version PuTTY_Release_0.58 Jul 23 10:28:43 sshserver sshd[14329]: debug1: no match: PuTTY_Release_0.58 Jul 23 10:28:43 sshserver sshd[14329]: debug1: Enabling compatibility mode for protocol 2.0 Jul 23 10:28:43 sshserver sshd[14329]: debug1: Local version string SSH-2.0-OpenSSH_4.1 Jul 23 10:28:43 sshserver sshd[14329]: debug2: fd 3 setting O_NONBLOCK Jul 23 10:28:43 sshserver sshd[14329]: debug2: Network child is on pid 14330 Jul 23 10:28:43 sshserver sshd[14329]: debug3: preauth child monitor started Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_receive entering Jul 23 10:28:43 sshserver sshd[14329]: debug3: monitor_read: checking request 0 Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_answer_moduli: got parameters: 1024 2048 8192 Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_send entering: type 1 Jul 23 10:28:43 sshserver sshd[14329]: debug2: monitor_read: 0 used once, disabling now Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_receive entering Jul 23 10:28:43 sshserver sshd[14329]: debug3: monitor_read: checking request 4 Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_answer_sign Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_answer_sign: signature 0x80064840(143) Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_send entering: type 5 Jul 23 10:28:43 sshserver sshd[14329]: debug2: monitor_read: 4 used once, disabling now Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_receive entering Jul 23 10:28:43 sshserver sshd[14329]: debug3: monitor_read: checking request 6 Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_answer_pwnamallow Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1 Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_send entering: type 7 Jul 23 10:28:43 sshserver sshd[14329]: debug2: monitor_read: 6 used once, disabling now Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_receive entering Jul 23 10:28:43 sshserver sshd[14329]: debug3: monitor_read: checking request 45 Jul 23 10:28:43 sshserver sshd[14329]: debug1: PAM: initializing for "myusername" Jul 23 10:28:43 sshserver sshd[14329]: debug3: Normalising mapped IPv4 in IPv6 address Jul 23 10:28:43 sshserver sshd[14329]: debug3: Trying to reverse map address 192.168.0.196. Jul 23 10:28:43 sshserver sshd[14329]: debug1: PAM: setting PAM_RHOST to "why.mydomain.com" Jul 23 10:28:43 sshserver sshd[14329]: debug1: PAM: setting PAM_TTY to "ssh" Jul 23 10:28:43 sshserver sshd[14329]: debug2: monitor_read: 45 used once, disabling now Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_receive entering Jul 23 10:28:43 sshserver sshd[14329]: debug3: monitor_read: checking request 3 Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_answer_authserv: service=ssh-connection, style= Jul 23 10:28:43 sshserver sshd[14329]: debug2: monitor_read: 3 used once, disabling now Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_receive entering Jul 23 10:28:43 sshserver sshd[14329]: debug3: monitor_read: checking request 10 Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_answer_authpassword: sending result 0 Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_send entering: type 11 Jul 23 10:28:43 sshserver sshd[14329]: Failed none for myusername from 192.168.0.196 port 2900 ssh2 Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_receive entering Jul 23 10:28:43 sshserver sshd[14329]: debug3: monitor_read: checking request 20 Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_answer_keyallowed entering Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_answer_keyallowed: key_from_blob: 0x800694f0 Jul 23 10:28:43 sshserver sshd[14329]: debug1: temporarily_use_uid: 1000/1000 (e=0/0) Jul 23 10:28:43 sshserver sshd[14329]: debug1: trying public key file /home/myusername/.ssh/authorized_keys Jul 23 10:28:43 sshserver sshd[14329]: debug3: secure_filename: checking '/home/myusername/.ssh' Jul 23 10:28:43 sshserver sshd[14329]: debug3: secure_filename: checking '/home/myusername' Jul 23 10:28:43 sshserver sshd[14329]: debug3: secure_filename: terminating check at '/home/myusername' Jul 23 10:28:43 sshserver sshd[14329]: debug1: matching key found: file /home/myusername/.ssh/authorized_keys, line 1 Jul 23 10:28:43 sshserver sshd[14329]: Found matching RSA key: eb:a7:8b:c8:4f:da:81:20:f4:38:1f:27:4a:9d:06:fe Jul 23 10:28:43 sshserver sshd[14329]: debug1: restore_uid: 0/0 Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_answer_keyallowed: key 0x800694f0 is allowed Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_send entering: type 21 Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_receive entering Jul 23 10:28:43 sshserver sshd[14329]: debug3: monitor_read: checking request 20 Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_answer_keyallowed entering Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_answer_keyallowed: key_from_blob: 0x80068598 Jul 23 10:28:43 sshserver sshd[14329]: debug1: temporarily_use_uid: 1000/1000 (e=0/0) Jul 23 10:28:43 sshserver sshd[14329]: debug1: trying public key file /home/myusername/.ssh/authorized_keys Jul 23 10:28:43 sshserver sshd[14329]: debug3: secure_filename: checking '/home/myusername/.ssh' Jul 23 10:28:43 sshserver sshd[14329]: debug3: secure_filename: checking '/home/myusername' Jul 23 10:28:43 sshserver sshd[14329]: debug3: secure_filename: terminating check at '/home/myusername' Jul 23 10:28:43 sshserver sshd[14329]: debug1: matching key found: file /home/myusername/.ssh/authorized_keys, line 1 Jul 23 10:28:43 sshserver sshd[14329]: Found matching RSA key: eb:a7:8b:c8:4f:da:81:20:f4:38:1f:27:4a:9d:06:fe Jul 23 10:28:43 sshserver sshd[14329]: debug1: restore_uid: 0/0 Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_answer_keyallowed: key 0x80068598 is allowed Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_send entering: type 21 Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_receive entering Jul 23 10:28:43 sshserver sshd[14329]: debug3: monitor_read: checking request 22 Jul 23 10:28:43 sshserver sshd[14329]: debug1: ssh_rsa_verify: signature correct Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_answer_keyverify: key 0x80068588 signature verified Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_send entering: type 23 Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_receive_expect entering: type 46 Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_receive entering Jul 23 10:28:43 sshserver sshd[14329]: debug1: do_pam_account: called Jul 23 10:28:43 sshserver sshd[14329]: debug3: PAM: do_pam_account pam_acct_mgmt = 0 (Success) Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_send entering: type 47 Jul 23 10:28:43 sshserver sshd[14329]: Accepted publickey for myusername from 192.168.0.196 port 2900 ssh2 Jul 23 10:28:43 sshserver sshd[14329]: debug1: monitor_child_preauth: myusername has been authenticated by privileged process Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_get_keystate: Waiting for new keys Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_receive_expect entering: type 24 Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_request_receive entering Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_newkeys_from_blob: 0x80069098(139) Jul 23 10:28:43 sshserver sshd[14329]: debug2: mac_init: found hmac-sha1 Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_get_keystate: Waiting for second key Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_newkeys_from_blob: 0x80069098(139) Jul 23 10:28:43 sshserver sshd[14329]: debug2: mac_init: found hmac-sha1 Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_get_keystate: Getting compression state Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_get_keystate: Getting Network I/O buffers Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_share_sync: Share sync Jul 23 10:28:43 sshserver sshd[14329]: debug3: mm_share_sync: Share sync end Jul 23 10:28:44 sshserver sshd[14329]: debug2: User child is on pid 14331 Jul 23 10:28:44 sshserver sshd[14329]: debug3: mm_request_receive entering Jul 23 10:28:44 sshserver sshd[14331]: debug3: PAM: opening session Jul 23 10:28:44 sshserver sshd[14331]: debug1: PAM: reinitializing credentials Jul 23 10:28:44 sshserver sshd[14331]: debug1: permanently_set_uid: 1000/1000 Jul 23 10:28:44 sshserver sshd[14331]: debug2: set_newkeys: mode 0 Jul 23 10:28:44 sshserver sshd[14331]: debug2: set_newkeys: mode 1 Jul 23 10:28:44 sshserver sshd[14331]: debug1: Entering interactive session for SSH2. Jul 23 10:28:44 sshserver sshd[14331]: debug2: fd 5 setting O_NONBLOCK Jul 23 10:28:44 sshserver sshd[14331]: debug2: fd 6 setting O_NONBLOCK Jul 23 10:28:44 sshserver sshd[14331]: debug1: server_init_dispatch_20 Jul 23 10:28:44 sshserver sshd[14331]: debug1: server_input_channel_open: ctype session rchan 256 win 16384 max 16384 Jul 23 10:28:44 sshserver sshd[14331]: debug1: input_session_request Jul 23 10:28:44 sshserver sshd[14331]: debug1: channel 0: new [server-session] Jul 23 10:28:44 sshserver sshd[14331]: debug1: session_new: init Jul 23 10:28:44 sshserver sshd[14331]: debug1: session_new: session 0 Jul 23 10:28:44 sshserver sshd[14331]: debug1: session_open: channel 0 Jul 23 10:28:44 sshserver sshd[14331]: debug1: session_open: session 0: link with channel 0 Jul 23 10:28:44 sshserver sshd[14331]: debug1: server_input_channel_open: confirm session Jul 23 10:28:44 sshserver sshd[14331]: debug1: server_input_channel_req: channel 0 request x11-req reply 1 Jul 23 10:28:44 sshserver sshd[14331]: debug1: session_by_channel: session 0 channel 0 Jul 23 10:28:44 sshserver sshd[14331]: debug1: session_input_channel_req: session 0 req x11-req Jul 23 10:28:44 sshserver sshd[14331]: debug1: X11 forwarding disabled in server configuration file. Jul 23 10:28:44 sshserver sshd[14331]: debug1: server_input_channel_req: channel 0 request pty-req reply 1 Jul 23 10:28:44 sshserver sshd[14331]: debug1: session_by_channel: session 0 channel 0 Jul 23 10:28:44 sshserver sshd[14331]: debug1: session_input_channel_req: session 0 req pty-req Jul 23 10:28:44 sshserver sshd[14331]: debug1: Allocating pty. Jul 23 10:28:44 sshserver sshd[14331]: debug3: mm_request_send entering: type 25 Jul 23 10:28:44 sshserver sshd[14329]: debug3: monitor_read: checking request 25 Jul 23 10:28:44 sshserver sshd[14329]: debug3: mm_answer_pty entering Jul 23 10:28:44 sshserver sshd[14329]: debug1: session_new: init Jul 23 10:28:44 sshserver sshd[14329]: debug1: session_new: session 0 Jul 23 10:28:44 sshserver sshd[14329]: debug3: mm_request_send entering: type 26 Jul 23 10:28:44 sshserver sshd[14329]: debug3: mm_answer_pty: tty /dev/pts/1 ptyfd 4 Jul 23 10:28:44 sshserver sshd[14329]: debug3: mm_request_receive entering Jul 23 10:28:44 sshserver sshd[14331]: debug3: mm_pty_allocate: waiting for MONITOR_ANS_PTY Jul 23 10:28:44 sshserver sshd[14331]: debug3: mm_request_receive_expect entering: type 26 Jul 23 10:28:44 sshserver sshd[14331]: debug3: mm_request_receive entering Jul 23 10:28:44 sshserver sshd[14331]: debug1: session_pty_req: session 0 alloc /dev/pts/1 Jul 23 10:28:44 sshserver sshd[14331]: debug3: tty_parse_modes: SSH2 n_bytes 11 Jul 23 10:28:44 sshserver sshd[14331]: debug3: tty_parse_modes: ispeed 38400 Jul 23 10:28:44 sshserver sshd[14331]: debug3: tty_parse_modes: ospeed 38400 Jul 23 10:28:44 sshserver sshd[14331]: debug1: server_input_channel_req: channel 0 request shell reply 1 Jul 23 10:28:44 sshserver sshd[14331]: debug1: session_by_channel: session 0 channel 0 Jul 23 10:28:44 sshserver sshd[14331]: debug1: session_input_channel_req: session 0 req shell Jul 23 10:28:44 sshserver sshd[14331]: debug1: PAM: setting PAM_TTY to "/dev/pts/1" Jul 23 10:28:44 sshserver sshd[14332]: debug1: Setting controlling tty using TIOCSCTTY. Jul 23 10:28:44 sshserver sshd[14332]: debug3: Normalising mapped IPv4 in IPv6 address Jul 23 10:28:44 sshserver sshd[14332]: debug3: channel 0: close_fds r -1 w -1 e -1 c -1 Jul 23 10:28:44 sshserver sshd[14331]: debug2: fd 3 setting TCP_NODELAY Jul 23 10:28:44 sshserver sshd[14331]: debug2: channel 0: rfd 8 isatty Jul 23 10:28:44 sshserver sshd[14331]: debug2: fd 8 setting O_NONBLOCK Jul 23 10:28:44 sshserver sshd[14331]: debug3: fd 7 is O_NONBLOCK Jul 23 10:28:46 sshserver sshd[14331]: debug1: Received SIGCHLD. Jul 23 10:28:46 sshserver sshd[14331]: debug1: session_by_pid: pid 14332 Jul 23 10:28:46 sshserver sshd[14331]: debug1: session_exit_message: session 0 channel 0 pid 14332 Jul 23 10:28:46 sshserver sshd[14331]: debug2: channel 0: request exit-status confirm 0 Jul 23 10:28:46 sshserver sshd[14331]: debug1: session_exit_message: release channel 0 Jul 23 10:28:46 sshserver sshd[14331]: debug2: channel 0: write failed Jul 23 10:28:46 sshserver sshd[14331]: debug2: channel 0: close_write Jul 23 10:28:46 sshserver sshd[14331]: debug2: channel 0: output open -> closed Jul 23 10:28:46 sshserver sshd[14331]: debug3: mm_request_send entering: type 27 Jul 23 10:28:46 sshserver sshd[14331]: debug2: notify_done: reading Jul 23 10:28:46 sshserver sshd[14331]: debug2: channel 0: read<=0 rfd 8 len -1 Jul 23 10:28:46 sshserver sshd[14329]: debug3: monitor_read: checking request 27 Jul 23 10:28:46 sshserver sshd[14329]: debug3: mm_answer_pty_cleanup entering Jul 23 10:28:46 sshserver sshd[14329]: debug1: session_by_tty: session 0 tty /dev/pts/1 Jul 23 10:28:46 sshserver sshd[14329]: debug3: mm_session_close: session 0 pid 14331 Jul 23 10:28:46 sshserver sshd[14329]: debug3: mm_session_close: tty /dev/pts/1 ptyfd 4 Jul 23 10:28:46 sshserver sshd[14329]: debug1: session_pty_cleanup: session 0 release /dev/pts/1 Jul 23 10:28:46 sshserver sshd[14329]: debug3: mm_request_receive entering Jul 23 10:28:46 sshserver sshd[14331]: debug2: channel 0: read failed Jul 23 10:28:46 sshserver sshd[14331]: debug2: channel 0: close_read Jul 23 10:28:46 sshserver sshd[14331]: debug2: channel 0: input open -> drain Jul 23 10:28:46 sshserver sshd[14331]: debug2: channel 0: ibuf empty Jul 23 10:28:46 sshserver sshd[14331]: debug2: channel 0: send eof Jul 23 10:28:46 sshserver sshd[14331]: debug2: channel 0: input drain -> closed Jul 23 10:28:46 sshserver sshd[14331]: debug2: channel 0: send close Jul 23 10:28:46 sshserver sshd[14331]: debug3: channel 0: will not send data after close Jul 23 10:28:46 sshserver sshd[14331]: debug2: channel 0: rcvd close Jul 23 10:28:46 sshserver sshd[14331]: debug3: channel 0: will not send data after close Jul 23 10:28:46 sshserver sshd[14331]: debug2: channel 0: is dead Jul 23 10:28:46 sshserver sshd[14331]: debug2: channel 0: gc: notify user Jul 23 10:28:46 sshserver sshd[14331]: debug1: session_by_channel: session 0 channel 0 Jul 23 10:28:46 sshserver sshd[14331]: debug1: session_close_by_channel: channel 0 child 14332 Jul 23 10:28:46 sshserver sshd[14331]: debug3: channel 0: will not send data after close Jul 23 10:28:46 sshserver sshd[14331]: debug2: channel 0: is dead Jul 23 10:28:46 sshserver sshd[14331]: debug2: channel 0: gc: notify user Jul 23 10:28:46 sshserver sshd[14331]: debug1: session_by_channel: session 0 channel 0 Jul 23 10:28:46 sshserver sshd[14331]: debug1: session_close_by_channel: channel 0 child 14332 Jul 23 10:28:46 sshserver sshd[14331]: debug1: session_close_by_channel: channel 0: has child Jul 23 10:28:46 sshserver sshd[14331]: debug2: channel 0: is dead Jul 23 10:28:46 sshserver sshd[14331]: debug2: channel 0: gc: notify user Jul 23 10:28:46 sshserver sshd[14331]: debug1: session_by_channel: session 0 channel 0 Jul 23 10:28:46 sshserver sshd[14331]: debug1: session_close_by_channel: channel 0 child 14332 Jul 23 10:28:46 sshserver sshd[14331]: debug1: session_close_by_channel: channel 0: has child Jul 23 10:28:46 sshserver sshd[14331]: Connection closed by 192.168.0.196 Jul 23 10:28:46 sshserver sshd[14331]: debug1: channel 0: free: server-session, nchannels 1 Jul 23 10:28:46 sshserver sshd[14331]: debug3: channel 0: status: The following connections are open:\r\n #0 server-session (t4 r256 i3/0 o3/0 fd -1/-1 cfd -1)\r\n Jul 23 10:28:46 sshserver sshd[14331]: debug3: channel 0: close_fds r -1 w -1 e -1 c -1 Jul 23 10:28:46 sshserver sshd[14331]: debug1: session_close: session 0 pid 14332 Jul 23 10:28:46 sshserver sshd[14331]: debug1: do_cleanup Jul 23 10:28:46 sshserver sshd[14331]: debug1: PAM: cleanup Jul 23 10:28:46 sshserver sshd[14331]: pam_krb5[14331]: no v5 creds for user 'myusername', skipping session cleanup Jul 23 10:28:46 sshserver sshd[14331]: debug3: PAM: sshpam_thread_cleanup entering Jul 23 10:28:46 sshserver sshd[14331]: Closing connection to 192.168.0.196 Jul 23 10:28:46 sshserver sshd[14331]: debug1: PAM: cleanup Jul 23 10:28:46 sshserver sshd[14331]: debug3: mm_request_send entering: type 58 Jul 23 10:28:46 sshserver sshd[14329]: debug3: monitor_read: checking request 58 Jul 23 10:28:46 sshserver sshd[14329]: debug3: mm_answer_term: tearing down sessions Jul 23 10:28:53 sshserver sshd[14328]: Received SIGHUP; restarting. Jul 23 10:28:53 sshserver sshd[14365]: Server listening on :: port 22.
