Hallo,

hier mal ein kleines Beispiel zur einfachen Verwendung / Konfiguration von Logging mit AspectJ:

Service Interface:

Code java:

1 2 3 4 5 6 7 8 9 10 11 12 13 14

package de.tutorials.training;   import static de.tutorials.training.util.Logging.logger; import de.tutorials.training.service.IService; import de.tutorials.training.service.internal.Service;   public class Main {     public static void main(String[] args) {         logger().info("Hallo Welt!");                 IService service = new Service();         service.operation1();     } }

Unsere Service Implementierung:

Code java:

1 2 3 4 5 6 7 8 9 10 11 12

package de.tutorials.training.service.internal;   import static de.tutorials.training.util.Logging.logger; import de.tutorials.training.service.IService;   public class Service implements IService {     public void operation1() {         if (logger().isDebugEnabled()) {             logger().debug("test");         }     } }

Wir verwenden hier eine statische Methode logger(), deren Implementierung so ausschaut:

Code java:

1 2 3 4 5 6 7 8 9

package de.tutorials.training.util;   import org.apache.log4j.Logger;   public class Logging {     public static Logger logger(){         return Logger.getLogger("default");     } }

So bekommt man immer den gleichen Logger. Will man nun für jede Klasse einen eigenen Logger haben so schreibt man für gewöhnlich

Code java:

1	Logger logger = Logger.getLogger(getClass());

Das bringt direkte Abhängigkeiten zu Logging-Frameworks in den Code.

Eine Alternative dazu wäre ein generischer (Compile time) Logging Aspect, der um den Aufruf
de.tutorials.training.util.Logger.logger() Code webt, welcher den entsprechenden Logger für die
aufrufende Klasse zurückliefert.

Unser Logging - Aspect:

Code java:

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20

package de.tutorials.training.aspects;   import java.util.Map; import java.util.concurrent.ConcurrentHashMap;   import org.apache.log4j.Logger;   public aspect Logging {     Logger around() : call(Logger de.tutorials.training.util.Logging.logger()){         Class<?> callingClass = thisEnclosingJoinPointStaticPart.getSignature().getDeclaringType();         Logger logger = loggers.get(callingClass);         if (logger == null) {             logger = Logger.getLogger(callingClass);             loggers.put(callingClass, logger);         }         return logger;     }         Map<Class<?>, Logger> loggers = new ConcurrentHashMap<Class<?>, Logger>(); }

Die Log4j Konfiguration:

Code :

1 2 3 4 5 6 7

log4j.rootLogger=INFO, stdout log4j.appender.stdout=org.apache.log4j.ConsoleAppender log4j.appender.stdout.layout=org.apache.log4j.PatternLayout log4j.appender.stdout.layout.ConversionPattern=%d %p [%c] - <%m>%n   log4j.logger.de.tutorials.training=INFO log4j.logger.de.tutorials.training.service=DEBUG

Ausgabe:

Code :

1 2	2009-11-03 12:25:39,823 INFO [de.tutorials.training.Main] - <Hallo Welt!> 2009-11-03 12:25:39,824 DEBUG [de.tutorials.training.service.internal.Service] - <test>

Gruß Tom

Hallo Tom,

Du kannst auch einfach im Stacktrace nachschauen, was die aufrufende Klasse ist:

Code :

1 2 3 4 5

public class Logging {     public static Logger logger(){         return Logger.getLogger(Thread.currentThread().getStackTrace()[3].getClassName());     } }

Gruß,
Arne

P.S.: Aber warum das Ganze? Über den Rückgabe-Wert Deiner logger()-Methode bekommst Du doch eh eine Abhängigkeit zu Deinem Logging-Framework!

Hallo,

Du kannst auch einfach im Stacktrace nachschauen, was die aufrufende Klasse ist:

Das funktioniert nur dann, wenn keine Proxies zwischen die Aufrufe geschaltet werden -> Sprich ist nicht sehr zuverlässig... insbesondere bei der Verwendung von Proxies oder auf bytecode Generiung basierten konfigurierbaren Security / Transaction / Caching Verfahren
ist der StackTrace nicht immer deterministisch.

Ber der oben genannten Methode kann so ein Fehler nicht passieren.

P.S.: Aber warum das Ganze? Über den Rückgabe-Wert Deiner logger()-Methode bekommst Du doch eh eine Abhängigkeit zu Deinem Logging-Framework!

Es ging mir eher darum, dass der Benutzer nicht mehr in Versuchung kommt "irgendwelche" Logger (Log4J/java.util.logger etc.) zu importieren... des weiteren kann man auch anstatt log4j LogBack, slf4j oder ein eigenes ILogger interface zurückgeben um den bytecode komplett unabhängig vom Logging Framework zu machen.

Gruß Tom

Hallo Tom,

In diesem Fall müsste der Stacktrace ganz gut funktionieren, da Du direkt aus Deinem Code heraus eine statische Methode aufrufst, d.h. die oberen drei Stacktrace-Elemente sind eigentlich eindeutig definiert. Ein Proxy kann sich da jedenfalls nirgends reinhängen und selbst wenn irgendein Framework den Bytecode Deiner logger()-Methode verändern würde, sollte das Stück Code auch funktionieren. Das einzige wäre, dass der Aufruf der logger()-Methode im Bytecode so verändert wird, dass nicht Deine statische Methode aufgerufen wird, sondern z.B. ein Proxy. Ein Framework, dass so einen Schweinkram macht, ist mir aber bisher noch nicht untergekommen.

Gruß,
Arne

Zitat von Thomas Darimont

Es ging mir eher darum, dass der Benutzer nicht mehr in Versuchung kommt "irgendwelche" Logger (Log4J/java.util.logger etc.) zu importieren...

Na gut, mit Deiner Variante schaffst Du jedenfalls eine einheitliche Stelle, von der der Logger kommt. Das würdest Du allerdings auch mit

Code :

1 2 3

public static Logger logger(Class<?> type) {     return Logger.getLogger(type); }

und dem Aufruf

Code :

1	Logger.logger(getClass())...;

erreichen.

Zitat von Thomas Darimont

des weiteren kann man auch anstatt log4j LogBack oder ein eigenes ILogger interface zurückgeben um den bytecode komplett unabhängig vom Logging Framework zu machen.

Nicht zu vergessen commons-logging und slf4j Logger und Logging-Wrapper gibt es genug!
In dem Zusammenhang habe ich nie verstanden, warum java.util.logging.Logger kein Interface ist...

Hallo,

In diesem Fall müsste der Stacktrace ganz gut funktionieren, da Du direkt aus Deinem Code heraus eine statische Methode aufrufst, d.h. die oberen drei Stacktrace-Elemente sind eigentlich eindeutig definiert. Ein Proxy kann sich da jedenfalls nirgends reinhängen und selbst wenn irgendein Framework den Bytecode Deiner logger()-Methode verändern würde, sollte das Stück Code auch funktionieren.

Leider stimmt das nicht ganz:

Code java:

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52

package de.tutorials;   import java.lang.reflect.InvocationHandler; import java.lang.reflect.Method; import java.lang.reflect.Proxy;   public class StackTracelocationProblemWithProxies {         public static void main(String[] args) {         Caller caller = new Caller();         caller.proxyCall();         caller.directCall();     }         static class Caller{         void proxyCall(){             IService service = (IService)Proxy.newProxyInstance(IService.class.getClassLoader(), new Class[]{IService.class}, createInvocationHandler(new Service()));             service.op();           }           void directCall() {             IService service = new Service();             service.op();                     }     }         private static InvocationHandler createInvocationHandler(final Object target) {         return new InvocationHandler() {             @Override public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {                 return method.invoke(target, args);             }         };     }       static interface IService{         void op();     }         static class Service implements IService{         @Override public void op() {             System.out.println("op");             log("bubu");         }             }         static void log(String message){         System.out.println(Thread.currentThread().getStackTrace()[3] +" " + message);     }     }

Ausgabe:

Code :

1 2 3 4

op sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) bubu op de.tutorials.StackTracelocationProblemWithProxies$Caller.directCall(StackTracelocationProblemWithProxies.java:23) bubu

Mit dem obigen AspectJ Aspect würde man anstatt sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) message
....Caller.proxyCall(...) sehen würde. Mich interessiert hier eher welcher BusinessCode hat mich aufgerufen... sprich ich möchte die Proxy calls etc ignorieren. Ich möchte die Stelle wissen wo direkt im Code der Mehodenaufruf steht.

Das lässt sich mit der Stacktrace Methode nicht ohne weiteres lösen (okay man könnte den StackTrace dynamisch ablaufen und ungewünschte Proxy aufrufe filtern,aber naja...) . Da wie schon gesagt der StackTrace durch Proxies und sonstige zwischen Aufrufe innerhalb dieser umgebogen werden kann, so dass man nicht mehr ohne weiteres sagen kann an welcher Stelle nun ein bestimmter Methoden Aufruf im Stacktrace steht.

Nicht zu vergessen commons-logging und slf4j Logger und Logging-Wrapper gibt es genug!
In dem Zusammenhang habe ich nie verstanden, warum java.util.logging.Logger kein Interface ist...

Ich wollte hier nicht alle Logging Frameworks aufzählen... btw. würde wohl bei neuen Projekten eher auf die Kombi: slf4j und Logback setzen. Hmmm ich glaub zur damaligen Zeit war es gerade Mode sein eigenes Logging Framework zu schreiben...

Gruß Tom

Interessant,

mit welcher Java-Version führst Du Deinen Code aus? Bei mir (mit 1.5.0_15) ist die Ausgabe Deines Code-Schnipsels:

Code :

1 2 3 4

op de.tutorials.StackTracelocationProblemWithProxies$Service.op(StackTracelocationProblemWithProxies.java:43) bubu op de.tutorials.StackTracelocationProblemWithProxies$Service.op(StackTracelocationProblemWithProxies.java:43) bubu

Das entspricht genau dem, was ich erwartet hätte. Die Stelle ist auch der Business-Code, also genau das, was man für das Logging bräuchte.

Gruß,
Arne

Hallo,

zuhause mit OpenJDK 1.6.0_0 und im Büro bekomme ich mit: SUN JDK 1.6.0_13 die Ausgabe (kompiliert mit Eclipse JDT Compiler):

Code :

1 2 3 4

op sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) bubu op de.tutorials.StackTracelocationProblemWithProxies$Caller.directCall(StackTracelocationProblemWithProxies.java:23) bubu

Code java:

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52

package de.tutorials;   import java.lang.reflect.InvocationHandler; import java.lang.reflect.Method; import java.lang.reflect.Proxy;   public class StackTracelocationProblemWithProxies {         public static void main(String[] args) {         Caller caller = new Caller();         caller.proxyCall();         caller.directCall();     }         static class Caller{         void proxyCall(){             IService service = (IService)Proxy.newProxyInstance(IService.class.getClassLoader(), new Class[]{IService.class}, createInvocationHandler(new Service()));             service.op();           }           void directCall() {             IService service = new Service();             service.op();                     }     }         private static InvocationHandler createInvocationHandler(final Object target) {         return new InvocationHandler() {             @Override public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {                 return method.invoke(target, args);             }         };     }       static interface IService{         void op();     }         static class Service implements IService{         @Override public void op() {             System.out.println("op");             log("bubu");         }             }         static void log(String message){         System.out.println(Thread.currentThread().getStackTrace()[3] +" " + message);     }     }

Die von dir gepostete Ausgabe bekomme ich nur dann hin, wenn ich anstatt:

Code java:

1	System.out.println(Thread.currentThread().getStackTrace()[3] +" " + message);

Code java:

1	System.out.println(Thread.currentThread().getStackTrace()[   2   ] +" " + message);

angebe. Mich interessiert aber der Caller von op und nicht der Caller von log! Nochmal, mit dem Beispiel wollte ich
nur demonstrieren, dass man sich nicht auf absolute StackTrace Positionen verlassen kann.

Gruß Tom

In Deinem ersten Beispiel interessiert schon der Aufrufer von logger() (nämlich, um den richtigen Logger zu ermitteln).

Der Stacktrace ist aber tatsächlich von Java-Version zu Java-Version unterschiedlich. Ich habe es ausprobiert. Mit Java 6 bekomme ich auch Dein Ergebnis.

Von daher muss ich Dir Recht geben: Mit Deinem Logging-Aspekt ist man auf der sicheren Seite. Proxies sind hier aber trotzdem kein Problem

Gruß,
Arne

Hallo Thomas,

ich denke da hat einer eine imho bessere Lösung im Sinn: http://marko-software-developer.blogspot.com/ .

Wobei mir die Idee gefällt, das auch noch dann geloggt wird, wenn der Aspekt nicht eingebunden wird. Aber besonders schön finde ich die Lösung nicht.

Nichts für ungut


Gruss Loddar