Debugging für Fortgeschrittene: Post-Mortem einer Java-Bugsuche

Damit hatten wir nicht gerechnet: nachdem Snow Leopard von Apple veröffentlicht wurde, zeigte sich, dass unsere UKLAN-Admin-Anwendung darunter nicht lief. Die Version von Java, die mit Snow Leopard auf Macs erstmalig der Standard ist, ist Java 6. Diese Version hatten Kollegen mit Windows- und Linux-Rechner schon längst ohne Probleme im Einsatz, so dass nicht zu erwarten gewesen war, dass das auf Macs anders sein könnte.
Das Problem lag bei der Authentifizierung. Beim Anmeldeversuch kam die Meldung, dass diese gescheitert sei. Im Log konnte man zu der Exception einen recht langen Stacktrace sehen. Die entscheidende Meldung lautete:

java.lang.IllegalArgumentException: EncryptionKey: Key bytes cannot be null!

Der Fehler trat in einer internen Javaklasse auf, die nie explizit verwendet werden soll: sun.security.krb5.EncryptionKey. Das allein machte für mich klar, dass es sich um keinen Fehler in unserem Programm handeln konnte, sondern entweder einen im Betriebssystem oder im mitgelieferten Java. Da abzusehen war, dass das Problem durch Apple nicht kurzfristig gelöst werden würde, habe ich mich auf die Suche nach der eigentlichen Ursache gemacht. Am Anfang der Suche standen Beobachtungen:

• Wenn man ein falsches Passwort eingab, wurde das korrekt als falsch erkannt. Das Problem trat also nur auf, wenn die Authentifizierung eigentlich erfolgreich war.
• Wenn man bereits ein Kerberos-Ticket hatte, konnte das (nach einer kleinen Programmänderung) verwendet werden, so dass das Passwort gar nicht geprüft werden musste.

Die zweite Erkenntnis hat uns zumindest einen ersten Workaround verschafft, wenngleich der für die Anwender etwas lästig war. Die eigentliche Ursache war hingegen immer noch unklar. Durch die tatkräftige Hilfe eines Forummitglieds auf forums.sun.com bin ich in mehreren Schritten zu weiteren Erkenntnissen gekommen:

• Die Exception wurde nur durch manche Ciphers verursacht – wie sich später zeigte, sind es die AES-basierten.
• Unmittelbare Ursache der Exception war ein leeres Salt – dass die AES-Ciphers das nicht mögen, war auf verschiedenen Plattformen reproduzierbar.
• Nach einer ganzen Weile wurde mir klar, dass die Authentifizierung manchmal klappte.

Das letzte Indiz wies mir den Weg. Wir befragen im Programm zunächst das DNS, welche Server im Active Directory der Uni als KDCs zur Verfügung stehen. Derzeit sind das sechs Stück:

% host -t srv _kerberos._udp.ad.uni-koeln.de
_kerberos._udp.ad.uni-koeln.de has SRV record 0 100 88 ads5.ad.uni-koeln.de.
_kerberos._udp.ad.uni-koeln.de has SRV record 0 100 88 advdc1.ad.uni-koeln.de.
_kerberos._udp.ad.uni-koeln.de has SRV record 0 100 88 rzkvdc1.ad.uni-koeln.de.
_kerberos._udp.ad.uni-koeln.de has SRV record 0 100 88 rzkvdc2.ad.uni-koeln.de.
_kerberos._udp.ad.uni-koeln.de has SRV record 0 100 88 rzkvdc3.ad.uni-koeln.de.
_kerberos._udp.ad.uni-koeln.de has SRV record 0 100 88 ads4.ad.uni-koeln.de.


Da die Authentifizierung manchmal klappte, lag der Verdacht nahe, dass nur manche der Server das Problem provozieren. Also habe ich die Server der Reihe nach fest im Programm verdrahtet. Dabei zeigte sich, dass Authentifizierung nur bei einem der sechs Server möglich war – wohlgemerkt, nur unter Java 6 auf Macs! Auf allen anderen Systemen funktionierten alle sechs Server. Wie ich vom zuständigen Kollegen erfuhr, läuft der funktionierende Server unter Windows Server 2008, die anderen hingegen noch unter Windows Server 2003. Aber in was unterschied sich die Authentifizierung? Mit Wireshark ließ sich beobachten, dass die Antwort des W2K8-Servers einen Unterschied aufwies.

W2K3:
Encryption type: rc4-hmac (23)
Salt:
Encryption type: des-cbc-md5 (3)
Salt: ...

W2K8:
Encryption type: rc4-hmac (23)
Encryption type: des-cbc-md5 (3)
Salt: ...


Hm, ein leeres Salt – war da nicht was? Richtig, das leere Salt produziert eine Exception. Aber wieso wird hier das leere Salt in der Antwort des Servers übernommen, auf anderen Plattformen aber nicht? Die Klasse mit dem relevanten Code gehört zum dem kleinen Teil, der nicht im Source verfügbar ist – mit Ausnahme von OpenJDK. Also habe ich dort nachgesehen. In Zeile 360 beginnt der Code, der das Salt auswertet, das der KDC in seiner Antwort übergibt:

360 // update salt in PrincipalName
361 byte[] newSalt = error.getSalt();
362 if (newSalt != null && newSalt.length > 0) {
363 princ.setSalt(new String(newSalt));
364 }


Im OpenJDK wird also explizit getestet, dass der String eine Länge > 0 hat. Hatte Apple diesen Test etwa entfernt? Ich hätte es bei der Spekulation belassen müssen, wenn ich nicht auf das javap-Kommando hingewiesen worden wäre. Damit kann man Javaklassen disassemblieren. Das funktioniert auch für die Systemklassen. Und da konnte man folgenden Unterschied erkennen:

javap -v sun.security.krb5.Credentials

JDK 5
85: invokevirtual #77 // Method sun/security/krb5/internal/KRBError.getSalt:()[B
88: astore 6
90: aload 6
92: ifnull 114
95: aload 6
97: arraylength
98: ifle 114
101: aload_0
102: new #44 // class java/lang/String
105: dup
106: aload 6
108: invokespecial #78 // Method java/lang/String."":([B)V
111: invokevirtual #79 // Method sun/security/krb5/PrincipalName.setSalt:(Ljava/lang/String;)V

In Zeile 98 wird die Länge getestet. Ist sie 0, springt das Programm zu Zeile 114, also hinter die setSalt()-Anweisung.

JDK 6
85: invokevirtual #81; //Method sun/security/krb5/internal/KRBError.getSalt:()[B
88: ifnull 107
91: aload_0
92: new #51; //class java/lang/String
95: dup
96: aload 5
98: invokevirtual #81; //Method sun/security/krb5/internal/KRBError.getSalt:()[B
101: invokespecial #82; //Method java/lang/String."":([B)V
104: invokevirtual #83; //Method sun/security/krb5/PrincipalName.setSalt:(Ljava/lang/String;)V
107: aload_2
108: ifnull 131
111: aload_2
112: aload_0
113: invokevirtual #84; //Method sun/security/krb5/PrincipalName.getSalt:()Ljava/lang/String;

Hier fehlt der Längentest! Der Vergleich mit einem Windowsrechner zeigte, dass das dortige Java 6 den Test enthielt. Es handelt sich also zweifelsfrei um einen Bug in Apples Javaversion. Nachdem ich all diese Rechercheergebnisse an Apple gemeldet hatte, wurde der Bug dort auch sofort anerkannt. Bis Apple einen Fix rausbringt, könnte allerdings erfahrungsgemäß noch einige Zeit vergehen. Da die Ursache jetzt aber erkannt war, konnte ich einen Workaround implementieren, der ohne Mitwirkung der Anwender funktioniert: wenn die besagte Exception auftritt, wird die Authentifizierung einfach nochmal durchgeführt, dann aber immer gegen den W2K8-Server. Der ist zwar jetzt ein „single point of failure“ für Macs mit Java 6, aber damit können wir leben.

Der Workaround ist nur in der Testversion von UKLAN-Admin enthalten.

Der geschilderte Fall zeigt, wie verzwickt die Fehlersuche sein kann. Der Fehler tritt schließlich nur auf, wenn man

• einen Mac einsetzt, der Java 6 als präferiertes Java eingestellt hat (d.h. alle Macs mit 10.6, sehr wenige mit 10.5)
• Kerberos 5 zur Authentifizierung nutzt
• kein anderweitig bezogenes Kerberos-Ticket besitzt
• keinen Windows 2008 Server hat (wie es mit anderen KDCs als W2K3 aussieht, weiß ich allerdings nicht)
• man nicht die Cipherliste in /Library/Preferences/edu.mit.Kerberos durch einen Eintrag für default_tkt_enctypes auf nicht-AES-Ciphers eingeschränkt hat (der Trick klappt allerdings nicht für WebStart-Programme)