Debugging shutdown issues on Windows 2003 with Winlogon tracing
Una din marile probleme cu Windows 2003 atunci cand faci administrare remote e ca nu stii niciodata daca atunci cand dai reboot sistemul tau reuseste sa se restarteze sau nu.
Windows 2008 e ceva mai avansat, dar nu pentru ca nu ar exista astfel de probleme ci pentru ca exista ceva procedee si tool-uri pentru a afla cauza problemei.
In schimb pe Windows 2003, tot ce stiam pana de curand era faza cu generearea unui crash dump in momentul in care sistemul “intepenea” in fereastra de shutdown.
Dar am aflat ca se mai poate face ceva ce poate ajuta in debugging. Si anume tracing pe Winlogon. Faza e ca nu merge activat in versiunea normala de Windows (free/retail build) ci numai in “checked/debug build”. Dar merge inlocuit si doar Winlogon.exe cu versiunea checked pe durata troubleshooting-ului. In caz ca nu aveti access la MSDN sa downloadati checked build, puteti downloada Service Pack 2 pentru Windows 2003 versiunea checked. Mai jos aveti link-ul pentru versiunea x86:
http://www.microsoft.com/en-us/download/confirmation.aspx?id=3685
Pasul urmator este sa setati urmatoarele variabile in registry:
HKLM\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Winlogon\DebugFlags (REG_SZ)
HKLM\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Winlogon\LogFile (REG_SZ)
Pentru a capta toate evenimentele va recomand sa setati DebugFlags cu urmatoarea valoare: Error, Warning, Trace, Init, Timeout, Sas, State, MPR, CoolSwitch, Profile, DebugLsa, DebugSpm, DebugMpr, DebugGo, Migrate, DebugServices, Setup, SC, Notify, Job
Si iata si cum arata log-ul:
14:52:06.936: 360.1956> Winlogon-Trace: Doing remote-initiated (W2K3\Administrator) Reboot=true, Force=true
14:52:06.951: 360.1956> Winlogon-Trace: Starting user thread for Logoff, flags = 3807
14:52:06.951: 360.2616> Winlogon-Trace: Doing immediate shutdown, LastGinaRet = b, Flags = 3804
14:52:06.951: 360.2616> Winlogon-Trace: Calling ExitWindowsEx(0x3804, 0)
14:52:07.842: 360.364> Winlogon-Trace-SAS: LOGONNOTIFY message 0
14:52:07.842: 360.364> Winlogon-Trace-SAS: WINLOGON : True
14:52:07.842: 360.364> Winlogon-Trace-SAS: SYSTEM : False
14:52:07.842: 360.364> Winlogon-Trace-SAS: SHUTDOWN : False
14:52:07.842: 360.364> Winlogon-Trace-SAS: REBOOT : False
14:52:07.842: 360.364> Winlogon-Trace-SAS: POWEROFF : False
14:52:07.842: 360.364> Winlogon-Trace-SAS: FORCE : True
14:52:07.842: 360.364> Winlogon-Trace-SAS: OLD_SYSTEM : False
14:52:07.842: 360.364> Winlogon-Trace-SAS: OLD_SHUTDOWN : True
14:52:07.842: 360.364> Winlogon-Trace-SAS: OLD_REBOOT : True
14:52:07.842: 360.364> Winlogon-Trace-SAS: OLD_POWEROFF : False
14:52:07.842: 360.364> Winlogon-Trace: Received SAS from winsrv, code 4 (User Logoff)
14:52:07.842: 360.364> Winlogon-Trace: In state LoggedOnUser, sending kill message to window
14:52:07.842: 360.364> Winlogon-Trace: Sending SAS code 4 (User Logoff) to window 50020 (Winlogon generic control dialog)
14:52:07.842: 360.364> Winlogon-Trace: ChangeStateForSAS: Went from 6 (LoggedOnUser) to 7 (LoggedOn_SAS)
14:52:07.842: 360.364> Winlogon-Trace: Source desktop was Default
14:52:07.842: 360.364> Winlogon-Trace: Switching desktop from Application to Winlogon
14:52:07.842: 360.364> Winlogon-Trace-State: SASRouter: In state LoggedOn_SAS
14:52:07.842: 360.364> Winlogon-Trace-Timeout: Disabling timeouts
14:52:07.842: 360.364> Winlogon-Trace: In Logoff()
14:52:07.842: 360.364> Winlogon-Trace: Switching desktop from Winlogon to Application
14:52:07.842: 360.364> Winlogon-Trace: Closing handle 3a8 to users desktop
14:52:07.857: 360.1468> Winlogon-Trace: StopUserGPOProcessing: Waiting for user group policy thread to terminate.
14:52:07.857: 360.1468> Winlogon-Trace: StopUserGPOProcessing: User group policy thread has terminated.
14:52:07.951: 360.364> Winlogon-Trace: Source desktop was Default
14:52:07.951: 360.364> Winlogon-Trace: Switching desktop from Application to Winlogon
14:52:07.967: 360.364> Winlogon-Trace: ProfileUserMapping Refs = 2
14:52:07.967: 360.364> Winlogon-Trace: ProfileUserMapping Refs = 1
14:52:07.967: 360.364> Winlogon-Error: [WUInstall] Failed to query WU value (2).
14:52:07.967: 360.364> Winlogon-Error: [WUInstall] Failed to clean WU value (2).
14:52:07.967: 360.364> Winlogon-Trace: Actually closing user mapping
14:52:07.967: 360.364> Winlogon-Trace: ProfileUserMapping Refs = 0
14:52:07.967: 360.3220> Winlogon-Trace: ExitWindowsEx called to shut down COM processes
14:52:07.998: 360.364> Winlogon-Trace: ProfileUserMapping Refs = 0
14:52:07.998: 360.364> Winlogon-Trace: Actually opening user mapping. User is logged on
14:52:07.998: 360.364> Winlogon-Trace: ProfileUserMapping Refs = 1
14:52:08.014: 360.364> Winlogon-Trace: Actually closing user mapping
14:52:08.014: 360.364> Winlogon-Trace: ProfileUserMapping Refs = 0
14:52:08.014: 360.364> Winlogon-Trace: In InternalWinStationNotifyLogoff
14:52:08.014: 360.2540> Winlogon-Error: [WUInstall] Skipping WU installs – Fail to open WU key (2).
14:52:08.154: 360.2540> Winlogon-Trace: [WUInstall] Skipping installs – not a shutdown.
14:52:08.154: 360.2540> Winlogon-Trace: [WUInstall] Skipping installs – not requested.
14:52:08.154: 360.2540> Winlogon-Trace: [WUInstall] Calling WUAutoUpdateAtShutdown(0)…
14:52:08.186: 360.2624> Winlogon-Trace: StopMachineGPOProcessing: Waiting for machine group policy thread to terminate.
14:52:08.201: 360.2624> Winlogon-Trace: StopMachineGPOProcessing: Machine group policy thread has terminated.
14:52:08.295: 2516.2280> Winlogon-Trace-SAS: LOGONNOTIFY message 9
Acum nu pot promite ca aceasta metoda o sa va rezolve problemele, insa este unul din putinele moduri in care poti face troubleshooting la asa ceva pe Windows 2003.
PS: mai sunt cateva variante cu windows debugger insa mi se par prea complicate pentru un sysadmin.