Marko's Software Development Blog

AOP und Logging - Teil III

2010-02-01T15:07:00.008+01:00

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:

zu teuer und
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:

Die Information richtet sich an die Entwickler.
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#) pointcut definition. Wo soll die Funktionalität eingebunden werden?
(#2#) Der advice header gibt an Wann (before, after) und eventuell auch Ob (around) die Funktionalität ausgeführt werden soll.
(#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.

AOP und Logging - Teil II

2010-01-02T17:10:00.026+01:00

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.

Im letzten Beitrag habe ich versprochen eine Lösung für das Logging mittels AOP bzw. AspectJ zu präsentieren. In einem ersten Schritt werde ich erst einmal eine Lösung ohne AspectJ präsentieren und dann werde ich diese Lösung in späteren Beiträgen weiter verfeinern.

Zunächst werden alle identifizierten Tracing-Einträge des Beispiels entfernt, da diese relativ einfach mit einem Aspect behandelt werden können. Dann sieht die Klasse wie folgt aus:

package ajlog.example;

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


public class MyClass {
  // #2#
  private static Logger logger = LoggerFactory.getLogger(MyClass.class);

  public Object doSomethingWith2Objects(Object a, Object b) {

    try {
      Number ai = (Number) a;
      Number bi = (Number) b;

      if (ai.intValue() > 100)
        logger.warn("a is not a tiny number"); // #3#

      if (bi.intValue() > 100)
        logger.warn("b is not a tiny number"); // #3#

      return new Long(ai.intValue() + bi.longValue());
    }
    catch (RuntimeException ex) {
    }

    return null;
  }
}

Nachdem die Tracing-Einträge entfernt wurden, sieht das ganze schon deutlich übersichtlicher und wartbarer aus. Unschön ist, dass es nach wie vor eine explizite Abhängigkeit zur Logging-Library und der Erzeugung einer Logging-Instanz habe (#1# und #2#). Zudem ist die Bedeutung, die hinter dem Loggingaufruf (#3#) steht, nicht repräsentiert. Der nächste Schritt ist also: Den Logging-Einträgen eine Bedeutung geben. Das könnte dann wie folgt aussehen:

package ajlog.example;

public class MyClass {

  public Object doSomethingWith2Objects(Object a, Object b) {

    try {
      Number ai = (Number) a;
      Number bi = (Number) b;

      if (ai.intValue() > 100)
        MyLog.isNotATinyNumber("a", ai, 100);

      if (bi.intValue() > 100)
        MyLog.isNotATinyNumber("b", bi, 100);

      return new Long(ai.intValue() + bi.longValue());
    }
    catch (RuntimeException ex) {
    }

    return null;
  }

}

und die dazugehörige Implementation von MyLog ...

package ajlog.example;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class MyLog {
  // #1# Only drawback : It's MyLog not MyClass the logger belongs to.
  private static Logger logger = LoggerFactory.getLogger(MyLog.class);

  public static void isNotATinyNumber(
         String varName, Number currValue, int compValue
      )
  {
    if (logger.isWarnEnabled()) {
      logger.warn("{} is not a tiny number ({} > {})",
          new Object[]{
              varName, currValue, new Integer(compValue)
          }
      );
    }
  }
}

Was haben wir dadurch dieses refactoring erreicht?

Zunächst mal das Offensichtliche:

Es wird keine Logging-Instanz mehr zur Klasse MyClass hinzugefügt und auch die imports fehlen. Die direkte Abhängigkeit ist aufgelöst worden.
Es gibt nur noch eine (Klassen-)Methode isNotATinyNumber(). D.h. es gibt nur noch eine (Logging-)Methode, egal ob dies Variable "a" oder "b" betrifft.

Das wichtigste an dieser Änderung ist aber folgendes:

Aus Logging-Eintrag ist eine bedeutungstragende Einheit, eine Logging-Methode geworden, die einer Logging-Klasse zusammengefasst werden können.
Die erzeugte Logging-Methode ist wiederverwendbar.
Das Logging kann systematisiert werden.
Die Logging Library ist (relativ schnell) austauschbar.
Es kann eine Cross Referenz Liste erstellt werden.
Mittels JavaDoc kann das gesamte Logging dokumentiert werden.
Der Level lässt sich ändern.
Der Text lässt sich ändern.

Und noch ein Sahnehäubchen:

Diese Art von Logging kann von einer IDE besser unterstützt werden: Die Logging-Klasse (MyLog) und die Logging-Methode (isNotATinyNumber) mit all ihren Parametern wird mehr oder weniger auf Knopfdruck erzeugt, bzw. bestehende Klassen und Methoden werden aufgelistet.
Eine einfache Art der Systematik: Man kann zwischen globalen (relevanten) und lokalen (weniger relevanten) Logging unterscheiden. Man nutzt einfach public static und (package) static zur Markierung der Logging-Methoden, also eine Klassenmethode ohne jeden Zugriffsqualifizierer (public, protected, private). Leztere wären dann Debug-Ausgaben. Erstere wären Info-, Warning-, Error- und Fatal-Ausgaben.

Kurz: Dieses refactoring müsste schon an sich sinnvoll, unabhängig davon, ob man AspectJ einsetzen will oder nicht.

Ein "Nachteil" (#1#) will nicht verschweigen: In der Logging-Ausgabe wird nicht protokoliert, wer die Quelle des Log-Eintrags war, also der Aufrufer von MyLog.isNotATinyNumber(). Aber dies gehört meiner Meinung nach nur in den Bereich eines Log-Eintrages auf dem Level des Debugging und ist ein zu verkraftender Nachteil (und lässt sich mit einem etwas einmalig erhöhten Aufwand sogar eliminieren).

Natürlich bin ich noch am Ziel meiner Träume, aber der erste grosse Schritt ist vollzogen. AspectJ hat nun Angriffspunkte: das Ausführen (execution) oder Aufrufen (call) von MyLog.isNotATinyNumber(). Für sind dies zwei mögliche sogenannte joint points, die mit einem poincut Designator selektierbar sind.

Was fehlt mir zu meinem Glück?

Ich würde gerne das ganze auch ausführen können, ohne das ich eine Logging Library im classpath habe.
Ich würde gerne Texte und Level anpassen können ohne neu zu builden.
Die versprochene Internationalisierung fehlt auch noch.
Ich will die Logging Library schmerzlos austauschen können. D.h. indem ich ein JAR im classpath austausche.

Ich mache es spannend und werde ein ersten naiven Aspekt im Teil III entwickeln ;-)

AOP und Logging - Teil I

2009-12-30T13:28:00.038+01:00

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.

In meinem ersten Beiträgen möchte ich mit einem meiner Lieblingsthemen beschäftigen: Aspect Oriented Programming (AOP).

AOP hat längst den Mainstream der (Java) Entwickler erreicht, ohne das die meisten Aspekte selber entwickeln (das muss nicht unbedingt schlecht sein): Man nutzt AOP im Rahmen eines Frameworks wie z.B. Spring ohne jedoch eigene Aspekte zu entwickeln. Dabei will AOP ein Problem lösen, das jeden Entwickler früher oder später (be-)trifft: Seperation of Concerns. Wenn eine neue Applikation erstellt wird, dann wird zunächst von den Kernfunktionalitäten (core concerns) gesprochen, den dahinter steht die Motivation die Applikation überhaupt zu erstellen. Aber leider ist dies nur die halbe Wahrheit ist. Die Kernfunktionalität ist vielleicht hinreichend für einen Prototyp, aber für eine lieferbare, wartbare Applikation, die den Entwickler ruhig schlafen lässt, ist dies nicht ausreichend. Ernsthafte Softwareentwicklung muss sich um die cross-cutting concerns kümmern, wie zum Beispiel die allseits bekannten nicht funktionale Anforderungen.

Das bekanntesten und damit am häufigsten genannten cross-cutting concerns sind Tracing und Logging. Die Anwendung dieser Aspekte durchziehen die meisten Applikationen. Diese beiden Aspekte sind so essentiell, das sie auch zur Motivation und als Standardbeispiele von AOP herhalten müssen. Leider hat Logging als Beispiel für AOP einen Webfehler: Logging und Tracing werden nicht sauber unterschieden.

Eine Anmerkung zum Thema Logging
Immer wieder wird AOP mit Logging erklärt. Warum schon wieder Logging? Gibt es nichts anderes auf dieser Welt wozu AOP dienen kann? Und ob. Aber Logging (das meist mit Tracing verwechselt wird) verunstaltet wie kein anderer Aspekt unseren Code. Ausserdem will ich zeigen, das hinter dem Thema Logging mehr steckt als man auf den ersten Blick erkennen kann.
Ich habe also eine Bitte an euch: Geduld. Am Ende soll neben eine verbessertes Verständnis von Logging und AspectJ, eine kleine aber feine AspectJ-Library entstehen: ajlog.

Wozu AOP noch taugt ausser Tracing und Logging, werde ich in weiteren Artikeln behandeln.

Wenn eine Library wie Log4J oder SLF4J eingesetzt wird, dann ist Tracing ein Level, der alle anderen Levels (DEBUG, INFO, ...) enthält. Aus Sicht der Levelhierachie ist somit ein Loggingeintrag ein verfolgbarer (traceable) Eintrag. Aus technischer Sicht ist dies auch richtig. Macht dies aber auch tatsächlich Sinn?

Schauen wir uns mal ein (zugegeben künstliches) Beispiel an:

package ajlog.example;

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


public class MyClass {
// #7# 
private static Logger logger = LoggerFactory.getLogger(MyClass.class);

  public Object doSomethingWith2Objects(Object a, Object b) {
    // #1#  Tracing : Enter method
    logger.trace("Enter doSomethingWith2Objects({},{})", a, b);

    try {
      // #5# : throws Exception
      Number ai = (Number) a;
      Number bi = (Number) b;

      if (ai.intValue() > 100)
        logger.warn("a is not a tiny number"); // #6#

      if (bi.intValue() > 100)
        logger.warn("b is not a tiny number"); // #6#

      Number result = new Long(ai.intValue() + bi.longValue());

      // #2#  Tracing : Leave method
      logger.trace("Leave doSomethingWith2Objects(...) -> {}", result);

      return result;
    }
    catch (RuntimeException ex) {
      // #4#  Tracing? : Report unexpected behaviour
      logger.error("a or b is not a number", ex);
    }

    // #3#  Tracing : Leave method
    logger.trace("Leave doSomethingWith2Objects(...) -> null");
    return null;
  }
}

#1#, #2# und #3# sind unbestreitbar Tracing-Einträge und dies nicht wegen des Levels. Über #4# lässt sich streiten, da hier nicht nur die Exception ausgegeben wird, sondern auch in den Verlauf eingegriffen wird. Würde die Exception anschliessend wieder geworfen wäre dies IMHO ein Tracing (trotz des Levels ERROR). Diese Tracingmeldung kann durch eine potentielle Exception bei #5# ausgelöst werden.
Bleiben die beiden logger.warn() Einträge (#6#): Dies sind Logging-Einträge, wie sie Entwickler immer wieder in den Code einstreuen, die dem Applikationsbetreuer wertvolle Informationen während der Laufzeit oder post mortem hinterlässt - auch wenn sie in diesem Fall sehr technisch erscheinen.

Die Tracing-Einträge lassen sich sehr einfach mit behandeln, da sie sich mit einem Pointcut Definition (z.B. pointcut traceable() : execution(public * *.*(..)) erreichen lassen. Für die beiden Logging-Einträge gilt dies nicht. Warum ist dies so?

Sie haben eine Bedeutung, die nicht durch den Aufruf von logger.warn() abgedeckt ist. Ihre Expressivität erhalten sie durch den Logging Inhalt ("a is not a tiny number") und der ist für Code Weaver (so) nicht erreichbar. Eine mögliche Lösung wäre, das man ein zusätzliche Methode einführt, dann wäre diese wieder verfolgbar, aber dann wäre Logging identisch mit Tracing und man hätte Schwierigkeiten den Level gescheit zu setzen.

Natürlich würde kein Entwickler, der bei Sinnen ist, auf so wenig Codezeilen soviele Tracing- respektive Logging-Einträge vornehmen - es ist ein künstliches Beispiel. Aber selbst wenn man die offensichtlichen Tracing-Einträge entfernt, verbleibt die direkte Abhängigkeit zur Logging-Library (#7#) und die Logging-Einträge. Und diese müssen bleiben! Was nicht bleiben muss ist die direkte Abhängigkeit zur Logging-Library.

Zusammenfassend:

Logging als Motivation für AOP ist in Ordnung, den unbestreitbar handelt es sich um ein cross-cutting concern. Aber Logging ist aber kein einfach zu lösendes Beispiel für den Einsatz von AOP.

LOG4J und der legitime Nachfolger SLF4J (bzw. logback) sind grossartige Software. Aber leider reduzieren sie Logging auf den technischen Aspekt. Sie sind (leider?) so erfolgreich, das sie über die Welt von Java hinaus Einfluss hatten und haben.

Auch das automatische Induzieren von Logging-Instanzen (wie z.B. in Grails) löst dieses Problem nicht. Sie spart nur Tipparbeit, mit dem kleinen Haken, dass man sich an den Namen der Logging-Instanz erinnern muss.

Kurz: Es bedarf einer besseren Lösung. Aber einer Lösung, die auf bestehenden aufsetzt.

Im den nächsten Beiträgen werde ich eine elegante Lösung Logging mit AOP erarbeiten, die einige Vorteile in sich trägt:

Logging Einträge lassen sich sammeln
Logging Einträge lassen sich klassifizieren (unabhängig vom Level)
Logging Einträge lassen sich systematisieren und sind nicht mehr von den persönlichen Vorlieben des Entwicklers abhängig
Möglichkeit der Internationalisierung
Wiederverwendung von Logging Einträgen
Logging Texte lassen sich ändern (ohne Rebuild)
Logging Level lassen sich ändern (ohne Rebuild)
Die Entscheidung für eine Logging Library kann spät getroffen oder sogar revidiert werden
Cross Referenzen können gebildet werden
Unittest ohne Logging möglich