Missing "ticket cache refresh" after ticket expired, additional info
Henning Horst
horst.h at derooter.org
Fri Dec 10 06:01:30 EST 2010
Hi again,
I have captured the logging (please see bottom of mail) of the Network
Identity Manager for the behavior described in my last mail . It
includes a few log messages I wonder about:
1) Debug(1): Skipping credential. Credential expiration is too close to
the identity
2)
10:27:12.370 1632[233] Debug(1): No password entered, but a valid TGT
exists. Continuing
10:27:12.370 1632[233] Debug(1): Tickets successfully acquired
I have tracked down this logmessage to krb5newcreds.c
(src/windows/identity/plugins/krb5/) ll. 2315 (see below) and I am
wondering about this: Why is the dialog shown at all and handling a case
in which it *seems* (will be happy about insights) it is not needed to
show a dialog at all? Or may this be a result of requesting a TGT with
other properties than the one in the cache actually has? Or might this
stand in any connection to the "Skipping credential" message? Here is
the corresponding code:
<code>
/* special case: if there was no password entered, and
if there is a valid TGT we allow the credential
acquisition to go through */
if (g_fjob.state == FIBER_STATE_NONE &&
g_fjob.code &&
g_fjob.null_password &&
(nc->n_identities == 0 ||
nc->identities[0] == NULL ||
KHM_SUCCEEDED(kcdb_credset_find_filtered
(NULL,
-1,
k5_find_tgt_filter,
nc->identities[0],
NULL,
NULL)))) {
_reportf(L"No password entered, but a valid TGT exists.
Continuing");
g_fjob.code = 0;
</code>
Thanks again and looking forward to any ideas and comments...
Regards,
Henning
---<snip>----
10:25:39.260 [224] End
10:25:45.807 [226] Begin: Obtaining new credentials
10:25:45.823 [226] End
10:25:54.120 [227] Begin: Obtaining new credentials for foo at BAR
10:25:54.120 2744[227] Debug(1): Preparing to dispatch batch of
KMSG_CRED_PROCESS messages
10:25:54.120 2744[227] Debug(1): Queuing credtype Kerberos v5(3) for
processing
10:25:54.120 2744[227] Debug(1): Skipping credtype Kerberos v4(4).
Marked as disabled
10:25:54.120 2744[227] Debug(1): Skipping credtype KeyStore(1). Marked
as disabled
10:25:54.135 [228] Begin: Obtaining initial Kerberos v5 tickets (child
of [227])
10:25:54.135 1632[228] Debug(1): Confirming k5_kinit_task [01902CF0] for
principal [foo at BAR]
10:25:55.354 1632[228] Debug(1): Tickets successfully acquired
10:25:55.354 1632[228] Debug(1): Setting CCache [API:foo at BAR] for
identity [foo at BAR]
10:25:55.370 1632[228] Debug(1): Getting tickets from cache [API:foo at BAR]
10:25:55.370 1632[228] Debug(1): Found principal [foo at BAR]
10:25:55.370 1632[228] Debug(1): Ticket [krbtgt/BAR at BAR]
10:25:55.370 1632[228] Debug(1): Setting properties for identity (count=1)
10:25:55.370 1632[228] Info:(Krb5) krb5_cc_resolve() failed. No
credentials cache found (Code=195)
10:25:55.401 1632[228] Debug(1): Attempting to synchronize default
identity into MSLSA:
10:25:55.401 1632[228] Debug(1): Trying to copy CC API:foo at BAR to MSLSA:
10:25:55.541 1632[228] Info:(Krb5) krb5_cc_resolve() for dest failed. No
credentials cache found (Code=195)
10:25:55.541 [228] End
10:25:55.541 1632[227] Info:(Krb5) krb5_cc_resolve() for dest failed. No
credentials cache found (Code=195)
10:25:55.541 2020[227] Debug(1): Preparing to dispatch batch of
KMSG_CRED_PROCESS messages
10:25:55.557 2020[227] Debug(1): Skipping credtype Kerberos v5(3).
Marked as processed
10:25:55.557 2020[227] Debug(1): Skipping credtype Kerberos v4(4).
Marked as disabled
10:25:55.557 2020[227] Debug(1): Skipping credtype KeyStore(1). Marked
as disabled
10:25:55.557 2020[227] Debug(1): Done with processing
10:25:56.010 [227] End
10:26:00.370 [229] Begin: Refreshing timers
10:26:00.370 2744[229] Debug(1):(NetIDMgr) Starting with 0 timers
10:26:00.370 2744[229] Debug(1): Looking at cred [krbtgt/BAR at BAR]
10:26:00.370 2744[229] Debug(1): Updating identity marker timer for
[foo at BAR]. Expires at (unspecified)
10:26:00.370 2744[229] Debug(1): Updating identity timers ...
10:26:00.370 2744[229] Debug(1): Updating identity renewal timer for
[foo at BAR]. Expires at Friday, Decem
ber 10, 2010 3:26:10 PM
10:26:00.370 2744[229] Debug(1): Skipping credential. Credential
expiration is too close to the identity expiration
10:26:00.370 [230] Begin: Checking for expired timers (child of [229])
10:26:00.370 [230] End
10:26:00.370 2744[229] Debug(1):(NetIDMgr) Leaving with 2 timers
10:26:00.370 2744[229] (NetIDMgr) Checking for expired timers
10:26:00.370 [229] End
10:26:21.354 [231] Begin: Obtaining new credentials
10:26:21.401 [231] End
10:27:12.370 [232] Begin: Obtaining new credentials for foo at BAR
10:27:12.370 2744[232] Debug(1): Preparing to dispatch batch of
KMSG_CRED_PROCESS messages
10:27:12.370 2744[232] Debug(1): Queuing credtype Kerberos v5(3) for
processing
10:27:12.370 2744[232] Debug(1): Skipping credtype Kerberos v4(4).
Marked as disabled
10:27:12.370 2744[232] Debug(1): Skipping credtype KeyStore(1). Marked
as disabled
10:27:12.370 [233] Begin: Obtaining initial Kerberos v5 tickets (child
of [232])
10:27:12.370 1632[233] Debug(1): Confirming k5_kinit_task [0191A208] for
principal [foo at BAR]
10:27:12.370 1632[233] Debug(1): No password entered, but a valid TGT
exists. Continuing
10:27:12.370 1632[233] Debug(1): Tickets successfully acquired
10:27:12.385 1632[233] Debug(1): Setting CCache [API:foo at BAR] for
identity [foo at BAR]
10:27:12.385 1632[233] Debug(1): Getting tickets from cache [API:foo at BAR]
10:27:12.385 1632[233] Debug(1): Found principal [foo at BAR]
10:27:12.385 1632[233] Debug(1): Ticket [krbtgt/BAR at BAR]
10:27:12.385 1632[233] Debug(1): Setting properties for identity (count=1)
10:27:12.385 1632[233] Info:(Krb5) krb5_cc_resolve() failed. No
credentials cache found (Code=195)
10:27:12.385 1632[233] Debug(1): Attempting to synchronize default
identity into MSLSA:
10:27:12.385 1632[233] Debug(1): Trying to copy CC API:foo at BAR to MSLSA:
10:27:12.385 1632[233] Info:(Krb5) krb5_cc_resolve() for dest failed. No
credentials cache found (Code=195)
10:27:12.385 [233] End
10:27:12.385 1632[232] Info:(Krb5) krb5_cc_resolve() for dest failed. No
credentials cache found (Code=195)
10:27:12.385 2020[232] Debug(1): Preparing to dispatch batch of
KMSG_CRED_PROCESS messages
10:27:12.385 2020[232] Debug(1): Skipping credtype Kerberos v5(3).
Marked as processed
10:27:12.385 2020[232] Debug(1): Skipping credtype Kerberos v4(4).
Marked as disabled
10:27:12.385 2020[232] Debug(1): Skipping credtype KeyStore(1). Marked
as disabled
10:27:12.385 2020[232] Debug(1): Done with processing
10:27:12.401 [232] End
10:37:17.651 [234] Begin: Refreshing timers
10:37:17.651 2744[234] Debug(1):(NetIDMgr) Starting with 2 timers
10:37:17.651 2744[234] Debug(1): Looking at cred [krbtgt/BAR at BAR]
10:37:17.651 2744[234] Debug(1): Updating identity marker timer for
[foo at BAR]. Expires at (unspecified)
10:37:17.651 2744[234] Debug(1): Updating identity timers ...
10:37:17.651 2744[234] Debug(1): Updating identity renewal timer for
[foo at BAR]. Expires at Friday, Decem
ber 10, 2010 3:26:10 PM
10:37:17.651 2744[234] Debug(1): Skipping credential. Credential
expiration is too close to the identity expiration
10:37:17.651 2744[234] Debug(1): Looking at cred [host/npns01 at BAR]
10:37:17.651 2744[234] Debug(1): Updating identity marker timer for
[foo at BAR]. Expires at (unspecified)
10:37:17.651 2744[234] Debug(1): Skipping credential. Credential
expiration is too close to the identity expiration
10:37:17.651 [235] Begin: Checking for expired timers (child of [234])
10:37:17.651 [235] End
10:37:17.651 2744[234] Debug(1):(NetIDMgr) Leaving with 2 timers
10:37:17.651 2744[234] (NetIDMgr) Checking for expired timers
10:37:17.651 [234] End
---</snip>----
More information about the kfwdev
mailing list