Sign in
 
HomeWindows Server 2012Windows Server 2008 R2Windows Server 2003LibraryForums
Windows Server TechCenter >
> 
> 
running logoff scripts slow. How to enable logging.

Unanswered running logoff scripts slow. How to enable logging.

  • Wednesday, April 04, 2012 8:50 AM
     
     
    Sign In to Vote
    0

    Hi,

    Windows XP in a W2k3 domain.

    The computer takes very long during the stage running logoff scripts.

    I've been having a look at the Group Policy Results within the GPM and there's nothing different from others computers that shutdown/reboot normally.

    How could troubleshoot that?, is there any log file where events are recorded?

    Thanks in advance.

     

All Replies

  • Wednesday, April 04, 2012 12:11 PM
     
     
    Sign In to Vote
    0
     
    > How could troubleshoot that?, is there any log file where events are
    > recorded?
     
    If your scripts create log files - yes, then there are log files to be
    examined. If they don't - no, then you are out of luck.
     
    sincerely, Martin
     
    NO THEY ARE NOT EVIL, if you know what you are doing: Good or bad GPOs?
    Wenn meine Antwort hilfreich war, freue ich mich über eine Bewertung! If my answer was helpful, I'm glad about a rating!
     
  • Thursday, April 05, 2012 5:27 AM
    Moderator
     
     
    Sign In to Vote
    0

    Hi,

    Thanks for posting in Microsoft TechNet forums.

    I suggest we try using this user to log on other client computers to see if the problem persists. Also we can try using another user to log on this computer to see if it still takes long time to shutdown.

    We need to confirm whether the problem is caused by Computer Shutdown Scripts or User Logoff Scripts.

    If the problem actually occurs at the stage of running logoff scripts, it shall not persist if we use another user to log on/log off on this computer.

    Please give it a try and let us know the result.

    Regards

    Kevin

    TechNet Community Support

     
  • Friday, April 06, 2012 6:58 AM
     
     
    Sign In to Vote
    0

    Before troubleshooting the script or whatever is freezing the computer, I'd like to know who's the culprit.

    Doesn't Windows XP/7 have any log that says where the logoff process takes so long?.

    Thank you.

     
  • Monday, April 09, 2012 2:10 AM
    Moderator
     
     
    Sign In to Vote
    0

     

    Hi,

    We can try Event Viewer in this situation.

    Here are some links for your reference:

    How to view and manage event logs in Event Viewer in Windows XP

    http://support.microsoft.com/kb/308427

    Open Event Viewer (Windows 7)

    http://windows.microsoft.com/en-US/windows7/Open-Event-Viewer

    What information appears in event logs (Event Viewer)?

    http://windows.microsoft.com/en-US/windows7/What-information-appears-in-event-logs-Event-Viewer

    Regards

    Kevin

    TechNet Community Support

     
  • Friday, April 13, 2012 1:41 AM
    Moderator
     
     
    Sign In to Vote
    0

    Hi,

    As this thread has been quiet for a while, we assume that the issue has been resolved. At this time, we will mark it as ‘Answered’ as the previous steps should be helpful for many similar scenarios. If the issue still persists, please feel free to  reply this post directly so we will be notified to follow it up. You can also choose to unmark the answer as you wish.
     
    BTW, we’d love to hear your feedback about the solution. By sharing your experience you can help other community members facing similar problems. Thanks for your understanding and efforts.
     
    Best Regards
     
    Kevin

    TechNet Community Support

     
  • Friday, April 13, 2012 5:58 AM
     
     
    Sign In to Vote
    0

    Apart from checking the Event Viewer and trying to logon with the same user in different computers, in my opinion, the best way to torubleshoot the logoff issues would be to enable the Userenv log via Windows registry. You can have a look at this link: http://blogs.technet.com/b/askds/archive/2008/11/11/understanding-how-to-read-a-userenv-log-part-1.aspx

    Finally, it seems that the problems came from not having enabled the NetBIOS over TCP/IP in the computer. Could that detail be causing such a slow logoff?

    Thank you.

     
  • Friday, April 13, 2012 7:10 AM
    Moderator
     
     
    Sign In to Vote
    0

    Hi,

    Thank you for sharing the resolution with us.

    From your description, I understand that the problem is gone after enabling NetBIOS over TCP/IP.

    It is possible that some logoff scripts require this feature and caused the problem.

    For your information, here is an article regarding NetBIOS over TCP/IP:

    http://technet.microsoft.com/en-us/library/bb727013.aspx#EBAA

    Regards

    Kevin

    TechNet Community Support

     
  • Friday, April 13, 2012 7:37 AM
     
     
    Sign In to Vote
    0

    I'm afraid that wasn't the cuplrit. The user hadn't any problem yesterday in the mornint but he had the slow logoff again whe shutting down the computer in the afternoon.

    I do a copy/paste of the userenv.bak file and any help would be very appreciated. The shutdown process started at roughly 18:15. I see a 10 minutes gap after the line USERENV(1388.374) 18:16:13:025 LibMain: Process Name:  C:\WINNT\System32\WScript.exe. In my opinion, that could be related with any script launched, but I'm not able to get anymore useful information.

    USERENV(1100.1368) 18:15:09:993 LibMain: Process Name:  C:\Archivos de programa\Microsoft Office\OFFICE11\EXCEL.EXE
    USERENV(420.1480) 18:15:16:726 ImpersonateUser: Failed to impersonate user with 5.
    USERENV(420.1480) 18:15:16:741 GetUserNameAndDomain Failed to impersonate user
    USERENV(420.1480) 18:15:16:741 ImpersonateUser: Failed to impersonate user with 5.
    USERENV(420.1480) 18:15:16:741 GetUserDNSDomainName: Failed to impersonate user
    USERENV(15ec.1330) 18:15:16:741 LibMain: Process Name:  C:\ARCHIV~1\MICROS~2\OFFICE11\OUTLOOK.EXE
    USERENV(420.15dc) 18:15:16:804 ImpersonateUser: Failed to impersonate user with 5.
    USERENV(420.15dc) 18:15:16:804 GetUserNameAndDomain Failed to impersonate user
    USERENV(420.15dc) 18:15:16:804 ImpersonateUser: Failed to impersonate user with 5.
    USERENV(420.15dc) 18:15:16:804 GetUserDNSDomainName: Failed to impersonate user
    USERENV(420.1480) 18:15:17:585 ImpersonateUser: Failed to impersonate user with 5.
    USERENV(420.1480) 18:15:17:585 GetUserNameAndDomain Failed to impersonate user
    USERENV(420.1480) 18:15:17:600 ImpersonateUser: Failed to impersonate user with 5.
    USERENV(420.1480) 18:15:17:600 GetUserDNSDomainName: Failed to impersonate user
    USERENV(420.15dc) 18:15:17:866 ImpersonateUser: Failed to impersonate user with 5.
    USERENV(420.15dc) 18:15:17:866 GetUserNameAndDomain Failed to impersonate user
    USERENV(420.15dc) 18:15:17:866 ImpersonateUser: Failed to impersonate user with 5.
    USERENV(420.15dc) 18:15:17:882 GetUserDNSDomainName: Failed to impersonate user
    USERENV(420.15dc) 18:15:18:210 ImpersonateUser: Failed to impersonate user with 5.
    USERENV(420.15dc) 18:15:18:225 GetUserNameAndDomain Failed to impersonate user
    USERENV(420.15dc) 18:15:18:225 ImpersonateUser: Failed to impersonate user with 5.
    USERENV(420.15dc) 18:15:18:225 GetUserDNSDomainName: Failed to impersonate user
    USERENV(420.1480) 18:15:18:928 ImpersonateUser: Failed to impersonate user with 5.
    USERENV(420.1480) 18:15:18:928 GetUserNameAndDomain Failed to impersonate user
    USERENV(420.1480) 18:15:18:928 ImpersonateUser: Failed to impersonate user with 5.
    USERENV(420.1480) 18:15:18:928 GetUserDNSDomainName: Failed to impersonate user
    USERENV(420.1480) 18:15:18:944 ImpersonateUser: Failed to impersonate user with 5.
    USERENV(420.1480) 18:15:18:944 GetUserNameAndDomain Failed to impersonate user
    USERENV(420.1480) 18:15:18:959 ImpersonateUser: Failed to impersonate user with 5.
    USERENV(420.1480) 18:15:18:959 GetUserDNSDomainName: Failed to impersonate user
    USERENV(420.1480) 18:15:18:959 ImpersonateUser: Failed to impersonate user with 5.
    USERENV(420.1480) 18:15:18:959 GetUserNameAndDomain Failed to impersonate user
    USERENV(420.1480) 18:15:18:975 ImpersonateUser: Failed to impersonate user with 5.
    USERENV(420.1480) 18:15:18:975 GetUserDNSDomainName: Failed to impersonate user
    USERENV(420.1480) 18:15:19:037 ImpersonateUser: Failed to impersonate user with 5.
    USERENV(420.1480) 18:15:19:037 GetUserNameAndDomain Failed to impersonate user
    USERENV(420.1480) 18:15:19:037 ImpersonateUser: Failed to impersonate user with 5.
    USERENV(420.1480) 18:15:19:037 GetUserDNSDomainName: Failed to impersonate user
    USERENV(14bc.15a4) 18:16:12:635 LibMain: Process Name:  C:\WINNT\system32\userinit.exe
    USERENV(14bc.15a4) 18:16:12:713 GetProfileType:  Profile already loaded.
    USERENV(14bc.15a4) 18:16:12:713 GetProfileType: ProfileFlags is 0
    USERENV(1388.374) 18:16:13:025 LibMain: Process Name:  C:\WINNT\System32\WScript.exe
    USERENV(3e8.3ec) 18:26:36:401 UnloadUserProfile: Entering, hProfile = <0x120>
    USERENV(3e8.3ec) 18:26:36:401 UnloadUserProfile: In console winlogon process
    USERENV(3e8.3ec) 18:26:36:401 UnloadUserProfileP: Entering, hProfile = <0x120>
    USERENV(3e8.3ec) 18:26:36:401 GetExclusionListFromRegistry: Policy list is empty, returning user list = <Configuración local;Temporary Internet Files;Historial;Temp;Configuración local\Datos de programa\Microsoft\Outlook>
    USERENV(3e8.3ec) 18:26:36:401 CSyncManager::EnterLock <S-1-5-21-62063896-2015969293-495535119-62827>
    USERENV(3e8.3ec) 18:26:36:417 CSyncManager::EnterLock: No existing entry found
    USERENV(3e8.3ec) 18:26:36:417 CSyncManager::EnterLock: New entry created
    USERENV(3e8.3ec) 18:26:36:417 CHashTable::HashAdd: S-1-5-21-62063896-2015969293-495535119-62827 added in bucket 11
    USERENV(3e8.3ec) 18:26:36:417 UnloadUserProfileP: Wait succeeded.  In critical section.
    USERENV(3e8.3ec) 18:26:36:448 MyRegUnLoadKey: Returning 1.
    USERENV(3e8.3ec) 18:26:36:448 UnloadUserProfileP:  Succesfully unloaded profile
    USERENV(3e8.3ec) 18:26:36:464 MyRegUnLoadKey: Returning 1.
    USERENV(3e8.3ec) 18:26:36:464 UnLoadClassHive: Successfully unmounted S-1-5-21-62063896-2015969293-495535119-62827_Classes
    USERENV(3e8.3ec) 18:26:36:464 UnloadUserProfileP:  Successfully unloaded user classes
    USERENV(3e8.3ec) 18:26:36:464 UnloadUserProfileP: Impersonated user
    USERENV(3e8.3ec) 18:26:36:479 UnloadUserProfileP: Writing local ini file
    USERENV(3e8.3ec) 18:26:36:495 UnloadUserProfileP: Reverting to Self
    USERENV(3e8.3ec) 18:26:36:495 UnloadUserProfileP: exitting and cleaning up
    USERENV(3e8.3ec) 18:26:36:495 CSyncManager::LeaveLock <S-1-5-21-62063896-2015969293-495535119-62827>
    USERENV(3e8.3ec) 18:26:36:495 CSyncManager::LeaveLock: Lock released
    USERENV(3e8.3ec) 18:26:36:511 CHashTable::HashDelete: S-1-5-21-62063896-2015969293-495535119-62827 deleted
    USERENV(3e8.3ec) 18:26:36:511 CSyncManager::LeaveLock: Lock deleted
    USERENV(3e8.3ec) 18:26:36:511 UnloadUserProfileP: Leave critical section.
    USERENV(3e8.3ec) 18:26:36:511 UnloadUserProfileP: Leaving with a return value of 1
    USERENV(3e8.3ec) 18:26:36:511 UnloadUserProfile: UnloadUserProfileP succeeded
    USERENV(3e8.3ec) 18:26:36:511 UnloadUserProfile: returning 1
    USERENV(664.668) 18:26:59:287 GetUserNameAndDomain:  MyGetUserNameEx failed for NT4 style name with 1115
    USERENV(dfc.bc) 18:26:59:802 LibMain: Process Name:  C:\WINNT\system32\wuauclt.exe
    USERENV(414.11f8) 18:26:59:834 UnloadUserProfile: Entering, hProfile = <0x44c>
    USERENV(414.11f8) 18:26:59:834 GetInterface: Returning rpc binding handle
    USERENV(3e8.10e4) 18:26:59:834 IProfileSecurityCallBack: client authenticated.
    USERENV(3e8.10e4) 18:26:59:834 DropClientContext: Got client token 000003B0, sid = S-1-5-18
    USERENV(3e8.10e4) 18:26:59:834 MIDL_user_allocate enter
    USERENV(3e8.10e4) 18:26:59:834 DropClientContext: load profile object successfully made
    USERENV(3e8.10e4) 18:26:59:834 DropClientContext: Returning 0
    USERENV(414.11f8) 18:26:59:834 UnLoadUserProfile: Calling DropClientToken (as self) succeeded
    USERENV(3e8.410) 18:26:59:834 IProfileSecurityCallBack: client authenticated.
    USERENV(3e8.410) 18:26:59:834 UnloadUserProfileP: Entering, hProfile = <0x510>
    USERENV(3e8.410) 18:26:59:834 UnloadUserProfileP: ImpersonateUser <000003b0>, old token is <00000000>
    USERENV(3e8.410) 18:26:59:834 GetExclusionListFromRegistry: Policy list is empty, returning user list = <Configuración local;Temporary Internet Files;Historial;Temp>
    USERENV(3e8.410) 18:26:59:834 CSyncManager::EnterLock <S-1-5-19>
    USERENV(3e8.410) 18:26:59:834 CSyncManager::EnterLock: No existing entry found
    USERENV(3e8.410) 18:26:59:834 CSyncManager::EnterLock: New entry created
    USERENV(3e8.410) 18:26:59:834 CHashTable::HashAdd: S-1-5-19 added in bucket 12
    USERENV(3e8.410) 18:26:59:834 UnloadUserProfileP: Wait succeeded.  In critical section.
    USERENV(3e8.410) 18:26:59:834 UnloadUserProfileP:  Didn't unload user profile, Ref Count is 2
    USERENV(3e8.410) 18:26:59:834 UnloadUserProfileP: Reverted back to user <00000000>
    USERENV(3e8.410) 18:26:59:834 CSyncManager::LeaveLock <S-1-5-19>
    USERENV(3e8.410) 18:26:59:834 CSyncManager::LeaveLock: Lock released
    USERENV(3e8.410) 18:26:59:834 CHashTable::HashDelete: S-1-5-19 deleted
    USERENV(3e8.410) 18:26:59:834 CSyncManager::LeaveLock: Lock deleted
    USERENV(3e8.410) 18:26:59:834 UnloadUserProfileP: Leave critical section.
    USERENV(3e8.410) 18:26:59:834 UnloadUserProfileP: Leaving with a return value of 1
    USERENV(3e8.410) 18:26:59:834 UnloadUserProfileI: returning 0
    USERENV(414.11f8) 18:26:59:834 UnloadUserProfile: Calling UnloadUserProfileI succeeded
    USERENV(3e8.10e4) 18:26:59:834 IProfileSecurityCallBack: client authenticated.
    USERENV(3e8.10e4) 18:26:59:834 ReleaseClientContext: Releasing context
    USERENV(3e8.10e4) 18:26:59:834 ReleaseClientContext_s: Releasing context
    USERENV(3e8.10e4) 18:26:59:834 MIDL_user_free enter
    USERENV(414.11f8) 18:26:59:834 ReleaseInterface: Releasing rpc binding handle
    USERENV(414.11f8) 18:26:59:834 UnloadUserProfile: returning 1
    USERENV(664.668) 18:27:00:771 GetUserDNSDomainName:  Domain name is NT Authority.  No DNS domain name available.
    USERENV(414.87c) 18:27:01:052 UnloadUserProfile: Entering, hProfile = <0x428>
    USERENV(414.87c) 18:27:01:052 GetInterface: Returning rpc binding handle
    USERENV(3e8.410) 18:27:01:052 IProfileSecurityCallBack: client authenticated.
    USERENV(3e8.410) 18:27:01:052 DropClientContext: Got client token 00000648, sid = S-1-5-18
    USERENV(3e8.410) 18:27:01:052 MIDL_user_allocate enter
    USERENV(3e8.410) 18:27:01:052 DropClientContext: load profile object successfully made
    USERENV(3e8.410) 18:27:01:052 DropClientContext: Returning 0
    USERENV(414.87c) 18:27:01:052 UnLoadUserProfile: Calling DropClientToken (as self) succeeded
    USERENV(3e8.10e4) 18:27:01:052 IProfileSecurityCallBack: client authenticated.
    USERENV(3e8.10e4) 18:27:01:052 UnloadUserProfileP: Entering, hProfile = <0x688>
    USERENV(3e8.10e4) 18:27:01:052 UnloadUserProfileP: ImpersonateUser <00000648>, old token is <00000000>
    USERENV(3e8.10e4) 18:27:01:052 GetExclusionListFromRegistry: Policy list is empty, returning user list = <Configuración local;Temporary Internet Files;Historial;Temp>
    USERENV(3e8.10e4) 18:27:01:052 CSyncManager::EnterLock <S-1-5-19>
    USERENV(3e8.10e4) 18:27:01:052 CSyncManager::EnterLock: No existing entry found
    USERENV(3e8.10e4) 18:27:01:052 CSyncManager::EnterLock: New entry created
    USERENV(3e8.10e4) 18:27:01:052 CHashTable::HashAdd: S-1-5-19 added in bucket 12
    USERENV(3e8.10e4) 18:27:01:052 UnloadUserProfileP: Wait succeeded.  In critical section.
    USERENV(3e8.10e4) 18:27:01:052 UnloadUserProfileP:  Didn't unload user profile, Ref Count is 1
    USERENV(3e8.10e4) 18:27:01:052 UnloadUserProfileP: Reverted back to user <00000000>
    USERENV(3e8.10e4) 18:27:01:052 CSyncManager::LeaveLock <S-1-5-19>
    USERENV(3e8.10e4) 18:27:01:052 CSyncManager::LeaveLock: Lock released
    USERENV(3e8.10e4) 18:27:01:052 CHashTable::HashDelete: S-1-5-19 deleted
    USERENV(3e8.10e4) 18:27:01:052 CSyncManager::LeaveLock: Lock deleted
    USERENV(3e8.10e4) 18:27:01:052 UnloadUserProfileP: Leave critical section.
    USERENV(3e8.10e4) 18:27:01:052 UnloadUserProfileP: Leaving with a return value of 1
    USERENV(3e8.10e4) 18:27:01:052 UnloadUserProfileI: returning 0
    USERENV(414.87c) 18:27:01:052 UnloadUserProfile: Calling UnloadUserProfileI succeeded
    USERENV(3e8.410) 18:27:01:052 IProfileSecurityCallBack: client authenticated.
    USERENV(3e8.410) 18:27:01:052 ReleaseClientContext: Releasing context
    USERENV(3e8.410) 18:27:01:052 ReleaseClientContext_s: Releasing context
    USERENV(3e8.410) 18:27:01:052 MIDL_user_free enter
    USERENV(414.87c) 18:27:01:052 ReleaseInterface: Releasing rpc binding handle
    USERENV(414.87c) 18:27:01:052 UnloadUserProfile: returning 1

    Thank you.

     
  • Friday, April 13, 2012 7:40 AM
     
     
    Sign In to Vote
    0

    I give more information that could be useful for the case.

    When trying to troubleshoot the issue, I ran commands the likes of msinfo32, gpresult /V, gpupdate... and took a long time to show the output for all of them.

    What it's more annoying is that it doesn't happen always.

    Thank you.


    • Edited by fedayn1 Friday, April 13, 2012 7:45 AM
    •  
     
  • Friday, April 13, 2012 1:45 PM
     
     
    Sign In to Vote
    1
     
    > I do a copy/paste of the userenv.bak file and any help would be very
    > appreciated. The shutdown process started at roughly 18:15. I see a 10
    > minutes gap after the line USERENV(1388.374) 18:16:13:025 LibMain:
    > Process Name:  C:\WINNT\System32\WScript.exe. In my opinion, that
    > could be related with any script launched, but I'm not able to get
    > anymore useful information. USERENV(1100.1368) 18:15:09:993 LibMain:
    > Process Name:
     
    Please create a gpresult /h report and check for shutdown scripts. They
    have a column "Last executed", examine carefully what scripts were run
    at shutdown and when they did finish...
     
    sincerely, Martin
     
    NO THEY ARE NOT EVIL, if you know what you are doing: Good or bad GPOs?
    Wenn meine Antwort hilfreich war, freue ich mich über eine Bewertung! If my answer was helpful, I'm glad about a rating!
     
  • Monday, April 16, 2012 3:32 PM
     
     
    Sign In to Vote
    0
     
    Please create a gpresult /h report and check for shutdown scripts. They
    have a column "Last executed", examine carefully what scripts were run
    at shutdown and when they did finish...

    May be I'm wrong, but I think the switch /h only works in Vista or later. The issues happen in a Windows XP computer.

    Than kyou

     
  • Wednesday, April 18, 2012 6:23 AM
     
     
    Sign In to Vote
    0
     
    > May be I'm wrong, but I think the switch /h only works in Vista or
    > later. The issues happen in a Windows XP computer.
     
    You're right - I don't use XP anymore, so I forgot.
    Ok, instead use GPMC.MSC and create your report from there.
     
    sincerely, martin
     
    NO THEY ARE NOT EVIL, if you know what you are doing: Good or bad GPOs?
    Wenn meine Antwort hilfreich war, freue ich mich über eine Bewertung! If my answer was helpful, I'm glad about a rating!
     
  • Thursday, April 19, 2012 5:39 AM
     
     
    Sign In to Vote
    0

    Matin,

    Do you think the issue comes from a problematica logoff script?

    Thank you.

     
  • Thursday, April 19, 2012 8:00 AM
     
     
    Sign In to Vote
    0

    Hi

    I think Martin is right the most likely cause is a logoff script. There is a large pause in your logfile of 10 minutes and 23 seconds

    USERENV(1388.374) 18:16:13:025 LibMain: Process Name:  C:\WINNT\System32\WScript.exe
    USERENV(3e8.3ec) 18:26:36:401 UnloadUserProfile: Entering, hProfile = <0x120>

    The fact that it is running WScript.exe  suggests that a script is trying to run and timing out on something

    The second pause is only 13 seconds

    USERENV(3e8.3ec) 18:26:36:511 UnloadUserProfile: returning 1
    USERENV(664.668) 18:26:59:287 GetUserNameAndDomain:  MyGetUserNameEx failed for NT4 style name with 1115

    This may be due to difficulties with unloading registry hives. It might speed up your logoff if you install User Profile Hive Cleanup. It's a Microsoft product and we have it installed on our estate.

    http://www.microsoft.com/download/en/details.aspx?id=6676

    Cheers

    Alex

     
  • Thursday, April 19, 2012 10:53 AM
     
     
    Sign In to Vote
    0
     
    > Do you think the issue comes from a problematica logoff script?
     
    Yes, I do so. The time elapsing after wscript.exe is a clear hint that
    the default GPO script timeout of 600 seconds expired and the script was
    terminated. Again: Please create a RSOP report (Group Policy Management
    Console offers the ability to do so) and check which shutdown scripts
    you have in place...
     
    NO THEY ARE NOT EVIL, if you know what you are doing: Good or bad GPOs?
    Wenn meine Antwort hilfreich war, freue ich mich über eine Bewertung! If my answer was helpful, I'm glad about a rating!