[krbdev.mit.edu #8672] KFW 4.1 credential cache issue

Hong Ye via RT rt-comment at KRBDEV-PROD-APP-1.mit.edu
Fri May 11 12:59:54 EDT 2018 

Hi Greg,

In our code, we use “CUWAkutil”+ threadID in Hex as credential cache name. In kfw-4.1 source code, I added thread ID in hex in trace. Here is the log when running two requests at the same time. At the button of the log in red, you can see thread ID in hex is 880, but it stores cred in credential cache name “CUWAkutil1144”

[5036|880] 1526045678.612023: Getting initial credentials for http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU
[5036|880] 1526045678.612024: Looked up etypes in keytab: aes256-cts, aes128-cts
[5036|880] 1526045678.612026: Sending request (215 bytes) to CIT.CORNELL.EDU
[5036|880] 1526045678.612027: Resolving hostname kerberos.test.login.cornell.edu
[5036|880] 1526045678.612028: Sending initial UDP request to dgram 132.236.200.162:88
[5036|880] 1526045678.628000: Received answer (903 bytes) from dgram 132.236.200.162:88
[5036|1144] 1526045680.299000: Response was not from master KDC
[5036|1144] 1526045680.299001: Processing preauth types: 19
[5036|1144] 1526045680.299002: Selected etype info: etype aes256-cts, salt "CIT.CORNELL.EDUhttp-externalwebauthtest.security.cucloud.net", params ""
[5036|1144] 1526045680.299003: Produced preauth for next request: (empty)
[5036|1144] 1526045680.299004: Getting AS key, salt "CIT.CORNELL.EDUhttp-externalwebauthtest.security.cucloud.net", params ""
[5036|1144] 1526045680.299005: Retrieving http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU from FILE:c:\cuwebauth64\http-external.webauthtest.security.cucloud.net.keytab (vno 0, enctype aes256-cts) with result: 0/Success
[5036|1144] 1526045680.299006: AS key obtained from gak_fct: aes256-cts/0F3F
[5036|1144] 1526045680.299007: Decrypted AS reply; session key is: aes256-cts/67E1
[5036|1144] 1526045680.299008: FAST negotiation: available
[5036|1144] 1526045680.299009: Storing http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> krbtgt/CIT.CORNELL.EDU at CIT.CORNELL.EDU in MEMORY:CUWAkutil1144
[5036|1144] 1526045680.299013: Retrieving http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> permitd/test at CIT.CORNELL.EDU from MEMORY:CUWAkutil1144 with result: -1765328243/Matching credential not found
[5036|1144] 1526045680.299014: Retrieving http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> krbtgt/CIT.CORNELL.EDU at CIT.CORNELL.EDU from MEMORY:CUWAkutil1144 with result: 0/Success
[5036|1144] 1526045680.299015: Starting with TGT for client realm: http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> krbtgt/CIT.CORNELL.EDU at CIT.CORNELL.EDU
[5036|1144] 1526045680.299016: Requesting tickets for permitd/test at CIT.CORNELL.EDU, referrals on
[5036|1144] 1526045680.299017: Generated subkey for TGS request: aes256-cts/DAB5
[5036|1144] 1526045680.299018: etypes requested in TGS request: aes256-cts, aes128-cts, des3-cbc-sha1, rc4-hmac, camellia128-cts, camellia256-cts
[5036|1144] 1526045680.299020: Encoding request body and padata into FAST request
[5036|1144] 1526045680.299021: Sending request (1029 bytes) to CIT.CORNELL.EDU
[5036|1144] 1526045680.299022: Resolving hostname kerberos.test.login.cornell.edu
[5036|1144] 1526045680.299023: Sending initial UDP request to dgram 132.236.200.162:88
[5036|1144] 1526045680.315000: Received answer (1036 bytes) from dgram 132.236.200.162:88
[5036|880] 1526045680.331000: Response was not from master KDC
[5036|880] 1526045680.331001: Processing preauth types: 19
[5036|880] 1526045680.331002: Selected etype info: etype aes256-cts, salt "CIT.CORNELL.EDUhttp-externalwebauthtest.security.cucloud.net", params ""
[5036|880] 1526045680.331003: Produced preauth for next request: (empty)
[5036|880] 1526045680.331004: Getting AS key, salt "CIT.CORNELL.EDUhttp-externalwebauthtest.security.cucloud.net", params ""
[5036|880] 1526045680.331005: Retrieving http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU from FILE:c:\cuwebauth64\http-external.webauthtest.security.cucloud.net.keytab (vno 0, enctype aes256-cts) with result: 0/Success
[5036|880] 1526045680.331006: AS key obtained from gak_fct: aes256-cts/0F3F
[5036|880] 1526045680.331007: Decrypted AS reply; session key is: aes256-cts/4687
[5036|880] 1526045680.331008: FAST negotiation: available
[5036|880] 1526045680.331009: Storing http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> krbtgt/CIT.CORNELL.EDU at CIT.CORNELL.EDU in MEMORY:CUWAkutil880
[5036|880] 1526045680.331013: Retrieving http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> permitd/test at CIT.CORNELL.EDU from MEMORY:CUWAkutil1144 with result: -1765328243/Matching credential not found
[5036|880] 1526045680.331014: Retrieving http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> krbtgt/CIT.CORNELL.EDU at CIT.CORNELL.EDU from MEMORY:CUWAkutil1144 with result: 0/Success
[5036|880] 1526045680.331015: Starting with TGT for client realm: http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> krbtgt/CIT.CORNELL.EDU at CIT.CORNELL.EDU
[5036|880] 1526045680.331016: Requesting tickets for permitd/test at CIT.CORNELL.EDU, referrals on
[5036|880] 1526045680.331017: Generated subkey for TGS request: aes256-cts/1755
[5036|880] 1526045680.331018: etypes requested in TGS request: aes256-cts, aes128-cts, des3-cbc-sha1, rc4-hmac, camellia128-cts, camellia256-cts
[5036|880] 1526045680.331020: Encoding request body and padata into FAST request
[5036|880] 1526045680.331021: Sending request (1029 bytes) to CIT.CORNELL.EDU
[5036|880] 1526045680.331022: Resolving hostname kerberos.test.login.cornell.edu
[5036|880] 1526045680.331023: Sending initial UDP request to dgram 132.236.200.162:88
[5036|880] 1526045680.346000: Received answer (1036 bytes) from dgram 132.236.200.162:88
[5036|1144] 1526045682.2000: Response was not from master KDC
[5036|1144] 1526045682.2001: Decoding FAST response
[5036|1144] 1526045682.2002: FAST reply key: aes256-cts/C081
[5036|1144] 1526045682.2003: TGS reply is for http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> permitd/test at CIT.CORNELL.EDU with session key des3-cbc-sha1/1C04
[5036|1144] 1526045682.2004: TGS request result: 0/Success
[5036|1144] 1526045682.2005: Received creds for desired service permitd/test at CIT.CORNELL.EDU
[5036|1144] 1526045682.2006: Storing http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> permitd/test at CIT.CORNELL.EDU in MEMORY:CUWAkutil1144
[5036|1144] 1526045682.2008: Creating authenticator for http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> permitd/test at CIT.CORNELL.EDU, seqnum 909265593, subkey des3-cbc-sha1/CFDE, session key des3-cbc-sha1/1C04
[5036|1144] 1526045682.18000: Destroying ccache MEMORY:CUWAkutil1144
[5036|880] 1526045682.34000: Response was not from master KDC
[5036|880] 1526045682.34001: Decoding FAST response
[5036|880] 1526045682.34002: FAST reply key: aes256-cts/3F46
[5036|880] 1526045682.34003: TGS reply is for http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> permitd/test at CIT.CORNELL.EDU with session key des3-cbc-sha1/FB4D
[5036|880] 1526045682.34004: TGS request result: 0/Success
[5036|880] 1526045682.34005: Received creds for desired service permitd/test at CIT.CORNELL.EDU
[5036|880] 1526045682.34006: Storing http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> permitd/test at CIT.CORNELL.EDU in MEMORY:CUWAkutil1144

From: Hong Ye <hy93 at cornell.edu>
Date: Wednesday, May 9, 2018 at 12:07 PM
To: Greg Hudson via RT <rt-comment at krbdev.mit.edu>
Subject: Re: [krbdev.mit.edu #8672] KFW 4.1 credential cache issue


Hello,



I had the trace now. Our code is simply doing

code = krb5_init_context(&priv->ctx);

code = krb5_cc_resolve(priv->ctx, cache_name, &priv->cache);

code = gss_krb5_ccache_name(&minor_status, cache_name, NULL);

code = krb5_cc_initialize(priv->ctx, priv->cache, creds.client);

code = gss_init_sec_context(&minor_status, delegate_cred, &priv->ctx,

                                target_name, (gss_OID) gss_mech_krb5, (delegate?GSS_C_DELEG_FLAG:0), GSS_C_INDEFINITE,

                                GSS_C_NO_CHANNEL_BINDINGS, GSS_C_NO_BUFFER, &actual_mech,

                                &priv->buf, &avail_services, NULL);



Sometimes gss_init_sec_context called failed with error “No Credentials cache found”.


Here is the Kerberos trace when it worked. When the “No credentials cache found” error occurred, the whole block in red was missing in the trace. Any idea?

[2736] 1525805800.352010: Getting initial credentials for http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU

[2736] 1525805800.352011: Looked up etypes in keytab: aes256-cts, aes128-cts

[2736] 1525805800.352013: Sending request (215 bytes) to CIT.CORNELL.EDU

[2736] 1525805800.352014: Resolving hostname kerberos.test.login.cornell.edu

[2736] 1525805800.352015: Sending initial UDP request to dgram 132.236.200.162:88

[2736] 1525805800.368000: Received answer (903 bytes) from dgram 132.236.200.162:88

[2736] 1525805802.55000: Response was not from master KDC

[2736] 1525805802.55001: Processing preauth types: 19

[2736] 1525805802.55002: Selected etype info: etype aes256-cts, salt "CIT.CORNELL.EDUhttp-externalwebauthtest.security.cucloud.net", params ""

[2736] 1525805802.55003: Produced preauth for next request: (empty)

[2736] 1525805802.55004: Getting AS key, salt "CIT.CORNELL.EDUhttp-externalwebauthtest.security.cucloud.net", params ""

[2736] 1525805802.55005: Retrieving http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU from FILE:c:\cuwebauth64\http-external.webauthtest.security.cucloud.net.keytab (vno 0, enctype aes256-cts) with result: 0/Success

[2736] 1525805802.55006: AS key obtained from gak_fct: aes256-cts/0F3F

[2736] 1525805802.55007: Decrypted AS reply; session key is: aes256-cts/F497

[2736] 1525805802.55008: FAST negotiation: available

[2736] 1525805802.55009: Storing http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> krbtgt/CIT.CORNELL.EDU at CIT.CORNELL.EDU in MEMORY:CUWAkutilDD4

[2736] 1525805802.55013: Getting credentials http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> permitd/test at CIT.CORNELL.EDU using ccache MEMORY:CUWAkutilDD4

[2736] 1525805802.55014: Retrieving http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> permitd/test at CIT.CORNELL.EDU from MEMORY:CUWAkutilDD4 with result: -1765328243/Matching credential not found

[2736] 1525805802.55015: Retrieving http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> krbtgt/CIT.CORNELL.EDU at CIT.CORNELL.EDU from MEMORY:CUWAkutilDD4 with result: 0/Success

[2736] 1525805802.55016: Starting with TGT for client realm: http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> krbtgt/CIT.CORNELL.EDU at CIT.CORNELL.EDU

[2736] 1525805802.55017: Requesting tickets for permitd/test at CIT.CORNELL.EDU, referrals on

[2736] 1525805802.55018: Generated subkey for TGS request: aes256-cts/FFCF

[2736] 1525805802.55019: etypes requested in TGS request: aes256-cts, aes128-cts, des3-cbc-sha1, rc4-hmac, camellia128-cts, camellia256-cts

[2736] 1525805802.55021: Encoding request body and padata into FAST request

[2736] 1525805802.55022: Sending request (1029 bytes) to CIT.CORNELL.EDU

[2736] 1525805802.55023: Resolving hostname kerberos.test.login.cornell.edu

[2736] 1525805802.55024: Sending initial UDP request to dgram 132.236.200.162:88

[2736] 1525805802.71000: Received answer (1036 bytes) from dgram 132.236.200.162:88

[2736] 1525805803.759000: Response was not from master KDC

[2736] 1525805803.759001: Decoding FAST response

[2736] 1525805803.759002: FAST reply key: aes256-cts/D871

[2736] 1525805803.759003: TGS reply is for http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> permitd/test at CIT.CORNELL.EDU with session key des3-cbc-sha1/28A7

[2736] 1525805803.759004: TGS request result: 0/Success

[2736] 1525805803.759005: Received creds for desired service permitd/test at CIT.CORNELL.EDU

[2736] 1525805803.759006: Storing http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> permitd/test at CIT.CORNELL.EDU in MEMORY:CUWAkutilDD4

[2736] 1525805803.759008: Creating authenticator for http-external/webauthtest.security.cucloud.net at CIT.CORNELL.EDU -> permitd/test at CIT.CORNELL.EDU, seqnum 574934456, subkey des3-cbc-sha1/C958, session key des3-cbc-sha1/28A7

[2736] 1525805803.790000: Destroying ccache MEMORY:CUWAkutilDD4

Thanks,
Hong

More information about the krb5-bugs mailing list