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@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@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@CIT.CORNELL.EDU -> krbtgt/CIT.CORNELL.EDU@CIT.CORNELL.EDU in MEMORY:CUWAkutil1144

[5036|1144] 1526045680.299013: Retrieving http-external/webauthtest.security.cucloud.net@CIT.CORNELL.EDU -> permitd/test@CIT.CORNELL.EDU from MEMORY:CUWAkutil1144 with result: -1765328243/Matching credential not found

[5036|1144] 1526045680.299014: Retrieving http-external/webauthtest.security.cucloud.net@CIT.CORNELL.EDU -> krbtgt/CIT.CORNELL.EDU@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@CIT.CORNELL.EDU -> krbtgt/CIT.CORNELL.EDU@CIT.CORNELL.EDU

[5036|1144] 1526045680.299016: Requesting tickets for permitd/test@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@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@CIT.CORNELL.EDU -> krbtgt/CIT.CORNELL.EDU@CIT.CORNELL.EDU in MEMORY:CUWAkutil880

[5036|880] 1526045680.331013: Retrieving http-external/webauthtest.security.cucloud.net@CIT.CORNELL.EDU -> permitd/test@CIT.CORNELL.EDU from MEMORY:CUWAkutil1144 with result: -1765328243/Matching credential not found

[5036|880] 1526045680.331014: Retrieving http-external/webauthtest.security.cucloud.net@CIT.CORNELL.EDU -> krbtgt/CIT.CORNELL.EDU@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@CIT.CORNELL.EDU -> krbtgt/CIT.CORNELL.EDU@CIT.CORNELL.EDU

[5036|880] 1526045680.331016: Requesting tickets for permitd/test@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@CIT.CORNELL.EDU -> permitd/test@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@CIT.CORNELL.EDU

[5036|1144] 1526045682.2006: Storing http-external/webauthtest.security.cucloud.net@CIT.CORNELL.EDU -> permitd/test@CIT.CORNELL.EDU in MEMORY:CUWAkutil1144

[5036|1144] 1526045682.2008: Creating authenticator for http-external/webauthtest.security.cucloud.net@CIT.CORNELL.EDU -> permitd/test@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@CIT.CORNELL.EDU -> permitd/test@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@CIT.CORNELL.EDU

[5036|880] 1526045682.34006: Storing http-external/webauthtest.security.cucloud.net@CIT.CORNELL.EDU -> permitd/test@CIT.CORNELL.EDU in MEMORY:CUWAkutil1144

 

From: Hong Ye <hy93@cornell.edu>
Date: Wednesday, May 9, 2018 at 12:07 PM
To: Greg Hudson via RT <rt-comment@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@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@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@CIT.CORNELL.EDU -> krbtgt/CIT.CORNELL.EDU@CIT.CORNELL.EDU in MEMORY:CUWAkutilDD4

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

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

[2736] 1525805802.55015: Retrieving http-external/webauthtest.security.cucloud.net@CIT.CORNELL.EDU -> krbtgt/CIT.CORNELL.EDU@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@CIT.CORNELL.EDU -> krbtgt/CIT.CORNELL.EDU@CIT.CORNELL.EDU

[2736] 1525805802.55017: Requesting tickets for permitd/test@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@CIT.CORNELL.EDU -> permitd/test@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@CIT.CORNELL.EDU

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

[2736] 1525805803.759008: Creating authenticator for http-external/webauthtest.security.cucloud.net@CIT.CORNELL.EDU -> permitd/test@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