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( JoinPoint joinPoint ) {
    if( LOG.isDebugEnabled() ) {
      String targetClassName = joinPoint.getTarget().getClass().getName();
      Log targetLog = LogFactory.getLog( targetClassName );
      if( targetLog.isDebugEnabled() ) {
        Object[] args = joinPoint.getArgs();
        String name = joinPoint.getSignature().toLongString();
        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( JoinPoint joinPoint, Object result ) {
    if( LOG.isDebugEnabled() ) {
      String targetClassName = joinPoint.getTarget().getClass().getName();
      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( ProceedingJoinPoint call ) throws Throwable {
    Object returnValue;
    if( LOG.isDebugEnabled() ) {
      String targetClassName = call.getTarget().getClass().getName();
      String targetMethodName = call.getSignature().getName();
      Log targetLog = LogFactory.getLog( targetClassName );
      if( targetLog.isDebugEnabled() ) {
        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

    • Denis
    • 18. Dezember 2007

    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
    • 18. Dezember 2007

    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

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

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

  1. No trackbacks yet.

Schreibe einen Kommentar

Trage deine Daten unten ein oder klicke ein Icon um dich einzuloggen:

WordPress.com-Logo

Du kommentierst mit Deinem WordPress.com-Konto. Abmelden / Ändern )

Twitter-Bild

Du kommentierst mit Deinem Twitter-Konto. Abmelden / Ändern )

Facebook-Foto

Du kommentierst mit Deinem Facebook-Konto. Abmelden / Ändern )

Google+ Foto

Du kommentierst mit Deinem Google+-Konto. Abmelden / Ändern )

Verbinde mit %s

%d Bloggern gefällt das: