Logging mit Spring AOP
Logging ist wichtig. Trotzdem spricht vieles gegen zu viel Logging in Anwendungen:
- Logging ist für die Funktion einer Anwendung unnötig.
- Logging macht den Quellcode unübersichtlich.
- Logging beeinträchtigt die Performance.
Alle diese Nachteile lassen sich vermeiden und trotzdem kann der Aufruf jeder Methode incl. Parameter und Rückgabewerte und die Laufzeit geloggt werden. Möglich machen dies Spring und Aspektorientierte Programmierung (AOP).
Eine Klasse übernimt das Logging der Methodenaufrufe, die andere das Laufzeitlogging:
Methodenlogger:
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.aspectj.lang.JoinPoint;
public class MethodenLogger {
private static final Log LOG = LogFactory.getLog( MethodenLogger.class );
public void logMethodEntry( final JoinPoint joinPoint ) {
if( LOG.isDebugEnabled() ) {
final String targetClassName = joinPoint.getTarget().getClass().getName();
final Log targetLog = LogFactory.getLog( targetClassName );
if( targetLog.isDebugEnabled() ) {
final Object[] args = joinPoint.getArgs();
final String name = joinPoint.getSignature().toLongString();
final StringBuffer sb = new StringBuffer( name + ” called with: [" );
for( int i = 0; i < args.length; i++ ){
final Object o = args[ i ];
sb.append( o );
sb.append( ( i == args.length - 1 ) ? ”]” : ”, ” );
}
LOG.debug( sb );
}
}
}
public void logMethodExit( final JoinPoint joinPoint, final Object result ) {
if( LOG.isDebugEnabled() ) {
final String targetClassName = joinPoint.getTarget().getClass().getName();
final Log targetLog = LogFactory.getLog( targetClassName );
if( targetLog.isDebugEnabled() ) {
final String name = joinPoint.getSignature().toLongString();
LOG.debug( name + ” returning: [" + result + "]“ );
}
}
}
}
Laufzeitlogger:
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.aspectj.lang.ProceedingJoinPoint;
import org.springframework.core.Ordered;
import org.springframework.util.StopWatch;
public class LaufzeitLogger {
private static final Log LOG = LogFactory.getLog( LaufzeitLogger.class );
// this method is the around advice
public Object loggeLaufzeit( final ProceedingJoinPoint call ) throws Throwable {
Object returnValue;
if( LOG.isDebugEnabled() ) {
final String targetClassName = call.getTarget().getClass().getName();
final String targetMethodName = call.getSignature().getName();
final Log targetLog = LogFactory.getLog( targetClassName );
if( targetLog.isDebugEnabled() ) {
final StopWatch clock = new StopWatch( getClass().getName() );
try {
clock.start( call.toShortString() );
returnValue = call.proceed();
}
finally {
clock.stop();
final StringBuffer sb = new StringBuffer( ”Laufzeit ” );
sb.append( targetMethodName ).append( ”: ” );
sb.append( Hilfsmethoden.erzeugeLesbareDauer( clock.getTotalTimeMillis() ) );
targetLog.debug( sb.toString() );
}
}
else {
returnValue = call.proceed();
}
}
else {
returnValue = call.proceed();
}
return returnValue;
}
}
Wie aber werden die Methoden loggeLaufzeit, logMethodEntry und logMethodExit aufgerufen? Die Spring Beans werden so konfiguriert, dass beim Aufruf jeder beliebigen Methoden in den Beans die Logger benutzt werden können. Die Konfiguration erfolgt deklarativ in der Spring XML Definition der Beans:
<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns=”http://www.springframework.org/schema/beans”
xmlns:xsi=”http://www.w3.org/2001/XMLSchema-instance”
xmlns:aop=”http://www…org/schema/aop”
xmlns:tx=”http://www…org/schema/tx”
xsi:schemaLocation=”
http://www…org/schema/beans http://www…org/schema/beans/spring-beans-2.0.xsd
http://www…org/schema/tx http://www…org/schema/tx/spring-tx-2.0.xsd
http://www…org/schema/aop http://www…org/schema/aop/spring-aop-2.0.xsd”>
<!– Laufzeit-Logger aspect –>
<bean id=”laufzeitLogger” class=”com.carano.aop.LaufzeitLogger” />
<!– Aufruf-Logger aspect –>
<bean id=”methodenLogger” class=”com.carano.aop.MethodenLogger” />
<aop:config>
<aop:pointcut id=”statusServiceMothoden”
expression=”execution(* ServiceHandlerHibernate.*(..))” />
<aop:pointcut id=”daoMothoden”
expression=”execution(* hibernate.*Dao.*(..))” />
<aop:aspect id=”profilingAspect” ref=”laufzeitLogger”>
<aop:around method=”loggeLaufzeit”
pointcut-ref=”statusServiceMothoden” />
<aop:around method=”loggeLaufzeit”
pointcut-ref=”daoMothoden” />
</aop:aspect>
<aop:aspect id=”loggingAspect” ref=”methodenLogger”>
<aop:before method=”logMethodEntry”
pointcut-ref=”statusServiceMothoden” />
<aop:after-returning method=”logMethodExit”
returning=”result” pointcut-ref=”statusServiceMothoden” />
<aop:before method=”logMethodEntry”
pointcut-ref=”daoMothoden” />
<aop:after-returning method=”logMethodExit” returning=”result”
pointcut-ref=”daoMothoden” />
</aop:aspect>
</aop:config>
</beans>
In den Parametern expression der aop:pointcut Elemente wird definiert welche Methoden geloggt werden. Geloggt wird nur, wenn auch die log4j Einstellungen entsprechend gesetzt sind. Das Loglevel des LaufzeitLogger bzw. MethodenLogger und der Klasse, die die Methode enthält muss auf DEBUG gestellt sein.
Der deklarative Ansatz hat den Vorteil, das durch das Entfernen der Konfiguration oben, das Logging aus der Anwendung “verschwindet”. Es gibt dann kein Beeinträchtigung der Laufzeit mehr durch das Logging. Durch die Auslagerung in Aspekte, bleibt die Anwendung frei von Logging-Statements. Der Code ist übersichtlich und enthält nur den funktionalen Teil.
Hier ein Auszug aus dem Logfile:
DEBUG [aop.MethodenLogger]
public Code hibernate.CodeDao.sucheCode(java.lang.String,java.lang.String) called with: [JOB_STATUS, NEU]
DEBUG [aop.MethodenLogger]
public Code hibernate.CodeDao.sucheCode(java.lang.String,java.lang.String) returning: [hibernate.entities.Code@110278e]
DEBUG [hibernate.CodeDao] Laufzeit sucheCode: 45ms
Dokumentation:
Denis sagte,
18. Dezember 2007 @ 8:07 Uhr nachmittags
Super Artikel!
Herzlichen Dank, hab schon lange davon geträumt und wusste, dass es schnell und effektiv zu machen ist.
Eine Frage nur: Kann es sein, dass die Aspekte nur auf die beans wirken die auch im Spring Kontext deklariert sind. Irgendwie werden die JavaKlassen, die nicht im Springcontainer
erwähnt wurden bei mir nicht durch die beiden Aspekte aufgegriffen, obwohl der Pointcut richtig zu sein scheint.
Denis sagte,
18. Dezember 2007 @ 8:10 Uhr nachmittags
Ach bitte noch eventuell das Bibliotheken Problem erwähnen, das ist ganz schreklich! Hab einen ganz Tag dran verbraten.
Hier ist die Lösung:
asm
asm
2.2.2
org.hibernate
hibernate
3.2.2.ga
asm
asm
asm
asm-attrs
cglib
cglib
asm
asm-all
2.2.3
cglib
cglib-nodep
2.1_3
murygin sagte,
19. Dezember 2007 @ 11:45 Uhr vormittags
Kommentar 1: Richtig, die Aspekte wirken nur auf Beans aus dem Spring Kontext.. Allerdings kann man ja leicht aus jeder Klasse ein Spring Bean machen. Nur mit Klassen aus Bibliotheken geht das nicht…
murygin sagte,
19. Dezember 2007 @ 12:01 Uhr nachmittags
Kommentar 2: Du benutzt auch Maven wie ich sehe…
Oh ja - die Bibliotheken sind ein Problem! Es gibt Konflikte wenn man Spring AOP und Hibernate benutzt, da beide verschiedene Versionen von ASM und cglib benutzen, die nicht kompatibel sind. Aus dem Abhängigkeiten von Hibernate muss man daher ASM und cglib ausschließen und andere Versionen der Bibliotheken benutzen: cglib-nodep-2.1_3 und asm-2.2.3. Hier meine Dependencies:
<!– Hibernate –>
<dependency>
<groupId>org.hibernate</groupId>
<artifactId>hibernate</artifactId>
<version>[3.2.2.ga]</version>
<exclusions>
<exclusion>
<groupId>asm</groupId>
<artifactId>asm</artifactId>
</exclusion>
<exclusion>
<groupId>asm</groupId>
<artifactId>asm-attrs</artifactId>
</exclusion>
<exclusion>
<groupId>cglib</groupId>
<artifactId>cglib</artifactId>
</exclusion>
</exclusions>
</dependency>
<dependency>
<groupId>cglib</groupId>
<artifactId>cglib-nodep</artifactId>
<version>2.1_3</version>
</dependency>
<dependency>
<groupId>net.sourceforge.jtds</groupId>
<artifactId>jtds</artifactId>
<version>1.2</version>
<scope>runtime</scope>
</dependency>
<dependency>
<groupId>net.sf.ehcache</groupId>
<artifactId>ehcache</artifactId>
<version>1.2.4</version>
<scope>runtime</scope>
</dependency>
<!– Spring –>
<dependency>
<groupId>org.springframework</groupId>
<artifactId>spring-core</artifactId>
<version>2.0.7</version>
</dependency>
<dependency>
<groupId>org.springframework</groupId>
<artifactId>spring-context</artifactId>
<version>2.0.7</version>
</dependency>
<dependency>
<groupId>org.springframework</groupId>
<artifactId>spring-hibernate3</artifactId>
<version>2.0.7</version>
</dependency>
<dependency>
<groupId>org.springframework</groupId>
<artifactId>spring-aspects</artifactId>
<version>2.0.7</version>
</dependency>
<dependency>
<groupId>org.springframework</groupId>
<artifactId>spring-aop</artifactId>
<version>2.0.7</version>
</dependency>
<dependency>
<groupId>org.springframework</groupId>
<artifactId>spring-jmx</artifactId>
<version>2.0.7</version>
</dependency>
<dependency>
<groupId>xerces</groupId>
<artifactId>xerces</artifactId>
<version>2.4.0</version>
</dependency>
<dependency>
<groupId>xerces</groupId>
<artifactId>xercesImpl</artifactId>
<version>2.4.0</version>
</dependency>
<dependency>
<groupId>aspectj</groupId>
<artifactId>aspectjrt</artifactId>
<version>1.5.3</version>
</dependency>
<dependency>
<groupId>asm</groupId>
<artifactId>asm-commons</artifactId>
<version>2.2.3</version>
</dependency>