User logon debugging

[CHR1S]

Does anyone know of a tool or similar that can log and debug every step from the user entering their password to the point of a working desktop?

 

So it can log which server it goes to to get different things, where its being delayed and obviously whats causing the bottleneck.

[bio]

i would start out with wireshark to see whats happening "on the wire"

 

bio..

[CHR1S]

Yeh, where do you install it tho? On both DCs or somewhere else?

[CHR1S]

I ran it on the PDCE and got these weird file lookups for things that dont exist -

 

 

This is a pupil account and the files its looking for are in the home area, anyone know why its doing this?

 

Another file it looks for earlier in the logon is system.mdb, again in the home area and again not finding it.

[srochford]

You can turn on user environment debug logging - there's some info here What is logged to the Userenv.log file? - AD Troubleshooting - Site Home - TechNet Blogs - about how to do this and the info you get.

 

You will see all sorts of stuff which looks wrong if you use wireshark (or process monitor) - often it's not wrong; just not ideal.

 

For example, when Windows goes to load an executable file it will try each folder in the path until it finds it. If you've got network folders in your path ahead of the actual file location then these will appear on the Wireshark trace.

 

On a fairly clean machine path might look something like this:

PATH=C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;c:\ic-utils

 

On a machine with more stuff installed it can look like this:

PATH=C:\Program Files (x86)\NAG\FL22\fldll224ml\batch;C:\Program Files (x86)\NAG\FL22\fldll224ml\bin;C:\Program Files (x86)\NAG\FL22\fldll224ml\MKL_ia32_10.1\bin;C:\Program Files (x86)\Intel\Compiler\11.1\065\mkl\em64t\bin;C:\Program Files (x86)\Intel\ICTCE\4.0.0.022\mpi\em64t\bin;C:\Program Files (x86)\Intel\ICTCE\4.0.0.022\Compiler\lib\Intel64;C:\Program Files (x86)\Intel\ICTCE\4.0.0.022\Compiler\lib\ia32;C:\Program Files (x86)\Intel\ICTCE\4.0.0.022\Compiler\lib\Intel64;C:\Program Files (x86)\Intel\ICTCE\4.0.0.022\Compiler\lib\ia32;C:\Program Files (x86)\Intel\ICTCE\4.0.0.022\bin;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;c:\ic-utils;C:\Program Files (x86)\QuickTime\QTSystem\;C:\Program Files (x86)\Enterprise Vault\EVClient\;c:\MATLAB\r2010a\runtime\win64;c:\MATLAB\r2010a\bin;c:\mingw\bin;c:\msys\1.0\bin;c:\Program Files (x86)\Microsoft SQL Server\90\Tools\binn\;C:\Program Files (x86)\Common Files\Intel\Shared Files\IDVC;C:\Program Files\NAG\FL22\flw6i22dcl\bin;C:\Program Files\NAG\FL22\flw6i22dcl\bin

This can lead to a slow down - a file which is actually in c:\windows\system32 could be checked in quite a few folders before it's found (and, yes, we should fix our build process to tidy this up - but it's down to some bad packages which prepend their own folder instead of appending it)

[CHR1S]

My Path just has 4 entries, nothing too major.

 

Only ENV errors are -

 

USERENV(2c8.38c) 10:21:56:670 ReadMembershipList: Group S-1-5-21-937451352-3369531182-3383592120-1009 not in current list of token groups

USERENV(2c8.38c) 10:21:57:701 ProcessGPORegistryPolicy: Failed to move archive file to temporary file due to error: 2.

USERENV(2c8.8e4) 10:55:27:091 ProcessGPOs: Forced option changed policy mode.

USERENV(2c8.2cc) 10:56:36:156 CUserProfile::CleanupUserProfile: Ref Count is not 0

USERENV(2c8.2cc) 10:56:36:156 CUserProfile::CleanupUserProfile: Ref Count is not 0

USERENV(2c8.2cc) 10:56:36:156 CUserProfile::CleanupUserProfile: Ref Count is not 0

USERENV(2c8.820) 10:59:28:233 PolicyChangedThread: UpdateUser failed with 6.

USERENV(2c8.af0) 11:15:06:718 PolicyChangedThread: UpdateUser failed with 6.

USERENV(2c8.c58) 11:18:49:576 ReadMembershipList: Group S-1-5-21-937451352-3369531182-3383592120-1009 not in current list of token groups

USERENV(2c8.c58) 11:18:49:998 ProcessGPORegistryPolicy: Failed to move archive file to temporary file due to error: 2.

USERENV(2c8.9c4) 11:25:38:123 PolicyChangedThread: UpdateUser failed with 6.

USERENV(2c8.d4c) 11:27:41:139 PolicyChangedThread: UpdateUser failed with 6.

USERENV(2c8.a70) 11:28:36:420 PolicyChangedThread: UpdateUser failed with 6.

USERENV(2c8.2e0) 11:29:38:482 PolicyChangedThread: UpdateUser failed with 6.

USERENV(2c8.3a0) 11:34:18:722 PolicyChangedThread: UpdateUser failed with 6.

Edited January 21, 2011 by CHR1S

[CHR1S]

Right, im getting this sorted now, but there is one last thing thats bothering me.

When a user logs in several seconds of the proccess is used to look for SMB information on mplayrc.exe.

 

 

Now the only reference to it is a shortcut that points to an application drive where it runs. Why would this file be queried so much at logon and more specificley the exe from which the shortcut points?

 

Thanks