The case of the... WS_E_OPERATION_TIMED_OUT
In dieser Kategorie veröffentliche ich Blogeinträge, 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:
Jedoch ist der Fehler nicht persistent, nach vier bis sechs Versuchen klappt es und das Zertifikat wird ausgestellt.
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.
Install-WindowsFeature Web-Http-Tracing
cd "$ENV:SystemRoot\system32\inetsrv\"
# Configure what you want to log
.\appcmd.exe set config "Default Web Site"-section:system.webServer/tracing/traceFailedRequests /+"\[path='\*'\]"
.\appcmd.exe set config "Default Web Site"-section:system.webServer/tracing/traceFailedRequests /+"\[path='\*'\].traceAreas.\[provider='WWW Server',areas='Authentication,Security,Filter,StaticFile,CGI,Compression,Cache,RequestNotifications,Module,FastCGI,WebSocket',verbosity='Verbose'\]"
.\appcmd.exe set config "Default Web Site"-section:system.webServer/tracing/traceFailedRequests /"\[path='\*'\].failureDefinitions.statusCodes:400-900"
# Enable Failed Requests Logging
.\appcmd.exe set config -section:system.applicationHost/sites "/\[name='Default Web Site'\].traceFailedRequestsLogging.enabled:True" /commit:apphost
.\appcmd.exe set config -section:system.applicationHost/sites "/\[name='Default Web Site'\].traceFailedRequestsLogging.maxLogFiles:50" /commit:apphost
.\appcmd.exe set config -section:system.applicationHost/sites "/\[name='Default Web Site'\].traceFailedRequestsLogging.directory:%SystemDrive%\" /commit:apphost
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.
do { netstat -an | findstr ":443" ; "NEXT" ; Start-Sleep 1 } while (1)
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.
Set-ItemProperty -Path "HKLM:\System\CurrentControlSet\Control\SecurityProviders\SCHANNEL" -Name "EventLogging" -Value "4"
# Reboot is necessary
Restart-Computer
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.
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 an “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.
CertUtil -syncWithWU C:\inetpub\RootCertificates
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 bei der Abfrage der Root Zertifikate.
