[OpenAFS-win32-devel] Slow Windows logins with AFS installed

Ted Anderson ota@surfvi.com
Wed, 01 Feb 2006 23:34:21 -0400


This is a multi-part message in MIME format.
--------------010202050908090907050709
Content-Type: text/plain; charset=us-ascii; format=flowed
Content-Transfer-Encoding: 7bit

Ted Anderson wrote:
 >> On 02/01/2006 03:01, Jeffrey Altman wrote:
 >>>> If you are seeing delays after you know the AFS Client Service is
 >>>> running, then please turn on logging for the Integrate Login
 >>>> functionality and send the Event Log output to
 >>>> openafs-bugs@openafs.org.
 >
 >> I reinstalled to set things back they way they were, set the various
 >> registery keys to enable more tracing, then reproduced the delays.  I
 >> now have an event log with lots of AFS traffic in it.  How do I get
 >> "the Event Log output", in a file so I can send it to you.  I don't
 >> want to send the whole .evt file as that has lots of other events
 >> from the rest of the system that I'd rather not publish.  I couldn't
 >> find a built in tool to get the output in any reasonable format.  I
 >> downloaded log parser, but it is a hairball.
 >>
 >> Are you only interested in AFS Logon events, or are AFS Client and
 >> TransarcAFSDaemon entries also of interest?
 >
 > The Event Log Viewer has a Filter function and a Save As ... function.
 > Please export all AFS related events and please do not send e-mail to
 > me personally.   Please keep discussions in public forums.  Either on
 > a mailing list or in the bug tracker so that others can gain from your
 > experience.

The Event Log Viewer only seemed to know how to export the whole log,
even with filtering turned on.  I eventually got LogParser to do
something useful (I used v2.0, but v2.2 is available[2]), so I ran the
following command:

% logparser -e 3 -i:evt -o:nat "select TimeGenerated, SourceName, 
Strings from application to c:/temp/afs-logon.txt where SourceName = 
'AFS Logon' or SourceName = 'AFS Client' or SourceName = 
'TransarcAFSDaemon'" -ignoremsgerr ON

I cleaned up the output a bit, compressed it and have attached it to
this message as afs-logon.txt.gz.

I reinstalled the OpenAFS client from the 1.4.1rc5 (non-debug) bits and
configured it by deselecting all the integrated logon features.  I used
RegEdit to turn on extra tracing.  I verified with Spybot - search and
destroy, that AfsLogon and KFWLogon were reattached to afslogon.dll in
System.ini as reported earlier[1].  Then I rebooted at about 20:30.
Here is the approximate timeline according to my notes:

20:40    After the system came up, I verified that AFS worked in my home
	 cell inside the VPN.
20:43:30 touched a file.
20:44:30 logout, completed in 10-15 seconds
20:45:03 login, "applying your personal settings..."
20:46:08 dialog boxes about failing to restore SMB connections.
20:46:22 desktop displayed
	 Did not restart the VPN.  Instead listed the public directory
	 //afs/sipb.mit.edu/contrib/wedding.  All okay.
21:00:00 logout
21:00:10 login dialog appears
21:01:00 login, applying settings...
21:02:00 problems restoring SMB shares:, hit OK button several times.
21:02:20 desktop, listing above directory in sipb.mit.edu still works.

The SMB problem is due to the wireless card not being configured for
NetBUI.  I disabled the wireless card, and logged out and back in and
got the same 60 second delay, so I don't think it is relevant to this
problem.

Let me know if I can provide more helpful details about my configuration
or environment..

Ted Anderson

[1] 
http://lists.openafs.org/pipermail/openafs-win32-devel/2006-January/000399.html
[2] 
http://www.microsoft.com/downloads/details.aspx?FamilyID=890cd06b-abf8-4c25-91b2-f8d975cf8c07

On 01/31/2006 20:42, Ted Anderson wrote:
 > On 01/26/2006 22:42, Jeffrey Altman wrote:
 >> Ted Anderson wrote:
 >>> I don't believe this explanation applies to my case.  My AFS client
 >>> service is configured to start at boot time.  I do not use a roaming
 >>> profile and none of my profile stuff is stored in AFS.  The delay I
 >>> am seeing occurs when logging in and out without rebooting, and
 >>> while using AFS just fine both before logging out and after logging
 >>> back in.
 >>
 >> I am explaining to you how the code is written.  If the AFS Client
 >> Service has not started when you log in, the login will not complete
 >> until it does.
 >
 > It would seem that this would delay the first login after booting the
 > system, assuming the AFS is configured to start a boot time, which I
 > do.  But it does not seem like it would affect subsequent log ins.
 > Yet, it is slow logins long after the system has booted and AFS is
 > running correctly that I am referring to.
 >
 >> This has nothing to do with roaming profiles.  Let us imagine a local
 >> profile that accesses a resource stored in AFS.  For example, an
 >> update to the anti-virus dictionary.  The purpose of this
 >> functionality is to ensure that if AFS is installed on the machine
 >> that AFS is functional when the user logs in.  Not after the user
 >> logs in.
 >
 > Do you mean to say that the code "ensures" "that AFS is functional"
 > every time some one logs in?  What type of checks does it do?
 >
 > Ted
 >
 >> If you would like to avoid this behavior you can set AFS for manual
 >> start and activate it when you require it.
 >>
 >>> Right, this is part of the reason why I have enabled the freelance
 >>> client.  With freelance, the configuration of the default cell seems
 >>> to have little functional impact, but does provide the convenience
 >>> of not having to specify a cell when running klog and pts commands.
 >>>
 >>> Once I get logged in and start the VPN, AFS works just fine, both
 >>> with and without the registery settings I needed to alter.  Based on
 >>> this, my suggestion is that these settings should automatically be
 >>> removed when "Obtain AFS tokens when logging into Windows" is NOT
 >>> checked.
 >>
 >> All this means is that by the time the VPN has been started, the AFS
 >> Client Service has been started by Windows.
 >>
 >> Jeffrey Altman


--------------010202050908090907050709
Content-Type: application/x-gzip;
 name="afs-logon.txt.gz"
Content-Transfer-Encoding: base64
Content-Disposition: inline;
 filename="afs-logon.txt.gz"

H4sICO1z4UMCA2Fmcy1sb2dvbi50eHQA7V1bb9s4Fn4v0P9ADLBoA8QJKYq6AbtAJukNkybF
JLvz4DEKxaITIbLkleSm2V+/pGQn1sUWKZFuphijD25jft+58ZDn6MT9B4iS24WfZjQFIwow
GIUe/ZaDUeLFfg5+yWhEpzm4Duf0A41p6uc0OARXyTKd0gt/Ttn7PA3j2wzM0mQO/MUiCqd+
HiYxyBMw9Y5zOl8c+7NsxHiS+Cj/noOHO5rSDQzwT/Dm5P0VOOefeAOStOVnp1FI47zlh9ep
H2d+OmUfOvPpnAH8wnS4jZOUzrNbmqbg8uL1q9evKhqA8rWBtNai1+v1q1HzBVrfyr8YOjKO
ET42ICQAEc9gfxB4NkrxNsv9NAcLGgdMDSnRm+BuHTxdxrEcbAu4YXgEeYazCf7lPmeSp34Q
RMwpGc0yHjiFLsvFIYug5B6Y0IUWmGeHIJ7egIjGt/kdcMw2cAw3wafzryexHz3+j3rgo58G
Z9QPeBQA+n1KaUCDIynJq+AikiNkGciti+7iBrhRs7mQWbDt2g2zOEAJuGO32NzFK3BzFS3I
g4YHzXq0/HcZ5nmPcGkDd9XGeQUcYbVxvga3PcPyMN5plsYK1yPmTl3rKzBkOuxUoFxhr1Y4
HgsGbAtwVFaYRIqD4BY9WjSvriBSUvEVjrhUBi52ryXOUa4Q0txZrWDOwOyP2mitgCNTabQa
5ClDQLvLA0PAHQ8SpZJj9HRYIYs5Sqnkm+C2B6FCyY8LaIu7E5k8HoFCyavgLHSBSsnNEpyn
TRYrbhVc7CSEDjv5awcKcWvgTkNyEXALQ7sFG7Td+eRufC33OrlbXc16LHlhR87rDQDTkvNs
FcBkucSWuyRtAmDPxC3HjrgKBQBC/VVgqRkyjCESMACCe0tglDawe0tQAqAebiQrAKPY4z0k
qAAQC3QdcMdWucDmW5Pdf0HXGVpd4IJuBvspbxHXY5flTobKApZTOhmcZ6XtQokuhuoCt5vB
fVpgmPxW2clQWWDgbgYEn2IHI4FbXG1BM1a6g40f4wUCyzqo63LaidBWJwjIgFeblgUTbkEQ
kKGCgHpse0SeA475C/aQoYKAYQ8ZVkHPzGjaLfcpARkqCKiHL4xV+nLZCeQZBMgeIi39F53t
F5Xdl526CzYCbAIb9bRbw7Z5X0e6VDdc3OgDIIgLbPIc/Sx2LYWVegWbpUmVBUQN21RZp29i
M2eauuRm2ESX3MRsySKK5ObYrlK5nedTwJW+O8pgy14rd2Pj1QnKakzEiipHfs+biKWK1pJn
E5sd50jlvqxim0rtXcO21Nnb2ChgDcLNrc4mm9gY8jABT08birdfr0rPfX33jbMNwbYUFvU1
bMMEeuyN+R2xYpOLL8WbiyQPZ49gxP85jD8Fb+Ehck2DkANJ7A3oTzH4QPOzZO6HcfFPlwv+
sCgDsyQFS/4Uapzk/gSEMQiKD4Hxyfnlx8vPl7+fTDqwW4E9cOrHb3KQMBeA8scZuKePYGxM
JORmtigguLlXgnEQLvX4/PL05Pzj5dX1pJ9NkkU++teGzAx1GQfcBHf3FwvwELLEkT8uKBib
E1ns4OFsOZ8/ghvKJc9ozh/LBXTmL6O8V5zU5U5pnj5+inOafvMjCRoR7CyidKEe+wPzZfE0
EmTTNFzkHngbL6PooPfe2cDecOMYTg7BFZM9nFJwssyTIs2M0aQvNn97MsvKv43ANc3yJ/zf
u1LB8G6YzkbZ7hv4Tqs83IURfesz+xap9kDKBXot3i03i8Nkwcqk8PmhtIoorMn9juGrxP5a
vF0dlyNQGFUL9pc0mbLbFfh05gHDgoOwy9zvgafjRKG9eUa5+nTGL4U8JMZXIzQiIwONELIt
6NoIjpAFTcNAtm2NbINgkxATjxCEqHmqrS5W65OHbc9iyCFi+5adn8yVH07BzA/53XPMSEwb
GpiYrXmlhm16EHVgl2YSwW9gI6vN3v1fHQSDjN5OUPXqb+//6B/p/QiKvwnetHoRvIuDYT7A
SFlwthN0Rr94hIoQNNMZSzoznprPwpRO8yR9ZFdI78+zZLqcsw9kwGcmvKJFMZL9yS6r0gTl
D7hmG9mII0maaFUJXH3+tVmDQpDEtwnfF8kik3YyI2jMVYFv0wWA313HsYIbB0R+7AMCoiwG
SMnmbuU8TQLKSCFQ8mpy2j9AT3u7npbFEpRh3Py0ev7n9Mt4xTgBMX0YLcOAX8dithnGEz2c
n/17ekEf/s2KS2+T//CcqTwmk0OmM5PhkFefhTSH1+H0nua/XZ/yPTr2o+QumSepz7foRMqf
P33cVh1a1K0Vl1Zt1825s0ZZT20OKlW6yxUlVUtb5aIrVtpoNg6g1at5Dv1xQfOTIDhN4pgd
dOz4MN4egGw5LZ/ZKKORvHJUacyiqaYh2MVoBuflF6VNa/aFEtlXjEYy4cJ6wp1I+UbVvvnB
vtmWSdvd8/rV0dERmEXL7I7t1CiMaeZtt5DYp7crKrZe7iwQlukZMirDB5ThUzOruR65bU9H
s5lIEdcbc0eOq2GS9ZhoZ6+dGI5NnAOJ0CLrGQn1zfYGtsJmewNbYbO9ga2w2d7AVthsb5db
TbO9HVtNs70ZJ+qa7Q3sgc32n6Mh3rCKwqZ1A1ths33/cqtptnfJPaTZ3oatqtneiT2g2d7A
Vthsb80oiprtDBu5mprtDBubOluZjMB0dXbcGwSqO+6mVXOt6o67AMFzx13gvtVNoLohLqDB
sJY+I+jcAsPCtE6guuMuQDCs414SKG0OiBFUCqpVKTX38+ndqLO5JkbwPowDXqb/+ljYZmtD
NO7qgzZ8MLzp1Jdg13aoYRa/+DbUr2KYDVfCiisnfTCFvAdX3puIYcq2IfbQsN1Ht7bF4pVn
bGtN2HWUVc3IcI6MI4SPkOuClC6SlCv/LYlYvgIEW44NXWQBPwMxOzH9PPend8UQfIXDqU3D
auKw9XOgPehRncDVw2HgPXDsQQ9s7oWjK3M6w26fTm0SXY8e1d8A0MNBtMeVu4dc4noI7oHD
2QuH5tgV4rhRgjnoZrEFc9DNYgum7M2ihmnY+uMCE/0cpqmfg+jOBQTWvhtBG4fefco5XP16
IFs/h2Hp59B+r2j8br82DtWP+rVUQjoqHyBmjSGnyjbMIafKNswhp4pQJCAim1F+Hkz4AjAt
/dUl57A0ZAQRDrl91o9j0L6z1Iyr1DFt/T7VXs1zDlc/h/5T19JfaRNLf6VdcqiturZhDjof
t2AO3KcmUb9Pu+2JiBJ7/iUx4YvAJFD/viLa84Nd+34fPRz67xJ27ct5NXG4e+HQXH3bHjY6
94P5EjBN92/Ml45JzL8xXzYm/0bhvwamDt0VYyIPwtqvcw+eeZfCFJ87qlGgdfO4SrF9Et5B
tmOjg+EUygbit1Mom4vfYShV4/EtFL3G4zswe43Fi8gpOw4vgik7Bt+B2Wv8vQOz19h7B2av
4esOzF7D4j9KTtnhcLGtqmw2vKRAQhNwPUfExSl6T4pvp1A2ML6dQtnceEFR/S6SdWZWNT5e
UGAkRtHvK1sKCtPa4YvBI+TbKdROkpf/V0ibtdQOlMvwPM+VC9xehHnUjpfL6DNkyrz871Ys
1dEswaN25lyGZ8jo+ZpHx/eFiPEomkDfTqBoAl3GI70m0GUIhLdKg4AYqktERZj/Bzgf2GYn
bgAA
--------------010202050908090907050709--