Re: Problems with kinit invocations

classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

Re: Problems with kinit invocations

Greg Hudson
Operational questions about MIT krb5 or other Kerberos software should
go to [hidden email], not [hidden email] which is the MIT krb5
development list.  I am CCing this response to [hidden email] 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             [hidden email]
> https://mailman.mit.edu/mailman/listinfo/krbdev
>
________________________________________________
Kerberos mailing list           [hidden email]
https://mailman.mit.edu/mailman/listinfo/kerberos
Reply | Threaded
Open this post in threaded view
|

Re: Problems with kinit invocations

Jonathan Maron


> On Mar 25, 2018, at 4:11 PM, Greg Hudson <[hidden email]> wrote:
>
> Operational questions about MIT krb5 or other Kerberos software should
> go to [hidden email], not [hidden email] which is the MIT krb5
> development list.  I am CCing this response to [hidden email] 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             [hidden email]
>> 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           [hidden email]
https://mailman.mit.edu/mailman/listinfo/kerberos
Reply | Threaded
Open this post in threaded view
|

Re: Problems with kinit invocations

Jonathan Maron
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 <[hidden email]> wrote:
>
>
>
>> On Mar 25, 2018, at 4:11 PM, Greg Hudson <[hidden email]> wrote:
>>
>> Operational questions about MIT krb5 or other Kerberos software should
>> go to [hidden email], not [hidden email] which is the MIT krb5
>> development list.  I am CCing this response to [hidden email] 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             [hidden email]
>>> 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           [hidden email]
https://mailman.mit.edu/mailman/listinfo/kerberos
Reply | Threaded
Open this post in threaded view
|

Re: Problems with kinit invocations

Greg Hudson
On 03/27/2018 02:33 PM, Jonathan Maron wrote:
> 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?

The successful trace log from the original message also showed a
fallback to UDP.

Ignoring that, I don't see how the transport would be relevant, unless
the UDP port were being served by a different KDC process with a
slightly different database.

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

"preauth (encrypted_timestamp) verify failure: Decrypt integrity check
failed" is the expected message when encrypted timestamp is tried with
the wrong key (typically due to the wrong password being entered).
(More recent versions of the KDC would say "Preauthentication failed"
instead.)  I don't know why that's happening, since the same key was
used in the successful and unsuccessful trace logs.  But it also doesn't
account for the weird error processing in the client trace log.
________________________________________________
Kerberos mailing list           [hidden email]
https://mailman.mit.edu/mailman/listinfo/kerberos