Re: Problems using gssapi authentication from FreeBSD to Linux machines

On Dec 19, 2006, at 1:12 AM, Darren Tucker wrote:

> Quincey Koziol wrote:
> > On Dec 15, 2006, at 10:32 AM, Simon Wilkinson wrote:
> >
> > > On 15 Dec 2006, at 05:51, Quincey Koziol wrote:
> > > >     Any ideas what could be causing the ssh on FreeBSD to "not  
> > > > send a
> > > > packet"?
> > >
> > > The server failing the authentication, for some reason. More
> > > information as to why will be in the debug logs from the server.
> > >
> > > Whilst OpenSSH 3.9p1 is old (August 2004) - there shouldn't be any
> > > protocol changes between the GSSAPI support in it, and that in the
> > > latest releases.  You don't say what variety (and versions) of
> > > Kerberos you are using on each platform - I assume that FreeBSD is
> > > Heimdal - are your Linux boxes using MIT Kerberos? What encryption
> > > types are you using?
> [...]
> > > Finding out the error messages from the sshd will go a long why to
> > > pointing the finger of blame!
> >
> >     Well, here's the output from "sshd -d -d -d -p 2222" on the  
> > Linux box:
> [...]
> > debug1: rexec start in 4 out 4 newsock 4 pipe -1 sock 7
>
> To get sensible debug output from an sshd of that vintage you will  
> need
> to add "-e" to the command line to force the debug output to stderr.
> (That was fixed in more recent versions.)

Ah!  That certainly does give a lot more information, here's the  
relevent output from a login attempt from the FreeBSD box to the  
Linux box:

debug2: input_userauth_request: try method gssapi-with-mic
debug3: mm_request_send entering: type 38
debug3: mm_request_receive_expect entering: type 39
debug3: mm_request_receive entering
debug3: monitor_read: checking request 38
debug3: mm_request_send entering: type 39
debug3: mm_request_receive entering
Postponed gssapi-with-mic for koziol from ::ffff:192.17.35.73 port  
57823 ssh2
debug3: mm_request_send entering: type 40
debug3: mm_request_receive_expect entering: type 41
debug3: mm_request_receive entering
debug3: monitor_read: checking request 40
debug1: Received some client credentials
debug3: mm_request_send entering: type 41
debug3: mm_request_receive entering
debug3: mm_request_send entering: type 44
debug3: mm_request_receive_expect entering: type 45
debug3: mm_request_receive entering
debug3: monitor_read: checking request 44
debug3: mm_request_send entering: type 45
debug3: mm_request_receive entering
GSSAPI MIC check failed
Failed gssapi-with-mic for koziol from ::ffff:192.17.35.73 port 57823  
ssh2

Here's the similar section from a successful Kerberos authentication  
login from another Linux machine to the same Linux machine as above:

debug2: input_userauth_request: try method gssapi-with-mic
debug3: mm_request_send entering: type 38
debug3: mm_request_receive_expect entering: type 39
debug3: mm_request_receive entering
debug3: monitor_read: checking request 38
debug3: mm_request_send entering: type 39
debug3: mm_request_receive entering
Postponed gssapi-with-mic for koziol from ::ffff:192.17.35.81 port  
5149 ssh2
debug3: mm_request_send entering: type 40
debug3: mm_request_receive_expect entering: type 41
debug3: mm_request_receive entering
debug3: monitor_read: checking request 40
debug1: Received some client credentials
debug3: mm_request_send entering: type 41
debug3: mm_request_receive entering
debug3: mm_request_send entering: type 44
debug3: mm_request_receive_expect entering: type 45
debug3: mm_request_receive entering
debug3: monitor_read: checking request 44
debug3: mm_request_send entering: type 45
debug3: mm_request_receive entering
debug3: mm_request_send entering: type 42
debug3: mm_request_receive_expect entering: type 43
debug3: mm_request_receive entering
debug3: monitor_read: checking request 42
Authorized to koziol, krb5 principal koziol@xxxxxxxxxxxx (krb5_kuserok)
debug3: mm_answer_gss_userok: sending result 1
debug3: mm_request_send entering: type 43
Accepted gssapi-with-mic for koziol from ::ffff:192.17.35.81 port  
5149 ssh2
debug1: monitor_child_preauth: koziol has been authenticated by  
privileged proce
ss
debug3: mm_get_keystate: Waiting for new keys
debug3: mm_request_receive_expect entering: type 25
debug3: mm_request_receive entering
debug3: mm_ssh_gssapi_userok: user authenticated
Accepted gssapi-with-mic for koziol from ::ffff:192.17.35.81 port  
5149 ssh2

I'm having some difficulty following the source code for this, is PAM  
involved somehow? (45 == MONITOR_REQ_PAM_START)  Or, is there  
something else different that's causing the protocol exchange to  
differ and the login from the FreeBSD machine to cause the Linux  
machine to respond "GSSAPI MIC check failed"?

Full output from the FreeBSD login attempt below, in case it's useful.

        Thanks,
                Quincey


debug2: load_server_config: filename /etc/ssh/sshd_config.duty
debug2: load_server_config: done config len = 326
debug2: parse_server_config: config /etc/ssh/sshd_config.duty len 326
debug1: sshd version OpenSSH_3.9p1
debug1: private host key: #0 type 0 RSA1
debug3: Not a RSA1 key file /etc/ssh/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 /etc/ssh/ssh_host_dsa_key.
debug1: read PEM private key done: type DSA
debug1: private host key: #2 type 2 DSA
debug1: rexec_argv[0]='/usr/sbin/sshd'
debug1: rexec_argv[1]='-d'
debug1: rexec_argv[2]='-d'
debug1: rexec_argv[3]='-d'
debug1: rexec_argv[4]='-e'
debug1: rexec_argv[5]='-f'
debug1: rexec_argv[6]='/etc/ssh/sshd_config.duty'
debug1: rexec_argv[7]='-p'
debug1: rexec_argv[8]='2222'
debug2: fd 3 setting O_NONBLOCK
debug1: Bind to port 2222 on ::.
Server listening on :: port 2222.
debug2: fd 4 setting O_NONBLOCK
debug1: Bind to port 2222 on 0.0.0.0.
Bind to port 2222 on 0.0.0.0 failed: Address already in use.
Generating 768 bit RSA key.
RSA key generation complete.
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 326
debug3: ssh_msg_send: type 0
debug3: send_rexec_state: done
debug1: rexec start in 4 out 4 newsock 4 pipe -1 sock 7
debug3: recv_rexec_state: entering fd = 5
debug3: ssh_msg_recv entering
debug3: recv_rexec_state: done
debug2: parse_server_config: config rexec len 326
debug1: sshd version OpenSSH_3.9p1
debug1: private host key: #0 type 0 RSA1
debug3: Not a RSA1 key file /etc/ssh/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 /etc/ssh/ssh_host_dsa_key.
debug1: read PEM private key done: type DSA
debug1: private host key: #2 type 2 DSA
debug1: inetd sockets after dupping: 3, 3
Connection from ::ffff:192.17.35.73 port 57823
debug1: Client protocol version 2.0; client software version  
OpenSSH_4.5p1 FreeBSD-20061110
debug1: match: OpenSSH_4.5p1 FreeBSD-20061110 pat OpenSSH*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-1.99-OpenSSH_3.9p1
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: kex_parse_kexinit: 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-cbc,3des-cbc,blowfish-cbc,cast128- 
cbc,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@xxxxxxxxxxxxxx,aes128- 
ctr,aes192-ctr,aes256-ctr
debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128- 
cbc,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@xxxxxxxxxxxxxx,aes128- 
ctr,aes192-ctr,aes256-ctr
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac- 
ripemd160@xxxxxxxxxxx,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac- 
ripemd160@xxxxxxxxxxx,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- 
sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14- 
sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-dss,ssh-rsa
debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128- 
cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael- 
cbc@xxxxxxxxxxxxxx,aes128-ctr,aes192-ctr,aes256-ctr
debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128- 
cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael- 
cbc@xxxxxxxxxxxxxx,aes128-ctr,aes192-ctr,aes256-ctr
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac- 
ripemd160@xxxxxxxxxxx,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac- 
ripemd160@xxxxxxxxxxx,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib@xxxxxxxxxxx,zlib
debug2: kex_parse_kexinit: none,zlib@xxxxxxxxxxx,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_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
debug2: Network child is on pid 21091
debug3: preauth child monitor started
debug3: mm_request_receive entering
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_request_send entering: type 1
debug2: monitor_read: 0 used once, disabling now
debug3: mm_request_receive entering
debug3: mm_choose_dh: waiting for MONITOR_ANS_MODULI
debug3: mm_request_receive_expect entering: type 1
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: 116/256
debug2: bits set: 514/1024
debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT
debug2: bits set: 513/1024
debug3: mm_key_sign entering
debug3: mm_request_send entering: type 5
debug3: monitor_read: checking request 5
debug3: mm_answer_sign
debug3: mm_answer_sign: signature 0x900fa48(55)
debug3: mm_request_send entering: type 6
debug2: monitor_read: 5 used once, disabling now
debug3: mm_request_receive entering
debug3: mm_key_sign: waiting for MONITOR_ANS_SIGN
debug3: mm_request_receive_expect entering: type 6
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 koziol service ssh-connection  
method none
debug1: attempt 0 failures 0
debug3: mm_getpwnamallow entering
debug3: mm_request_send entering: type 7
debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM
debug3: mm_request_receive_expect entering: type 8
debug3: mm_request_receive entering
debug3: monitor_read: checking request 7
debug3: mm_answer_pwnamallow
debug3: auth_shadow_acctexpired: today 13506 sp_expire -1 days left  
-13507
debug3: account expiration disabled
debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
debug3: mm_request_send entering: type 8
debug2: monitor_read: 7 used once, disabling now
debug3: mm_request_receive entering
debug2: input_userauth_request: setting up authctxt for koziol
debug3: mm_inform_authserv entering
debug3: mm_request_send entering: type 3
debug3: mm_inform_authrole entering
debug3: mm_request_send entering: type 4
debug2: input_userauth_request: try method none
Failed none for koziol from ::ffff:192.17.35.73 port 57823 ssh2
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 4
debug3: mm_answer_authrole: role=
debug2: monitor_read: 4 used once, disabling now
debug3: mm_request_receive entering
debug1: userauth-request for user koziol service ssh-connection  
method gssapi-with-mic
debug1: attempt 1 failures 1
debug2: input_userauth_request: try method gssapi-with-mic
debug3: mm_request_send entering: type 38
debug3: mm_request_receive_expect entering: type 39
debug3: mm_request_receive entering
debug3: monitor_read: checking request 38
debug3: mm_request_send entering: type 39
debug3: mm_request_receive entering
Postponed gssapi-with-mic for koziol from ::ffff:192.17.35.73 port  
57823 ssh2
debug3: mm_request_send entering: type 40
debug3: mm_request_receive_expect entering: type 41
debug3: mm_request_receive entering
debug3: monitor_read: checking request 40
debug1: Received some client credentials
debug3: mm_request_send entering: type 41
debug3: mm_request_receive entering
debug3: mm_request_send entering: type 44
debug3: mm_request_receive_expect entering: type 45
debug3: mm_request_receive entering
debug3: monitor_read: checking request 44
debug3: mm_request_send entering: type 45
debug3: mm_request_receive entering
GSSAPI MIC check failed
Failed gssapi-with-mic for koziol from ::ffff:192.17.35.73 port 57823  
ssh2
debug1: userauth-request for user koziol service ssh-connection  
method password
debug1: attempt 2 failures 2
debug2: input_userauth_request: try method password
debug3: mm_auth_password entering
debug3: mm_request_send entering: type 11
debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD
debug3: mm_request_receive_expect entering: type 12
debug3: mm_request_receive entering
debug3: monitor_read: checking request 11
debug1: temporarily_use_uid: 2519/603 (e=0/0)
debug1: restore_uid: 0/0
debug1: temporarily_use_uid: 2519/603 (e=0/0)
debug1: restore_uid: 0/0
debug3: mm_answer_authpassword: sending result 1
debug3: mm_request_send entering: type 12
Accepted password for koziol from ::ffff:192.17.35.73 port 57823 ssh2
debug1: monitor_child_preauth: koziol has been authenticated by  
privileged process
debug3: mm_get_keystate: Waiting for new keys
debug3: mm_request_receive_expect entering: type 25
debug3: mm_request_receive entering
debug3: mm_auth_password: user authenticated
Accepted password for koziol from ::ffff:192.17.35.73 port 57823 ssh2
debug3: mm_send_keystate: Sending new keys: 0x90108b0 0x90102d8
debug3: mm_newkeys_to_blob: converting 0x90108b0
debug3: mm_newkeys_to_blob: converting 0x90102d8
debug3: mm_send_keystate: New keys have been sent
debug3: mm_send_keystate: Sending compression state
debug3: mm_request_send entering: type 25
debug3: mm_send_keystate: Finished sending state
debug3: mm_newkeys_from_blob: 0x9023698(118)
debug2: mac_init: found hmac-md5
debug3: mm_get_keystate: Waiting for second key
debug3: mm_newkeys_from_blob: 0x9023698(118)
debug2: mac_init: 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: 2519/603
debug2: set_newkeys: mode 0
debug2: set_newkeys: mode 1
debug1: Entering interactive session for SSH2.
debug2: fd 6 setting O_NONBLOCK
debug2: 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
debug2: User child is on pid 21092
debug3: mm_request_receive entering
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.
debug3: mm_request_send entering: type 26
debug3: monitor_read: checking request 26
debug3: mm_answer_pty entering
debug1: session_new: init
debug1: session_new: session 0
debug3: Normalising mapped IPv4 in IPv6 address
debug3: Trying to reverse map address 192.17.35.73.
debug3: mm_pty_allocate: waiting for MONITOR_ANS_PTY
debug3: mm_request_receive_expect entering: type 27
debug3: mm_request_receive entering
debug3: mm_request_send entering: type 27
debug3: mm_answer_pty: tty /dev/pts/5 ptyfd 5
debug3: mm_request_receive entering
debug1: session_pty_req: session 0 alloc /dev/pts/5
debug3: tty_parse_modes: SSH2 n_bytes 251
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
debug1: Ignoring unsupported tty mode opcode 11 (0xb)
debug3: tty_parse_modes: 12 18
debug3: tty_parse_modes: 13 23
debug3: tty_parse_modes: 14 22
debug1: Ignoring unsupported tty mode opcode 17 (0x11)
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: 38 1
debug3: tty_parse_modes: 39 1
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: 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 1
debug3: tty_parse_modes: 70 1
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: temporarily_use_uid: 2519/603 (e=2519/603)
debug1: restore_uid: (unprivileged)
debug1: Setting controlling tty using TIOCSCTTY.
debug2: fd 3 setting TCP_NODELAY
debug2: channel 0: rfd 9 isatty
debug2: fd 9 setting O_NONBLOCK
debug3: fd 8 is O_NONBLOCK
debug1: Received SIGCHLD.
debug2: channel 0: read<=0 rfd 9 len -1
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: session_by_pid: pid 21093
debug1: session_exit_message: session 0 channel 0 pid 21093
debug2: channel 0: request exit-status confirm 0
debug1: session_exit_message: release channel 0
debug2: channel 0: write failed
debug2: channel 0: close_write
debug2: channel 0: output open -> closed
debug1: session_close: session 0 pid 21093
debug3: mm_request_send entering: type 28
debug2: channel 0: send close
debug3: channel 0: will not send data after close
debug3: monitor_read: checking request 28
debug3: mm_answer_pty_cleanup entering
debug1: session_by_tty: session 0 tty /dev/pts/5
debug3: mm_session_close: session 0 pid 21092
debug3: mm_session_close: tty /dev/pts/5 ptyfd 5
debug1: session_pty_cleanup: session 0 release /dev/pts/5
debug3: mm_request_receive entering
debug2: channel 0: rcvd close
debug3: channel 0: will not send data after close
debug2: channel 0: is dead
debug2: channel 0: garbage collecting
debug1: channel 0: free: server-session, nchannels 1
debug3: channel 0: status: The following connections are open:
  #0 server-session (t4 r0 i3/0 o3/0 fd -1/-1 cfd -1)

debug3: channel 0: close_fds r -1 w -1 e -1 c -1
Connection closed by ::ffff:192.17.35.73
debug1: do_cleanup
debug1: krb5_cleanup_proc called
debug1: removing gssapi cred file"/tmp/krb5cc_2519_q21092"
Closing connection to ::ffff:192.17.35.73
debug3: mm_request_send entering: type 57
debug3: monitor_read: checking request 57
debug3: mm_answer_term: tearing down sessions

smime.p7s
Description: S/MIME cryptographic signature