Interessantes Verhalten von "setspn -x -f"

Hallo zusammen!

Die Verwaltung von SPNs im Active Directory dürfte Euch regelmäßig beschäftigen. Immer mehr Applikationen möchten Kerberos verwenden, nicht nur um das Authentifizierungsprotokoll zu verwenden, sondern auch um Delegation-Möglichkeiten zu nutzen, und ganz besonders interessant ist hier die „Protocol Transition“.
In diesem Blog soll es aber um was ganz anderes gehen. Es fängt alles damit an, dass sogfältige AD Admins bei der Verwaltung von Service Principal Names (SPN) Fehler vermeiden möchten. Und ein ganz häufiger Fehler ist, dass SPNs in der Domain oder im Forest doppelt definiert werden, und die Kerberos-Authentifizierung deswegen fehl schlägt.

Seit Windows Server 2008 gibt es nun zwei Wege mit den Tool SETSPN nach doppelten SPNs zu suchen:

• Wenn man bestehende Registrierungen für einen bestimmten SPN testen will: setspn /q <SPN>
• Wenn man bestehende beliebige doppelte SPNs suchen will: setspn /x

Beim zweiten Befehl könnt Ihr die Suche mit " /f" auf den ganzen Forest ausweiten. AD Admins können damit den Forest regelmäßig auf doppelte SPNs prüfen, eventuell noch bevor die Dienstbetreiber von dem Problem etwas bemerken. Soweit, so schön.

Das Problem

Nun haben wir von einem Kunden die Meldung bekommen, dass setspn time-out Fehler ausgibt. Das sieht dann so aus:

c:\>setspn -X -F -P
Checking forest DC=contoso,DC=com
Operation will be performed forestwide, it might take a while.
Ldap Error(0x55 -- Timeout): ldap_get_next_page_s

Was sehen wir in der Diagnose?

Im Netzwerk Trace sieht man, dass der gesamte Forest (Port 3268) mit dem Filter " (servicePrincipalName=*) " gesucht wird. SetSPN verwendet paged Queries mit einer Page Size von 100 Objekten. Die Antwortmenge sind etliche Seiten, und setspn zählt diese mit. Die Response-Zeiten nehmen besonders zum Ende hin zu. Wenn das Tool einmal komplett durchläuft sieht man, dass es die letzte Seite war, wo die größte Verzögerung auftritt. Für die folgende Ausgabe hat der Kunde gemeldet:
Customer also noticed that it usually hangs on record 84.

Interessante Daten gibt es oft, wenn ihr eine solche Query mit dem STATS Control ausführt. Mit LDP funktioniert das wie folgt:

Wen ihr in LDP verbunden und angemeldet seid, könnt ihr eine Query abschicken mit Browse\Search oder Strg-S. Um ein Control einzubinden, sind einige Klicks nötig.

Im Suchfenster tragt ihr die normalen Parameter ein, hier forciere ich einen anderen teuren Filter:

Achtet im Optionsfenster darauf, dass „Extended“ als Anfragetyp ausgewählt ist:

Im Controls-Fenster rechts unten sind die bekannten Controls gelistet. Um unteren Dritten befindet sich das „Search Stats“ Control. Wenn ihr es auswählt wird es automatisch „eingecheckt“:

In dem Fall sehen wir folgende Ergebnisse:

Call Time: 62198 (ms)
Entries Returned: 8508
Entries Visited: 43076

Used Filter: (servicePrincipalName=*)
Used Indices: idx_servicePrincipalName:13561:N
Pages Referenced : 801521
Pages Read From Disk : 259
Pages Pre-read From Disk : 1578
Pages Dirtied : 0
Pages Re-Dirtied : 0
Log Records Generated : 0
Log Record Bytes Generated: 0

Da sind einige interessante Zahlen versammelt. Es wurden 8508 Objekte zurückgegeben, aber insgesamt 43076 Objekte besucht. Dabei wandert die Query doch komplett über den Index für "servicePrincipalName". Man könnte also meinen, die Objekte werden genau einmal aus der Datenbank geholt und damit sollten auch nich tso viele Datenbankseiten gelesen werden müssen.

Also was passiert hier?

An der Stelle wirkt sich das besondere Verhalten von multi-valued, nicht gelinkten Attributen aus.

Damit ein Bild entsteht, möchte ich ein paar wichtige Datenpunkte zeigen:

1. Eine typische Workstation hat folgende SPNs:

servicePrincipalName: WSMAN/herbertm5
servicePrincipalName: WSMAN/herbertm5.europe.contoso.com
servicePrincipalName: TERMSRV/herbertm5.europe.contoso.com
servicePrincipalName: TERMSRV/HERBERTM5
servicePrincipalName: RestrictedKrbHost/HERBERTM5
servicePrincipalName: HOST/HERBERTM5
servicePrincipalName: RestrictedKrbHost/HERBERTM5.europe.contoso.com
servicePrincipalName: HOST/HERBERTM5.europe.contoso.com

2. Wenn die gleiche Query mit LDIFDE in den Time-Out läuft, sehen die letzten im Export gelisteten Objekte aus wie diese:

 dn:CN=svc_scvmm,OU=VMM,OU=Service Accounts,OU=Domain Management, DC=contoso,DC=com
servicePrincipalName: VMM/SCVMM.contoso.com
servicePrincipalName: VMM/SCVMM 

 dn:CN=HQSCCM2K3TEST,OU=SCCM,OU=Test Infrastructure,OU=Domain Management,DC=contoso,DC=com
servicePrincipalName: WSMAN/sccm2k3test
servicePrincipalName: WSMAN/sccm2k3test.contoso.com

Dem geübten Betrachter fällt auf, dass die SPN-Präfixes sehr weit hinten im Alphabet stehen. Die Konten haben zum Beispiel keinen Prefix mit "HOST". Für DCs sieht man oft als ersten Prefix im Alphabet den für AD Replikation „E3514235-4B06-11D1-AB04-00C04FC2DCD2“.

Wie kommt das zustande?

In LDAP Queries darf ein Objekt, obwohl es mehrere SPNs hat, nur einmal im Result Set auftauchen. Also muss der LDAP Server für jeden Treffer im Index kontrollieren, ob das zugehörige Objekt nicht mit einem anderen Index-Wert mit kleinerer Sortierung auftaucht und deswegen nochmals in den Antwortsatz kommen würde.

Als Beispiel:

Der erste Treffer für die Workstation oben ist „HOST/HERBERTM5“. Schon für den zweiten Treffer „HOST/HERBERTM5.europe.contoso.com“ zieht dieser Algorithmus und der zweite Treffer im Index wird ignoriert. Wenn der Server im Index dann beim Präfix „WSMAN“ angekommen ist, sind die allermeisten Computer schon in der Ergebnisliste, die meisten Objekte werden also übersprungen.

Auf der letzten Seite der Query (oben also für die letzten 8 der 8508 Objekte), wird deswegen ein sehr hoher Anteil der Index-Treffer verworfen. Das Objekt muss trotzdem angesehen werden, was relativ immer mehr Zeit kostet. Bis dann letztlich das Zeitfenster von einer Minute nicht reicht um die Seite zu füllen oder die Query komplett zu beenden.

Bei Domain Controllern mit wenig Speicher und/oder mit langsamer CPU kann das so weit kommen, dass für die letzte Seite die von SETSPN erlaubte Zeit von 60 Sekunden nicht ausreicht. Dann kommt es zum Time-Out des Kommandos.

Wenn die Query mit LDIFDE, LDP oder ADFIND wiederholt wird ist es gut möglich, dass sie erfolgreich durchläuft. Das liegt daran, dass diese Tools die Standard-Parameter für LDAP Queries verwenden. Dann liegt der Time-Out bei 120 Sekunden. Nur muss man selber die Ergebnisse der anderen Queries auf Dubletten prüfen.

Was kann man also tun?

Da gibt es folgende Möglichkeiten:

1. Wenn der Domain Controller wenig Speicher hat und viele Seiten von der Platte lesen müssen, dann kann Speicher hinzufügen das Problem vermeiden.
2. Wenn kein Speicherdruck besteht, ist ein wichtiger Faktor die "Single-Thread-Performance des Servers". Jede LDAP-Anfrage wird nämlich von genau einem Worker-Thread bearbeitet und läuft auf einem logischen Core des Servers.
3. Für Windows Server 2012 gibt es einen Update, der das Problem vermeiden hilft:
   2799960 Time-out error when you run Setspn.exe in Windows 8 or Windows Server 2012
   https://support.microsoft.com/kb/2799960/EN-US

Die Kombination von 1 und 2 war bei unserem Kunden das Problem, er hatte diese Anfragen auf einem unterdimensionierten virtuellen Server erstellt. Als er außerhalb der Geschäftszeiten einen neuen Hardware-DC dafür verwendet hat, lief die Query immer durch.

Wissenskontrolle

Wer den Artikel 2799960 gelesen hat, was war wohl die Änderung im Software Update?

<Auflösung nächste Woche>