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 apacket"?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 7To get sensible debug output from an sshd of that vintage you will needto 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 enteringPostponed 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 failedFailed 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 enteringPostponed 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 [EMAIL PROTECTED] (krb5_kuserok) debug3: mm_answer_gss_userok: sending result 1 debug3: mm_request_send entering: type 43Accepted 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 authenticatedAccepted 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 receiveddebug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha1,diffie- hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dssdebug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128- cbc,arcfour,aes192-cbc,aes256-cbc,[EMAIL PROTECTED],aes128- ctr,aes192-ctr,aes256-ctr debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128- cbc,arcfour,aes192-cbc,aes256-cbc,[EMAIL PROTECTED],aes128- ctr,aes192-ctr,aes256-ctr debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac- [EMAIL PROTECTED],hmac-sha1-96,hmac-md5-96 debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac- [EMAIL PROTECTED],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 0debug2: 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-rsadebug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128- cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael- [EMAIL PROTECTED],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- [EMAIL PROTECTED],aes128-ctr,aes192-ctr,aes256-ctr debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac- [EMAIL PROTECTED],hmac-sha1-96,hmac-md5-96 debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac- [EMAIL PROTECTED],hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,[EMAIL PROTECTED],zlib debug2: kex_parse_kexinit: none,[EMAIL PROTECTED],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 donedebug1: 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_pwnamallowdebug3: 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 enteringdebug1: 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 enteringPostponed 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 failedFailed 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 ssh2debug1: 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_20debug1: 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
