[OpenAFS] OpenAFS inconsistent behavior - Windows 7 32 bit
Dvorkin, Asya
dvorkias@umdnj.edu
Tue, 23 Aug 2011 15:20:03 -0400
Hi everyone,
I've been working on getting OpenAFS to work on Windows 7 32 bit and having=
some issues. A little bit about the system:
Virtual Machine running on Mac (tested on a desktop as well with similar re=
sults)
Windows 7 32bit fully patched.
OpenAFS - 1.5.9906
MIT Kerberos - 1.3.1.0
My problem that it works very inconsistently. It's working (case 1) I rebo=
ot and all of a sudden it stops working (case 2). Could it be related to t=
he network performance? There is also a third case where it can't even suc=
cessfully get initial kerberos credentials (case 3). All logs are below. =
Did anyone get OpenAFS work properly on Windows 7 32 bit? Thank you for al=
l your help.
1. Everything works.. kerberos authenticates and openafs works as it's supp=
osed to.
Log file:
15[10044]() 2011-8-23 15:25:49.384 Debug(1): Found principal [user@CO=
RE.UMDNJ.EDU]
15[10044]() 2011-8-23 15:25:49.384 Debug(1): Setting default identity=
to [user@CORE.UMDNJ.EDU]
15 2011-8-23 15:25:49.384 >> Context end --
14[10044](KMM) 2011-8-23 15:25:49.290 Info: Initialization of the plug-i=
n returned code 0.
14[10044](KMM) 2011-8-23 15:25:49.384 Info: Plug-in running
14 2011-8-23 15:25:49.384 >> Context end --
16[10048](KMM) 2011-8-23 15:25:49.384 Info: Initialization of the plug-i=
n returned code 0.
16[10048](KMM) 2011-8-23 15:25:49.384 Info: Plug-in running
16 2011-8-23 15:25:49.384 >> Context end --
17 2011-8-23 15:25:54.223 << Context begin --
17 Description: Refreshing timers
17[9912](NetIDMgr) 2011-8-23 15:25:54.223 Debug(1): Starting with 0 =
timers
17[9912](NetIDMgr) 2011-8-23 15:25:54.223 Debug(1): Looking at cred =
[krbtgt/CORE.UMDNJ.EDU@CORE.UMDNJ.EDU]
17[9912](NetIDMgr) 2011-8-23 15:25:54.223 Debug(1): Updating identit=
y marker timer for user@CORE.UMDNJ.EDU exp(49920-30203-18 0:0:0)
17[9912](NetIDMgr) 2011-8-23 15:25:54.223 Debug(1): Updating identit=
y renew timer for user@CORE.UMDNJ.EDU exp(2011-8-23 16:24:43)
17[9912](NetIDMgr) 2011-8-23 15:25:54.223 Debug(1): Skipping credent=
ial [krbtgt/CORE.UMDNJ.EDU@CORE.UMDNJ.EDU]. The expiry time is too close t=
o the identity expiry.
17[9912](NetIDMgr) 2011-8-23 15:25:54.223 Debug(1): Leaving with 2 t=
imers
17 2011-8-23 15:25:54.223 >> Context end --
13[10036](KMM) 2011-8-23 15:26:05.645 Info: Initialization of the plug-i=
n returned code 0.
13[10036](KMM) 2011-8-23 15:26:05.645 Info: Plug-in running
13 2011-8-23 15:26:05.645 >> Context end --
18 2011-8-23 15:26:05.645 << Context begin --
18 Description: Importing credentials from Windows
18[10032]() 2011-8-23 15:26:05.645 Debug(1): Begin : khm_krb5_ms2mit.=
save_cred=3D1
18[10032]() 2011-8-23 15:26:05.645 Debug(1): Resolving MSLSA
18[10032]() 2011-8-23 15:26:05.645 Debug(1): Getting principal
19 2011-8-23 15:26:05.645 << Context begin --
19 Description: Renewing credentials
20 2011-8-23 15:26:05.645 << Context begin --
20 Description: Renewing credentials for user@CORE.UMDNJ.EDU
21 2011-8-23 15:26:05.645 << Context begin --
21 Description: Renewing Krb5 credentials
21[10032]() 2011-8-23 15:26:06.785 Debug(1): Tickets successfully ren=
ewed
21 2011-8-23 15:26:06.785 >> Context end --
22 2011-8-23 15:26:06.785 << Context begin --
22 Description: Getting AFS tokens...
22[10036](AfsCred) 2011-8-23 15:26:06.785 Info: AFS Renew Creds :: i=
dent 01214838
22[10036](AfsCred) 2011-8-23 15:26:14.301 Info: Getting tokens for c=
ell rwjresearch.umdnj.edu with realm using method 0
22[10036]() 2011-8-23 15:26:14.301 Debug(1): Trying Kerberos 5
22[10036]() 2011-8-23 15:26:22.270 Debug(1): Code -1765328370 while g=
etting credentials
22[10036]() 2011-8-23 15:26:22.270 Debug(1): Trying Kerberos 4
22[10036]() 2011-8-23 15:26:22.270 Debug(1): Trying to find afs.rwjre=
search.umdnj.edu@
22[10036]() 2011-8-23 15:26:22.270 Debug(1): krb_get_cred returns 76 =
(no ticket file)
22[10036](AfsCred) 2011-8-23 15:26:22.270 Info: klog returns code 1
22[10036](AfsCred) 2011-8-23 15:26:22.270 ERROR: Credentials could n=
ot be obtained for cell rwjresearch.umdnj.edu.
22 2011-8-23 15:26:22.270 >> Context end --
20[10048]() 2011-8-23 15:26:06.785 Debug(1): Kerberos 4 is not enable=
d for this identity. Skipping
20[10032]() 2011-8-23 15:26:22.302 Debug(1): Getting tickets from cac=
he [API:user@CORE.UMDNJ.EDU]
20[10032]() 2011-8-23 15:26:22.302 Debug(1): Found principal [user@CO=
RE.UMDNJ.EDU]
20[10032]() 2011-8-23 15:26:22.302 Debug(1): Setting properties for i=
dentity (count=3D1)
20[10032]() 2011-8-23 15:26:22.302 Debug(1): Getting tickets from cac=
he [MSLSA:]
20 2011-8-23 15:26:22.302 >> Context end --
19 2011-8-23 15:26:22.302 >> Context end --
18[10032]() 2011-8-23 15:26:05.645 Debug(1): Received code=3D-17653=
28243
18 2011-8-23 15:26:22.302 >> Context end --
23 2011-8-23 15:26:27.302 << Context begin --
23 Description: Refreshing timers
23[9912](NetIDMgr) 2011-8-23 15:26:27.302 Debug(1): Starting with 2 =
timers
23[9912](NetIDMgr) 2011-8-23 15:26:27.302 Debug(1): Looking at cred =
[krbtgt/CORE.UMDNJ.EDU@CORE.UMDNJ.EDU]
23[9912](NetIDMgr) 2011-8-23 15:26:27.302 Debug(1): Updating identit=
y renew timer for user@CORE.UMDNJ.EDU exp(2011-8-23 16:26:6)
23[9912](NetIDMgr) 2011-8-23 15:26:27.302 Debug(1): Skipping credent=
ial [krbtgt/CORE.UMDNJ.EDU@CORE.UMDNJ.EDU]. The expiry time is too close t=
o the identity expiry.
23[9912](NetIDMgr) 2011-8-23 15:26:27.302 Debug(1):
2. Kerberos and OpenAFS start, but it seems like Kerberos authenticates AFT=
ER OpenAFS starts up, thus OpenAFS doesn't work and only if I destroy old /=
obtain new credentials, it starts working.
Log file:
15[10072]() 2011-8-23 17:08:18.667 Debug(1): Found principal [user@CO=
RE.UMDNJ.EDU]
15[10072]() 2011-8-23 17:08:18.667 Debug(1): Setting default identity=
to [user@CORE.UMDNJ.EDU]
15 2011-8-23 17:08:18.667 >> Context end --
14[10072](KMM) 2011-8-23 17:08:18.620 Info: Initialization of the plug-i=
n returned code 0.
14[10072](KMM) 2011-8-23 17:08:18.667 Info: Plug-in running
14 2011-8-23 17:08:18.667 >> Context end --
16[9168](KMM) 2011-8-23 17:08:18.667 Info: Initialization of the plug-i=
n returned code 0.
16[9168](KMM) 2011-8-23 17:08:18.667 Info: Plug-in running
16 2011-8-23 17:08:18.667 >> Context end --
13[9184](KMM) 2011-8-23 17:08:19.894 Info: Initialization of the plug-i=
n returned code 0.
13[9184](KMM) 2011-8-23 17:08:19.894 Info: Plug-in running
13 2011-8-23 17:08:19.894 >> Context end --
17 2011-8-23 17:08:19.894 << Context begin --
17 Description: Importing credentials from Windows
17[9544]() 2011-8-23 17:08:19.894 Debug(1): Begin : khm_krb5_ms2mit.=
save_cred=3D1
17[9544]() 2011-8-23 17:08:19.894 Debug(1): Resolving MSLSA
17[9544]() 2011-8-23 17:08:19.894 Debug(1): Getting principal
18 2011-8-23 17:08:19.894 << Context begin --
18 Description: Renewing credentials
19 2011-8-23 17:08:19.894 << Context begin --
19 Description: Renewing credentials for user@CORE.UMDNJ.EDU
20 2011-8-23 17:08:19.894 << Context begin --
20 Description: Renewing Krb5 credentials
20[9544]() 2011-8-23 17:08:20.109 Debug(1): Tickets successfully ren=
ewed
20 2011-8-23 17:08:20.109 >> Context end --
21 2011-8-23 17:08:20.109 << Context begin --
21 Description: Getting AFS tokens...
22 2011-8-23 17:08:24.906 << Context begin --
22 Description: Refreshing timers
22[9396](NetIDMgr) 2011-8-23 17:08:24.906 Debug(1): Starting with 0 =
timers
22[9396](NetIDMgr) 2011-8-23 17:08:24.906 Debug(1): Looking at cred =
[krbtgt/CORE.UMDNJ.EDU@CORE.UMDNJ.EDU]
22[9396](NetIDMgr) 2011-8-23 17:08:24.906 Debug(1): Updating identit=
y marker timer for user@CORE.UMDNJ.EDU exp(49920-30472-18 0:0:0)
22[9396](NetIDMgr) 2011-8-23 17:08:24.906 Debug(1): Updating identit=
y renew timer for user@CORE.UMDNJ.EDU exp(2011-8-23 18:7:27)
22[9396](NetIDMgr) 2011-8-23 17:08:24.906 Debug(1): Skipping credent=
ial [krbtgt/CORE.UMDNJ.EDU@CORE.UMDNJ.EDU]. The expiry time is too close t=
o the identity expiry.
22[9396](NetIDMgr) 2011-8-23 17:08:24.906 Debug(1): Looking at cred =
[afs@rwjresearch.umdnj.edu]
22[9396](NetIDMgr) 2011-8-23 17:08:24.906 Debug(1): Updating credent=
ial renew timer for afs@rwjresearch.umdnj.edu exp(2011-8-23 22:49:10)
22[9396](NetIDMgr) 2011-8-23 17:08:24.906 Debug(1): Leaving with 3 t=
imers
22 2011-8-23 17:08:24.906 >> Context end --
21[9184](AfsCred) 2011-8-23 17:08:20.109 Info: AFS Renew Creds :: i=
dent 01214838
21[9184](AfsCred) 2011-8-23 17:08:27.609 Info: Getting tokens for c=
ell rwjresearch.umdnj.edu with realm using method 0
21[9184]() 2011-8-23 17:08:27.625 Debug(1): Trying Kerberos 5
21[9184]() 2011-8-23 17:08:35.344 Debug(1): Trying K5 SetToken
21[9184](AfsCred) 2011-8-23 17:08:42.876 Info: klog returns code 0
21 2011-8-23 17:08:42.876 >> Context end --
19[9168]() 2011-8-23 17:08:20.109 Debug(1): Kerberos 4 is not enable=
d for this identity. Skipping
19[9544]() 2011-8-23 17:08:42.891 Debug(1): Getting tickets from cac=
he [API:user@CORE.UMDNJ.EDU]
19[9544]() 2011-8-23 17:08:42.891 Debug(1): Found principal [user@CO=
RE.UMDNJ.EDU]
19[9544]() 2011-8-23 17:08:42.891 Debug(1): Setting properties for i=
dentity (count=3D1)
19[9544]() 2011-8-23 17:08:42.891 Debug(1): Getting tickets from cac=
he [MSLSA:]
19 2011-8-23 17:08:42.891 >> Context end --
18 2011-8-23 17:08:42.891 >> Context end --
17[9544]() 2011-8-23 17:08:19.894 Debug(1): Received code=3D-17653=
28243
17 2011-8-23 17:08:42.891 >> Context end --
23 2011-8-23 17:08:47.907 << Context begin --
23 Description: Refreshing timers
23[9396](NetIDMgr) 2011-8-23 17:08:47.907 Debug(1): Starting with 3 =
timers
23[9396](NetIDMgr) 2011-8-23 17:08:47.907 Debug(1): Looking at cred =
[krbtgt/CORE.UMDNJ.EDU@CORE.UMDNJ.EDU]
23[9396](NetIDMgr) 2011-8-23 17:08:47.907 Debug(1): Updating identit=
y renew timer for user@CORE.UMDNJ.EDU exp(2011-8-23 18:8:20)
23[9396](NetIDMgr) 2011-8-23 17:08:47.907 Debug(1): Skipping credent=
ial [krbtgt/CORE.UMDNJ.EDU@CORE.UMDNJ.EDU]. The expiry time is too close t=
o the identity expiry.
23[9396](NetIDMgr) 2011-8-23 17:08:47.907 Debug(1): Looking at cred =
[afs@rwjresearch.umdnj.edu]
23[9396](NetIDMgr) 2011-8-23 17:08:47.907 Debug(1): Skipping credent=
ial [afs@rwjresearch.umdnj.edu]. The expiry time is too
3. For a different user often times I can't even get Kerberos credentials. =
Once I manually add credentials, AFS works properly as well.
15[3264]() 2011-8-23 17:48:51.461 Debug(1): Found principal [diff_us=
er@CORE.UMDNJ.EDU]
15[3264]() 2011-8-23 17:48:51.461 Debug(1): Setting default identity=
to [diff_user@CORE.UMDNJ.EDU]
15 2011-8-23 17:48:51.461 >> Context end --
14[3264](KMM) 2011-8-23 17:48:51.414 Info: Initialization of the plug-i=
n returned code 0.
14[3264](KMM) 2011-8-23 17:48:51.461 Info: Plug-in running
14 2011-8-23 17:48:51.461 >> Context end --
16[3268](KMM) 2011-8-23 17:48:51.461 Info: Initialization of the plug-i=
n returned code 0.
16[3268](KMM) 2011-8-23 17:48:51.461 Info: Plug-in running
16 2011-8-23 17:48:51.461 >> Context end --
13[3260](KMM) 2011-8-23 17:48:52.708 Info: Initialization of the plug-i=
n returned code 0.
13[3260](KMM) 2011-8-23 17:48:52.708 Info: Plug-in running
13 2011-8-23 17:48:52.708 >> Context end --
17 2011-8-23 17:48:52.708 << Context begin --
17 Description: Importing credentials from Windows
17[3244]() 2011-8-23 17:48:52.708 Debug(1): Begin : khm_krb5_ms2mit.=
save_cred=3D1
17[3244]() 2011-8-23 17:48:52.708 Debug(1): Resolving MSLSA
17[3244]() 2011-8-23 17:48:52.708 Debug(1): Getting principal
17[3244]() 2011-8-23 17:48:52.708 Debug(1): Unparsing name
17[3244]() 2011-8-23 17:48:52.708 Debug(1): Unparsed name [diff_user=
@CORE.UMDNJ.EDU]
17[3244]() 2011-8-23 17:48:52.708 Debug(1): Setting CCache [API:diff=
_user@CORE.UMDNJ.EDU] for identity [diff_user@CORE.UMDNJ.EDU]
17[3244]() 2011-8-23 17:48:52.708 Debug(1): Resolving target cache [=
API:diff_user@CORE.UMDNJ.EDU]
17[3244]() 2011-8-23 17:48:52.708 Debug(1): Initializing ccache
17[3244]() 2011-8-23 17:48:52.708 Debug(1): Copying credentials
17[3244]() 2011-8-23 17:48:52.708 Debug(1): Received code=3D0
17[3244]() 2011-8-23 17:48:52.708 Debug(1): Setting CCache [API:diff=
_user@CORE.UMDNJ.EDU] for identity [diff_user@CORE.UMDNJ.EDU]
17[3244]() 2011-8-23 17:48:52.708 Debug(1): Getting tickets from cac=
he [API:diff_user@CORE.UMDNJ.EDU]
17[3244]() 2011-8-23 17:48:52.708 Debug(1): Found principal [diff_us=
er@CORE.UMDNJ.EDU]
17[3244]() 2011-8-23 17:48:52.708 Debug(1): Getting tickets from cac=
he [MSLSA:]
18 2011-8-23 17:48:52.724 << Context begin --
18 Description: Obtaining new credentials
18 2011-8-23 17:48:52.739 >> Context end --
17[3244]() 2011-8-23 17:48:52.708 Debug(1): Found principal [diff_us=
er@CORE.UMDNJ.EDU]
17[3396](NetIDMgr) 2011-8-23 17:48:52.724 (None): Obtaining new cred=
entials
17 2011-8-23 17:48:52.739 >> Context end --
19 2011-8-23 17:48:57.724 << Context begin --
19 Description: Refreshing timers
19[3396](NetIDMgr) 2011-8-23 17:48:57.724 Debug(1): Starting with 0 =
timers
19[3396](NetIDMgr) 2011-8-23 17:48:57.724 Debug(1): Leaving with 0 t=
imers
19 2011-8-23 17:48:57.724 >> Context end --
20 2011-8-23 17:49:08.583 << Context begin --
20 Description: Obtaining new credentials for diff_user@CORE.UMDNJ.E=
DU
21 2011-8-23 17:49:08.583 << Context begin --
21 Description: Obtaining initial Krb5 credentials
21[3244]() 2011-8-23 17:49:08.583 Debug(1): In khm_krb5_kinit
21[3244]() 2011-8-23 17:49:08.583 Debug(1): Setting CCache [API:diff=
_user@CORE.UMDNJ.EDU] for identity [diff_user@CORE.UMDNJ.EDU]
21[3244]() 2011-8-23 17:49:08.583 Debug(1): krb5_cc_resolve returns =
code 0
21[3244]() 2011-8-23 17:49:18.099 Debug(1): krb5_get_init_creds_pass=
word returns code 0
21[3244]() 2011-8-23 17:49:18.099 Debug(1): krb5_cc_initialize retur=
ns code 0
21[3244]() 2011-8-23 17:49:18.099 Debug(1): krb5_cc_store_cred retur=
ns code 0
21[3244]() 2011-8-23 17:49:18.099 Debug(1): Tickets successfully acq=
uired
21[3244]() 2011-8-23 17:49:18.115 Debug(1): Setting CCache [API:diff=
_user@CORE.UMDNJ.EDU] for identity [diff_user@CORE.UMDNJ.EDU]
21[3244]() 2011-8-23 17:49:18.115 Debug(1): Getting tickets from cac=
he [API:diff_user@CORE.UMDNJ.EDU]
21[3244]() 2011-8-23 17:49:18.115 Debug(1): Found principal [diff_us=
er@CORE.UMDNJ.EDU]
21[3244]() 2011-8-23 17:49:18.115 Debug(1): Setting properties for i=
dentity (count=3D1)
21[3244]() 2011-8-23 17:49:18.115 Debug(1): Getting tickets from cac=
he [MSLSA:]
21[3244]() 2011-8-23 17:49:18.115 Debug(1): Found principal [diff_us=
er@CORE.UMDNJ.EDU]
21 2011-8-23 17:49:18.130 >> Context end --
22 2011-8-23 17:49:18.130 << Context begin --
22 Description: Getting AFS tokens...
22[3260](AfsCred) 2011-8-23 17:49:18.130 Info: AFS New Creds :: ide=
nt 01310EE0
22[3260](AfsCred) 2011-8-23 17:49:18.130 Info: Getting tokens for c=
ell rwjresearch.umdnj.edu with realm using method 0
22[3260]() 2011-8-23 17:49:25.646 Debug(1): Trying Kerberos 5
Thank you!
Asya