[32139] in Kerberos
Re: KfW killing Cisco VPN under Windows 7
daemon@ATHENA.MIT.EDU (Jeff Blaine)
Fri Mar 12 22:20:04 2010
Message-ID: <4B9B0457.2020001@kickflop.net>
Date: Fri, 12 Mar 2010 22:19:51 -0500
From: Jeff Blaine <jblaine@kickflop.net>
MIME-Version: 1.0
To: kerberos@mit.edu
Content-Type: multipart/mixed; boundary="------------070308010401060400080408"
Errors-To: kerberos-bounces@mit.edu
This is a multi-part message in MIME format.
--------------070308010401060400080408
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: 7bit
Here's the nidmdbg.log FWIW
22:10 is a clean instance of VPN running, "Obtain new credentials",
and VPN being killed.
--------------070308010401060400080408
Content-Type: text/plain;
name="nidmdbg.log"
Content-Transfer-Encoding: 8bit
Content-Disposition: attachment;
filename="nidmdbg.log"
Logging started for Network Identity Manager at 2010-3-12 22:08:24.221
Product: NetIDMgr 2.0.0.304
Copyright © 2006-2010 Secure Endpoints Inc.
Official build. Please send bug reports to netidmgr@secure-endpoints.com
Logon session: [jblaine]@[MM160939-PC]
UPN: []
Logon server: [MM160939-PC] @[]
Authentication package: [NTLM]
Authentication package: [NTLM], Logon Type: Interactive
Token privileges:
: SeShutdownPrivilege (Disabled)
: SeChangeNotifyPrivilege (Enabled)
: SeUndockPrivilege (Disabled)
: SeIncreaseWorkingSetPrivilege (Disabled)
: SeTimeZonePrivilege (Disabled)
Process tokens have no admin privileges.
22:08:24.221 Begin logging
22:08:24.237 [1] Begin: Load default modules
22:08:24.237 [2] Begin: Initializing module [OpenAFS] (child of [1])
22:08:24.253 [3] Begin: Initializing plug-in [AfsCred] (child of [2])
22:08:24.253 2600[3] Info:(KMM) Placing plug-in [AfsCred] on hold
22:08:24.253 2600[3] Info:(KMM) Leaving plug-in [AfsCred] in state [4]
22:08:24.253 [3] End
22:08:24.253 2600[2] Info:(KMM) Module [OpenAFS] is in state [4]
22:08:24.253 [2] End
22:08:24.253 [4] Begin: Initializing module [MITKrb5] (child of [1])
22:08:24.253 [5] Begin: Initializing plug-in [Krb5Ident] (child of [4])
22:08:24.253 2600[5] Info:(KMM) Placing plug-in [Krb5Ident] on hold
22:08:24.253 2600[5] Info:(KMM) Leaving plug-in [Krb5Ident] in state [4]
22:08:24.253 [5] End
22:08:24.253 [6] Begin: Initializing plug-in [Krb5Cred] (child of [4])
22:08:24.253 2600[6] Info:(KMM) Leaving plug-in [Krb5Cred] in state [5]
22:08:24.253 [6] End
22:08:24.253 2600[4] Info:(KMM) Module [MITKrb5] is in state [4]
22:08:24.253 [4] End
22:08:24.253 [7] Begin: Initializing module [MITKrb4] (child of [1])
22:08:24.253 [8] Begin: Starting plug-in [Krb5Cred]
22:08:24.253 972[8] Info:(KMM) Initialization of the plug-in returned code 0.
22:08:24.253 972[8] Info:(KMM) Plug-in running
22:08:24.253 [8] End
22:08:24.253 [9] Begin: Initializing plug-in [Krb4Cred] (child of [7])
22:08:24.253 2600[9] Info:(KMM) Leaving plug-in [Krb4Cred] in state [5]
22:08:24.253 [9] End
22:08:24.253 2600[7] Info:(KMM) Module [MITKrb4] is in state [4]
22:08:24.253 [7] End
22:08:24.253 [10] Begin: Initializing module [KeyStore] (child of [1])
22:08:24.253 [11] Begin: Starting plug-in [Krb4Cred]
22:08:24.253 [12] Begin: Initializing plug-in [KeyStoreCred] (child of [10])
22:08:24.253 2600[12] Info:(KMM) Leaving plug-in [KeyStoreCred] in state [5]
22:08:24.253 [12] End
22:08:24.253 [13] Begin: Initializing plug-in [KeyStoreIdentity] (child of [10])
22:08:24.253 2600[13] Info:(KMM) Placing plug-in [KeyStoreIdentity] on hold
22:08:24.253 2600[13] Info:(KMM) Leaving plug-in [KeyStoreIdentity] in state [4]
22:08:24.253 [13] End
22:08:24.253 2600[10] Info:(KMM) Module [KeyStore] is in state [4]
22:08:24.253 [10] End
22:08:24.253 [1] End
22:08:24.253 [14] Begin: Initializing plug-in [AfsCred]
22:08:24.253 2600[14] Info:(KMM) Leaving plug-in [AfsCred] in state [5]
22:08:24.253 [14] End
22:08:24.253 [15] Begin: Initializing plug-in [Krb5Ident]
22:08:24.253 2600[15] Info:(KMM) Leaving plug-in [Krb5Ident] in state [5]
22:08:24.253 [15] End
22:08:24.253 [16] Begin: Starting plug-in [AfsCred]
22:08:24.253 [17] Begin: Starting plug-in [KeyStoreCred]
22:08:24.253 1244[17] Info:(KMM) Initialization of the plug-in returned code 0.
22:08:24.253 1244[17] Info:(KMM) Plug-in running
22:08:24.253 [17] End
22:08:24.253 [18] Begin: Initializing plug-in [KeyStoreIdentity]
22:08:24.253 [19] Begin: Starting plug-in [Krb5Ident]
22:08:24.253 2920[19] Info:(KMM) Initialization of the plug-in returned code 0.
22:08:24.253 [20] Begin: Refreshing default identity (child of [19])
22:08:24.253 3304[11] Info:(KMM) Initialization of the plug-in returned code 0.
22:08:24.253 3304[11] Info:(KMM) Plug-in running
22:08:24.253 [11] End
22:08:24.253 2600[18] Info:(KMM) Leaving plug-in [KeyStoreIdentity] in state [5]
22:08:24.253 [18] End
22:08:24.253 [21] Begin: Starting plug-in [KeyStoreIdentity]
22:08:24.253 2336[21] Info:(KMM) Initialization of the plug-in returned code 0.
22:08:24.253 2336[21] Info:(KMM) Plug-in running
22:08:24.253 [21] End
22:08:24.253 2920[20] Debug(1): CC name is [jblaine@RCF.OUR.ORG]
22:08:24.253 2920[20] Debug(1): Found principal [jblaine@RCF.OUR.ORG]
22:08:24.253 2920[20] Debug(1): Setting default identity to [jblaine@RCF.OUR.ORG]
22:08:24.253 [20] End
22:08:24.253 2920[19] Info:(KMM) Plug-in running
22:08:24.253 [19] End
22:08:27.543 [DBG] SNACNP Attached!
22:08:27.543 [DBG] "C:\Program Files\MIT\Kerberos\bin\netidmgr.exe"
22:08:27.543 [DBG] SNACNP::NPGetCaps::WNNC_NET_TYPE
22:08:27.543 [DBG] SNACNP::NPGetCaps::WNNC_USER
22:08:27.543 [DBG] SNACNP::NPGetCaps::WNNC_CONNECTION
22:08:27.543 [DBG] SNACNP::NPGetCaps::WNNC_ENUMERATION
22:08:27.543 [DBG] SNACNP::NPGetCaps::WNNC_ADMIN
22:08:27.543 [DBG] SNACNP::NPGetCaps::WNNC_DIALOG
22:08:31.770 [22] Begin: Importing credentials from Windows
22:08:31.770 972[22] Debug(1): Begin : khm_krb5_ms2mit. save_cred=1
22:08:31.770 972[22] Info:(Krb5) krb5_cc_get_principal() for MSLSA: failed. Matching credential not found (Code=141)
22:08:31.770 [23] Begin: Renewing credentials (child of [22])
22:08:31.785 [24] Begin: Renewing credentials for jblaine@RCF.OUR.ORG (child of [23])
22:08:31.785 3868[24] Debug(1): Preparing to dispatch batch of KMSG_CRED_PROCESS messages
22:08:31.785 3868[24] Debug(1): Credtype Kerberos v4(2) waiting for completion of (null)(1)
22:08:31.785 3868[24] Debug(1): Queuing credtype KeyStore(3) for processing
22:08:31.785 3868[24] Debug(1): Queuing credtype KeyStore(3) for processing
22:08:31.785 3868[24] Debug(1): Queuing credtype KeyStore(3) for processing
22:08:31.785 3868[24] Debug(1): Queuing credtype Kerberos v5 tickets(1) for processing
22:08:31.785 [25] Begin: Renewing Kerberos v5 tickets (child of [24])
22:08:32.082 972[25] Info:(Krb5) krb5_get_renewed_creds() failed. Cannot resolve network address for KDC in requested realm (Code=220)
22:08:32.082 972[25] Warning:(Krb5) Cannot resolve network address for KDC in requested realm
22:08:32.082 [25] End
22:08:32.082 3868[24] Debug(1): Preparing to dispatch batch of KMSG_CRED_PROCESS messages
22:08:32.082 3868[24] Debug(1): Queuing credtype Kerberos v4(2) for processing
22:08:32.082 3868[24] Debug(1): Skipping credtype KeyStore(3). Marked as processed
22:08:32.082 3868[24] Debug(1): Skipping credtype Kerberos v5 tickets(1). Marked as processed
22:08:32.082 3304[24] Debug(1): Kerberos 4 is not enabled for this identity. Skipping
22:08:32.082 3868[24] Debug(1): Preparing to dispatch batch of KMSG_CRED_PROCESS messages
22:08:32.082 3868[24] Debug(1): Skipping credtype Kerberos v4(2). Marked as processed
22:08:32.082 3868[24] Debug(1): Skipping credtype KeyStore(3). Marked as processed
22:08:32.082 3868[24] Debug(1): Skipping credtype Kerberos v5 tickets(1). Marked as processed
22:08:32.082 3868[24] Debug(1): Done with processing
22:08:32.128 972[24] Debug(1): Getting tickets from cache [API:jblaine@RCF.OUR.ORG]
22:08:32.128 972[24] Debug(1): Found principal [jblaine@RCF.OUR.ORG]
22:08:32.128 972[24] Debug(1): Ticket [krbtgt/RCF.OUR.ORG@RCF.OUR.ORG]
22:08:32.128 972[24] Debug(1): Setting properties for identity (count=1)
22:08:32.128 972[24] Debug(1): Getting tickets from cache [MSLSA:]
22:08:32.128 [24] End
22:08:32.128 [23] End
22:08:32.128 [22] End
22:08:33.376 [26] Begin: Destroying credentials
22:08:33.376 [27] Begin: Destroying Krb5 tickets (child of [26])
22:08:33.392 972[27] Debug(1): Getting tickets from cache [API:jblaine@RCF.OUR.ORG]
22:08:33.392 972[27] Debug(1): Found principal [jblaine@RCF.OUR.ORG]
22:08:33.392 972[27] Debug(1): Ticket [krbtgt/RCF.OUR.ORG@RCF.OUR.ORG]
22:08:33.392 972[27] Debug(1): Setting properties for identity (count=1)
22:08:33.392 972[27] Debug(1): Getting tickets from cache [MSLSA:]
22:08:33.392 972[27] Debug(1): Destroying ccache [API:jblaine@RCF.OUR.ORG]
22:08:33.392 [27] End
22:08:33.392 972[26] Debug(1): Getting tickets from cache [MSLSA:]
22:08:33.392 972[26] Debug(1): Getting tickets from cache [MSLSA:]
22:08:33.392 972[26] Debug(1): Getting tickets from cache [MSLSA:]
22:08:33.438 [26] End
22:08:38.413 [28] Begin: Refreshing timers
22:08:38.413 2072[28] Debug(1):(NetIDMgr) Starting with 0 timers
22:08:38.413 [29] Begin: Checking for expired timers (child of [28])
22:08:38.413 [29] End
22:08:38.413 2072[28] Debug(1):(NetIDMgr) Leaving with 0 timers
22:08:38.413 2072[28] (NetIDMgr) Checking for expired timers
22:08:38.413 [28] End
22:08:39.677 1140[16] Info:(KMM) Initialization of the plug-in returned code 0.
22:08:39.677 1140[16] Info:(KMM) Plug-in running
22:08:39.677 [16] End
22:08:52.886 [30] Begin: Processing commandline
22:08:52.886 2072[30] Debug(1): Selected identity provider [Kerberos 5]
22:08:52.886 2072[30] Debug(1): Default identity [jblaine@RCF.OUR.ORG]
22:08:52.886 [31] Begin: Importing credentials from Windows (child of [30])
22:08:52.886 2072[30] Debug(1): Importing...
22:08:52.886 972[31] Debug(1): Begin : khm_krb5_ms2mit. save_cred=1
22:08:52.886 972[31] Info:(Krb5) krb5_cc_get_principal() for MSLSA: failed. Matching credential not found (Code=141)
22:08:52.886 [32] Begin: Processing commandline (child of [31])
22:08:52.886 [32] End
22:08:52.886 2072[31] Processing commandline
22:08:52.886 [31] End
22:08:52.886 [30] End
22:10:08.087 [33] Begin: Obtaining new credentials
22:10:08.134 [33] End
22:10:12.422 [34] Begin: Obtaining new credentials for jblaine@RCF.OUR.ORG
22:10:12.422 2072[34] Debug(1): Preparing to dispatch batch of KMSG_CRED_PROCESS messages
22:10:12.422 2072[34] Debug(1): Queuing credtype Kerberos v5(1) for processing
22:10:12.422 2072[34] Debug(1): Credtype AFS(5) waiting for completion of Kerberos v5(1)
22:10:12.422 2072[34] Debug(1): Skipping credtype Kerberos v4(2). Marked as disabled
22:10:12.422 2072[34] Debug(1): Skipping credtype KeyStore(3). Marked as disabled
22:10:12.422 [35] Begin: Obtaining initial Kerberos v5 tickets (child of [34])
22:10:12.422 972[35] Debug(1): Confirming k5_kinit_task [0141E5F0] for principal [jblaine@RCF.OUR.ORG]
22:10:13.670 972[35] Debug(1): Tickets successfully acquired
22:10:13.686 972[35] Debug(1): Setting CCache [API:jblaine@RCF.OUR.ORG] for identity [jblaine@RCF.OUR.ORG]
22:10:13.686 972[35] Debug(1): Getting tickets from cache [API:jblaine@RCF.OUR.ORG]
22:10:13.686 972[35] Debug(1): Found principal [jblaine@RCF.OUR.ORG]
22:10:13.686 972[35] Debug(1): Ticket [krbtgt/RCF.OUR.ORG@RCF.OUR.ORG]
22:10:13.701 972[35] Debug(1): Setting properties for identity (count=1)
22:10:13.701 972[35] Debug(1): Getting tickets from cache [MSLSA:]
22:10:13.701 972[35] Debug(1): Attempting to synchronize default identity into MSLSA:
22:10:13.701 972[35] Debug(1): Trying to copy CC API:jblaine@RCF.OUR.ORG to MSLSA:
22:10:13.701 972[35] Info:(Krb5) krb5_cc_copy_creds() failed. Ccache function not supported: read-only ccache type (Code=246)
22:10:13.701 [35] End
22:10:13.701 3868[34] Debug(1): Preparing to dispatch batch of KMSG_CRED_PROCESS messages
22:10:13.701 3868[34] Debug(1): Skipping credtype Kerberos v5(1). Marked as processed
22:10:13.701 3868[34] Debug(1): Credtype AFS(5) waiting for disabled credtype Kerberos v4(2). Ignoring dependency.
22:10:13.701 3868[34] Debug(1): Queuing credtype AFS(5) for processing
22:10:13.701 3868[34] Debug(1): Skipping credtype Kerberos v4(2). Marked as disabled
22:10:13.701 3868[34] Debug(1): Skipping credtype KeyStore(3). Marked as disabled
22:10:13.701 [36] Begin: Getting AFS tokens... (child of [34])
22:10:13.701 1140[36] Info:(AfsCred) AFS New Creds :: ident 0140B008
22:10:13.701 1140[36] Info:(AfsCred) Getting tokens for cell rcf.our.org with realm using method 0
22:10:13.701 1140[36] Debug(1): Trying Kerberos 5
22:10:18.707 [37] Begin: Refreshing timers
22:10:18.707 2072[37] Debug(1):(NetIDMgr) Starting with 0 timers
22:10:18.707 2072[37] Debug(1): Looking at cred [krbtgt/RCF.OUR.ORG@RCF.OUR.ORG]
22:10:18.707 2072[37] Debug(1): Updating identity marker timer for [jblaine@RCF.OUR.ORG]. Expires at (unspecified)
22:10:18.707 2072[37] Debug(1): Updating identity timers ...
22:10:18.707 2072[37] Debug(1): Updating identity renewal timer for [jblaine@RCF.OUR.ORG]. Expires at Tuesday, March 16, 2010 11:10:11 AM
22:10:18.707 2072[37] Debug(1): Skipping credential. Credential expiration is too close to the identity expiration
22:10:18.707 [38] Begin: Checking for expired timers (child of [37])
22:10:18.707 [38] End
22:10:18.707 2072[37] Debug(1):(NetIDMgr) Leaving with 2 timers
22:10:18.707 2072[37] (NetIDMgr) Checking for expired timers
22:10:18.707 [37] End
22:10:30.279 1140[36] Debug(1): Code -1765328164 while getting credentials
22:10:30.279 1140[36] Debug(1): Trying Kerberos 4
22:10:30.279 1140[36] Debug(1): Trying to find afs.rcf.our.org@RCF.OUR.ORG
22:10:30.279 1140[36] Debug(1): krb_get_cred returns 76 (no ticket file)
22:10:30.279 1140[36] Info:(AfsCred) klog returns code 1
22:10:30.279 1140[36] ERROR:(AfsCred) Credentials could not be obtained for cell rcf.our.org.
--------------070308010401060400080408
Content-Type: text/plain; charset="us-ascii"
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
Content-Disposition: inline
________________________________________________
Kerberos mailing list Kerberos@mit.edu
https://mailman.mit.edu/mailman/listinfo/kerberos
--------------070308010401060400080408--
