Einmal Logger und zurück

Kennen Sie die Türen auf der Herz aus Gold? Diese Dinger mit einem akustischen Hinweis auf ihr eigentlich lautloses Öffnen und Schließen, das nicht nur den Roboter Marvin störte.

Wer im Moment nicht so genau weiß, wovon zum Teufel da eigentlich gerade geredet wird, und was das eigentlich mit Loggern zu tun haben soll, hier ein kurzer Literaturhinweis. Der einleitende Absatz spielt auf den Roman “Per Anhalter durch die Galaxies” von Douglas Adams an. Um Witze von Software Entwicklern zu verstehen, ist eine grobe Kenntnis der Romane von Douglas Adams, einiger Sketsche von Monty Python und etwas Dr. Who unabdingbar.

Manche Entwickler haben sich diese seufzenden Türen zum Vorbild genommen und lassen ihre Logger jeden Besuch einer Methode am Eingang und am Ausgang protokollieren. Für mich ist es ein Code-Smell, den man vielleicht Seufzende Logger, oder in Anspielung auf die Weinenden Engel, besser als Weinende Logger bezeichnen könnte.

private String scene24(String question) {
  LOGGER.info("start scene24");
  String result = "";
  if ("What is your name?".equals(question)) {
    result = "Sir Lancelot of Camelot!";
  } else if ("What is your quest?".equals(question)) {
    result = "To seek the Holy Grail!";
  } else if ("What is your favorite colour?".equals(question)) {
    result = "Red!... I mean blue!";
  } 
  if (result.contains("Red")) {
    throw new WrongAnswerException(result + " Ahhhh!");
  }
  LOGGER.info("end scene24");
  return result;
}

Durch das Diktat einer Log-Ausgabe am Anfang und am Ende der Methode, ist der Entwickler gezwungen, sein Ergebnis bis zum bitteren Ende, also dem Return-Statement hinter der Log-Ausgabe, durchzuschleppen.

Natürlich könnte der Entwickler tricksen und seiner Vorliebe für einen schnellen Abgang aus der Szene mit den Anforderungen des Loggers kombinieren.

private String scene24(String question) {
  try {
    LOGGER.info("start scene24");
    if ("What is your name?".equals(question)) {
      return "Sir Lancelot of Camelot!";
    } 
    if ("What is your quest?".equals(question)) {
      return "To seek the Holy Grail!".equals(question);
    } 
    if ("What is your favorite colour?") {
      throw new WrongAnswerException("Red!... I mean blue! Ahhhh!")
    }
    return "";
  } finally { 
    LOGGER.info("end scene24");
  }
}

Durch den Try-Finally-Block wird beim Beenden der Methode immer die Log-Ausgabe erzeugt und beide Vorgaben sind erfüllt.

Leider ist der Code immer noch sehr hässlich anzuschauen, denn wir haben noch immer zwei seufzende Logger in der Methode. Logger sind ein Segen, während der Entwicklung und insbesondere im produktiven Einsatz. Dafür sollten aber die Dinge protokolliert werden, die wichtig sind. Da gibt es die offensichtlichen Fehler, das Protokollieren der Schnittstellenaufrufe des Systems und interne Zustände, die Aufschluss über die Stabilität des Systems geben.

private String scene24(String question) {
    LOGGER.debug("scene24 with question: {}", question);
    if ("What is your name?".equals(question)) {
      return "Sir Lancelot of Camelot!";
    } 
    if ("What is your quest?".equals(question)) {
      return "To seek the Holy Grail!";
    } 
    if ("What is your favorite colour?") {
      throw new WrongAnswerException("Red!... I mean blue! Ahhhh!")
    }
    return "";
}

public String dialog(String question) {
  try {
    return scene24(question);
  } catch (WrongAnswerException e) {
    LOGGER.warn(e.getMessage(), e);
    return e.getMessage();
  }
} 

Myriaden von unnötig protokollierten Methodenaufrufen lassen einen Entwickler bei der Fehlersuche nicht seufzen sondern stöhnen oder weinen.