annoying case of offline cached slow logon - 10-15 minutes

[damienharrison]

Hi all hope everyone is well.

we are having issues with slow cached offline logon.

Background

User logs on with Wndows XP machine whilst plugged into the network this takes 1-2 minutes at most.

User then logs in away from the network from a cold start (fully shutdown) this then takes a minmum of 10 minutes sometimes as long as 20.

I have turned on userenv.log details can be seen below.

USERENV(7ec.7f0) 14:13:43:750 LoadProfileInfo:  Failed to query central profile with error 2
USERENV(7ec.7f0) 14:13:43:750 GetProfileType: ProfileFlags is 0
USERENV(7ec.7f0) 14:13:43:765 Profile Ref Count is 1
USERENV(7ec.7f0) 14:13:43:765 LoadUserProfile: Leaving critical Section.
USERENV(7ec.7f0) 14:13:43:781 CSyncManager::LeaveLock <S-1-5-21-83552388-4163077686-3644841744-81624>
USERENV(7ec.7f0) 14:13:43:781 CSyncManager::LeaveLock: Lock released
USERENV(7ec.7f0) 14:13:43:781 CHashTable::HashDelete: S-1-5-21-83552388-4163077686-3644841744-81624 deleted
USERENV(7ec.7f0) 14:13:43:781 CSyncManager::LeaveLock: Lock deleted
USERENV(7ec.7f0) 14:13:43:796 LoadUserProfile: Impersonated user: 000001a4, 00000000
USERENV(7ec.7f0) 14:13:43:828 LoadUserProfile: Reverted to user: 00000000
USERENV(7ec.7f0) 14:13:43:828 LoadUserProfile: Leaving with a value of 1.
USERENV(7ec.7f0) 14:13:43:828 =========================================================
USERENV(7ec.7f0) 14:13:43:828 LoadUserProfile: LoadUserProfileP succeeded
USERENV(7ec.7f0) 14:13:43:843 LoadUserProfile:  Returning success.  Final Information follows:
USERENV(7ec.7f0) 14:13:43:843 lpProfileInfo->UserName = <ericgen>
USERENV(7ec.7f0) 14:13:43:843 lpProfileInfo->lpProfilePath = <>
USERENV(7ec.7f0) 14:13:43:843 lpProfileInfo->dwFlags = 0x0
USERENV(7ec.7f0) 14:13:43:843 LoadUserProfile: Returning TRUE. hProfile = <0x690>
USERENV(7ec.7f0) 14:13:43:890 IsSyncForegroundPolicyRefresh: Asynchronous, Reason: NoNeedForSync
USERENV(7ec.540) 14:13:43:906 IsSyncForegroundPolicyRefresh: Asynchronous, Reason: NoNeedForSync
USERENV(7ec.540) 14:13:43:906 ApplyGroupPolicy: Entering. Flags = e
USERENV(7ec.540) 14:13:43:906 ProcessGPOs:
USERENV(7ec.540) 14:13:43:921 ProcessGPOs:
USERENV(7ec.540) 14:13:43:921 ProcessGPOs: Starting user Group Policy (Async forground) processing...
USERENV(7ec.540) 14:13:43:921 ProcessGPOs:
USERENV(7ec.540) 14:13:43:921 ProcessGPOs:
USERENV(7ec.540) 14:13:43:937 EnterCriticalPolicySectionEx: Entering with timeout 600000 and flags 0x0
USERENV(7ec.540) 14:13:43:937 EnterCriticalPolicySectionEx: User critical section has been claimed.  Handle = 0x85c
USERENV(7ec.540) 14:13:43:937 EnterCriticalPolicySectionEx: Leaving successfully.
USERENV(7ec.540) 14:13:43:937 ProcessGPOs:  Machine role is 2.
USERENV(7ec.540) 14:13:43:953 ProcessGPOs: The DC for domain **** is not available. aborting
USERENV(7ec.540) 14:13:43:953 ProcessGPOs: No WMI logging done in this policy cycle.
USERENV(7ec.540) 14:13:43:968 ProcessGPOs: Processing failed with error 1355.
USERENV(7ec.540) 14:13:43:968 LeaveCriticalPolicySection: Critical section 0x85c has been released.
USERENV(7ec.540) 14:13:43:968 ProcessGPOs: User Group Policy has been applied.
USERENV(7ec.540) 14:13:43:984 ProcessGPOs: Leaving with 0.
USERENV(7ec.540) 14:13:43:984 ApplyGroupPolicy: Leaving successfully.
USERENV(7ec.55c) 14:13:43:984 GPOThread:  Next refresh will happen in 114 minutes
USERENV(7ec.7f0) 14:13:44:375 IsSyncForegroundPolicyRefresh: Asynchronous, Reason: NoNeedForSync
USERENV(7ec.684) 14:13:44:390 IsSyncForegroundPolicyRefresh: Asynchronous, Reason: NoNeedForSync
USERENV(534.6a4) 14:13:44:406 LibMain: Process Name:  C:\Program Files\Nortel\Nortel VPN Client\NvcSvcMgr.exe
USERENV(750.754) 14:13:44:703 LibMain: Process Name:  C:\Program Files\Sophos\Sophos Anti-Virus\SAVAdminService.exe
USERENV(c4.1ac) 14:13:45:156 LibMain: Process Name:  C:\Program Files\Sophos\Remote Management System\ManagementAgentNT.exe
USERENV(224.228) 14:13:45:359 LibMain: Process Name:  C:\Program Files\Sophos\Remote Management System\RouterNT.exe
USERENV(268.824) 14:13:46:140 LibMain: Process Name:  C:\WINDOWS\system32\CCM\CLICOMP\RemCtrl\Wuser32.exe
USERENV(834.a3c) 14:13:47:781 LibMain: Process Name:  C:\WINDOWS\system32\CCM\CcmExec.exe
USERENV(2ec.398) 14:13:48:890 GetUserDNSDomainName:  Domain name is NT Authority.  No DNS domain name available.
USERENV(df0.df4) 14:13:48:984 LibMain: Process Name:  C:\WINDOWS\system32\wbem\wmiprvse.exe
USERENV(2ec.3a0) 14:13:48:984 GetUserDNSDomainName:  Domain name is NT Authority.  No DNS domain name available.
USERENV(2ec.3f0) 14:13:49:328 GetUserDNSDomainName:  Domain name is NT Authority.  No DNS domain name available.
USERENV(2ec.f8) 14:13:49:343 GetUserDNSDomainName:  Domain name is NT Authority.  No DNS domain name available.
USERENV(bc.384) 14:13:50:765 LoadUserProfile: Yes, we can impersonate the user. Running as self
USERENV(bc.384) 14:13:50:781 =========================================================
USERENV(bc.384) 14:13:50:796 LoadUserProfile: Entering, hToken = <0x30>, lpProfileInfo = 0xc3f698
USERENV(bc.384) 14:13:50:812 LoadUserProfile: lpProfileInfo->dwFlags = <0x9>
USERENV(bc.384) 14:13:50:812 LoadUserProfile: lpProfileInfo->lpUserName = <LocalService>
USERENV(bc.384) 14:13:50:828 LoadUserProfile: NULL central profile path
USERENV(bc.384) 14:13:50:828 LoadUserProfile: NULL default profile path
USERENV(bc.384) 14:13:50:843 LoadUserProfile: NULL server name
USERENV(bc.384) 14:13:50:843 GetInterface: Returning rpc binding handle
USERENV(2ec.3b0) 14:13:52:390 GetUserDNSDomainName:  Domain name is NT Authority.  No DNS domain name available.
USERENV(2ec.3a8) 14:13:52:406 GetUserDNSDomainName:  Domain name is NT Authority.  No DNS domain name available.
USERENV(f88.f8c) 14:14:31:281 LibMain: Process Name:  C:\WINDOWS\system32\wuauclt.exe
USERENV(2ec.f8) 14:14:32:578 GetUserDNSDomainName:  Domain name is NT Authority.  No DNS domain name available.
USERENV(2ec.3bc) 14:14:32:593 GetUserDNSDomainName:  Domain name is NT Authority.  No DNS domain name available.
USERENV(674.488) 14:17:47:046 LibMain: Process Name:  \\?\C:\WINDOWS\system32\WBEM\WMIADAP.EXE
USERENV(49c.4bc) 14:17:47:468 LibMain: Process Name:  C:\WINDOWS\system32\wbem\wmiprvse.exe
USERENV(7ec.90) 14:13:50:859 IProfileSecurityCallBack: client authenticated.
USERENV(7ec.90) 14:36:26:765 DropClientContext: Got client token 00000154, sid = S-1-5-18
USERENV(7ec.90) 14:36:26:765 MIDL_user_allocate enter
USERENV(7ec.90) 14:36:26:781 DropClientContext: load profile object successfully made
USERENV(7ec.90) 14:36:26:796 DropClientContext: Returning 0
USERENV(bc.384) 14:36:26:796 LoadUserProfile: Calling DropClientToken (as self) succeeded
USERENV(7ec.1e4) 14:36:26:812 IProfileSecurityCallBack: client authenticated.
USERENV(7ec.1e4) 14:36:26:828 In LoadUserProfileP
USERENV(7ec.1e4) 14:36:26:843 LoadUserProfile: Running as client
USERENV(7ec.1e4) 14:36:26:859 =========================================================
USERENV(7ec.1e4) 14:36:26:875 LoadUserProfile: Entering, hToken = <0x604>, lpProfileInfo = 0x12a7c50
USERENV(7ec.1e4) 14:36:26:875 LoadUserProfile: lpProfileInfo->dwFlags = <0x9>
USERENV(7ec.1e4) 14:36:26:890 LoadUserProfile: lpProfileInfo->lpUserName = <LocalService>
USERENV(7ec.1e4) 14:36:26:906 LoadUserProfile: NULL central profile path
USERENV(7ec.1e4) 14:36:26:906 LoadUserProfile: NULL default profile path
USERENV(7ec.1e4) 14:36:26:921 LoadUserProfile: NULL server name
USERENV(7ec.1e4) 14:36:26:921 LoadUserProfile: User sid: S-1-5-19
USERENV(7ec.1e4) 14:36:26:921 CSyncManager::EnterLock <S-1-5-19>
USERENV(7ec.1e4) 14:36:26:937 CSyncManager::EnterLock: No existing entry found
USERENV(7ec.1e4) 14:36:26:937 CSyncManager::EnterLock: New entry created
USERENV(614.618) 14:36:26:953 LibMain: Process Name:  C:\WINDOWS\system32\userinit.exe
USERENV(7ec.1e4) 14:36:26:953 CHashTable::HashAdd: S-1-5-19 added in bucket 12
USERENV(7ec.1e4) 14:36:26:953 LoadUserProfile: Wait succeeded. In critical section.
USERENV(7ec.1e4) 14:36:26:968 TestIfUserProfileLoaded:  Profile already loaded.
USERENV(7ec.1e4) 14:36:26:968 Profile Ref Count is 5
USERENV(7ec.1e4) 14:36:26:968 LoadUserProfile: Leaving critical Section.
USERENV(7ec.1e4) 14:36:26:984 CSyncManager::LeaveLock <S-1-5-19>
USERENV(7ec.1e4) 14:36:26:984 CSyncManager::LeaveLock: Lock released
USERENV(7ec.1e4) 14:36:27:015 CHashTable::HashDelete: S-1-5-19 deleted
USERENV(7ec.1e4) 14:36:27:015 CSyncManager::LeaveLock: Lock deleted
USERENV(7ec.1e4) 14:36:27:015 LoadUserProfile: Impersonated user: 00000604, 00000a0c
USERENV(2ec.398) 14:36:27:031 GetUserDNSDomainName:  Domain name is NT Authority.  No DNS domain name available.
USERENV(7ec.1e4) 14:36:27:031 LoadUserProfile: Reverted to user: 00000000
USERENV(7ec.1e4) 14:36:27:031 LoadUserProfile: Reverted back to user <00000000>
USERENV(7ec.1e4) 14:36:27:031 LoadUserProfile: Leaving with a value of 1.
USERENV(7ec.1e4) 14:36:27:046 =========================================================

I think the issue is related to the computer looking for the domain have also turned on ProcessMonitor on bootup but I cant see anything odd in that log file (will try post it here but is 800meg)

If user logs off and then back on it only takes 1-2 minutes same if another user logs on initially.



Any help or pointers will be greatfully recieved if anyone solves the case of the slow logon I will owe you a beer or 2.

Kind regards

Damien Harrison

[damienharrison]

System Event Log

31/08/2010,15:47:58,Service Control Manager,Information,None,7036,N/A,RAS104413,The Windows Installer service entered the stopped state.
31/08/2010,15:37:58,Service Control Manager,Information,None,7036,N/A,RAS104413,The Windows Installer service entered the running state.
31/08/2010,15:37:58,Service Control Manager,Information,None,7035,NT AUTHORITY\SYSTEM,RAS104413,The Windows Installer service was successfully sent a start control.
31/08/2010,14:47:58,Service Control Manager,Information,None,7036,N/A,RAS104413,The Windows Installer service entered the stopped state.
31/08/2010,14:36:55,Service Control Manager,Information,None,7036,N/A,RAS104413,The IMAPI CD-Burning COM Service service entered the stopped state.
31/08/2010,14:36:50,Service Control Manager,Information,None,7035,NT AUTHORITY\SYSTEM,RAS104413,The SMS Process Event Driver service was successfully sent a start control.
31/08/2010,14:36:49,Service Control Manager,Information,None,7036,N/A,RAS104413,The IMAPI CD-Burning COM Service service entered the running state.
31/08/2010,14:36:49,Service Control Manager,Information,None,7035,NT AUTHORITY\SYSTEM,RAS104413,The IMAPI CD-Burning COM Service service was successfully sent a start control.
31/08/2010,14:36:37,Service Control Manager,Information,None,7036,N/A,RAS104413,The SSDP Discovery Service service entered the running state.
31/08/2010,14:36:37,Service Control Manager,Information,None,7035,NT AUTHORITY\SYSTEM,RAS104413,The SSDP Discovery Service service was successfully sent a start control.
31/08/2010,14:36:37,Service Control Manager,Information,None,7036,N/A,RAS104413,The Application Layer Gateway Service service entered the running state.
31/08/2010,14:36:37,Service Control Manager,Information,None,7035,NT AUTHORITY\SYSTEM,RAS104413,The Application Layer Gateway Service service was successfully sent a start control.
31/08/2010,14:36:32,Service Control Manager,Information,None,7036,N/A,RAS104413,The Remote Access Connection Manager service entered the running state.
31/08/2010,14:36:28,Service Control Manager,Information,None,7036,N/A,RAS104413,The Windows Installer service entered the running state.
31/08/2010,14:36:28,Service Control Manager,Information,None,7036,N/A,RAS104413,The Terminal Services service entered the running state.
31/08/2010,14:36:28,Service Control Manager,Information,None,7035,NT AUTHORITY\SYSTEM,RAS104413,The Windows Installer service was successfully sent a start control.
31/08/2010,14:36:28,Service Control Manager,Information,None,7036,N/A,RAS104413,The Network Location Awareness (NLA) service entered the running state.
31/08/2010,14:36:28,Service Control Manager,Information,None,7035,NT AUTHORITY\SYSTEM,RAS104413,The Network Location Awareness (NLA) service was successfully sent a start control.
31/08/2010,14:36:28,Service Control Manager,Information,None,7035,NT AUTHORITY\SYSTEM,RAS104413,The Terminal Services service was successfully sent a start control.
31/08/2010,14:36:28,Service Control Manager,Information,None,7035,NT AUTHORITY\SYSTEM,RAS104413,The Remote Access Connection Manager service was successfully sent a start control.
31/08/2010,14:36:28,Service Control Manager,Information,None,7036,N/A,RAS104413,The Telephony service entered the running state.
31/08/2010,14:36:28,Service Control Manager,Information,None,7036,N/A,RAS104413,The Sophos Device Control Service service entered the running state.
31/08/2010,14:36:28,Service Control Manager,Information,None,7035,NT AUTHORITY\LOCAL SERVICE,RAS104413,The Sophos Device Control Service service was successfully sent a start control.
31/08/2010,14:13:18,NETw5x32,Information,None,7036,N/A,RAS104413,The  service entered the Intel(R) Centrino(R) Advanced-N 6200 AGN state.
31/08/2010,14:13:18,e1kexpress,Information,None,32,N/A,RAS104413,Intel(R) 82577LM Gigabit Network Connection
 Network link has been established at 1Gbps full duplex.

31/08/2010,14:13:42,NETLOGON,Error,None,5719,N/A,RAS104413,"No Domain Controller is available for domain *** due to the following: 
There are currently no logon servers available to service the logon request. . 
Make sure that the computer is connected to the network and try again. If the problem persists, please contact your domain administrator."
31/08/2010,14:13:30,EventLog,Information,None,6005,N/A,RAS104413,The Event log service was started.
31/08/2010,14:13:30,EventLog,Information,None,6009,N/A,RAS104413,Microsoft (R) Windows (R) 5.01. 2600 Service Pack 3 Multiprocessor Free.

[damienharrison]

Update

If you wait 1 minute on system load up the desktop loads straight away hmmmmmmmmmmmmmm

[rosswilson]

If you wait 1 minute on system load up the desktop loads straight away hmmmmmmmmmmmmmm

So when a user trys to login as soon as the machine boots, thats when the problem occurs? But if they wait a minute after sitting at the logon screen their logon processes as normal?

Then could the computer be trying to connect to the network just after the login screen appears, and when the user trys to login the computer hasn't yet realised the network is unavailable? I've seen this happen for laptops that cannot connect to the wireless network until actually logged in so that the (poorly written) drivers can load up on logon.

In Group Policy there is a policy setting called "Always wait for the network at login" (maybe worded slightly similar, can't remember the exact wording). Could this be of some help?

Ross