Problems with kinit invocations

Sun Mar 25 11:46:52 EDT 2018

Hi,

  I’m wondering if someone might be able to provide some help in trying to identify an issue we are having with client authentication via kinit.

  We have a cluster of multiple VMs (linux-based).  One VM is configured as a KDC host, the others with the required kerberos client packages.  The cluster was working as expected for a number of weeks:  clients could invoke ‘kinit <principal>” from the client hosts, provide the password, and successfully receive a ticket.  However, as of late the kinit invocations have started to fail with a "kinit: Generic preauthentication failure while getting initial credentials” error message.  A kinit invocation on the KDC host succeeds.  I have tried the following:

1)  Made sure NTP is running in the cluster and that the clocks on the various hosts are in synch.  They are.
2)  Traced the kinit invocations for both a working kinit invocation (on KDC host) and non-working host.  The one of the non-working host appears to restart the pre-authentication sequence:

working invocation:

80150] 1521574873.153642: Getting initial credentials for ####
[80150] 1521574873.154104: Sending request (292 bytes) to ####
[80150] 1521574873.154322: Resolving hostname ####
[80150] 1521574873.155253: Initiating TCP connection to stream ####
[80150] 1521574873.155359: Sending TCP request to stream ####
[80150] 1521574873.614430: Received answer from stream ####
[80150] 1521574873.614552: Response was not from master KDC
[80150] 1521574873.614597: Received error from KDC: -1765328359/Additional pre-authentication required
[80150] 1521574873.614660: Processing preauth types: 136, 19, 2, 133
[80150] 1521574873.614684: Selected etype info: etype aes128-cts, salt "'h???	Ɋ*5<Ko?^Ӻx???*r\#", params ""
[80150] 1521574873.614692: Received cookie: MIT
[80150] 1521574877.618611: AS key obtained for encrypted timestamp: aes128-cts/B82E
[80150] 1521574877.618662: Encrypted timestamp (for 1521574877.618625): plain 301AA011180F32303138303332303139343131375AA1050203097081, encrypted 0479223B008CB7A6F96EE392F783F93F39585B8D1660381B3E227BC267DA3131B2ADED467A6997D184A7C27DB4B4CBB6595275307EA18B4F
[80150] 1521574877.618682: Preauth module encrypted_timestamp (2) (flags=1) returned: 0/Success
[80150] 1521574877.618687: Produced preauth for next request: 133, 2
[80150] 1521574877.618718: Sending request (385 bytes) to ####
[80150] 1521574877.618751: Resolving hostname ####
[80150] 1521574877.619079: Initiating TCP connection to stream ####
[80150] 1521574877.619129: Sending TCP request to stream ####
[80150] 1521574878.620241: Sending initial UDP request to dgram ####
[80150] 1521574878.774329: Received answer from dgram ####
[80150] 1521574878.774438: Response was not from master KDC
[80150] 1521574878.774482: Processing preauth types: 19
[80150] 1521574878.774496: Selected etype info: etype aes128-cts, salt "'h???	Ɋ*5<Ko?^Ӻx???*r\#", params ""
[80150] 1521574878.774506: Produced preauth for next request: (empty)
[80150] 1521574878.774522: AS key determined by preauth: aes128-cts/B82E
[80150] 1521574878.774604: Decrypted AS reply; session key is: aes128-cts/DEE0
[80150] 1521574878.774636: FAST negotiation: available
[80150] 1521574878.774680: Initializing FILE:/tmp/krb5cc_0 with default princ ####

a failed attempt:

[88371] 1521576411.260486: Getting initial credentials for ####
[88371] 1521576411.260972: Sending request (292 bytes) to ####
[88371] 1521576411.261185: Resolving hostname ####
[88371] 1521576411.262487: Initiating TCP connection to stream ####
[88371] 1521576411.263075: Sending TCP request to stream ####
[88371] 1521576411.865682: Received answer from stream ####
[88371] 1521576411.865815: Response was not from master KDC
[88371] 1521576411.865859: Received error from KDC: -1765328359/Additional pre-authentication required
[88371] 1521576411.865929: Processing preauth types: 136, 19, 2, 133
[88371] 1521576411.865954: Selected etype info: etype aes128-cts, salt "'h???	Ɋ*5<Ko?^Ӻx???*r\#", params ""
[88371] 1521576411.865963: Received cookie: MIT
[88371] 1521576415.513703: AS key obtained for encrypted timestamp: aes128-cts/B82E
[88371] 1521576415.513819: Encrypted timestamp (for 1521576415.513746): plain 301AA011180F32303138303332303230303635355AA105020307D6D2, encrypted CE8492E64612EA10077FEEE1763A74333420F1E845D20B493AC0144A38B3EEBC381F8C496A143AFCFC152F34ED9D9C078AC404A183BC2A0A
[88371] 1521576415.513856: Preauth module encrypted_timestamp (2) (flags=1) returned: 0/Success
[88371] 1521576415.513881: Produced preauth for next request: 133, 2
[88371] 1521576415.513903: Sending request (385 bytes) to ####
[88371] 1521576415.513962: Resolving hostname ####
[88371] 1521576415.514399: Initiating TCP connection to stream ####
[88371] 1521576415.514955: Sending TCP request to stream ####
[88371] 1521576416.516063: Sending initial UDP request to dgram ####
[88371] 1521576416.516402: Received answer from dgram ####
[88371] 1521576416.516550: Response was not from master KDC
[88371] 1521576416.516599: Processing preauth types: 136, 19, 2, 133
[88371] 1521576416.516616: Selected etype info: etype aes128-cts, salt "'h???	Ɋ*5<Ko?^Ӻx???*r\#", params ""
[88371] 1521576416.516626: Received cookie: MIT
[88371] 1521576416.516635: Skipping previously used preauth module encrypted_timestamp (2)
[88371] 1521576416.516663: Produced preauth for next request: 133
[88371] 1521576416.516686: Retrying AS request with master KDC
[88371] 1521576416.516696: Getting initial credentials for ####
[88371] 1521576416.516794: Sending request (292 bytes) to #### (master)

3)  I do see a corresponding failure on the server side, though a ticket does appear to get issued by the KDC (see tcpdump trace info below):

Mar 25 15:02:42 devdatascience-bdcsce-1 krb5kdc[12895](info): AS_REQ (4 etypes {18 17 16 23}) ####: NEEDED_PREAUTH: principal@…. for krbtgt/…@..., Additional pre-authentication required
Mar 25 15:02:42 devdatascience-bdcsce-1 krb5kdc[12895](info): closing down fd 18
Mar 25 15:02:48 devdatascience-bdcsce-1 krb5kdc[12895](info): preauth (encrypted_timestamp) verify failure: Decrypt integrity check failed
Mar 25 15:02:48 devdatascience-bdcsce-1 krb5kdc[12895](info): AS_REQ (4 etypes {18 17 16 23}) ####: PREAUTH_FAILED: principal at ... for krbtgt/…@…., Decrypt integrity check failed
Mar 25 15:02:49 devdatascience-bdcsce-1 krb5kdc[12895](info): closing down fd 18
Mar 25 15:02:49 devdatascience-bdcsce-1 krb5kdc[12895](info): DISPATCH: repeated (retransmitted?) request from ####, resending previous response

4)  As noted, though there is a failure, the sequence of messages and their content seems to indicate that a ticket is being returned as part of the AS-REP:

30	43.343512	##.##.##.##	##.##.##.##	KRB5	368	AS-REQ
32	43.905743	##.##.##.##	##.##.##.##	KRB5	483	KRB Error: KRB5KDC_ERR_PREAUTH_REQUIRED
40	49.140458	##.##.##.##	##.##.##.##	KRB5	461	AS-REQ
42	50.141740	##.##.##.##	##.##.##.##	KRB5	433	AS-REQ
45	50.246960	##.##.##.##	##.##.##.##	KRB5	1109 AS-REP
47	50.248711	##.##.##.##	##.##.##.##	KRB5	1081 AS-REP

5)  The client does appear to send out a series of TCP resets and there is some a retransmission from the server during the reply sequence:

48	50.257059	KDC HOST     CLIENT     TCP	66	[TCP Retransmission] 88→57260 [FIN, ACK] Seq=1044 Ack=397 Win=28032 Len=0 TSval=201965879 TSecr=231179621
49	50.258890	CLIENT	KDC HOST	TCP	54	57260→88 [RST] Seq=397 Win=0 Len=0
50	50.258912	CLIENT	KDC HOST	TCP	54	57260→88 [RST] Seq=397 Win=0 Len=0
51	50.258920	CLIENT	KDC HOST	TCP	54	57260→88 [RST] Seq=397 Win=0 Len=0

6)  The salt being leveraged, as can be seen from above, does not appear to be UTF-8, and I understand could cause issues with certain clients.  It, however, wouldn’t explain why the kinit on the KDC host would work (I don’t believe)

Additional info:

- Version used:  Kerberos 5 version 1.10.3
- The realm to which the principal is authenticating is backed by an LDAP server.  The logging from the LDAP server indicates successful interactions to either lookup or modify the principal’s records.
- Similar clusters deployed to other development and staging environments are not displaying this issue.
- As noted above, kinit attempts on the same cluster were working at one point.  I have been unable to identify any significant changes to the infrastructure that could trigger this issue.
- The KDC is also configured with a realm backed by a local kerberos db.  Kinit invocations from client hosts to authenticate against that realm are working.