Benutzeranmeldung über VPN dauert sehr lange

[v-rtc 82]

Guten Morgen zusammen.

 

Der Beitrag ist etwas älter, aber ich wollte keinen neuen aufmachen.

 

Wir haben auch schon einiges versucht, aber vielleicht habt Ihr noch ein paar Ideen.

 

Folgendes:

 

Windows 2003 Domäne. Anmeldung im Haus wunderbar. Dazu haben wir Aussenstellen die über eine VPN Verbindung angeschlossen sind (Cisco VPN).

Diese Aussenstellen funkionieren bei allen wunderbar, bis auf 2!

Dort haben wir nun folgendes Problem.

Router baut eine DSL Verbindung auf, danach wird die VPN Verbindung aufgebaut. Hinter dem Router stecken direkt 1 PC und 1 IP Telefon.

Das Telefon funktioniert einwandfrei. Gute Qualität. Beim PC aber passiert folgendes.

PC startet, Computereinstellungen werden geladen, Benutzer meldet sich an,

Computereinstellungen werden kurz geladen, danach die Benutzeranmeldung.

Doch diese bleibt stehen. 10 Minuten, 20 Minuten, 30 Minuten... irgendwann ist er dann angemeldet. Wenn man das Netzwerkkabel zieht geht es innerhalb 1 Minute.

Was wir intern gesehen haben, ist das der DC zum Teil die Verbindung zu dem Client ablehnt. Firewall Regeln wurden extra angepasst vorrübergehend. Die sollten also nicht schuld daran sein. Ein 3. DC steht in einem anderen Subnetz, worauf der Client kein Zugriff hat, da aber die anderen 2 im verfügbaren Subnetz stehen, sollte dies ja kein Problem sein, oder?

 

Wir haben schon 2 Router getestet, 2 PC, Telekom Leitung geprüft. Alles nicht viel gebracht. Vielleicht habt Ihr noch ein Gedankenschubser.

 

Vielen Dank.

 

Grüße

 

Rolf

[Dr.Melzer 191]

Ich habe deinen Beitrag von dem gekaperten Thread abgetrennt.

 

Es macht keinen Sinn alte Beiträge mit neuen Fragen zu kapern, zumal der gekaperte Beitrag schon fast fünf Jahre alt war...

[olc 18]

Hi Rolf,

 

zieh doch von so einem problematischen Benutzeranmeldungsvorgang ein UserEnv Debug Log: How to enable user environment debug logging in retail builds of Windows

 

Der betroffene Client läuft auf Windows XP?

 

In dem Log sollte man sehen, wo es hängt. Falls Du es hier (über einen externen Anbieter) hosten möchtest, denke bitte vorher an das Thema "Datenschutz" - in dem Log sind so einige Informationen drin, die man vielleicht nicht weltweit verteilen möchte. ;)

 

Viele Grüße

olc

[v-rtc 82]

Hallo olc.

 

Hatten nun eine ganze Zeit lang Ruhe.

Heute musste ich aber doch ein Log erstellen.

 

Werde es mir mal anschauen und dann Teile daraus posten.

 

Vielen Dank.

 

Grüße

 

Rolf

[v-rtc 82]

Hallo zusammen.

 

Haben nun mal das debugging ausprobiert.

Da ich so ein Logfile noch nie "gelesen" habe, sehe ich dort nicht allzuviel.

 

Eins was ich sehe, sind 4 Minuten zwischen folgenden Einträgen:

 

USERENV(46c.cdc) 13:53:46:749 ProcessGPOs: DSGetDCName failed with 59.
USERENV(46c.cdc) 13:53:46:749 ProcessGPOs: No WMI logging done in this policy cycle.
USERENV(46c.cdc) 13:53:46:749 ProcessGPOs: Processing failed with error 59.
USERENV(46c.cdc) 13:53:46:749 LeaveCriticalPolicySection: Critical section 0x6ac has been released.
USERENV(46c.cdc) 13:53:46:749 ProcessGPOs: User Group Policy has been applied.
USERENV(46c.cdc) 13:53:46:749 ProcessGPOs: Leaving with 0.
USERENV(46c.cdc) 13:53:46:749 ApplyGroupPolicy: Leaving successfully.
USERENV(46c.b08) 13:53:46:749 GPOThread:  Next refresh will happen in 115 minutes
USERENV(46c.470) 13:53:46:796 IsSyncForegroundPolicyRefresh: Synchronous, Reason: policy set to SYNC
USERENV(46c.458) 13:53:46:796 IsSyncForegroundPolicyRefresh: Synchronous, Reason: policy set to SYNC
USERENV(cf0.a0c) 13:53:46:827 LibMain: Process Name:  C:\WINDOWS\system32\userinit.exe
USERENV(3f4.ac0) 13:55:49:025 LibMain: Process Name:  C:\WINDOWS\system32\userinit.exe
USERENV(9fc.ee8) 13:57:49:972 LibMain: Process Name:  C:\WINDOWS\system32\userinit.exe

 

oder hier:

 

USERENV(c58.d38) 13:57:50:941 LibMain: Process Name:  C:\Programme\Kaspersky Lab\Kaspersky Anti-Virus 6.0 for Windows Workstations MP4\avp.exe
USERENV(b4c.8f8) 13:57:55:254 LibMain: Process Name:  C:\WINDOWS\system32\imapi.exe
USERENV(d50.a10) 13:58:01:786 LibMain: Process Name:  C:\WINDOWS\system32\userinit.exe
USERENV(4a4.f58) 14:03:32:891 ImpersonateUser: Failed to impersonate user with 5.

 

Habe das komplette Logfile mal angehängt.

 

Grüße

 

Rolf

userenv.txt

[v-rtc 82]

Jemand schon mal angeschaut?

 

Danke.

 

Grüße

 

Rolf

[zahni 524]

Deine DC's sind über VPN möglicherweise nicht per ICMP erreichbar (PING):

 

USERENV(46c.cdc) 13:53:13:762 ProcessGPOs:
USERENV(46c.cdc) 13:53:13:762 ProcessGPOs:
USERENV(46c.cdc) 13:53:13:762 ProcessGPOs: Starting user Group Policy (Background) processing...
USERENV(46c.cdc) 13:53:13:762 ProcessGPOs:
USERENV(46c.cdc) 13:53:13:762 ProcessGPOs:
USERENV(46c.cdc) 13:53:13:762 EnterCriticalPolicySectionEx: Entering with timeout 600000 and flags 0x0
USERENV(46c.cdc) 13:53:13:762 EnterCriticalPolicySectionEx: User critical section has been claimed.  Handle = 0x6ac
USERENV(46c.cdc) 13:53:13:762 EnterCriticalPolicySectionEx: Leaving successfully.
USERENV(46c.cdc) 13:53:13:762 ProcessGPOs:  Machine role is 2.
USERENV(46c.cdc) 13:53:13:762 PingComputer: PingBufferSize set as 2048
USERENV(46c.cdc) 13:53:13:762 PingComputer: Adapter speed 100000000 bps
USERENV(46c.cdc) 13:53:13:793 PingComputer:  First time:  27
USERENV(46c.cdc) 13:53:19:246 PingComputer:  Second send failed with 11010
USERENV(46c.cdc) 13:53:19:262 PingComputer:  First time:  26
USERENV(46c.cdc) 13:53:24:747 PingComputer:  Second send failed with 11010
USERENV(46c.cdc) 13:53:24:763 PingComputer:  First time:  27
USERENV(46c.cdc) 13:53:30:247 PingComputer:  Second send failed with 11010
USERENV(46c.cdc) 13:53:30:247 PingComputer:  No data available
USERENV(46c.cdc) 13:53:30:372 PingComputer: PingBufferSize set as 2048
USERENV(46c.cdc) 13:53:30:372 PingComputer: Adapter speed 100000000 bps
USERENV(46c.cdc) 13:53:30:388 PingComputer:  First time:  27
USERENV(46c.cdc) 13:53:35:748 PingComputer:  Second send failed with 11010
USERENV(46c.cdc) 13:53:35:763 PingComputer:  First time:  27
USERENV(46c.cdc) 13:53:41:248 PingComputer:  Second send failed with 11010
USERENV(46c.cdc) 13:53:41:264 PingComputer:  First time:  28
USERENV(46c.cdc) 13:53:46:749 PingComputer:  Second send failed with 11010
USERENV(46c.cdc) 13:53:46:749 PingComputer:  No data available

 

Die siehst auch, dass hier am meisten Zeit "verbraucht" wird.

 

Siehe dazu u.a. auch How to troubleshoot Group Policy object processing failures that occur across multiple forests

 

"Scenario 2: A cross-forest GPO application fails if ICMP is not enabled".

 

-Zahni

[v-rtc 82]

Danke Dir zahni.

 

Grüße

 

Rolf

[olc 18]

Hi,

 

sorry, hab den Thread übersehen.

 

Zahni sagte schon richtig, daß Du wegen der fehlenden ICMP Pakete immer einen "fast link" bekommst, dadurch werden Scripts, Orderumleitung usw. ausgeführt, was über eine langsame Leitung ggf. zu Problemen führen kann.

 

Aus dem UserEnv Log geht jedoch nicht wirklich etwas "sinnvolles" hervor.

 

Zuerst findet eine Abmeldung statt, die um 13:51:14 beendet ist:

USERENV(46c.470) 13:51:14:205 UnloadUserProfile: returning 1

 

Es folgt nun folgerichtig die Anmeldung des Benutzers:

USERENV(46c.470) 13:53:13:590 LoadUserProfile: Yes, we can impersonate the user. Running as self
USERENV(46c.470) 13:53:13:590 =========================================================
USERENV(46c.470) 13:53:13:590 LoadUserProfile: Entering, hToken = <0x7d8>, lpProfileInfo = 0x6e3e0
USERENV(46c.470) 13:53:13:590 LoadUserProfile: lpProfileInfo->dwFlags = <0x0>
USERENV(46c.470) 13:53:13:590 LoadUserProfile: lpProfileInfo->lpUserName = <Jansen>

 

Das Laden des Profils ist dann jedoch innerhalb kürzester Zeit beendet (es liegt lokal schon ein Profil vor):

USERENV(46c.470) 13:53:13:699 LoadUserProfile: Leaving with a value of 1.
USERENV(46c.470) 13:53:13:699 =========================================================
USERENV(46c.470) 13:53:13:699 LoadUserProfile: LoadUserProfileP succeeded
USERENV(46c.470) 13:53:13:699 LoadUserProfile:  Returning success.  Final Information follows:
USERENV(46c.470) 13:53:13:699 lpProfileInfo->UserName = <Jansen>
USERENV(46c.470) 13:53:13:699 lpProfileInfo->lpProfilePath = <>
USERENV(46c.470) 13:53:13:699 lpProfileInfo->dwFlags = 0x0
USERENV(46c.470) 13:53:13:699 LoadUserProfile: Returning TRUE. hProfile = <0x240>

 

Hier sehe ich also keine Verzögerung.

 

Danach erfolgt nur noch ein "background processing":

USERENV(46c.cdc) 13:53:13:762 IsSyncForegroundPolicyRefresh: Synchronous, Reason: policy set to SYNC
USERENV(46c.cdc) 13:53:13:762 ApplyGroupPolicy: Entering. Flags = 6
USERENV(46c.cdc) 13:53:13:762 ProcessGPOs:
USERENV(46c.cdc) 13:53:13:762 ProcessGPOs:
USERENV(46c.cdc) 13:53:13:762 ProcessGPOs: Starting user Group Policy (Background) processing...

 

--> Kann es sein, daß Ihr dort im Autostart des Benutzers ein lokales Script liegen habt, welches ein "GPUPDATE" durchführt? Prüfe das doch einmal mittels "Autoruns": AutoRuns for Windows

 

Wenn ich dann das hier sehe, ist zu vermuten, daß die DNS Auflösung der Domäne zu diesem Zeitpunkt auch gar nicht funktioniert:

USERENV(46c.cdc) 13:53:46:749 ProcessGPOs: DSGetDCName failed with 59.

 

--> Daraus ergibt sich die Frage, ob Du hier wirklich den Fehlerfall gepostet hast? War zum Zeitpunkt der mit dem UserEnv Log mitgeschnittenen Anmeldung tatsächlich das VPN hergestellt und kam es zu einer Logon-Verzögerung?

 

Aus meiner Perspektive müssen beide Fragen mit "nein" beantwortet werden. ;)

Also schneide es noch einmal im Fehlerfall mit und poste es erneut.

 

Viele Grüße

olc

[zahni 524]

@olc,

 

ich sehe bei loaduserprofile keine Fehler. Der User hat ein lokales Profile und im netlogon existiert ein zentrales "default user" Profile, dass bei Bedarf (wenn User noch keins hat) geladen wird.

 

ProcessGPOs: DSGetDCName failed with 59 kannst Du in diesen Zusammenhang (Debug-Meldung) ignorieren. Die taucht auch in dem KB-Artikel auf.

 

Die GPO's werden vermutlich darum nicht im Hintergrund ausgeführt, weil die entsprechnde Gruppenrichtlinie dafür gesetzt ist. Ist bei uns auch so.

 

Ich vermute mal, dass in seinem VPN-Tunnel ICMP gefiltert wird.

 

-Zahni

[v-rtc 82]

Hallo olc.

 

Macht nichts. :-)

Danke Dir für die ausführliche Antwort.

 

Wir haben den User ab- und wieder angemeldet, da das anmelden allgemein sehr lange dauert.

 

Die ICMP Pakete habe ich nun mal erlaubt an der FW. Mal sehen, ob das etwas bringt.

 

Bei diesen Zeilen hier verliert die Anmeldung ebenfalls viel Zeit

USERENV(c58.d38) 13:57:50:941 LibMain: Process Name:  C:\Programme\Kaspersky Lab\Kaspersky Anti-Virus 6.0 for Windows Workstations MP4\avp.exe
USERENV(b4c.8f8) 13:57:55:254 LibMain: Process Name:  C:\WINDOWS\system32\imapi.exe
USERENV(d50.a10) 13:58:01:786 LibMain: Process Name:  C:\WINDOWS\system32\userinit.exe
USERENV(4a4.f58) 14:03:32:891 ImpersonateUser: Failed to impersonate user with 5.

 

Beim anmelden sieht man dann nur das die Einstellungen geladen werden und danach kommt ein balauer Bildschrim. Nach Minuten hat er es dann geschafft und zeigt den Desktop an.

 

Die Meldungen mit dem DNS machen mich ebenfalls sehr stutzig.

Warum er aber die Domäne nicht findet, kann ich mir momentan nicht erklären.

Grund dafür ist: Der Router hält konstant eine VPN Verbindung (Cisco Easy VPN), sodass der Computer sofort eine Antwort von der Domäne bekommen sollte.

Das witzige ist, der User ist einer von vielen. Bei den anderen klappt es zum Teil wunderbar. Bzw. niemals so lang wie bei diesem.

 

Das Log war aus einer Anmeldung heraus, die sich länger hält als bei anderen Anmeldungen von anderen VPN Usern.

 

Kann aber gerne noch mal eins erstellen lassen.

 

Grüße

 

Rolf

[zahni 524]

Ist die Richtlinie "Always wait for the network at computer startup and logon" in einer User und/oder Computer-GPO aktiviert ?

[v-rtc 82]

Hallo zahni.

 

Die ist aktiv in der Default GPO.

 

Grüße

 

Rolf

[olc 18]

Hi zusammen,

 

ich sehe bei loaduserprofile keine Fehler.

 

Genau, ich (wie ich auch schrieb) nämlich auch nicht. Und genau das ist der Punkt: Weder Fehler noch eine Zeitverzögerung. Ich denke also nicht, daß wir hier einen "Schlecht-Fall" sehen.

 

Der User hat ein lokales Profile und im netlogon existiert ein zentrales "default user" Profile, dass bei Bedarf (wenn User noch keins hat) geladen wird.

 

Korrekt, ich habe auch nichts gegenteiliges behauptet.

 

ProcessGPOs: DSGetDCName failed with 59 kannst Du in diesen Zusammenhang (Debug-Meldung) ignorieren. Die taucht auch in dem KB-Artikel auf.

 

Das kann sein, muß aber nicht. Je nach Konstellation kann es ein Hinweis auf ein Problem sein. Und da es sich hier um eine VPN Fragestellung handelt, ist nicht auzuschließen, daß der DsgetDc Call fehlschlägt, weil kein Domänen-Netz vorhanden ist. Also prüfen.

 

Die GPO's werden vermutlich darum nicht im Hintergrund ausgeführt, weil die entsprechnde Gruppenrichtlinie dafür gesetzt ist. Ist bei uns auch so.

 

Welche Gruppenrichtlinie meinst Du genau? Wenn sich ein Benutzer anmeldet, dann ist das "Foreground processing". Zyklische Hintergrundaktualisierungen können zu diesem Zeitpunkt nicht stattfinden. Das ist jedoch das, was im Anschluß an das Laden des Profils passiert.

 

Oder verstehe ich Dich da falsch?

 

Ich vermute mal, dass in seinem VPN-Tunnel ICMP gefiltert wird.

 

Kein Widerspruch, so wie ich es auch oben geschrieben habe. ;)

 

Wir haben den User ab- und wieder angemeldet, da das anmelden allgemein sehr lange dauert.

 

Ok, und die Anmeldung hat in diesem konkreten Log-Fall tatsächlich lange gedauert?

 

USERENV(c58.d38) 13:57:50:941 LibMain: Process Name:  C:\Programme\Kaspersky Lab\Kaspersky Anti-Virus 6.0 for Windows Workstations MP4\avp.exe
USERENV(b4c.8f8) 13:57:55:254 LibMain: Process Name:  C:\WINDOWS\system32\imapi.exe
USERENV(d50.a10) 13:58:01:786 LibMain: Process Name:  C:\WINDOWS\system32\userinit.exe
USERENV(4a4.f58) 14:03:32:891 ImpersonateUser: Failed to impersonate user with 5.

 

Das sind alles unterschiedliche Prozesse, was Du an den in Klammern stehenden HEX-Werten siehst (inkl. Threads nach dem Punkt). Zu diesem Zeitpunkt ist jedoch aus meiner Sicht des letzten Logfiles die Anmeldung schon abgeschlossen. D.h. die Prozesse werden im Autostart des Benutzers abgearbeitet. Der startet jedoch erst mit dem Explorer, das heißt es müßten schon Icons auf dem Desktop langsam angezeigt werden.

 

Wie oben schon geschrieben solltest Du die Autostart Einträge des Benutzers einmal prüfen und ggf. alle nicht-Microsoft Starts und Dienste testweise deaktivieren. Der Virenscanner ist in jedem Fall ein heißer Kandidat.

 

Das Log war aus einer Anmeldung heraus, die sich länger hält als bei anderen Anmeldungen von anderen VPN Usern.

 

Ganz sicher? Bitte noch einmal generieren und zusätzlich die Ereignisprotokolleinträge zu diesem Zeitpunkt mit posten (Application, System)

 

P.S.: Wobei mir gerade auffällt, daß der Explorer tatsächlich erst sehr spät geladen wird... Check einmal wie beschrieben die Autostarts und deaktiviere alles, was als Autostart und als Dienst "nicht-Microsoft" ist.

 

Viele Grüße

olc

[v-rtc 82]

Guten Morgen zusammen und ein gutes Neues!

 

Anbei die neuen Daten. ICMP war erlaubt, hat aber die Anmeldung laut User auf 20 Min erhöht.

 

Grüße

 

Rolf

userenv2.txt

userenv3.txt