MIT Kerberos using invalid in-memory credential cache

[Vipul Mehta]

Hi,

In our service, multiple threads are involved which makes HTTP call to
server via cURL and cURL uses MIT Kerberos. Our service directly uses MIT
Kerberos as well to interact with other services.

Sometimes, assertion is generated from MIT Kerberos and on debugging we
found that invalid(already destroyed) credential cache is being used by MIT
Kerberos. This started to occur when we upgraded cURL from 7.37.1 to 7.68.
Platform - Windows
MIT Kerberos Version - 1.14

I was able to generate stacktrace for the thread which destroys the
in-memory ccache:
19: krb5_cc_destroy - 0x7493EE10,
E:\WS\TPL\10.4.0\MitKerberos\1.14\src\lib\krb5\ccache\ccfns.c:339
18: krb5_gss_release_cred - 0x74FA23C4,
E:\WS\TPL\10.4.0\MitKerberos\1.14\src\lib\gssapi\krb5\rel_cred.c:54
17: gss_release_cred - 0x74F886A4,
E:\WS\TPL\10.4.0\MitKerberos\1.14\src\lib\gssapi\mechglue\g_rel_cred.c:78
16: KerberosGSSCredential::~KerberosGSSCredential - 0x14477D0,
D:\1050PC\build\powrmart\kam_cpp\kam\src\kerberosgsscredential.cpp:47
15: KerberosGSSCredential::`scalar deleting destructor' - 0x1447720
14: KerberosGSSAcceptorSecContext::~KerberosGSSAcceptorSecContext -
0x1447A80,
D:\1050PC\build\powrmart\kam_cpp\kam\src\kerberosgssacceptorseccontext.cpp:51
13: KerberosGSSAcceptorSecContext::`scalar deleting destructor' - 0x1447A40
12: SLoadManager::disposeKerberosAcceptor - 0x400B3470,
D:\1050PC\build\powrmart\server\lm\server.cpp:3709
11: SAuthenticatedKerberosUserGuard::~SAuthenticatedKerberosUserGuard -
0x40012C20, D:\1050PC\build\powrmart\server\lm\authenticatedkerberos.cpp:72
10: SLMConnection::`scalar deleting destructor' - 0x4001CE10
9: SFConnectionManager::releaseConnection - 0xDFF2D0
8: SFConnectionGuard::~SFConnectionGuard - 0xDFC8C0
7: SFThreadJob::operator< - 0xDF4270
6: SFThreadPool::resume - 0xE1AE30
5: ACE_Task_Base::svc_run - 0x58885820
4: ACE_Thread_Adapter::invoke_i - 0x58885DE0
3: ACE_Thread_Adapter::invoke - 0x58885CE0
2: o__realloc_base - 0x78BAFB20
1: BaseThreadInitThunk - 0x7BCD84C0
0: RtlUserThreadStart - 0x7BDD1770

Following is stacktrace from another thread in which ccache destroyed by
above is being used:
37: krb5_cc_store_cred - 0x7493EFB4,
E:\WS\TPL\10.4.0\MitKerberos\1.14\src\lib\krb5\ccache\ccfns.c:379
36: complete - 0x74980B50,
E:\WS\TPL\10.4.0\MitKerberos\1.14\src\lib\krb5\krb\get_creds.c:449
35: step_referrals - 0x74980F18,
E:\WS\TPL\10.4.0\MitKerberos\1.14\src\lib\krb5\krb\get_creds.c:560
34: krb5_tkt_creds_step - 0x7497F8F0,
E:\WS\TPL\10.4.0\MitKerberos\1.14\src\lib\krb5\krb\get_creds.c:1252
33: krb5_tkt_creds_get - 0x7497F5C4,
E:\WS\TPL\10.4.0\MitKerberos\1.14\src\lib\krb5\krb\get_creds.c:1190
32: krb5_get_credentials - 0x7497F284,
E:\WS\TPL\10.4.0\MitKerberos\1.14\src\lib\krb5\krb\get_creds.c:1279
31: get_credentials - 0x74FA3120,
E:\WS\TPL\10.4.0\MitKerberos\1.14\src\lib\gssapi\krb5\init_sec_context.c:195
30: kg_new_connection - 0x74FA3DA4,
E:\WS\TPL\10.4.0\MitKerberos\1.14\src\lib\gssapi\krb5\init_sec_context.c:585
29: krb5_gss_init_sec_context_ext - 0x74FA2A70,
E:\WS\TPL\10.4.0\MitKerberos\1.14\src\lib\gssapi\krb5\init_sec_context.c:985
28: krb5_gss_init_sec_context - 0x74FA2994,
E:\WS\TPL\10.4.0\MitKerberos\1.14\src\lib\gssapi\krb5\init_sec_context.c:1101
27: gss_init_sec_context - 0x74F88860,
E:\WS\TPL\10.4.0\MitKerberos\1.14\src\lib\gssapi\mechglue\g_init_sec_context.c:210
26: init_ctx_call_init - 0x74F9B664,
E:\WS\TPL\10.4.0\MitKerberos\1.14\src\lib\gssapi\spnego\spnego_mech.c:900
25: spnego_gss_init_sec_context - 0x74F96B38,
E:\WS\TPL\10.4.0\MitKerberos\1.14\src\lib\gssapi\spnego\spnego_mech.c:1066
24: gss_init_sec_context - 0x74F88860,
E:\WS\TPL\10.4.0\MitKerberos\1.14\src\lib\gssapi\mechglue\g_init_sec_context.c:210
23: Curl_gss_init_sec_context - 0x59728320,
E:\WS\TPL\10.5.0\cURL\7.68.0\lib\curl_gssapi.c:292
22: Curl_auth_decode_spnego_message - 0x597675E0,
E:\WS\TPL\10.5.0\cURL\7.68.0\lib\vauth\spnego_gssapi.c:172
21: Curl_input_negotiate - 0x5973BFB0,
E:\WS\TPL\10.5.0\cURL\7.68.0\lib\http_negotiate.c:106
20: Curl_output_negotiate - 0x5973C120,
E:\WS\TPL\10.5.0\cURL\7.68.0\lib\http_negotiate.c:151
19: output_auth_headers - 0x5973B3F0,
E:\WS\TPL\10.5.0\cURL\7.68.0\lib\http.c:655
18: Curl_http_output_auth - 0x597399F0,
E:\WS\TPL\10.5.0\cURL\7.68.0\lib\http.c:811
17: Curl_http - 0x59736E50, E:\WS\TPL\10.5.0\cURL\7.68.0\lib\http.c:2126
16: multi_do - 0x597469B0, E:\WS\TPL\10.5.0\cURL\7.68.0\lib\multi.c:1362
15: multi_runsingle - 0x59746E60,
E:\WS\TPL\10.5.0\cURL\7.68.0\lib\multi.c:1836
14: curl_multi_perform - 0x59746140,
E:\WS\TPL\10.5.0\cURL\7.68.0\lib\multi.c:2346
13: easy_transfer - 0x5972CB30, E:\WS\TPL\10.5.0\cURL\7.68.0\lib\easy.c:599
12: easy_perform - 0x5972CA00, E:\WS\TPL\10.5.0\cURL\7.68.0\lib\easy.c:696
11: PcsfProtocol::sendRequest - 0x147F450,
D:\1050PC\build\powrmart\pcsf\common\protocol\pcsfprtcl.cpp:683
10: PcsfCommLib::sendRequest - 0x1475560,
D:\1050PC\build\powrmart\pcsf\common\protocol\pcsfcommlib.cpp:146
9: PcsfLogFileManager::sendRequest - 0x1CAB20
8: PcsfLogFile::sendRequest - 0x1CA910
7: PcsfRemoteLogFile::executeTask - 0x1C8140
6: PcsfLogFileManager::run - 0x1CA5E0
5: PcsfLogFileManager::run - 0x1CA8E0
4: ACE_Thread_Adapter::invoke_i - 0x58885DE0
3: ACE_Thread_Adapter::invoke - 0x58885CE0
2: o__realloc_base - 0x78BAFB20
1: BaseThreadInitThunk - 0x7BCD84C0
0: RtlUserThreadStart - 0x7BDD1770

I have modified ccfns.c file to generate stacktrace so line number won't
match (please see the method name for reference). Exact statement that
gives assertion is :
Assertion failed r==0, at MitKerberos\1.14\src\include\krb5-thread.h line
384
> krb5_64.dll!k5_mutex_lock(k5_os_mutex * m) Line 384 C
  krb5_64.dll!k5_cc_mutex_lock(_krb5_context * context, _k5_cc_mutex * m)
Line 461 C
  krb5_64.dll!krb5_mcc_store(_krb5_context * ctx, _krb5_ccache * id,
_krb5_creds * creds) Line 624 C
  krb5_64.dll!krb5_cc_store_cred(_krb5_context * context, _krb5_ccache *
cache, _krb5_creds * creds) Line 88 C


I am not sure if this is due to some issue in cURL or MIT Kerberos. How MIT
Kerberos keeps track of in memory ccache ? Isn't there mechanism to track
already invalidated ccache and not use it ?

I see that some fix has been done in newer version :
https://github.com/krb5/krb5/commit/146dadec8fe7ccc4149eb2e3f577cc320aee6efb#diff-8f14845d698c6c1242bf1288e7bfec3db113dd57279601af016ec0df4a20949e

Will it help ? How to debug this issue further in our service ?

-- 
Regards,
Vipul