Beispiel für einfache Logging Configuration mit AspectJ

Thomas Darimont

Thomas Darimont

Erfahrenes Mitglied
Hallo,

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

Service Interface:
Java: 
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:
Java: 
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:
Java: 
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
Java: 
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:
Java: 
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: 
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: 
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: 
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:
Zum Vergrößern anklicken....
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!
Zum Vergrößern anklicken....
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
 
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...
Zum Vergrößern anklicken....
Na gut, mit Deiner Variante schaffst Du jedenfalls eine einheitliche Stelle, von der der Logger kommt. Das würdest Du allerdings auch mit
Code: 
public static Logger logger(Class<?> type) {
    return Logger.getLogger(type);
}
und dem Aufruf
Code: 
    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.
Zum Vergrößern anklicken....
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.
Zum Vergrößern anklicken....

Leider stimmt das nicht ganz:
Java: 
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: 
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...
Zum Vergrößern anklicken....
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: 
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: 
op
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) bubu
op
de.tutorials.StackTracelocationProblemWithProxies$Caller.directCall(StackTracelocationProblemWithProxies.java:23) bubu

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

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

Java: 
 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
 
Um antworten zu können musst du eingeloggt sein.

Neue Beiträge

Zurück