I’ve noticed that the kinit failures correlate to situations in which TCP fails
and UDP is used. In every case when the client waits a second and switches to
UDP the kinit invocation fails. Does this ring any bells?
> On Mar 26, 2018, at 10:35 AM, Jonathan Maron <jonathan.ma...@oracle.com>
> wrote:
>
>
>
>> On Mar 25, 2018, at 4:11 PM, Greg Hudson <ghud...@mit.edu> wrote:
>>
>> 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.
>
> 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@... 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://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=
________________________________________________
Kerberos mailing list Kerberos@mit.edu
https://mailman.mit.edu/mailman/listinfo/kerberos
