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!

XML und Immutable Objects

Unveränderliche Objekte – also ohne Setter, sind enorm praktisch und gemeinhin guter Stil. Ok, nicht immer, aber für enorm viele Datenklassen macht es total Sinn – insbesondere, weil sie Threadsafe sind und in Interfaces Seiteneffekte durch call by reference vermeiden.

Nun sind eben genau diese Typen gerne mal zu schreiben und JAXB verlangt einen Defaultconstructor. Ich habe dazu die absurdesten Klimmzüge im Netz gefunden mit Mapperklassen und ähnlichem. Das hier ist simpel und funktioniert:

@XmlRootElement
public class ImmutableName {

  @XmlElement
  private String firstname;
  @XmlElement
  private String surname;

  private ImmutableName() {
  }

  public ImmutableName(String firstname, String surname) {
    this.firstname = firstname;
    this.surname = surname;
  }

  public String getFirstname() {
    return firstname;
  }

  public String getSurname() {
    return surname;
  }

}