Problems with kinit invocations

Mon Mar 26 10:35:11 EDT 2018

> On Mar 25, 2018, at 4:11 PM, Greg Hudson <ghudson at mit.edu> wrote:
> 
> Operational questions about MIT krb5 or other Kerberos software should
> go to kerberos at mit.edu, not krbdev at mit.edu which is the MIT krb5
> development list.  I am CCing this response to kerberos at mit.edu with the
> full question quoted.
> 
> I see several things here which look a bit off, but no smoking gun:
> 
> * I am curious how you wound up with a binary salt string for this
> principal.  But only RC4 keys are required to have UTF-8 salt strings,
> and the successful and failing cases compute the same AS key
> ("aes128-cts/B82E" appears in both traces; B82E is an abbreviated hash
> of the key).  So I don't think that's the problem.
> 
> * 1.10 is about six years old at this point, but I don't know of any bug
> in 1.10.3 which would account fot these symptoms.  A 1.16 client would
> have somewhat better trace logging, if you want to try it.
> 
> * The client configuration appears to prefer TCP, but doesn't appear to
> be able to contact the KDC via TCP, so it waits a second and falls back
> to UDP.  That's not likely to be related to the problem, though.
> 
> * Perhaps most confusingly, in the failing trace log, there is no
> "Received error from KDC: ..." line after the "Received answer" line for
> the preauthenticated request, but the padata in the next "Processing
> preauth types:" message appears to be a padata list which would
> accompany a PREAUTH_REQUIRED or PREAUTH_FAILED error, and the way the
> client process it (particularly where it skips over encrypted timestamp)
> also suggests the client believes it is processing padata in an error.
> I can't really account for that.

Could the error processing be related to the decrypt integrity check failure noted in the server log?

> 
> On 03/25/2018 11:46 AM, Jonathan Maron wrote:
>> 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.
>> 
>> 
>> _______________________________________________
>> krbdev mailing list             krbdev at mit.edu
>> https://urldefense.proofpoint.com/v2/url?u=https-3A__mailman.mit.edu_mailman_listinfo_krbdev&d=DwIDaQ&c=RoP1YumCXCgaWHvlZYR8PZh8Bv7qIrMUB65eapI_JnE&r=3NQsp6PIYxO7VWBohwGYHIBt64VaQ9OvKYbnE9oOezg&m=CH8mTWKrFgFEwy-WTAvMIYU4GnfGBFeQahZGMueclnQ&s=HFStDWEMIfFP-1XF_6Rrc_mW_6byQPMjKg-wsM17RWI&e=
>> 