ssh gssapi-with-mic and "Key table entry not found"

[Matt Garman]

Hi,

I'm trying to get ssh working using gssapi-with-mic authentication. I have
about 40 machines running CentOS 5.7. (My bigger goal is to use NFSv4
mounts with "krb5p" security. All these machines mount the same NFSv4 share
(think home directories) so my users need to be able to forward their TGT
around.)

What I'm ultimately running into is sshd complaining "Key table entry not
found" on *most* of the servers---a random handful work, and I can't figure
out how the working ones are different.

So, here's an example: I'm trying to ssh from "lnxsvr3" to "lnxsvr11" using
gssapi-with-mic authentication.

Here's the output of trying to ssh:
[matt@lnxsvr3 ~]$ ssh -v -o"PreferredAuthentications
gssapi-with-mic" lnxsvr11
OpenSSH_4.3p2, OpenSSL 0.9.8e-fips-rhel5 01 Jul 2008
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: Applying options for *
debug1: Connecting to lnxsvr11 [192.168.187.67] port 22.
debug1: Connection established.
debug1: identity file /mnt/home/matt/.ssh/identity type -1
debug1: identity file /mnt/home/matt/.ssh/id_rsa type 1
debug1: identity file /mnt/home/matt/.ssh/id_dsa type -1
debug1: loaded 3 keys
debug1: Remote protocol version 2.0, remote software version OpenSSH_4.3
debug1: match: OpenSSH_4.3 pat OpenSSH*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_4.3
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug1: kex: server->client aes128-ctr hmac-md5 none
debug1: kex: client->server aes128-ctr hmac-md5 none
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
debug1: Host 'lnxsvr11' is known and matches the RSA host key.
debug1: Found key in /mnt/home/matt/.ssh/known_hosts:207
debug1: ssh_rsa_verify: signature correct
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug1: SSH2_MSG_NEWKEYS received
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug1: Authentications that can continue:
publickey,gssapi-with-mic,password
debug1: Next authentication method: gssapi-with-mic
debug1: Delegating credentials
debug1: Authentications that can continue:
publickey,gssapi-with-mic,password
debug1: Authentications that can continue:
publickey,gssapi-with-mic,password
debug1: Authentications that can continue:
publickey,gssapi-with-mic,password
debug1: No more authentication methods to try.
Permission denied (publickey,gssapi-with-mic,password).

On the server side, /var/log/secure, with sshd running with LogLevel DEBUG:
Aug 7 11:53:06 lnxsvr11 sshd[4998]: debug1: rexec start in 4 out
4 newsock 4 pipe 6 sock 7
Aug 7 11:53:06 lnxsvr11 sshd[4804]: debug1: Forked child 4998.
Aug 7 11:53:06 lnxsvr11 sshd[4998]: debug1: inetd sockets after
dupping: 3, 3
Aug 7 11:53:06 lnxsvr11 sshd[4998]: Connection from
192.168.187.61 port 43559
Aug 7 11:53:06 lnxsvr11 sshd[4998]: debug1: Client protocol
version 2.0; client software version OpenSSH_4.3
Aug 7 11:53:06 lnxsvr11 sshd[4998]: debug1: match: OpenSSH_4.3 pat OpenSSH*
Aug 7 11:53:06 lnxsvr11 sshd[4998]: debug1: Enabling
compatibility mode for protocol 2.0
Aug 7 11:53:06 lnxsvr11 sshd[4998]: debug1: Local version string
SSH-2.0-OpenSSH_4.3
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: permanently_set_uid: 74/74
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: list_hostkey_types:
ssh-rsa,ssh-dss
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: SSH2_MSG_KEXINIT sent
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: SSH2_MSG_KEXINIT received
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: kex: client->server
aes128-ctr hmac-md5 none
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: kex: server->client
aes128-ctr hmac-md5 none
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1:
SSH2_MSG_KEX_DH_GEX_REQUEST received
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: expecting
SSH2_MSG_KEX_DH_GEX_INIT
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: SSH2_MSG_NEWKEYS sent
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: expecting SSH2_MSG_NEWKEYS
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: SSH2_MSG_NEWKEYS received
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: KEX done
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: userauth-request for
user matt service ssh-connection method none
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: attempt 0 failures 0
Aug 7 11:53:06 lnxsvr11 sshd[4998]: debug1: PAM: initializing for "matt"
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: userauth-request for
user matt service ssh-connection method gssapi-with-mic
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: attempt 1 failures 1
Aug 7 11:53:06 lnxsvr11 sshd[4998]: debug1: PAM: setting
PAM_RHOST to "lnxsvr3.mydomain.com"
Aug 7 11:53:06 lnxsvr11 sshd[4998]: debug1: PAM: setting PAM_TTY to "ssh"
Aug 7 11:53:06 lnxsvr11 sshd[5001]: Postponed gssapi-with-mic for
matt from 192.168.187.61 port 43559 ssh2
Aug 7 11:53:06 lnxsvr11 sshd[4998]: debug1: Unspecified GSS
failure. Minor code may provide more information\nKey table entry not
found\n
Aug 7 11:53:06 lnxsvr11 sshd[4998]: debug1: Got no client credentials
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: userauth-request for
user matt service ssh-connection method gssapi-with-mic
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: attempt 2 failures 2
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: userauth-request for
user matt service ssh-connection method gssapi-with-mic
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: attempt 3 failures 3
Aug 7 11:53:06 lnxsvr11 sshd[5001]: Connection closed by 192.168.187.61
Aug 7 11:53:06 lnxsvr11 sshd[5001]: debug1: do_cleanup
Aug 7 11:53:06 lnxsvr11 sshd[4998]: debug1: do_cleanup
Aug 7 11:53:06 lnxsvr11 sshd[4998]: debug1: PAM: cleanup

Based on the web searching I've done for this issue, it seems the most common
culprit is DNS issues. But as far as I can tell, my /etc/hosts and DNS are
set up correctly and in agreement. So here is the output of various commands
on lnxsvr11:

[root@lnxsvr11 ~]# klist -ekt
Keytab name: FILE:/etc/krb5.keytab
KVNO Timestamp Principal
---- -----------------
--------------------------------------------------------
5 08/07/12 11:39:04 host/lnxsvr11.m...@MYDOMAIN.COM
(DES cbc mode with CRC-32)
5 08/07/12 11:39:45 nfs/lnxsvr11.m...@MYDOMAIN.COM (DES
cbc mode with CRC-32)

[root@lnxsvr11 ~]# hostname
lnxsvr11.mydomain.com
[root@lnxsvr11 ~]# hostname
lnxsvr11
[root@lnxsvr11 ~]# hostname -s
lnxsvr11
[root@lnxsvr11 ~]# hostname -f
lnxsvr11.mydomain.com

[root@lnxsvr11 ~]# grep 192.168.187.67 /etc/hosts
192.168.187.67 lnxsvr11.mydomain.com lnxsvr11
[root@lnxsvr11 ~]# grep "lnxsvr11\." /etc/hosts
192.168.187.67 lnxsvr11.mydomain.com lnxsvr11
[root@lnxsvr11 ~]# grep "lnxsvr11$" /etc/hosts
192.168.187.67 lnxsvr11.mydomain.com lnxsvr11

[root@lnxsvr11 ~]# dig -x 192.168.187.67

; <<>> DiG 9.3.6-P1-RedHat-9.3.6-16.P1.el5 <<>> -x 192.168.187.67
;; global options: printcmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 13806
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 1, ADDITIONAL: 1

;; QUESTION SECTION:
;67.187.168.192.in-addr.arpa. IN PTR

;; ANSWER SECTION:
67.187.168.192.in-addr.arpa. 604800 IN PTR lnxsvr11.mydomain.com.

;; AUTHORITY SECTION:
187.168.192.in-addr.arpa. 604800 IN NS ns1.mydomain.com.

;; ADDITIONAL SECTION:
ns1.mydomain.com. 604800 IN A 192.168.184.7

;; Query time: 1 msec
;; SERVER: 192.168.184.7#53(192.168.184.7)
;; WHEN: Tue Aug 7 11:59:35 2012
;; MSG SIZE rcvd: 120

Can anyone see anything obvious that I'm missing?

Thanks,
Matt

[Simo Sorce]

What does the 'hostname' command return on your machine ?

Simo.

--
Simo Sorce * Red Hat, Inc * New York

[Matt Garman]

On Tue, Aug 7, 2012 at 12:49 PM, Simo Sorce <si...@redhat.com> wrote:
> What does the 'hostname' command return on your machine ?
>
> Simo.

[root@lnxsvr11 ~]# hostname
lnxsvr11

[root@lnxsvr11 ~]# hostname -s
lnxsvr11

[root@lnxsvr11 ~]# hostname -f
lnxsvr11.mydomain.com

-Matt

[Simo Sorce]

Does ssh works if you change the hostname to be the fully qualified
hostname ? (-f doesn't really count)

[Matt Garman]

On Tue, Aug 7, 2012 at 1:21 PM, Simo Sorce <si...@redhat.com> wrote:
> On Tue, 2012-08-07 at 12:58 -0500, Matt Garman wrote:
>> On Tue, Aug 7, 2012 at 12:49 PM, Simo Sorce <si...@redhat.com> wrote:
>> > What does the 'hostname' command return on your machine ?
>> >

>> [root@lnxsvr11 ~]# hostname
>> lnxsvr11
>>
>> [root@lnxsvr11 ~]# hostname -s
>> lnxsvr11
>>
>> [root@lnxsvr11 ~]# hostname -f
>> lnxsvr11.mydomain.com
>>
>
> Does ssh works if you change the hostname to be the fully qualified
> hostname ? (-f doesn't really count)

No. I did a "hostname lnxsvr11.mydomain.com". Then "hostname" alone
returns the same as with -f. In the same shell, I started a new sshd
on a unique port. I then tried to ssh in again (on the special port),
and the result is the same.

Thanks again!
Matt

[Greg Hudson]

On 08/07/2012 01:23 PM, Matt Garman wrote:
> [root@lnxsvr11 ~]# grep 192.168.187.67 /etc/hosts
> 192.168.187.67 lnxsvr11.mydomain.com lnxsvr11
> [root@lnxsvr11 ~]# grep "lnxsvr11\." /etc/hosts
> 192.168.187.67 lnxsvr11.mydomain.com lnxsvr11
> [root@lnxsvr11 ~]# grep "lnxsvr11$" /etc/hosts
> 192.168.187.67 lnxsvr11.mydomain.com lnxsvr11

I didn't see a smoking gun in the output you sent, but here are some
pointers. You need the following three things to match:

1. The canonicalization of lnxsvr11 on the client
2. The canonicalization of the result of gethostname() on the server
3. The hostname in the keytab entry

By default, canonicalization is done using getaddrinfo() forward
resolution and then getnameinfo() reverse resolution. Depending on the
Kerberos version, canonicalization may or may not be restricted to IPv4
lookups. (2) can be ignored if your sshd has sxw's patches using the
"GSSAPIStrictAcceptorCheck no" option, but I don't think CentOS 5.7's
build of sshd has those patches.

You can see what (1) is by running klist on the client after attempting
the ssh. That would be useful information for debugging this problem.

You should be able to see what (2) is on the server by getting tickets
for somebody and then running "kvno -S host lnxsvr11" and seeing what
principal that gets (or tries to get) server tickets for. (There are
easier ways to do this with more recent versions of MIT Kerberos--in 1.9
or later, it would appear in the sshd debug output, for instance. But
CentOS only has krb5 1.6.1 as far as I can tell.)

It's of course easy to see what (3) is, and you've already provided that.

[Matt Garman]

Now it is magically working, and in fact, it is working for all machines.

I was having the problem yesterday, and the last thing I did was send
the last email to this list. I went home, came in this morning to
work through your suggestions, but the problem no longer exists.

I tried another machine: it didn't work, but I didn't have the
"host/hostname" principal's key exported to the keytab file. So I
went through all machines and made sure they had the "host/hostname"
key in the keytab.

On that last remaining non-working target machine, I did a "klist
-kte" and realized I had exported the "nfs/hostname" key to the keytab
twice, instead of "nfs/hostname" and "host/hostname". I fixed the
keytab, restarted sshd, yet the problem persisted. So I was gearing
up to work through your suggestions, but I thought maybe my original
TGT (on lnxsvr3) was somehow messed up. So I did a kdestroy followed
by kinit, then logged into that machine successfully.

I don't know enough about how Kerberos works, but I'll speculate a
guess as to what was wrong yesterday: after a failed gssapi-with-mic
login attempt, some "residual stuff" gets attached to the original
TGT, some kind of "cache" of the "permission denied" situation. IOW,
no matter what I do on the target machine, that the client still
"remembers" it didn't work means it continues to not work, until the
ticket is destroyed or expires (and my tickets are currently set to
the default 24h expiry). Note that all that is a guess, maybe the
more knowledgeable folks can confirm (assuming you can make sense of
what I'm trying to convey!).

If nothing else, it seems that when troubleshooting these kinds of
issues in the future, I should always do a kdestroy, kinit between
each ssh attempt.

Thanks again for your help Simo and Greg.
-Matt

[Greg Hudson]

On 08/08/2012 12:03 PM, Matt Garman wrote:
> I don't know enough about how Kerberos works, but I'll speculate a
> guess as to what was wrong yesterday: after a failed gssapi-with-mic
> login attempt, some "residual stuff" gets attached to the original
> TGT, some kind of "cache" of the "permission denied" situation.

There's no cache for failure, but there is a cache of service tickets.
For example, if you ssh to a host, then roll over the host's key without
keeping the old key in the host's keytab, then ssh to it again, you will
get a failure because the client has a cached ticket encrypted in the
old key. Running kdestroy and kinit (or just kinit) gets rid of any
cached services tickets. This is why, by default, kadmin ktadd adds to
the existing keytab rather than overwriting it.

If the server is running krb5 1.7 or later, this kind of problem should
result in a "Wrong principal in request" error in the sshd output (which
is still not very clear, but at least helps distinguish the problem from
sshd trying to acquire the wrong credentials). If the server is running
krb5 1.6.x (as in your case), the error will be "Key able entry not found".

[Greg Hudson]

On 08/08/2012 12:33 PM, Greg Hudson wrote:
> If the server is running krb5 1.7 or later, this kind of problem should
> result in a "Wrong principal in request" error in the sshd output (which
> is still not very clear, but at least helps distinguish the problem from
> sshd trying to acquire the wrong credentials). If the server is running
> krb5 1.6.x (as in your case), the error will be "Key able entry not found".

Apologies; I made a mistake when reading the 1.6.x code. In krb5 1.6.x,
the error in this situation will be "Key version number for principal in
key table is incorrect", which is pretty clear. So perhaps your
problems yesterday were not the result of key version mismatches, since
you were getting "Key table entry not found" errors.

(I was right about what the error will be in 1.7.x or later. This is a
regression, and I'll open a bug about it. But that problem is not
germane to your situation.)