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.
