The case of the… WS_E_OPERATION_TIMED_OUT

In dieser Kategorie möchte ich über die Zeit eine Vielzahl von Blogeinträgen veröffentlichen, in denen ich ein Problem, die Lösung und den Weg dorthin erläutere.

Der Name ist Homage an „The Case of the Unexplained“ von Mark Russinovich.

Der Fehler

Bei einer automatisierten Zertifikatsanfrage, auf einem neu installierten Server, kommt es zu der folgende Fehlermeldung:

An Error occured requesting Certificate [TEMPLATENAME] from Issuing CA ‚https//pki.lab.cloudbrothers.info/ADPolicyProvider_CEP_UsernamePassword/service.svc/CEP‘
CX509EnrollmentPolicyWebService::LoadPolicy: The operation did not complete within the time allotted.
0x803d0006 (-2143485946 WS_E_OPERATION_TIMED_OUT)

Jedoch ist der Fehler nicht persistent, nach vier bis sechs Versuchen klappt es und das Zertifikat wird ausgestellt.

TL;DR – Wem die komplette Beschreibung zu lang ist geht direkt zur Lösung am Ende.

Die Analyse

Erste Vermutung: Es gibt ein Problem auf der Issuing CA oder dem Enrollment Web Service. Eventuell wird die Anfrage durch fehlerhafte Authentifizierung geblockt.

Der IIS Server

Also auf dem Server, auf dem der CEP installiert ist, das IIS Feature „Tracing“ installiert, konfiguriert und aktiviert. Dadurch werden alle Fehler mit dem Fehlercode 400-900 durch die Funktion „Failed Requests Logging“ in ein definiertes Verzeichnis geloggt.

Anschließend das Script erneut ausgeführt und…

…keine neuen Logdateien vorhanden. Die Anfrage kommt also beim Webserver nicht an, bzw. verursacht keinen Fehler in dem definierten Bereich.

Wenn nichts ankommt prüfe ich gerne den Weg vom Client zum Server. Eine beliebte Hürde die dabei die Firewall.

Die Netzwerkverbindung

Mittels „netstat“ lässt sich ziemlich einfach analysieren ob eine Verbindung zu einem bestimmten Dienst aufgebaut wurde.

Leider ist es häufig ein ziemliches Timingproblem den Befehl genau in dem Moment auszuführen wenn die Verbindung aufgebaut wird. Hierbei hilft mir ein folgender Einzeiler.

So erhalte ich jede Sekunde den aktuellen Status zu den Verbindungen. Das „findstr“ Kommando filtert die Ausgabe direkt auf alle Verbindungen die den Port 443 verwenden.

Leider ist auch das der nächste Reinfall. Es ist eine Verbindung vom Client zum PKI Server mit dem Status „ESTABLISHED“ zu sehen. Hätte hier die Firewall interveniert würde die Verbindung auf dem Server nicht ankommen und auf dem Client im Status „SYN_SENT“ hängenbleiben.

Es wird also erfolgreich eine TCP Verbindung vom Client zum Server aufgebaut. Jedoch zeigt der IIS Server keinerlei Logs an. Das Problem liegt also zwischen TCP und HTTP. Da hier eine Verbindung zu Port 443 aufgebaut wird, liegt also auf Protokollebene noch SSL dazwischen.

SCHANNEL Logging

Auf dem Client richte ich daher das erweiterte SCHANNEL Event Logging ein. Dazu reicht es den Registrywert „EventLogging“ auf den Wert 4 zu erhöhen. Dadurch werden alle Events ab der Stufe „Informational and success“ mitgeschnitten.

Nach dem obligatorischen Neustart werden die Ereignisse in das System Eventlog geschrieben.
Doch auch hier finde ich nur Erfolgsnachrichten.

Zeit die großen Geschütze in Stellung zu bringen.

Netzwerkanalyse mit Wireshark

Nach der Installation von Wireshark inkl. WinPcap starte ich einen Netzwerkmitschnitt und filtere dabei nur alle RDP Verbindungen raus. Dazu nutze ich den Capturefilter „not port 3389“. Es reicht seit Windows 2012 nicht mehr nur TCP/3389 zu filtern, da RDP auch UDP/3389 nutzt.

Im Anschluss starte ich das Script in einer Schleife, die stoppt sobald das Zertifikat erfolgreich ausgestellt wurde.

Im Netzwerkmitschnitt ist gut zu erkennen, dass die TCP Verbindung (SYN – SYN/ACK – ACK) sauber aufgebaut wird. Bei der SSL Verbindung läuft auch alles super (Client Hello – Server Hello). Jedoch ist nach dem „Server Hello“ Schluss. Es kommt zu einer längeren Pause im Netzwerktraffic, was an den Timestamps sehr gut zu sehen ist. Nach 35 Sekunden beendet der Client die Verbindung dann mit einem RST.

Das Verhalten erklärt warum im IIS nie eine Anfrage ankommt, jedoch nicht warum nach 35 Sekunden die Verbindung abgebrochen wird. Windows scheint auf etwas zu warten.

Die Ursache

Die Ursache für dieses Verhalten findet sich in den Paketen direkt nach dem Verbindungsaufbau.

Hier wird eine DNS Anfrage für den Host „ctldl.windowsupdate.com“ gesendet und auch eine Antwort zurückgeliefert. Die Verbindung zu diesem Host kann jedoch nicht aufgebaut werden. Zugriff auf das Internet hat der Client nicht.

Eine Suche nach dem Domainnamen bringt folgenden KB Artikel zum Vorschein: „An automatic updater of untrusted certificates is available for Windows Vista, Windows Server 2008, Windows 7, and Windows Server 2008 R2

Dahinter steckt der Ansatz von Microsoft die Trusted und Untrusted RootCAs nicht mehr über Windows Update zu verteilen, sondern über Webserver von Microsoft. Sollte ein System in einer, nicht mit dem Internet verbundenen, Umgebung stehen, können diese Daten nicht abgerufen werden.

If the system does not have access to Windows Update, either because the system is not connected to the Internet or because Windows Update is blocked by firewall rules, the network retrieval will time-out before the service can continue its startup procedure. In some cases, this network retrieval time-out may exceed the service startup time-out of 30 seconds. If a service cannot report that startup has completed after 30 seconds, the service control manager (SCM) stops the service.

Der Workaround

Um dem Problem auf dem Weg zu gehen, kann auch den betroffenen Systemen eine Gruppenrichtlinieneinstellung gesetzt werden.

Unter „Computer Configuration“ – „Windows Settings“ – „Security Settings“ – „Pubic Key Policies“ – „Certificate Path Validation Settings“ muss dazu die Option „Automatically update certificates in the Microsoft Root Certificate Program“ deaktiviert werden. Wie am nachstehenden „Recommended“ erkennbar, ist das aber keine echte Lösung und führt nur zu weiteren Problemen. Auch wenn einige Microsoft Seiten dies sogar selbst als Lösung präsentieren!

Die beiden hier angezeigten Timeout Werte ergeben zusammen exakt den in Wireshark beobachtet Zeitraum von 35 Sekunden.

Die Lösung

Um auch auf Systemen ohne Internetverbindung die Funktion des Automatischen Updates der Root Zertifikate zu nutzen muss KB2813430 installiert und über die Gruppenrichtlinie ein interner Pfad zu diesen Root Zertifikaten verteilt werden.

Dazu erlaubt man einem System den Zugriff auf das Internet und richtet dort einen Scheduled Task ein. Dieser aktualisiert die Zertifikate einmal am Tag.

Den Ordner (C:\inetpub\RootCertificates) veröffentlicht man anschließend über einen installierten IIS. Durch den entsprechenden Registryeintrag (HKLM:\SOFTWARE\Microsoft\SystemCertificates\AuthRoot\AutoUpdate\RootDirURL), verteilt über die GPO, nutzen die Clients nun diesen internen Server und es kommt nicht mehr zu Timeouts oder Fehlern in Verbindung mit dieser Funktion.