Troubleshooting con Process Monitor
Salve a tutti!
Nel nostro lavoro quotidiano, utilizziamo diversi strumenti, Windbg, Process Explorer, Process Monitor, che ci permettono di capire cosa sta succedendo nel sistema operativo in un dato momento, permettendoci di individuare la ragione del problema che stiamo affrontando.
Volevo introdurre con questo post il Process Monitor.
Mark Russinovich, autore e creatore del tool insieme a Bryce Cogswell, nel suo blog presenta ogni tanto dei problemi che ha risolto con l’utiilzzo di questo tool.
Anche nel nostro lavoro quotidiano, molto spesso ricorriamo a questo tool perchè se utilizzato in modalità avanzata, con l’aiuto dei simboli di debug e dei file sorgente, permette cose che altrimenti costerebbero ore e ore di debug con Windbg.
Installazione e configurazione.
Quando devo indicare a clienti ed amici di usare questo strumento, invio queste istruzioni:
X86 (32 bit)
- Installate l’ultima versione di Windbg da questo link: http://www.microsoft.com/whdc/devtools/debugging/installx86.mspx in C:\Debuggers.
- Installate Process Monitor da questo link: http://technet.microsoft.com/en-gb/sysinternals/bb896645.aspx
- Configurate Process Monitor.
- Eseguitelo forzando lesecuzione a 32 bit: "C:\Program Files\SysInternals\Procmon.exe" /Run32
- Dal Menu Options-> Configure Symbols, fate puntare dbghelp.dll a quella fornita con Windbg e non a quella del sistema operativo, modificando quindi il percorso in “C:\Debuggers\dbghelp.dll”
- Se la macchina è collegata ad Internet, potete anche configurare i simboli pubblici con questa stringa:
- srv*C:\Symbols*http://msdl.microsoft.com/download/symbols
- In questo modo, i simboli pubblici verranno scaricati dal Symbol server pubblico di Microsoft e scaricati nella cache locale in “C:\Symbols”.
- Se non avete accesso ad internet, potete scaricare i simboli pubblici del sistema oeprativo che state usando direttamente da qui: http://www.microsoft.com/whdc/DevTools/Debugging/symbolpkg.mspx
X64 (64 bit)
- Installate l’ultima versione di Windbg da questo link: http://www.microsoft.com/whdc/devtools/debugging/install64bit.mspx in C:\Debuggers64.
- Installate Process Monitor da questo link: http://technet.microsoft.com/en-gb/sysinternals/bb896645.aspx
- Configurate Process Monitor.
- Eseguitelo direttamente e come per la versione a 32 bit
- Dal Menu Options-> Configure Symbols, fate puntare dbghelp.dll a quella fornita con Windbg e non con il sistema operativo, modificando quindi il percorso in “C:\Debuggers64\dbghelp.dll”
- Se la macchina è collegata ad Internet, potete configurare i simboli pubblici con la solita stringa:
- srv*C:\Symbols*http://msdl.microsoft.com/download/symbols
- o scaricare il pacchetto completo da http://www.microsoft.com/whdc/DevTools/Debugging/symbolpkg.mspx
Se avete i simboli di debug privati delle vostre componenti, potete aggiungerli allo store. I simboli vanno aggiunti nello store non a caso, cioè semplicemente copiando i file nel folder, ma usando un tool, installato da Windbg, chiamato Symstore:
symstore add /f c:\Project\Myapp\Bin\debug\*.pdb /s c:\symbols /t "Symbols for MyApp"
Questo creerà la struttura necessaria dei folder, sotto C:\Symbols, ed eviterà il conflitto delle versioni consentendo di debuggare più versioni contemporaneamente.
E’ fondamentale per il funzionamento avanzato che si utilizzi la dbghelp.dll di Windbg, perchè solo grazie a questa sarà possibile per Process Monitor registrare quelle informazioni aggiuntive in grado più tardi, incrociando i dati di simboli e binario (exe o dll che sia), di mostrare lo stack dei thread in esecuzione al momento della registrazione dell’operazione.
E’ importante chiarire subito che Process Monitor “registra” tutte le informazioni relative a certe categorie di “eventi”. Cioè, quando accade un certo evento, tipo la scrittura di un file o la lettura di una chiave di registry, Process Monitor "fotografa" il thread che ha eseguito quell’operazione.
Chiaramente tra un’operazione e la successiva, possono essere eseguiti molti altri thread e moltissimo altro codice. Bisogna tenere sempre conto di questo, perchè altrimenti ci si potrebbe imbattere in un falso positivo che ci mada poi fuori strada.
Una delle feature più importanti di Process Monitor è il “Boot Logging”. Options-> Enable Boot Logging.
Quando questa feature viene abilitata, al successivo reboot, Process Monitor inizierà a registrare informazioni, fin dalle primissime operazioni eseguite dal sistema operativo, grazie al fatto che installa un driver e configura il sistema per caricarlo come uno dei primissimi driver di distema.
Questo permette di collezionare informazioni relative a processi che normalmente non sono accessibili, tipo Userinit.exe e Winlogon.exe, e quindi di raccogliere informazioni che riguardano l’interazione del sistema con codice molto particolare, come una custom GINA o un Winlogon Notification Package.
Process Monitor all’opera.
Un pò di tempo fa mi sono trovato a dover risolvere un problema di un Winlogon Notification Package.
Questi sono componenti, nella forma di dll, che vengono caricate all’interno del processo Winlogon.exe ed interagiscono con quello.
Uno degli usi più comuni è quello di gestire le notifiche di Logon e Logoff e soprattutto di Lock / Unlock della workstation, in modo da poter sfruttare i momenti in cui la macchina non è in uso per fare altro.
In questo caso specifico, questa dll era responsabile di avviare un processo sul desktop di winlogon, che permetteva di effettuare alcune operazioni, considerate di importanza relativa, per cui il cliente non riteneva necessario che alcun utente fosse loggato alla macchina. L’applicazione avviata prima del logon rimaneva attiva anche durante il lock della workstation, ma al logoff dell’utente, doveva eseguire determinate operazioni di log, in modo da registrare chi si fosse loggato a quella macchina, per quanto tempo, ecc..
Il problema in questo caso era che quando questa dll era presenta sulla macchina, e registrata come Winlogon Notification Package, il logoff impiegava circa un minuto.
Ho chiesto al cliente di creare un boot log di Process Monitor, e di inviarmelo insieme ai simboli e al sorgente della dll incriminata.
Quella dll scriveva molte informazioni di log su un proprio file, e grazie a quegli “eventi” mi è stato possibile “vedere” l’interazione di questa dll con il winlogon.
Ad esempio si è potuto notare una scrittura sul file di log “C:\Windows\temp\wlmon.log” ripetuta molte volte e sullo stack del thread relativo a quell’evento si è visto che il tutto era generato dalla funzione WlpExecuteNotify di Winlogon nel thread 2864.
Controllando il codice sorgente del cliente, considerato che eravamo nella fase di Logoff, quindi all’interno della funzione WLEventLogoff, è stato possibile determinare che eravamo in questo loop:
while (TRUE)
{
wsprintf(szMessage, _T("sessionid %d\r\n"), dwSessionId);
OutputToLog (glogfile, szMessage);
bTest = GetSessionUserName(dwSessionId, uname);
wsprintf(szMessage, _T("Session UserName = %s\r\n"), uname.c_str());
OutputToLog (glogfile, szMessage);
if (uname.length() == 0)
break;
Sleep(refresh);
}
Praticamente il codice cercava di verificare continuamente il nome dell’utente loggato per decidere se la fase di logoff era terminata completamente o meno.
“Refresh” era impostato a 250, e nel log si potevano trovare eventi di scrittura nel file di log (WriteFile) ogni 250ms.
e così via fino ad un minuto.
Dando un’occhiata al call stack di qualche altro thread di Winlogon si capiva che eravamo nella fase in cui winlogon stava eseguendo le routine di notifica dei Winlogn Notification Package installati e registrati nel sistema, come SensApi.dll, WlNotify.dll, Sclgntfy.dll e così via.
L’esame dello stack ha permesso di capire che eravamo all’interno del codice delle funzioni Logoff e WlWalkNotifyList di Winlogon.exe.
WlWalkNotifyList blocca la lista delle dll da notificare, usando LockNotifyList, e quindi procede a notificare tutte le dll registrate, una per una.
Se l’evento è Logoff o Shutdown però, questa notifica viene eseguita in modo sincrono.
if ( ( Operation == WL_NOTIFY_LOGOFF ) || ( Operation == WL_NOTIFY_SHUTDOWN ) )
{
bAsync = FALSE;
}
Viene usato un nuovo thread creato appositamente per eseguire la notifica al Winlogon Notification Package. Come per tutti gli oggetti che estendono le funzionalità del sistema e si integrano con quello, il tutto avviene attraverso interfacce pubbliche che devono essere implementate nelle dll e registrate nel registry.
Il nuovo thread appena creato, quindi chiama la funzione WLEventLogoff esposta dalla dll che conteneva quel pezzo di codice riportato sopra che era in loop.
Anche il thread di winlogon, come estrema misura di sicurezza, ora entra in un loop, nel quale verifica se il thread avviato per chiamare la WLEventLogoff è ritornato o meno.
if ( ThreadHandle )
{
if ( !bAsync )
{
DWORD WaitStatus ;
DWORD TotalWait = 0 ;
while ( TotalWait < Notify->dwMaxWait )
{
WaitStatus = WaitForSingleObject( ThreadHandle, 5000 );
if ( WaitStatus == STATUS_WAIT_0 )
{
break;
}
TotalWait += 5 ;
}
}
CloseHandle( ThreadHandle );
}
else
{
LocalFree( Boot );
}
}
Qui il codice di winlogon praticamente ogni 5 secondi verifica in che stato si trovi il thread avviato e incrementa un contatore che viene comparato con il valore dwMaxWait, che fa riferimento alla chiave di registry MaxWait relativa al Winlogon Notification Package. Se quella chiave non è stata definita, il valore di default è 60 secondi, che è esattamente il nostro problema. Infatti passati i 60 second il thread creato apposta per chiamare la funzione nella dll esterna viene forzatamente chiuso e il tutto può proseguire regolarmente.
Siamo, involontariamente, finiti in un classico deadlock: il winlogon ha chiamato una funzione in modo sincrono mentre sta terminando la sessione; la funzione chiamata a sua volta si mette in attesa che la sessione termini prima di rilasciare il controllo.
E’ bastato aggiungere la chiave di registry come controprova, impostando il valora MaxWait a 10 per vedere la sessione chiudersi in esattamente 10 secondi..
Chiaramente il codice del cliente poi è stato modificato in modo da eliminare l’attesa, in quanto Winlogon garantisce che quando si arriva in quella chiamata, la sessione è stata terminata, anche se per motivi legati al multithreading del sistema operativo stesso, ci sono magari ancora operazioni in esecuzione, che terminareanno tra un pò. Quando si arriva a questo punto però, non si torna più indietro, quindi quel controllo di sicurezza aggiunto dal cliente era inutile.
Il Process Monitor, se utilizzato con la dbghelp.dll di Windbg e in unione ai simboli di debug e ai file sorgenti è uno strumento potentissimo che permette di analizzare problemi che altrimenti avrebbero richiesto configurazioni particolari (tipo un Terminal Server) per verificare e risolvere il problema, che invece così è stato evidenziato immediatamente.
Alla prossima!
Senior Support Engineer
Platform Development Support Team