AOP und Logging - Teil III

Inhaltsübersicht:

AOP und Logging - Teil I

Einführung in das Thema Logging und AOP. Was ist Logging? Was ist Tracing? Motivation für einen neuen Ansatz.

AOP und Logging - Teil II

Eine Lösungsansatz ohne AspectJ.

AOP und Logging - Teil III

Logging vs. Debugging und eine erste einfache Lösung.

Bevor ich eine erste Lösung für das Logging Problem mittels AspectJ präsentiere, möchte ich mich noch dem Thema Logging und Debugging beschäftigen. Auch diese werden nicht sauber getrennt: Der Adressat (oder primäre Stakeholder) von Logging- bzw. Debugginginformationen wird nicht beachtet und ausserdem wird der Logging-Level einerseits als Filter, andererseits als Gewichtung verstanden.

In der Javawelt (wahrscheinlich nicht nur dort) ist der Zweck und der Adressat von Logging ein wenig unter die Räder gekommen, darum werde ich zu diesem Zwecke ein Schritt zurücktreten und schauen: Wie sieht es den in der Realen Welt aus? Was sind die Ursprünge des Loggings?

Wen das nicht interessiert kann sich direkt die Version 0.1 anschauen.

Das Logbuch in der Schifffahrt

Ein Kapitän der Seefahrt ist gezwungen ein Logbuch zu führen. Es dient dem Zweck seine Entscheidungen und die Entscheidungsgrundlagen zu dokumentieren. Diese können und werden bei notwendigen Untersuchen z.B. in juristischen Prozessen benutzt. Das bedeutet natürlich auch das Kapitän nicht Dinge in dieses Logbuch schreibt, wie zum Beispiel die Konsistenz seines Stuhlganges, die nicht von Bedeutung sind. (Dies hat er vielleicht in sein Tagebuch geschrieben.) Entscheidungsgrundlagen können Zustände des Schiffs sein wie z.B. Art und Menge der Beladung. Aber auch der aktuelle Kurs, Funksprüche und natürlich die Wetterlage bilden Entscheidungsgrundlagen.

Ein weiter wichtiger Punkt ist, das nicht der Kapitän entscheidet was ins Logbuch gehört, sondern dies ist eine von Dritten verfasste Vorschrift.

Also zusammenfassend: Ein Logbuch enthält also alle potentiell relevante Informationen, die nötig sind Entscheidungen nachträglich beurteilen zu können.

Was hat das mit Debugging zu tun? Natürlich nichts. Debugginginformationen werden nicht aufgezeichnet. In der Schifffahrt wird post mortem beispielsweise auf die Besatzung zurückgegriffen, falls eine Untersuchung notwendig sein sollte. Also irrelevante Informationen, die ich mal als Debugginginformationen definiere, haben nichts im Logbuch verloren.

Die Entwicklung von Autos

Nun ist Logging nur bedingt mit dem Logbuch eines Schifffahrtskapitän vergleichbar. Ein anderes passendes Beispiel zur Softwareentwicklung ist die Entwicklung von Autos.

Während der Entwicklung wird ein Auto mit einer Vielzahl an Sensoren versehen, die in ein produktiven Version entfernt werden. Übrig bleiben Sensoren und entsprechende Aufzeichnungselektronik, die den Werkstätten der Wartung des Fahrzeuges dienen oder den Besitzer auf Missstände hinweisen. Nach der Entwicklung wird der Umfang und Detaillierungsgrad der Informationen reduziert.

Die in der Produktion übrig bleibenden Sensorik würde dem Logging und die Entwicklungssensorik dem Debugging entsprechen. Und man beachte das Bild: Sensor- und Aufzeichnungselektronik. Der Sensor entspricht den Aufrufen der Logging-Library und die Aufzeichnungselektronik der eingesetzen Library.

Wie man unschwer erkennen kann, macht es wenig Sinn alle Sensoren in der Produktion zu belassen:

1. zu teuer und
2. der fehlender Adressat.

Während der fehlende Adressat kein schlagendes Argument ist, sind Kosten immer ein Argument. Kurz: Das Gute in der Autoentwicklung ist, das die Kosten ein disziplinierendes Element sind.

Logging und Debugging

Dieses Disziplin haben wir in der Softwareentwicklung leider nicht. Hier wird protokolliert was das Zeug hält. Einzig der Entwickler entscheidet, was protokolliert wird und was nicht. Es ist nicht mehr wirklich ersichtlich, welche Bedeutung ein Loggingeintrag hat.

In C/C++ kann mittels eines Compilerflags alle Debugginginformationen aus dem Code entfernt werden. In Java gibt es diese Möglichkeit nicht, das hat dazu geführt, dass in LOG4J und Co ein Level DEBUG eingeführt wurde. Der Level DEBUG hat zwei verschiedene Bedeutungen:

1. Die Information richtet sich an die Entwickler.
2. DEBUG ist eine Gewichtung der Information (mit einer Wichtigkeit unterhalb INFO). 

Der wesentliche Punkt ist, dass durch die Markierung einer Meldung mit dem Level DEBUG diese den Adressat Entwickler hat. Die darüberliegenden Level (INFO, WARNING, ...) richten sich an die Applikationsbetreuer.

Zusammenfassung

In der nachfolgenden Tabelle habe ich die drei Bedeutungen der Protokollierung zusammengefasst:

	Wem dient es?	Wann?	Wozu?
Tracing	Entwickler	gelegentlich bei Tests	Dient zur Verfolgung von Abläufen. Kann auch dem Refactoring oder Einarbeitung dienen.
Debugging	Entwickler	Unit- und Integrationstest (evtl. BETA Test)	Vom Entwickler eingestreute (lokale) Information dient der Fehlerbeseitigung.
Logging	Applikationsbetreuer	Produktion	Ein für den Applikationsbetreuer global relevante Informationen, die der u.a. der Überwachung der Applikation bzw. einen Moduls dient.

Obwohl Debugging sehr viel Gemeinsamkeiten mit Logging hat (zumindest in technischer Hinsicht), macht es Sinn Logging,  Debugging und natürlich auch Tracing für sich zu betrachten, da sich Adressat und Zweck unterscheiden.

In AOP bedeutet dies, für jeden einen eigenen Aspekt bereitzustellen, auch wenn darunter die gleiche Logging-Library genutzt wird.

Logging - Version 0.1

Da wir nun hoffentlich den gordischen Knoten des Loggings sprachlich und gedanklich zerschlagen haben, können wir uns einer ersten naiven Lösung des Loggings respektive Logbuches widmen:

// MyLogbook Example 
package ajlog.example;

import ajlog.annotations.Info;
import ajlog.annotations.Logbook;

// #1#
@Logbook
public class MyLogbook {
  // #2#
  @Info("'{}' is not a tiny number ({}>={})")
  public static void isNotATinyNumber1(String varName, Number currValue,
      int compValue) {
  }
}

Ein Logbuch ist eine mit Logbook Annotation (#1#) markierte Utility-Klasse, also einer Klasse ohne Konstruktor ausschliesslich aus Klassenmethoden bestehend.

(#2#) Jede Klassenmethode, die mit einem Level markiert ist (hier exemplarisch Info) entspricht einem potentiellen Logbucheintrag. Die Annotation Info enthält den Ausgabetext mit den Platzhaltern {}.

Wie man sieht gibt es keine einzige Referenz zu einer Logging-Implementation.


Die Nutzung ist trivial. Einfach die Klassenmethoden aufrufen. Hier der Einfachheit wegen in einem JUnit-Test demonstriert:

// JUnit-Test
package ajlog.example;

import junit.framework.TestCase;

public class MyLogbookTest extends TestCase {
  public void testAnnontationBasedLogging() {
    MyLogbook.isNotATinyNumber1("any var", new Long(100), 99);
  }
}

Die zugehörige Ausgabe könnte dann wie folgt aussehen.

23:39:34.884 [main] INFO  ajlog.example.MyLogbook - 'any var' is not a tiny number (100>=99)

Ein entsprechender Aspekt könnte folgendermassen aussehen:

package ajlog.aspects.simple;

// #1#
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import ajlog.annotations.Info;
import ajlog.annotations.Logbook;

public aspect LoggingAspect {
  // #1# The Info pointcut defintion
  pointcut infoMethodPc(Info level) :
     // #4# any public void class method within @Logbook annotated class
     execution(public static void (@Logbook *).*(..) ) 
     // #5# Method annotation Info
     && @annotation(level);
     

  // #2# the advice header
  before(Info level) : infoMethodPc(level) {
    // #3# the advice body

    // #7# resolve Logger instance
    Logger logger = LoggerFactory.getLogger(thisJoinPointStaticPart
        .getSignature().getDeclaringType());

    if (logger.isInfoEnabled()) {
      // #6# Perform the logging using @Info.value() 
      logger.info(level.value(), thisJoinPoint.getArgs());
    }
  }
}

Ein Aspekt ist ein Bündelung von drei Dingen:

1. (#1#) pointcut definition. Wo soll die Funktionalität eingebunden werden?
2. (#2#) Der advice header gibt an Wann (before, after) und eventuell auch Ob (around) die Funktionalität ausgeführt werden soll.
3. (#3#) Der advice body legt fest Was ausgeführt werden soll. Der advice body enthält die Funktionalität des Advices.

In einem Satz kann man den LoggingAspect wie folgt ausdrücken: An jeder mit Logbook markierten Utilityklasse führe vor der Ausführung jede mit Info markierten öffentlichen Klassenmethode (ohne Rückgabewert) ein Logging mittels SLF4J durch.

Der benannte pointcut infoMethodPc (#1#) setzt sich zusammen aus:

• (#4#)  Ausführung (execution) von öffentlichen (public) Klassenmethoden (static) ohne Rückgabewert (void) die Teil einer mit @Logbook markierten Klassen sind   und
• (#5#) die Methode ist mit @Info markiert.

Mittels infoMethodePc(Info level): /*... */ && @annotation(level)  kann im advice body (#3#) auf den Logging Textvorlage (level.value() #6#) zugegriffen werden. (Das Format des in @Info hinterlegten Textes entspricht dem von SLF4J's MessageFormatter).

Mittels des Schlüsselwortes before wird im advice header (#2#) festgelegt, das vor dem pointcut infoMethodPc der nachfolgende advice body ausgeführt wird. D.h. insbesondere werden die vom pointcut selektierten Methoden immer ausgeführt.

Der advice body (#3#) ist hingegen sehr einfach und bedarf eigentlich keiner Erklärung, sondern entspricht bis auf (#7#) der Erwartung: Es ist allerdings unschön und auch nicht sonderlich der Performance dienlich, bei jedem Aufruf erneut die Logger Instanz holen zu müssen. (Aber hier geht es erst einmal um das Prinzip und das wird einer späteren Version verbessert werden.) Schön ist, dass man auf die aktuellen Variablen direkt zugreifen kann, da diese im JointPoint Objekt als Object-Array abgelegt sind (thisJointPoint.getArgs()).

Abschliessend, der Vollständigkeit wegen, die beiden Annotations:

// Logbook annotation 
package ajlog.annotations;

import java.lang.annotation.Documented;
import java.lang.annotation.ElementType;
import java.lang.annotation.Inherited;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.TYPE)
@Inherited @Documented
public @interface Logbook {
}

und

// Info annotation
package ajlog.annotations;

import java.lang.annotation.Documented;
import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
@Documented
public @interface Info {
  String value() default "";
}

Natürlich ist dies erst eine naive Lösung, aber es zeigt die wichtigsten Elemente:

• Die Logbook-Annotation und die
  
• Level-Annotation(s) mit einer Textvorlage. Exemplarisch habe ich dies für den Level Info aufgezeigt. Weitere Levels können analog zu Info bereitgestellt werden.
  

Was haben wir erreicht?

• Allein die Annotations bilden die "Schnittstelle". Man kann es sehr einfach erweitern ohne bestehende Nutzungen zu beeinträchtigen (mittels sinnvollen Defaults).
• Die Entscheidung für eine Logging-Library kann auf einen sehr späten Zeitpunkt verlagert werden. Zur Not sogar auf den Auslieferungszeitpunkt der fertigen Software.
• Wenn kein Logging erwünscht wird, kann dieses komplett entfernt werden.
• Durch die Festlegung von Annotations ist es möglich eine ganz andere Implementation zu hinterlegen, ohne das die Entwicklung davon betroffen ist. Sogar die Entscheidung eine gänzlich neue Logging-Library zu entwickeln ist möglich.
• Keine Logging-Instanz mehr in den Klassen.
• Es können Statistiken über die Logeinträge geführt werden, da diese eindeutige Namen haben.
• An den Methoden können weitere Aspekte greifen.

Und einige interessante Möglichkeiten möchte ich für Entwicklern von Libraries, Frameworks und Co unterstreichen:

• Der Nutzer entscheidet welche Logging-Library eingesetzt wird. (Auch wenn dies mit SLF4J bzw. Jakarta Commons Logging (JCL) jetzt schon möglich ist.)
• Noch wichtiger: Die Logbook-Instanzen sind mittels Javadoc dokumentiert und würden für mich zur Auslieferungsdokumentation gehören. D.h. die Entwickler von Libraries müssen sich Gedanken dazumachen, wozu ein Logeintrag vorhanden ist und was für den Anwendungsentwickler bzw. Anwendungsbetreuer daraus abzuleiten ist! Das entspricht der Diskussion die ich oben geführt habe.
• Da Level und Texte anpassbar sind (jetzt noch nicht implementiert), hat der Nutzer die Möglichkeit das Logging an seine Bedürfnisse hin auszupassen ohne auf den source code zurückgreifen zu müssen.

Was ist noch verbesserungswürdig?

• Das Format der Textvorlage (@Info.value()) ist an SLF4J gebunden.
• Der Zugriff auf die Logging-Instanz innerhalb des Advices ist nicht besonders hübsch. Mit ein paar Tricks ist es möglich die Logging-Instanz genau einmal zu ermitteln.
• Zwei Versprechen sind noch nicht eingelöst worden: Der Level und der Text kann nicht revidiert werden ohne eine erneutes Build.
• Es ist noch recht mühsam die Logging-Library zu ersetzen. Das geht (noch) besser.
• Internationalisierung.
• Es gibt eine nette Lösung für Bedingte Logbucheinträge mittels AspectJ (conditional logging).

Aber diese Verbesserungen sind das Thema meines nächsten Beitrages.