# Beispiel für einfache Logging Configuration mit AspectJ



## Thomas Darimont (3. November 2009)

Hallo,

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

Service Interface:

```
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:

```
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:

```
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

```
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:

```
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:

```
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:

```
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


----------



## arnelim (2. Januar 2010)

Hallo Tom,

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

```
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!


----------



## Thomas Darimont (2. Januar 2010)

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


----------



## arnelim (2. Januar 2010)

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


----------



## arnelim (2. Januar 2010)

Thomas Darimont hat gesagt.:


> 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

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

```
Logger.logger(getClass())...;
```
erreichen.



Thomas Darimont hat gesagt.:


> 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...


----------



## Thomas Darimont (2. Januar 2010)

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:

```
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:

```
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


----------



## arnelim (4. Januar 2010)

Interessant,

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

```
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


----------



## Thomas Darimont (4. Januar 2010)

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):

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


```
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:


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


```
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


----------



## arnelim (4. Januar 2010)

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


----------



## loddar rocks (3. Februar 2010)

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


----------

