Operational questions about MIT krb5 or other Kerberos software should
go to kerberos@mit.edu, not krb...@mit.edu which is the MIT krb5
development list.  I am CCing this response to kerberos@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.

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@... 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             krb...@mit.edu
> https://mailman.mit.edu/mailman/listinfo/krbdev
> 
________________________________________________
Kerberos mailing list           Kerberos@mit.edu
https://mailman.mit.edu/mailman/listinfo/kerberos

Reply via email to