Dinge, auf die man mal gucken kann

Es gibt sie mitunter, diese Tage. Das Wetter ist Mist, im Fernsehen läuft auch nichts und die Release Notes vom letzten Framework Download sind irgendwie auch unspektakulär seit das so verbreitet ist. Also kann man sich mal Dinge angucken, die man vorher nicht so beachtet hat. Zeitverschwendung ist sowas nie, da selbst, wenn sich die Technologie als völliger Irrweg herausstellen sollte, man etwas dabei gelernt hat. Ich werde unter dieser Kategorie immer mal ein paar Dinge anschneiden, die ich für beachtenswert halte. Wenn sie sehr beachtenswert sind, gibt es dafür dann ggf. noch einmal einen eigenen Beitrag.

Wildfly

Wildfly ist der neue JBoss. JBoss hat seinerzeit arg an Beachtung eingebüßt, als Glassfish rauskam. Glassfish war schlank, GUI bedienbar, innovativ, man konnte alles über die GUI machen, schnell, man konnte sogar in der GUI sehen, wie schnell und hatte vor allem eine Admin DAU Entwickler taugliche GUI. Eine der tragenden Säulen des Glassfish Projekts Arun Gupta, ist zu RedHat gewechselt und kümmert sich dort um Wildfly. Das in Kombination mit der Einstellung des kommerziellen Supports von Glassfish durch Oracle macht Wildfly zu dem zur Zeit interessantesten Applicationserver.  Wer Java EE macht und nicht in Festanstellung in einer Versicherung die nächsten 20 Jahre entspannt mit WebSphere verbringt, wird nicht drum rum kommen, sich den mal anzugucken. Da ist eine enorme Menge coooles Zeug drin womit man sich das eine oder andere Wochenende ruinieren vertreiben kann.

 Node.js und Avatar

Node.js ist eine Eventgetriebene Plattform für Web-Anwendungen die auch Serverseitig mit JavaScript realisiert werden. Es gibt verdammt viele Anwendungsfälle für die so etwas Sinn macht. Ok, das Konzept ist nicht so wahnsinnig neu. Das konnte nginx schon vor einer IT-Ewigkeit und auch ich habe zu Beginn des Jahrtausends in einer Firma gearbeitet, wo ein AppServer mit einer derartigen Technik entwickelt wurde, aber mit den aktuellen Anforderungen durch Ajax und die Einführung von WebSockets ist das Thema relevanter denn je. Klar, gibt es sowas auch in Java EE aber halt noch nicht so lange und für Node.js gibt es bereits jede Menge Module. So cool Node.js auch ist, gibt es doch einige Nachteile, wie die Integration von aufwändigen Berechnungen oder ganz triviale Dinge wie Datum mit Zeitzonen oder BigDecimal.

Javas Erfolgsrezept war es immer alles zu integrieren, was gerade hip ist – also gibt es Projekt Avatar, was im wesentlichen die Funktionalität von Node.js und Java EE verbinden soll. Es ist ein recht junges Projekt. Es braucht Java 8 Nashorn und installiert derzeit nur auf einem Glassfish. Ich werde vermutlich demnächst mal eine kleine App auf der Basis posten.

 Blender

Hmm, das passt irgendwie nicht so ganz in meine sonstigen Themen. Blender ist ein 3d Designtool für Animationen, Spiele – an sich alles, was man so im 3d Umfeld machen kann und es ist Open Source und es kostet nichts und es gibt unglaublich viele Tutorials. Ok, warum sollte sich ein Softwareentwickler mit einem 3d Designtool auseinandersetzen? Naja, 3d wird kommen. Eher früher als später. Das zeigt schon der Aufkauf von Occulus durch Facebook, die Ankündigung von Sony oder die Integration von Unity3d in den Browser So wie man als Entwickler wissen sollte, wie eine Webseite funktioniert, sollte man auch eine Idee haben, wie 3d funktioniert. Außerdem macht es einfach Spaß! 😉

Logging hilft!

Auf der Suche nach einem unangenehmen Problem in einem Live System strahlten mich aus der Logdatei einige Stacktraces an, gegen die dieser  wie eine FSK12 Version anmutet. Ein kurzer Blick in den Code zeigte dann etwa dies:

try {
    meinBackend.machTotalVielKompliziertesZeug(meineBestellung);
} catch (Exception e) {
    LOGGER.log(Level.SEVERE, "Ups", e);
}

Und das war in etwa das einzige Log-Statement im Code. Das ist natürlich schon mal besser als nichts – aber auch nicht wirklich viel besser. In einem kleinen, sinnfreien Beispiel sieht das etwa so aus:

Apr 09, 2014 7:10:46 PM logtest.LogTest machDingeDieDannInDerGuiAngezeigtWerden
SCHWERWIEGEND: Ups
java.lang.NullPointerException
	at logtest.LogTest$Backend.machTotalVielKompliziertesZeug(LogTest.java:22)
	at logtest.LogTest.machDingeDieDannInDerGuiAngezeigtWerden(LogTest.java:53)
	at logtest.LogTest.main(LogTest.java:47)

Der Senior Developer guckte mich etwas traurig an, zuckte mit den Schultern und sagte, da müsse man halt reindebuggen.

Ok, mit dem Debugger auf das Produnktivsystem ist selten die beste Idee. Also wird der Produktivstand auf eine Testumgebung gezogen und der Fehler nachgestellt. Moment, „der Fehler Nachgestellt“ mit welchen Parametern überhaupt? Was ist da passiert? Was wurde versucht?

Agile trifft auf BWL

Logging hat in vielen Firmen keine Priorität. Das liegt oft an einem sehr eigenwilligen Scrumm Konstrukt: Der Product Owner ist automatisch Repräsentant des Endkunden. Wenn dieser die Applikation nicht selber betreibt, wird er Logging nicht explizit als Feature fordern, also fließt kein Geld, also ist es nicht relevant. Die Betreiber In House produzieren ohnehin nur Kosten und haben deshalb auch kein Budget für Anforderungen. Ich habe bisher tatsächlich maximal gesehen, dass Logging als Best Practice in einem Code Review mit Priorität so um D-F angeregt wird, jedoch nie, dass es als tatsächliche Anforderung auftaucht. (Vielleicht hat ja jemand da draußen das System geknackt und kann hilfreiche Anregungen bieten, wie sich Betriebsanforderungen in die Requirements mit einem Kostenträger einbinden lassen.)

Bis dahin subsumiere ich Logging mal unter Technical Debt und fordere es als Best Practice ein.

Was Loggen?

Gutes Logging vereinfacht die Fehlersuche. Ein paar strategisch sinnvoll untergebrachte Log Statements lassen einen gleich viel klarer sehen:

public void machDingeDieDannInDerGuiAngezeigtWerden() {
    Bestellung meineBestellung = new Bestellung("42");
    try {
        meinBackend.machTotalVielKompliziertesZeug(meineBestellung);
    } catch (Exception e) {
        LOGGER.log(Level.SEVERE, "Problem beim Dinge machen für die GUI.", e);
    }
}

und in der aufgerufenen Methode dann:

public void machTotalVielKompliziertesZeug(Bestellung bestellung) {
    LOGGER.log(Level.INFO, "mache kompliziertes Zeug mit der Bestellung {0}.", bestellung);

    konfiguration.getConfigFor("live");

    nochVielKomplizierteresZeug();
}

ergibt schon mal

Apr 09, 2014 8:11:39 PM logtest.LogTest$Backend machTotalVielKompliziertesZeug
INFORMATION: mache kompliziertes Zeug mit der Bestellung 42.
Apr 09, 2014 8:11:39 PM logtest.LogTest machDingeDieDannInDerGuiAngezeigtWerden
SCHWERWIEGEND: Problem beim Dinge machen für die GUI.
java.lang.NullPointerException: Konfiguration ist Null.
    at logtest.LogTest$Konfiguration.getConfigFor(LogTest.java:22)
    at logtest.LogTest$Backend.machTotalVielKompliziertesZeug(LogTest.java:34)
    at logtest.LogTest.machDingeDieDannInDerGuiAngezeigtWerden(LogTest.java:70)
    at logtest.LogTest.main(LogTest.java:64)

(Dem aufmerksamen Leser wird nicht entgangen sein, dass sich der Stack Trace ändert, weil ich nach und nach das Beispiel größer mache. Es geht aber auch nicht um den Stacktrace…)
Man könnte jetzt also schon einmal sehen, dass da offensichtlich etwas in der Konfiguration schief gegangen ist bei der Bestellung 42. Der wichtige Aspekt hierbei ist, dass die Bestellung, um die es geht, mit ausgegeben wird. Jetzt wieß man zumindest schon mal worum es geht und kann ggf. in der Datenbank mal fix Nachschlagen. Aber hier handelt es sich scheinbar um ein Konfigurationsproblem. Kümmern wir uns also um die Konfigurationsmethode:

public String getConfigFor(String key) {
    String value = config.get(key);
    if (value == null) {
        value = fallback.get(key);
        if (value == null) {
            LOGGER.log(Level.SEVERE, "Keine Konfiguration für \"{0}\" vorhanden.", key);
            throw new NullPointerException("Konfiguration für \"" + key + "\" ist Null.");
        } else {
            LOGGER.log(Level.WARNING, "Keine Konfiguration für \"{0}\". Benutze Defaulteintrag \"{1}\".", new Object[]{key, value});
        }
    } else {
        LOGGER.log(Level.INFO, "Konfiguration für \"{0}\" ist: \"{1}\"", new Object[]{key, value});
    }
    return value;
}

Damit hätten wir dann etwa folgende Ausgabe:

Apr 09, 2014 9:16:25 PM logtest.LogTest$Konfiguration 
INFORMATION: Lade konfiguration von /var/web/configs/config.cfg
Apr 09, 2014 9:16:25 PM logtest.LogTest$Backend machTotalVielKompliziertesZeug
INFORMATION: mache kompliziertes Zeug mit der Bestellung 42.
Apr 09, 2014 9:16:25 PM logtest.LogTest$Konfiguration getConfigFor
WARNUNG: Keine Konfiguration für "DB". Benutze Defaulteintrag "localhost:1234".
Apr 09, 2014 9:16:25 PM logtest.LogTest$Konfiguration getConfigFor
INFORMATION: Konfiguration für "Cachefolder" ist: "/var/webservers/globalcahe"
Apr 09, 2014 9:16:25 PM logtest.LogTest$Konfiguration getConfigFor
WARNUNG: Keine Konfiguration für "live" vorhanden.
Apr 09, 2014 9:16:25 PM logtest.LogTest machDingeDieDannInDerGuiAngezeigtWerden
SCHWERWIEGEND: Problem beim Dinge machen für die GUI.
java.lang.NullPointerException: Konfiguration für "live" ist Null.
    	at logtest.LogTest$Konfiguration.getConfigFor(LogTest.java:40)
	    at logtest.LogTest$Backend.machTotalVielKompliziertesZeug(LogTest.java:60)
	    at logtest.LogTest.machDingeDieDannInDerGuiAngezeigtWerden(LogTest.java:96)
	    at logtest.LogTest.main(LogTest.java:90)

Mit einer derartigen Ausgabe könnte vermutlich bereits der Administrator etwas anfangen und das Problem würde gar nicht erst bis in die Entwicklungsabteilung durchgereicht. Ihm würde vermutlich auch gleich noch auffallen, dass die DB Verbindung als Fallback localhost nimmt, was vermutlich nur auf dem Rechner des Entwicklers zu dem gewünschten Ergebnis führt.

Es ist also durchaus hilfreich, wenn auch jemand ohne der Quellcode sehen kann, was in der Anwendung vorgeht. Wichtig ist vor allem, dass nicht nur ausgegeben wird, was getan wird, sondern vor allem auch womit etwas getan wird.

Jetzt kommen hoffentlich die Einwände „Aber Level Info möchte ich im Produktivsystem doch gar nicht sehen!“…

Wie viel loggen?

Richtig. INFO will man in einem Produktivsystem gar nicht sehen. An sich möchte man im laufenden Betrieb gar nichts sehen, so lange es keine Probleme gibt. Sprich, eine Anwendung sollte Log-Clean sein. Am Ende des Tages schreibt ein log irgendwo hin und das kostet Zeit und ist im Fall des Filesystems nicht parallelisierbar. Deswegen ist es wichtig, dass die Log Level dynamisch angehoben werden können. Es muss möglich sein, ohne durchstarten des Systems den Loglevel auf einem Cluster Node mal kurzfristig auf INFO zu setzen, damit man ohne einen Debugger Probleme im Betrieb finden kann.

Nun ist es dafür meist zu spät, wenn das Kind bereits in den Brunnen gefallen ist und Fehler auf der schwerwiegendsten Stufe produziert hat. Dafür gibt es eine total brillante Erfindung:  den Memory Logger. Hier werden, ähnlich, wie bei einem Flugschreiber, die Logs in einen Buffer geschrieben, der eine Anzahl von Einträgen zwischenspeichert und auf Kommando (meist das Auftreten einen schwerwiegenden Logmeldung) in das Log schreibt. Man sieht also im Fehlerfall eine begrenzte Zahl von INFO ausgaben, die dem Fehler direkt vorausgehen. Das ist enorm praktisch. J.U.L. hat den bereits standardmäßig dabei, für log4j muss man ihn laden oder schreiben und ähnliches gilt für logback.

Wie loggen?

Wie man in dem Beispielcode sieht, ist die API von J.U.L. nicht gerade sehr ansprechend. Weiterhin ist es bei Applicationservern hilfreich, den Logger des Applicationservers zu verwenden, da der mitunter spannende Dinge macht wie Filterung auf Anwendungsbasis. Von daher würde ich im produktiven Umfeld immer zu SLF4J greifen. Es hat den Vorteil, dass es beliebige Backends mit einer API bedient und die ist auch noch sehr angenehm zu benutzen.

Weiterhin sollte Logging so einfach wie möglich sein. Es ist das, was immer funktionieren muss. Loggen in eine Datei ist einfach und genau deshalb auch der Standard für jede Form von Appserver. Ich habe auch schon Log Appender gesehen, die hintenrum eine EJB bedienen, die dann über JMS Logs verteilt. Es hat zwar bestimmt Spaß gemacht, das zu entwickeln, widerspricht aber der grundlegenden Anforderung der Einfachheit. Mal ganz zu schweigen davon, dass das Logging in der Initialisierunsphase des Appservers ganz einfach nicht funktioniert.

Ich habe auch schon gesehen, dass in einem Cluster das Logging sämtlicher Nodes in ein NFS Share laufen. Die Idee daran war, eine zentrale Stelle zu haben, an der man die Logs einsehen kann. Das hat allerdings den Nachteil, neben der Preformanceproblematik eines NFS, dass der Komplette Cluster steht wenn das NFS nicht tut. Wenn man Logs aggregieren möchte, gibt es dafür prima Tools, die Logs von allen Systemen zusammensammeln und zentral verfügbar machen ohne die Funktionalität des Clusters zu beeinträchtigen.

Schreibt Logs!