Freigeben über

Profili di rete: lentezza e problemi nella fase di logon

  • Artikel

Come abilitare ed interpretare il file di log UserEnv.log

Ciao a tutti, spesso arrivano richieste da parte di utenti che lamentano una lentezza nel caricare il profilo, altri che a volte non riescono proprio a caricarlo.

Il problema riguarda in quasi la totalità dei casi i profili di rete, i Roaming Profiles o le Folder Redirection, che permettono ad un utente di collegarsi su qualsiasi postazione ed avere sempre a disposizione i propri documenti e le proprie impostazioni.

Per il primo scenario può infatti capitare che il caricamento del profilo sembra durare per parecchi minuti quando il profilo in sé pesa pochi megabyte, cosa che dovrebbe portar via pochi secondi…

La cosa interessante è che in genere è proprio così ma il risultato non concorda con questa affermazione e, soprattutto, non soddisfa l’utente finale.

Il secondo scenario invece capita in maniera random e a diversi utenti. Spesso si risolve semplicemente con un logoff e successivo logon. Ma come mai?

Per l’analisi servono pochi strumenti, anzi uno: notepad.

Chiaramente strumenti di testo più avanzati facilitano il compito. Personalmente quando notepad non mi fornisce una risposta veloce uso Microsoft Excel, che permette di filtrare i risultati ed evidenziare le varie sezioni in differenti colori.

Cominciamo con l’innalzamento del valore di logging.

Di default, in Windows, il log è al minimo, in modo da tracciare gli errori principali.
Per portarlo ad un livello sufficiente per l’analisi dobbiamo impostare in questa chiave:
HKEY_LOCAL_MACHINE\Software\Microsoft\Windows NT\CurrentVersion\Winlogon

il valore UserEnvDebugLevel a 0x10002 (in esadecimale), come documentato su:

KB 221833
How to enable user environment debug logging in retail builds of Windows
http://support.microsoft.com/default.aspx?scid=kb;EN-US;221833

Al successivo logon, non è necessario riavviare, sarà possibile cercare di capire che cosa succede dopo che l’utente preme “Invio” alla richiesta di nome utente e password.

Passiamo quindi all’analisi del file.

Dopo che l’utente si è lamentato del problema andiamo a prendere il file UserEnv.log creato in
%Systemroot%\Debug\UserMode\ (%systemroot% è la cartella che contiene windows)

creandone una copia, in quanto questo verrà facilmente sovrascritto.

Scenario 1: logon lento

Ecco un esempio di UserEnv opportunamente ridotto, dove andremo a verificare cosa succede…

USERENV(2d8.2dc) 12:42:27:906 InitializePolicyProcessing: Initialised Machine Mutex/Events
USERENV(2d8.2dc) 12:42:27:953 InitializePolicyProcessing: Initialised User Mutex/Events
USERENV(2d8.2dc) 12:42:27:953 LibMain: Process Name:  \??\C:\WINDOWS\system32\winlogon.exe
USERENV(2d8.2dc) 12:42:29:781 Entering CUserProfile::Initialize ...
USERENV(2d8.2dc) 12:42:29:781 CUserProfile::Initialize called by winlogon
USERENV(2d8.2dc) 12:42:29:781 CUserProfile::Initialize: critical section initialized
USERENV(2d8.2dc) 12:42:29:796 CSyncManager::Initialize: critical section initialized
USERENV(2d8.2dc) 12:42:29:796 CUserProfile::Initialize: registry key Software\Microsoft\Windows NT\CurrentVersion\ProfileList opened
USERENV(2d8.2dc) 12:42:29:796 CUserProfile::Initialize: Proccessing S-1-5-21-956999170-2411722574-1760982272-9735
USERENV(2d8.2dc) 12:42:29:796 CSyncManager::EnterLock <S-1-5-21-956999170-2411722574-1760982272-9735>
USERENV(2d8.2dc) 12:42:29:796 CSyncManager::EnterLock: No existing entry found
USERENV(2d8.2dc) 12:42:29:796 CSyncManager::EnterLock: New entry created

...

USERENV(3c8.3cc) 12:42:32:546 LibMain: Process Name:  C:\WINDOWS\system32\svchost.exe
USERENV(30c.310) 12:42:32:890 LoadUserProfile: Yes, we can impersonate the user. Running as self
USERENV(30c.310) 12:42:32:890
==========================================================
USERENV(30c.310) 12:42:32:890 LoadUserProfile: Entering, hToken = <0x2ec>, lpProfileInfo = 0x7fcf8
USERENV(30c.310) 12:42:32:890 LoadUserProfile: lpProfileInfo->dwFlags = <0x9>
USERENV(30c.310) 12:42:32:906 LoadUserProfile: lpProfileInfo->lpUserName = <NetworkService>
USERENV(30c.310) 12:42:32:906 LoadUserProfile: NULL central profile path

...

USERENV(570.574) 12:42:34:781 LibMain: Process Name:  C:\WINDOWS\system32\svchost.exe
USERENV(68c.690) 12:42:36:515 LibMain: Process Name:  C:\WINDOWS\system32\spoolsv.exe
USERENV(2d8.6f4) 12:42:36:953 IsSyncForegroundPolicyRefresh: Synchronous, Reason: policy set to SYNC
USERENV(2d8.6f4) 12:42:36:953 ApplyGroupPolicy: Entering. Flags = 7
USERENV(2d8.6f4) 12:42:36:953 ProcessGPOs:
USERENV(2d8.6f4) 12:42:36:953 ProcessGPOs:
USERENV(2d8.6f4) 12:42:36:953 ProcessGPOs:  Starting computer Group Policy (Background) processing...
USERENV(2d8.6f4) 12:42:36:968 ProcessGPOs:
USERENV(2d8.6f4) 12:42:36:968 ProcessGPOs:
USERENV(2d8.6f4) 12:42:36:968 EnterCriticalPolicySectionEx: Entering with timeout 600000 and flags 0x0

...

USERENV(2d8.2dc) 12:42:50:281 LoadUserProfile: Yes, we can impersonate the user. Running as self
USERENV(2d8.2dc) 12:42:50:296 =========================================================
USERENV(2d8.2dc) 12:42:50:296 LoadUserProfile: Entering, hToken = <0x61c>, lpProfileInfo = 0x6e3e0
USERENV(2d8.2dc) 12:42:50:296 LoadUserProfile: lpProfileInfo->dwFlags = <0x0>
USERENV(2d8.2dc) 12:42:50:296 LoadUserProfile: lpProfileInfo->lpUserName = <UserName>
USERENV(2d8.2dc) 12:42:50:296 LoadUserProfile: NULL central profile path
USERENV(2d8.2dc) 12:42:50:312 LoadUserProfile: lpProfileInfo->lpDefaultPath = \\Domain\netlogon\Default User
USERENV(2d8.2dc) 12:42:50:312 LoadUserProfile: NULL server name
USERENV(2d8.2dc) 12:42:50:312 LoadUserProfile: In console winlogon process
USERENV(2d8.2dc) 12:42:50:312 In LoadUserProfileP
USERENV(2d8.2dc) 12:42:50:312 =========================================================
...

USERENV(2d8.54c) 12:42:50:968 IsSyncForegroundPolicyRefresh: Synchronous, Reason: policy set to SYNC
USERENV(2d8.54c) 12:42:50:968 ApplyGroupPolicy: Entering. Flags = 6
USERENV(2d8.54c) 12:42:50:968 ProcessGPOs:
USERENV(2d8.54c) 12:42:50:984 ProcessGPOs:
USERENV(2d8.54c) 12:42:50:984 ProcessGPOs: Starting user Group Policy (Background) processing...
USERENV(2d8.54c) 12:42:50:984 ProcessGPOs:
USERENV(2d8.54c) 12:42:50:984 ProcessGPOs:
USERENV(2d8.54c) 12:42:50:984 EnterCriticalPolicySectionEx: Entering with timeout 600000 and flags 0x0

...

USERENV(2d8.54c) 12:42:51:203 ProcessGPO: ==============================
USERENV(2d8.54c) 12:42:51:203 ProcessGPO:  Searching <CN={31B2F340-016D-11D2-945F-00C04FB984F9},CN=Policies,CN=System,DC=domain,DC=com>
USERENV(2d8.54c) 12:42:51:203 ProcessGPO:  User has access to this GPO.
USERENV(2d8.54c) 12:42:51:203 ProcessGPO:  GPO passes the filter check.
USERENV(2d8.54c) 12:42:51:203 ProcessGPO:  Found functionality version of:  2
USERENV(2d8.54c) 12:42:51:203 ProcessGPO:  Found file system path of:  \\domain.com\sysvol\domain.com\Policies\{31B2F340-016D-11D2-945F-00C04FB984F9}
USERENV(2d8.54c) 12:42:51:203 ProcessGPO:  Found common name of:  <{31B2F340-016D-11D2-945F-00C04FB984F9}>
USERENV(2d8.54c) 12:42:51:203 ProcessGPO:  Found display name of:  <Default Domain Policy>
USERENV(2d8.54c) 12:42:51:203 ProcessGPO:  Found user version of:  GPC is 58, GPT is 58
USERENV(2d8.54c) 12:42:51:203 ProcessGPO:  ==============================
...

USERENV(2d8.54c) 12:43:06:755 ProcessGPOs: User Group Policy has been applied.
USERENV(2d8.54c) 12:43:06:755 ProcessGPOs: Leaving with 1.
USERENV(2d8.90c) 12:43:06:755 PolicyChangedThread: Calling UpdateUser with 0.
USERENV(2d8.54c) 12:43:06:755 ApplyGroupPolicy: Leaving successfully.
USERENV(2d8.910) 12:43:06:755 GPOThread:  Next refresh will happen in 104 minutes

...

USERENV(b8c.b90) 12:43:18:880 LibMain: Process Name:  C:\WINDOWS\system32\userinit.exe
USERENV(c4c.c50) 12:43:22:855 LibMain: Process Name:  C:\WINDOWS\system32\net.exe
USERENV(c70.c74) 12:43:23:852 LibMain: Process Name:  C:\WINDOWS\system32\net.exe
USERENV(c60.c64) 12:43:24:678 LibMain: Process Name:  C:\WINDOWS\System32\WScript.exe
USERENV(c88.c8c) 12:46:25:426 LibMain: Process Name:  C:\WINDOWS\system32\wuauclt.exe
USERENV(cd0.cd4) 12:46:26:579 LibMain: Process Name:  C:\WINDOWS\system32\net.exe
USERENV(cf4.cf8) 12:46:28:418 LibMain: Process Name:  C:\WINDOWS\System32\WScript.exe
USERENV(d24.d30) 12:46:29:992 LibMain: Process Name:  C:\WINDOWS\system32\net.exe
USERENV(d58.d5c) 12:46:30:647 LibMain: Process Name:  C:\WINDOWS\system32\net.exe
USERENV(dbc.dc0) 12:46:32:985 LibMain: Process Name:  C:\WINDOWS\System32\WScript.exe
USERENV(de4.de8) 12:49:34:278 LibMain: Process Name:  C:\WINDOWS\system32\imapi.exe
USERENV(e70.e74) 12:49:36:725 LibMain: Process Name:  C:\WINDOWS\system32\userinit.exe
USERENV(e7c.e80) 12:49:37:146 LibMain: Process Name:  C:\WINDOWS\system32\userinit.exe
USERENV(e8c.ba0) 12:50:21:421 LibMain: Process Name:  C:\WINDOWS\Explorer.EXE
USERENV(e8c.c14) 12:50:21:857 GetProfileType:  Profile already loaded.
USERENV(e8c.c14) 12:50:21:857 GetProfileType: ProfileFlags is 0
USERENV(e8c.c14) 12:50:21:888 GetProfileType:  Profile already loaded.
USERENV(e8c.c14) 12:50:21:904 GetProfileType: ProfileFlags is 0

...

Come leggerlo? Prendiamo una riga a caso:

USERENV(2d8.54c) 12:42:50:968 IsSyncForegroundPolicyRefresh

Domenico1_thumb2

Ecco quindi come procedere.

Una volta evidenziato l’utente problematico:

USERENV(2d8.2dc) 12:42:50:281 LoadUserProfile: Yes, we can impersonate the user. Running as self
USERENV(2d8.2dc) 12:42:50:296 =========================================================

USERENV(2d8.2dc) 12:42:50:296 LoadUserProfile: Entering, hToken = <0x61c>, lpProfileInfo = 0x6e3e0
USERENV(2d8.2dc) 12:42:50:296 LoadUserProfile: lpProfileInfo->dwFlags = <0x0>
USERENV(2d8.2dc) 12:42:50:296 LoadUserProfile: lpProfileInfo->lpUserName = <UserName>
USERENV(2d8.2dc) 12:42:50:296 LoadUserProfile: NULL central profile path
USERENV(2d8.2dc) 12:42:50:312 LoadUserProfile: lpProfileInfo->lpDefaultPath = \\Domain\netlogon\Default User
USERENV(2d8.2dc) 12:42:50:312 LoadUserProfile: NULL server name
USERENV(2d8.2dc) 12:42:50:312 LoadUserProfile: In console winlogon process

- Prendiamo nota dell’orario di partenza: 12.42.50

- Verifichiamo quando viene caricato Explorer.Exe (il desktop dell’utente):

USERENV(e8c.ba0) 12:50:21:421 LibMain: Process Name:  C:\WINDOWS\Explorer.EXE

Annotiamo il tempo: quasi 8 minuti! Ha ragione l’utente a lamentarsi.

Ma cosa causa il rallentamento?

Le policy? “Beh, sono state modificate ma non più di tanto...”. Vediamo:

- inizio: USERENV(2d8.54c) 12:42:50:984 ProcessGPOs: Starting user Group Policy (Background) processing...

- fine: USERENV(2d8.54c) 12:43:06:755 ProcessGPOs: User Group Policy has been applied.

Effettivamente passano solo 16 secondi, abbastanza normale se ci sono impostazioni di registry (si pensi alla personalizzazione di IE) o comunque parecchie policy da applicare.

Direi che si possono escludere le policy di dominio.

Non ci sono folder redirection configurate, quindi escludiamo la rete per la copia dei files...

Al volo si può vedere che il rallentamento è causato da alcuni script in esecuzione, che bloccano l’utente per circa 7 minuti:

USERENV(c60.c64) 12:43:24:678 LibMain: Process Name:  C:\WINDOWS\System32\WScript.exe
USERENV(c88.c8c) 12:46:25:426 LibMain: Process Name:  C:\WINDOWS\system32\wuauclt.exe
...
USERENV(dbc.dc0) 12:46:32:985 LibMain: Process Name:  C:\WINDOWS\System32\WScript.exe
USERENV(de4.de8) 12:49:34:278 LibMain: Process Name:  C:\WINDOWS\system32\imapi.exe

Ecco il rallentamento!

In questo caso è necessario fare tuning sugli script o modificarne la loro esecuzione in modalità asincrona (come in genere è di default), in modo da non dover attenderne il termine prima di caricare Explorer.Exe:

User Configuration\Administrative Templates\System\Scripts\Run Logon Scripts Synchronously -> Disabled

Scenario 2: Impossibile caricare il profilo.

Per questo secondo caso bisogna cercare nell’userenv errori simili a questo:

USERENV(2d4.d4c) 14:58:37:269 ReconcileFile: E:\Utente\Desktop\my doc.pdf ==> C:\Documents and Settings\Utente\Desktop\my doc.pdf  [OK]
USERENV(2d4.d40) 14:58:37:285 ReconcileFile: E:\Utente\Desktop\my doc.xls ==> C:\Documents and Settings\Utente\Desktop\my doc.xls  [OK]
USERENV(2d4 .d34) 14:58:37:285 ReconcileFile: Failed to delete file <C:\Documents and Settings\Utente\Desktop\prf75.tmp> with error = 32 <--- ERROR_SHARING_VIOLATION

USERENV(2d4.d3c) 14:58:37:300 ReconcileFile: E:\Utente\Desktop\My doc 2.pdf ==> C:\Documents and Settings\Utente\Desktop\My doc 2.pdf  [OK]
USERENV(2d4 .d34) 14:58:37:300 ReportError: Impersonating user.
USERENV(2d4.d38) 14:58:37:300 ReconcileFile: E:\Utente\Desktop\my doc 2.xls ==> C:\Documents and Settings\Utente\Desktop\my doc 2.xls  [OK]
USERENV(2d4.d44) 14:58:37:316 ReconcileFile: E:\Utente\Desktop\My doc.rtf ==> C:\Documents and Settings\Utente\Desktop\My doc.rtf  [OK]
USERENV(2d4.d48) 14:58:37:332 ReconcileFile: E:\Utente\Desktop\My Doc.doc ==> C:\Documents and Settings\Utente\Desktop\My Doc.doc  [OK]
USERENV(2d4 .d34) 14:58:37:332 GetShareName: WNetGetConnection initially returned error 2250
USERENV(2d4.d40) 14:58:37:332 ReconcileFile: E:\Utente\Desktop\My Doc 2.doc ==> C:\Documents and Settings\Utente\Desktop\My Doc 2.doc  [OK]
USERENV(2d4 .d34) 14:58:37:332 ReportError: Logging Error <Impossibile copiare il file \\Server\Share\Utente\Desktop\My Doc 3.doc sul percorso C:\Documents and Settings\Utente\Desktop\My Doc 3.doc. L'errore può essere causato da problemi di rete o privilegi di protezione insufficienti. Se il problema persiste, contattare l'amministratore della rete.
Dettagli: Impossibile accedere al file. Il file è utilizzato da un altro processo.
USERENV(2d4.d34) 14:58:37:332 ErrorDialogEx: Calling DialogBoxParam
USERENV(2d4.d4c) 14:58:37:332 ReconcileFile: E:\Utente\Desktop\My Doc 3.xls ==> C:\Documents and Settings\Utente\Desktop\My Doc 3.xls  [OK]
USERENV(2d4.d34) 14:58:37:332 ErrorDlgProc:: DialogBoxParam
USERENV(2d4.2d8) 14:58:44:085 CopyProfileDirectoryEx: Leaving with a return value of 0
USERENV(2d4.2d8) 14:58:44:100 RestoreUserProfile:  CopyProfileDirectory failed.  Issuing default profile
USERENV(2d4.2d8) 14:58:44:100 RestoreUserProfile:  Issuing default profile
USERENV(2d4.2d8) 14:58:44:100 RestoreUserProfile:  Deleting cached profile directory <C:\Documents and Settings\Utente>.

Da questi dati è possibile notare che la copia in locale del file remoto, è fallita in quanto il file è in uso da un altro processo:

Error 32

  ERROR_SHARING_VIOLATION

# The process cannot access the file because it is being used
# by another process.

Molto probabilmente un servizio di indicizzazione o l’antivirus potrebbero non rilasciare correttamente il file in tempo, interrompendo quindi il processo di sincronizzazione del profilo.

In questi casi è necessario escludere durante la fase di caricamento del profilo qualsiasi servizio di terze parti che possa influire con le operazioni sui file.

Un tool utile che vi consiglio è built-in in Windows XP (per 2000 basta copiarlo): MSCONFIG.EXE.

Una volta lanciato è possibile escludere ogni servizio o programma caricato all’avvio del sistema.

In breve quindi questo file di log è utilissimo per qualsiasi problema legato al caricamento del profilo.

Alla prossima! Con nuovi post sull’uso di questo log ed altre problematiche di esempio.

 

Domenico Costa
Senior Support Engineer
Microsoft Enterprise Platform Support

Comments

  • Anonymous
    January 01, 2003
    Questo è un post molto molto interessante e utile. Continuate così.... Giovanni Rastelli

  • Anonymous
    February 10, 2009
    The comment has been removed

  • Anonymous
    February 11, 2009
    Ciao Valerio, il tuo caso andrebbe approfondito in quanto dalle informazioni postate si evince solo un problema di Sharing Violation (il file esiste già). Posso indicarti quest'articolo, verifica se è il tuo caso: 826379 Userenv Errors 1504 and 1509 in the Windows XP Application Event Log After You Apply a Redirector Hotfix http://support.microsoft.com/default.aspx?scid=kb;EN-US;826379 Tieni anche presente che Profili, DFS su FSR e CSC insieme non sono supportati: 830856 A roaming profile is not loaded from a DFS share http://support.microsoft.com/default.aspx?scid=kb;EN-US;830856 "Microsoft does not support storing roaming profiles on DFS shares that are replicated by using FRS and that are made offline-available." http://www.microsoft.com/windowsserver2003/techinfo/overview/dfsfaq.mspx Leggi quanto indicato su "Can I use DFS with Offline Files and redirected My Documents folders?" nel paragrafo "Managing DFS." Spero ti sia di aiuto! Ciao Domenico

  • Anonymous
    February 11, 2009
    Domenico , grazie per l'attenzione. L'ambiente è composto da 6  Windows  2003  sp2  Ts ed i server  dfs sono  2 server  Windows 2003 R2 non sono utilizzati apparati  netapp solo dischi locali.I profili sono in DFS e FRS, CSC non è abilitato. Il problema è molto casuale e si verifica u file diversi ed utenti diversi. Controllando attentamente il log ho notato che al momento di aggiornare il file NTUSER.DAT, per quegli utenti che si registrano problemi esegue la stessa operazione ma con un path diverso . Un untente normalmente chiude la sessione aggiornando il file NTUSER.DAT in questo modo USERENV(200.541c) 12:31:59:946 ReconcileFile: C:Documents and SettingscaldipNTUSER.DAT ==> E:CaldiPNTUSER.DAT  [OK] Mentre per gli utenti che hanno problemi viene eseguito questo USERENV(200.22c) 12:58:06:536 ReconcileFile: Failed to rename file <E:CardilloRprf11FB.tmp> to <E:CardilloRNTUSER.DAT> with error = 183 Il path è sbagliato ! lo stesso utente qualche ora prima aveva eseguito l'operazione correttamente. Per qualche motivo esegue l'operazione con un path errato. Tutti gli utenti sono limitati ad 1 sola sessione contemporanea all'interno della farm, quindi non posso verificarsi problemi di condivisione del file. Vi è qualche documentazione su come interpretare il file UserEnv.log che puo essere d'aiuto ? Grazie Ciao

  • Anonymous
    February 26, 2009
    Ciao Valerio, non c'è una guida in merito a come interpretare questo log. Puoi cercare nel nostro sito per le singole voci. Se non riesci a risolvere puoi sempre utilizzare il nostro supporto tecnico. Trovi tutte le informazioni su: http://support.microsoft.com/italy Ciao! Domenico